diff --git a/mm2src/mm2_main/tests/docker_tests/docker_tests_inner.rs b/mm2src/mm2_main/tests/docker_tests/docker_tests_inner.rs index fdb66d6284..08906e3402 100644 --- a/mm2src/mm2_main/tests/docker_tests/docker_tests_inner.rs +++ b/mm2src/mm2_main/tests/docker_tests/docker_tests_inner.rs @@ -5543,11 +5543,12 @@ fn test_peer_time_sync_validation() { let timeoffset_tolerable = TryInto::::try_into(MAX_TIME_GAP_FOR_CONNECTED_PEER).unwrap() - 1; let timeoffset_too_big = TryInto::::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, @@ -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, @@ -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" @@ -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); + 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" diff --git a/mm2src/mm2_main/tests/docker_tests/swap_watcher_tests.rs b/mm2src/mm2_main/tests/docker_tests/swap_watcher_tests.rs index 3097db34c3..36196bba85 100644 --- a/mm2src/mm2_main/tests/docker_tests/swap_watcher_tests.rs +++ b/mm2src/mm2_main/tests/docker_tests/swap_watcher_tests.rs @@ -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()); 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()); @@ -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()); @@ -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()); @@ -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(); @@ -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(); diff --git a/mm2src/mm2_main/tests/docker_tests/swaps_file_lock_tests.rs b/mm2src/mm2_main/tests/docker_tests/swaps_file_lock_tests.rs index 6446fa3a4f..9d82bb5091 100644 --- a/mm2src/mm2_main/tests/docker_tests/swaps_file_lock_tests.rs +++ b/mm2src/mm2_main/tests/docker_tests/swaps_file_lock_tests.rs @@ -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))); diff --git a/mm2src/mm2_main/tests/integration_tests_common/mod.rs b/mm2src/mm2_main/tests/integration_tests_common/mod.rs index cd017f89be..8b0a76eaaa 100644 --- a/mm2src/mm2_main/tests/integration_tests_common/mod.rs +++ b/mm2src/mm2_main/tests/integration_tests_common/mod.rs @@ -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}; @@ -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)) } } diff --git a/mm2src/mm2_test_helpers/src/for_tests.rs b/mm2src/mm2_test_helpers/src/for_tests.rs index ab87949619..e8a7c1ce05 100644 --- a/mm2src/mm2_test_helpers/src/for_tests.rs +++ b/mm2src/mm2_test_helpers/src/for_tests.rs @@ -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()); @@ -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::(&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); + } + } + Timer::sleep(1.).await + } } /// Wait for the node to start listening to new P2P connections. @@ -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); } } @@ -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::>() + .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 +}