Clean up timestamps in test logs

test/test-manager/src/logging.rs

@@ -19,7 +19,7 @@ struct LoggerInner {
 
 struct StoredRecord {
     level: log::Level,
-    time: chrono::DateTime<chrono::Local>,
+    time: chrono::DateTime<chrono::Utc>,
     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,43 +237,47 @@ 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 {
                     Ok(log_files) => {
                         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!("<no output>");
+            println_with_time!("<no output>");
         } 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());
     }
 }

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<TunnelState, Error> {
     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)
 }

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