Skip to content

feat(tests): allow RUST_LOG with multiple tags for native executables #2452

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Draft
dimxy wants to merge 9 commits into
base: dev
Choose a base branch
from
+96 −39
Draft

feat(tests): allow RUST_LOG with multiple tags for native executables #2452

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
9cc04cf
feature(tests): allow RUST_LOG with multiple tags for native exe in t…
May 12, 2025
fa67138
refactor (borngraced): nits parsing envs
May 12, 2025
864e7e5
temp enable outer watcher log (to debug tests)
May 12, 2025
fda8099
remove commented log code in watcher tests
May 12, 2025
9675bd8
add lp_swap=info to log tags
May 13, 2025
31d9d69
review (mariocynicys): replace 'module=off' on 'info', remove unused …
May 13, 2025
a2dca34
Merge remote-tracking branch 'origin/dev' into allow-rust-log-tags
shamardy Jul 24, 2025
66a293d
Refactor test code (mariocynicys review): better name for connected p…
Jul 24, 2025
5c6569a
Merge branch 'dev' into allow-rust-log-tags
Jul 25, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 7 additions & 5 deletions mm2src/mm2_main/tests/docker_tests/docker_tests_inner.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -5543,11 +5543,12 @@ fn test_peer_time_sync_validation() {
let timeoffset_tolerable = TryInto::<i64>::try_into(MAX_TIME_GAP_FOR_CONNECTED_PEER).unwrap() - 1;
let timeoffset_too_big = TryInto::<i64>::try_into(MAX_TIME_GAP_FOR_CONNECTED_PEER).unwrap() + 1;

let start_peers_with_time_offset = |offset: i64| -> (Json, Json) {
let start_peers_with_time_offset = |offset: i64, skip_peers_check: bool| -> (Json, Json) {
let (_ctx, _, bob_priv_key) = generate_utxo_coin_with_random_privkey("MYCOIN", 10.into());
let (_ctx, _, alice_priv_key) = generate_utxo_coin_with_random_privkey("MYCOIN1", 10.into());
let coins = json!([mycoin_conf(1000), mycoin1_conf(1000)]);
let bob_conf = Mm2TestConf::seednode(&hex::encode(bob_priv_key), &coins);
let mut bob_conf = Mm2TestConf::seednode(&hex::encode(bob_priv_key), &coins);
bob_conf.conf["skip_peers_check"] = skip_peers_check.into();
let mut mm_bob = block_on(MarketMakerIt::start_with_envs(
bob_conf.conf,
bob_conf.rpc_password,
Expand All @@ -5557,8 +5558,9 @@ fn test_peer_time_sync_validation() {
.unwrap();
let (_bob_dump_log, _bob_dump_dashboard) = mm_dump(&mm_bob.log_path);
block_on(mm_bob.wait_for_log(22., |log| log.contains(">>>>>>>>> DEX stats "))).unwrap();
let alice_conf =
let mut alice_conf =
Mm2TestConf::light_node(&hex::encode(alice_priv_key), &coins, &[mm_bob.ip.to_string().as_str()]);
alice_conf.conf["skip_peers_check"] = skip_peers_check.into();
let mut mm_alice = block_on(MarketMakerIt::start_with_envs(
alice_conf.conf,
alice_conf.rpc_password,
Expand Down Expand Up @@ -5595,7 +5597,7 @@ fn test_peer_time_sync_validation() {
};

// check with small time offset:
let (bob_peers, alice_peers) = start_peers_with_time_offset(timeoffset_tolerable);
let (bob_peers, alice_peers) = start_peers_with_time_offset(timeoffset_tolerable, false);
assert!(
bob_peers["result"].as_object().unwrap().len() == 1,
"bob must have one peer"
Expand All @@ -5606,7 +5608,7 @@ fn test_peer_time_sync_validation() {
);

// check with too big time offset:
let (bob_peers, alice_peers) = start_peers_with_time_offset(timeoffset_too_big);
Copy link
Collaborator

@mariocynicys mariocynicys May 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

how did this used to work before even tho the default behavior is setting skip_seednodes_check = false?

Copy link
Collaborator Author

@dimxy dimxy Jul 24, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It had worked before this PR because the node waited for log message 'Completed IAmrelay handling for peer' and this message always was added to the log when a peer connected (even if the peer was later rejected due to big time diff)

let (bob_peers, alice_peers) = start_peers_with_time_offset(timeoffset_too_big, true); // skip_peers_check = true as there should not be connected peers
assert!(
bob_peers["result"].as_object().unwrap().is_empty(),
"bob must have no peers"
Expand Down
12 changes: 6 additions & 6 deletions mm2src/mm2_main/tests/docker_tests/swap_watcher_tests.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -304,8 +304,6 @@ fn run_taker_node(
envs,
))
.unwrap();
let (_dump_log, _dump_dashboard) = mm.mm_dump();
log!("Log path: {}", mm.log_path.display());
Comment on lines -307 to -308
Copy link
Collaborator

@mariocynicys mariocynicys May 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why are we removing these. and other occurrences too.

Copy link
Collaborator Author

@dimxy dimxy Jul 24, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

removing _dump_log inside the run_watcher_node because _dump_log here, when dropped on run_watcher_node exit, dumps incomplete log.
Instead new _watcher_dump_log is added in the test fn itself (so it dumps the log when the test finishes).


generate_utxo_coin_with_privkey("MYCOIN", 100.into(), H256::from_str(&privkey).unwrap());
generate_utxo_coin_with_privkey("MYCOIN1", 100.into(), H256::from_str(&privkey).unwrap());
Expand Down Expand Up @@ -355,8 +353,6 @@ fn run_maker_node(
envs,
))
.unwrap();
let (_dump_log, _dump_dashboard) = mm.mm_dump();
log!("Log path: {}", mm.log_path.display());

generate_utxo_coin_with_privkey("MYCOIN", 100.into(), H256::from_str(&privkey).unwrap());
generate_utxo_coin_with_privkey("MYCOIN1", 100.into(), H256::from_str(&privkey).unwrap());
Expand Down Expand Up @@ -385,8 +381,6 @@ fn run_watcher_node(
envs,
))
.unwrap();
let (_dump_log, _dump_dashboard) = mm.mm_dump();
log!("Log path: {}", mm.log_path.display());

generate_utxo_coin_with_privkey("MYCOIN", 100.into(), H256::from_str(&privkey).unwrap());
generate_utxo_coin_with_privkey("MYCOIN1", 100.into(), H256::from_str(&privkey).unwrap());
Expand Down Expand Up @@ -427,6 +421,9 @@ fn test_taker_saves_the_swap_as_successful_after_restart_panic_at_wait_for_taker
log!("Alice log path: {}", mm_alice.log_path.display());
alice_conf.conf["dbdir"] = mm_alice.folder.join("DB").to_str().unwrap().into();

let (_watcher_dump_log, _watcher_dump_dashboard) = mm_watcher.mm_dump();
log!("Watcher log path: {}", mm_watcher.log_path.display());

block_on(mm_alice.wait_for_log(120., |log| log.contains(WATCHER_MESSAGE_SENT_LOG))).unwrap();
block_on(mm_bob.wait_for_log(120., |log| log.contains(&format!("[swap uuid={}] Finished", &uuids[0])))).unwrap();
block_on(mm_watcher.wait_for_log(120., |log| log.contains(MAKER_PAYMENT_SPEND_SENT_LOG))).unwrap();
Expand Down Expand Up @@ -488,6 +485,9 @@ fn test_taker_saves_the_swap_as_successful_after_restart_panic_at_maker_payment_
log!("Alice log path: {}", mm_alice.log_path.display());
alice_conf.conf["dbdir"] = mm_alice.folder.join("DB").to_str().unwrap().into();

let (_watcher_dump_log, _watcher_dump_dashboard) = mm_watcher.mm_dump();
log!("Watcher log path: {}", mm_watcher.log_path.display());

block_on(mm_alice.wait_for_log(120., |log| log.contains(WATCHER_MESSAGE_SENT_LOG))).unwrap();
block_on(mm_bob.wait_for_log(120., |log| log.contains(&format!("[swap uuid={}] Finished", &uuids[0])))).unwrap();
block_on(mm_watcher.wait_for_log(120., |log| log.contains(MAKER_PAYMENT_SPEND_SENT_LOG))).unwrap();
Expand Down
2 changes: 1 addition & 1 deletion mm2src/mm2_main/tests/docker_tests/swaps_file_lock_tests.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -166,7 +166,7 @@ fn test_swaps_should_kick_start_if_process_was_killed() {
// dropping instead of graceful stop to retain swap file locks
drop(mm_alice);

alice_conf["skip_seednodes_check"] = true.into();
alice_conf["skip_peers_check"] = true.into();
let mut mm_alice_dup = MarketMakerIt::start(alice_conf, "pass".to_string(), None).unwrap();
let (_alice_dup_dump_log, _alice_dup_dump_dashboard) = mm_dump(&mm_alice_dup.log_path);
log!("{:?}", block_on(enable_native(&mm_alice_dup, "MYCOIN", &[], None)));
Expand Down
20 changes: 5 additions & 15 deletions mm2src/mm2_main/tests/integration_tests_common/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,5 +1,4 @@
use common::executor::Timer;
use common::log::LogLevel;
use common::{block_on, log, now_ms, wait_until_ms};
use crypto::privkey::key_pair_from_seed;
use mm2_main::{lp_main, lp_run, LpMainParams};
Expand All @@ -14,26 +13,17 @@ use mm2_test_helpers::structs::{
use serde_json::{self as json, Value as Json};
use std::collections::HashMap;
use std::env::var;
use std::str::FromStr;

/// This is not a separate test but a helper used by `MarketMakerIt` to run the MarketMaker from the test binary.
#[test]
#[cfg(not(target_arch = "wasm32"))]
fn test_mm_start() {
test_mm_start_impl();
}

pub fn test_mm_start_impl() {
if let Ok(conf) = var("_MM2_TEST_CONF") {
if let Ok(log_var) = var("RUST_LOG") {
if let Ok(filter) = LogLevel::from_str(&log_var) {
log!("test_mm_start] Starting the MarketMaker...");
let conf: Json = json::from_str(&conf).unwrap();
let params = LpMainParams::with_conf(conf).log_filter(Some(filter));
let ctx = block_on(lp_main(params, &|_ctx| (), "TEST".into(), "TEST".into())).unwrap();
block_on(lp_run(ctx))
}
}
log!("test_mm_start] Starting the MarketMaker...");
let conf: Json = json::from_str(&conf).unwrap();
let params = LpMainParams::with_conf(conf);
let ctx = block_on(lp_main(params, &|_ctx| (), "TEST".into(), "TEST".into())).unwrap();
block_on(lp_run(ctx))
}
}

Expand Down
89 changes: 77 additions & 12 deletions mm2src/mm2_test_helpers/src/for_tests.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1390,14 +1390,15 @@ impl MarketMakerIt {
let executable = try_s!(env::args().next().ok_or("No program name"));
let executable = try_s!(Path::new(&executable).canonicalize());
let log = try_s!(fs::File::create(&log_path));
let envs_fixed = fix_rust_log_if_present(envs);
let child = try_s!(Command::new(executable)
.arg("test_mm_start")
.arg("--nocapture")
.current_dir(&folder)
.env("_MM2_TEST_CONF", try_s!(json::to_string(&conf)))
.env("MM2_UNBUFFERED_OUTPUT", "1")
.env("RUST_LOG", "debug")
.envs(envs.to_vec())
.env("RUST_LOG", read_rust_log().as_str())
.envs(envs_fixed.into_iter())
.stdout(try_s!(log.try_clone()))
.stderr(log)
.spawn());
Expand Down Expand Up @@ -1679,14 +1680,37 @@ impl MarketMakerIt {
.map_err(|e| ERRL!("{:?}", e))
}

/// Currently, we cannot wait for the `Completed IAmrelay handling for peer` log entry on WASM node,
/// because the P2P module logs to a global logger and doesn't log to the dashboard.
/// Check if the node is connected to at least one seednode,
/// the rpc is used instead of checking the log for DEBUG messages (to opt out p2p debug logging)
#[cfg(not(target_arch = "wasm32"))]
pub async fn check_seednodes(&mut self) -> Result<(), String> {
// wait for at least 1 node to be added to relay mesh
self.wait_for_log(22., |log| log.contains("Completed IAmrelay handling for peer"))
.await
.map_err(|e| ERRL!("{}", e))
pub async fn check_if_any_peer_connected(&mut self) -> Result<(), String> {
let timeout_sec = 22.;
let start = now_float();
loop {
if let Ok(res) = self.rpc(&json!({
"userpass": self.userpass,
"method": "get_directly_connected_peers",
}))
.await {
if res.0.is_success() {
let res_value = serde_json::from_str::<Json>(&res.1).unwrap();
if let Some(peers) = res_value["result"].as_object() {
if peers.len() > 0 {
return Ok(());
}
}
}
}
if now_float() - start > timeout_sec {
return ERR!("Timeout expired waiting for connected peers");
}
if let Some(ref mut pc) = self.pc {
if !pc.running() {
return ERR!("MM process terminated prematurely at: {:?}.", self.folder);
}
}
Comment on lines +1707 to +1711
Copy link
Collaborator

@mariocynicys mariocynicys May 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

didn't understand why we had this, but looks like it's some logic found in wait_for_log that was used before.

i think the fact that the rpc replied to us is enough to determine that mm2 is alive, so such a check isn't really needed.

Copy link
Collaborator Author

@dimxy dimxy Jul 24, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I'd better catch the error from self.rpc() so we can progress and stop with the known "MM process terminated prematurely" error

Timer::sleep(1.).await
}
}

/// Wait for the node to start listening to new P2P connections.
Expand Down Expand Up @@ -1723,9 +1747,9 @@ impl MarketMakerIt {
try_s!(self.wait_for_p2p_listen().await);
}

let skip_seednodes_check = conf["skip_seednodes_check"].as_bool().unwrap_or_default();
if conf["seednodes"].as_array().is_some() && !skip_seednodes_check {
try_s!(self.check_seednodes().await);
let skip_peers_check = conf["skip_peers_check"].as_bool().unwrap_or_default();
if conf["seednodes"].as_array().is_some() && !skip_peers_check {
try_s!(self.check_if_any_peer_connected().await);
}
}

Expand Down Expand Up @@ -4131,3 +4155,44 @@ pub async fn active_swaps(mm: &MarketMakerIt) -> ActiveSwapsResponse {
assert_eq!(response.0, StatusCode::OK, "'active_swaps' failed: {}", response.1);
json::from_str(&response.1).unwrap()
}

/// Helper to read RUST_LOG env variable and ensure it contains module=info for certain modules needed for tests (wait_for_log to work correctly)
#[cfg(not(target_arch = "wasm32"))]
fn read_rust_log() -> String {
let rust_log = env::var("RUST_LOG").unwrap_or_else(|_| "debug".to_string()); // assume RUST_LOG=debug by default
ensure_needed_modules_logged(&rust_log)
}

/// Helper to ensure that RUST_LOG (if present in env_vars) contains module=info for certain modules needed for tests (wait_for_log to work correctly)
#[cfg(not(target_arch = "wasm32"))]
fn fix_rust_log_if_present(env_vars: &[(&str, &str)]) -> Vec<(String, String)> {
env_vars.iter().map(|(key, value)| {
if *key == "RUST_LOG" {
(key.to_string(), ensure_needed_modules_logged(value))
} else {
(key.to_string(), value.to_string())
}
})
.collect()
}

#[cfg(not(target_arch = "wasm32"))]
fn ensure_needed_modules_logged(rust_log: &str) -> String {
// Add module=info or replace module=off with module=info
let ensure_contains_info = |source: &str, module: &str| {
let mut updated = source.split(',')
.filter(|s| s != &&(module.to_owned() + "=off"))
.collect::<Vec<_>>()
.join(",");
if !updated.contains(&(module.to_owned() + "=")) { // don't override existing module tag (but ignore submodules)
if updated.len() > 0 {
updated.push(',');
}
updated.push_str(&(module.to_owned() + "=info"));
}
updated
};
let updated = ensure_contains_info(rust_log, "mm2_p2p");
let updated = ensure_contains_info(updated.as_str(), "mm2_main::lp_swap");
updated
}
Loading