refactor(transport): reuse now in qlog whereever available

Instead of using `QLogStream::add_event_data_now`, which internally calls
`std::time::Instant::now()`, pass `now to
`QLogStream::add_event_data_with_instant`.

neqo-common/Cargo.toml

@@ -29,6 +29,7 @@ windows = { version = "0.58", default-features = false, features = ["Win32_Media
 
 [dev-dependencies]
 test-fixture = { path = "../test-fixture" }
+regex = { version = "1.9", default-features = false, features = ["unicode-perl"] }
 
 [features]
 ci = []

neqo-common/src/qlog.rs

@@ -11,7 +11,7 @@ use std::{
     io::BufWriter,
     path::PathBuf,
     rc::Rc,
-    time::SystemTime,
+    time::{Instant, SystemTime},
 };
 
 use qlog::{
@@ -95,20 +95,33 @@ impl NeqoQlog {
     }
 
     /// If logging enabled, closure may generate an event to be logged.
-    pub fn add_event<F>(&self, f: F)
+    pub fn add_event_with_instant<F>(&self, f: F, now: Instant)
     where
         F: FnOnce() -> Option<qlog::events::Event>,
     {
         self.add_event_with_stream(|s| {
             if let Some(evt) = f() {
-                s.add_event(evt)?;
+                s.add_event_with_instant(evt, now)?;
             }
             Ok(())
         });
     }
 
     /// If logging enabled, closure may generate an event to be logged.
-    pub fn add_event_data<F>(&self, f: F)
+    pub fn add_event_data_with_instant<F>(&self, f: F, now: Instant)
+    where
+        F: FnOnce() -> Option<qlog::events::EventData>,
+    {
+        self.add_event_with_stream(|s| {
+            if let Some(ev_data) = f() {
+                s.add_event_data_with_instant(ev_data, now)?;
+            }
+            Ok(())
+        });
+    }
+
+    /// If logging enabled, closure may generate an event to be logged.
+    pub fn add_event_data_now<F>(&self, f: F)
     where
         F: FnOnce() -> Option<qlog::events::EventData>,
     {
@@ -184,7 +197,10 @@ pub fn new_trace(role: Role) -> qlog::TraceSeq {
 
 #[cfg(test)]
 mod test {
+    use std::time::Instant;
+
     use qlog::events::Event;
+    use regex::Regex;
     use test_fixture::EXPECTED_LOG_HEADER;
 
     const EV_DATA: qlog::events::EventData =
@@ -205,15 +221,14 @@ mod test {
     }
 
     #[test]
-    fn add_event() {
+    fn add_event_with_instant() {
         let (log, contents) = test_fixture::new_neqo_qlog();
-        log.add_event(|| Some(Event::with_time(1.1, EV_DATA)));
+        log.add_event_with_instant(|| Some(Event::with_time(0.0, EV_DATA)), Instant::now());
         assert_eq!(
-            contents.to_string(),
-            format!(
-                "{EXPECTED_LOG_HEADER}{e}",
-                e = EXPECTED_LOG_EVENT.replace("\"time\":0.0,", "\"time\":1.1,")
-            )
+            Regex::new("\"time\":[0-9].[0-9]*,")
+                .unwrap()
+                .replace(&contents.to_string(), "\"time\":0.0,"),
+            format!("{EXPECTED_LOG_HEADER}{EXPECTED_LOG_EVENT}"),
         );
     }
 }

neqo-http3/src/qlog.rs

@@ -11,7 +11,7 @@ use neqo_transport::StreamId;
 use qlog::events::{DataRecipient, EventData};
 
 pub fn h3_data_moved_up(qlog: &NeqoQlog, stream_id: StreamId, amount: usize) {
-    qlog.add_event_data(|| {
+    qlog.add_event_data_now(|| {
         let ev_data = EventData::DataMoved(qlog::events::quic::DataMoved {
             stream_id: Some(stream_id.as_u64()),
             offset: None,
@@ -26,7 +26,7 @@ pub fn h3_data_moved_up(qlog: &NeqoQlog, stream_id: StreamId, amount: usize) {
 }
 
 pub fn h3_data_moved_down(qlog: &NeqoQlog, stream_id: StreamId, amount: usize) {
-    qlog.add_event_data(|| {
+    qlog.add_event_data_now(|| {
         let ev_data = EventData::DataMoved(qlog::events::quic::DataMoved {
             stream_id: Some(stream_id.as_u64()),
             offset: None,

neqo-qpack/src/qlog.rs

@@ -13,7 +13,7 @@ use qlog::events::{
 };
 
 pub fn qpack_read_insert_count_increment_instruction(qlog: &NeqoQlog, increment: u64, data: &[u8]) {
-    qlog.add_event_data(|| {
+    qlog.add_event_data_now(|| {
         let raw = RawInfo {
             length: Some(8),
             payload_length: None,