diff --git a/test/test-manager/src/logging.rs b/test/test-manager/src/logging.rs index ce7477cd69e9..4f7d6e1e911a 100644 --- a/test/test-manager/src/logging.rs +++ b/test/test-manager/src/logging.rs @@ -19,7 +19,7 @@ struct LoggerInner { struct StoredRecord { level: log::Level, - time: chrono::DateTime, + time: chrono::DateTime, mod_path: String, text: String, } @@ -70,7 +70,12 @@ impl Logger { for stored_record in std::mem::take(&mut inner.stored_records) { println!( "[{} {} {}] {}", - stored_record.time, stored_record.level, stored_record.mod_path, stored_record.text + stored_record + .time + .to_rfc3339_opts(chrono::SecondsFormat::Secs, true), + stored_record.level, + stored_record.mod_path, + stored_record.text ); } } @@ -99,7 +104,7 @@ impl log::Log for Logger { let mod_path = record.module_path().unwrap_or(""); inner.stored_records.push(StoredRecord { level: record.level(), - time: chrono::Local::now(), + time: chrono::Utc::now(), mod_path: mod_path.to_owned(), text: record.args().to_string(), }); @@ -191,15 +196,25 @@ impl TestResult { } } +macro_rules! println_with_time { + ($fmt:tt$(, $($args:tt)*)?) => { + println!( + concat!("[{}] ", $fmt), + chrono::Utc::now().to_rfc3339_opts(chrono::SecondsFormat::Secs, true), + $($($args)*)? + ) + }; +} + impl TestOutput { pub fn print(&self) { match &self.result { TestResult::Pass => { - println!("{}", format!("TEST {} SUCCEEDED!", self.test_name).green()); + println_with_time!("{}", format!("TEST {} SUCCEEDED!", self.test_name).green()); return; } TestResult::Fail(e) => { - println!( + println_with_time!( "{}", format!( "TEST {} RETURNED ERROR: {}", @@ -210,7 +225,7 @@ impl TestOutput { ); } TestResult::Panic(panic_msg) => { - println!( + println_with_time!( "{}", format!( "TEST {} PANICKED WITH MESSAGE: {}", @@ -222,12 +237,12 @@ impl TestOutput { } } - println!("{}", format!("TEST {} HAD LOGS:", self.test_name).red()); + println_with_time!("{}", format!("TEST {} HAD LOGS:", self.test_name).red()); match &self.log_output { Some(log) => { match &log.settings_json { - Ok(settings) => println!("settings.json: {}", settings), - Err(e) => println!("Could not get settings.json: {}", e), + Ok(settings) => println_with_time!("settings.json: {}", settings), + Err(e) => println_with_time!("Could not get settings.json: {}", e), } match &log.log_files { @@ -235,30 +250,34 @@ impl TestOutput { for log in log_files { match log { Ok(log) => { - println!("Log {}:\n{}", log.name.to_str().unwrap(), log.content) + println_with_time!( + "Log {}:\n{}", + log.name.to_str().unwrap(), + log.content + ) } - Err(e) => println!("Could not get log: {}", e), + Err(e) => println_with_time!("Could not get log: {}", e), } } } - Err(e) => println!("Could not get logs: {}", e), + Err(e) => println_with_time!("Could not get logs: {}", e), } } - None => println!("Missing logs for {}", self.test_name), + None => println_with_time!("Missing logs for {}", self.test_name), } - println!( + println_with_time!( "{}", format!("TEST RUNNER {} HAD RUNTIME OUTPUT:", self.test_name).red() ); if self.error_messages.is_empty() { - println!(""); + println_with_time!(""); } else { for msg in &self.error_messages { - println!("{}", msg); + println_with_time!("{}", msg); } } - println!("{}", format!("TEST {} END OF OUTPUT", self.test_name).red()); + println_with_time!("{}", format!("TEST {} END OF OUTPUT", self.test_name).red()); } } diff --git a/test/test-manager/src/tests/helpers.rs b/test/test-manager/src/tests/helpers.rs index 3eb0be0cc238..2ebc5eb7ada0 100644 --- a/test/test-manager/src/tests/helpers.rs +++ b/test/test-manager/src/tests/helpers.rs @@ -29,7 +29,7 @@ use std::{ collections::HashMap, net::{IpAddr, Ipv4Addr, SocketAddr}, path::Path, - time::Duration, + time::{Duration, Instant}, }; use talpid_types::net::wireguard::{PeerConfig, PrivateKey, TunnelConfig}; use test_rpc::{ @@ -432,6 +432,8 @@ pub async fn connect_and_wait( ) -> Result { log::info!("Connecting"); + let initial_time = Instant::now(); + mullvad_client.connect_tunnel().await?; let new_state = wait_for_tunnel_state(mullvad_client.clone(), |state| { matches!( @@ -445,7 +447,10 @@ pub async fn connect_and_wait( return Err(Error::UnexpectedErrorState(error_state)); } - log::info!("Connected"); + log::info!( + "Connected after {} seconds", + initial_time.elapsed().as_secs() + ); Ok(new_state) } diff --git a/test/test-manager/src/tests/tunnel_state.rs b/test/test-manager/src/tests/tunnel_state.rs index 5fd81f33750e..5ccf0f863ea9 100644 --- a/test/test-manager/src/tests/tunnel_state.rs +++ b/test/test-manager/src/tests/tunnel_state.rs @@ -22,6 +22,7 @@ use talpid_types::net::{Endpoint, TransportProtocol, TunnelEndpoint, TunnelType} use test_macro::test_function; use test_rpc::ServiceClient; +/// Set up nftables rules to drop packets larger than `max_packet_size` on the host. #[cfg(target_os = "linux")] async fn setup_nftables_drop_pings_rule( max_packet_size: u16, @@ -33,7 +34,7 @@ async fn setup_nftables_drop_pings_rule( .unwrap(); log::debug!( - "Set NF-tables ruleset to:\n{}", + "Set nftables ruleset to:\n{}", String::from_utf8(output.stdout).unwrap() );