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

mm2src/mm2_main/tests/docker_tests/docker_tests_inner.rs

@@ -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,
@@ -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"

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();

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)));

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))
     }
 }
 

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::<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);
+                }
+            }
+            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::<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
+}