refactor(transport): reuse now in qlog wherever available (#2216)

* 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`. * Move regex to workspace dep * Don't prefix now, before and after with time_ * Document preference for _with_time --------- Co-authored-by: Lars Eggert <[email protected]>
mozilla · Nov 14, 2024 · fe76cdc · fe76cdc
1 parent 978aa4e
commit fe76cdc
Show file tree

Hide file tree

Showing 17 changed files with 651 additions and 488 deletions.
diff --git a/Cargo.toml b/Cargo.toml
@@ -34,6 +34,7 @@ enum-map = { version = "2.7", default-features = false }
 log = { version = "0.4", default-features = false }
 qlog = { version = "0.13", default-features = false }
 quinn-udp = { version = "0.5.6", default-features = false, features = ["direct-log"] }
+regex = { version = "1.9", default-features = false, features = ["unicode-perl"] }
 static_assertions = { version = "1.1", default-features = false }
 url = { version = "2.5", default-features = false, features = ["std"] }
 

diff --git a/neqo-bin/Cargo.toml b/neqo-bin/Cargo.toml
@@ -39,7 +39,7 @@ neqo-transport = { path = "./../neqo-transport" }
 neqo-udp = { path = "./../neqo-udp" }
 qlog = { workspace = true }
 quinn-udp = { workspace = true }
-regex = { version = "1.9", default-features = false, features = ["unicode-perl"] }
+regex = { workspace = true }
 tokio = { version = "1", default-features = false, features = ["net", "time", "macros", "rt", "rt-multi-thread"] }
 url = { workspace = true }
 

diff --git a/neqo-common/Cargo.toml b/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 = { workspace = true }
 
 [features]
 ci = []

diff --git a/neqo-common/src/qlog.rs b/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,41 @@ 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.
+    ///
+    /// This function is similar to [`NeqoQlog::add_event_data_with_instant`],
+    /// but it does not take `now: Instant` as an input parameter. Instead, it
+    /// internally calls [`std::time::Instant::now`]. Prefer calling
+    /// [`NeqoQlog::add_event_data_with_instant`] when `now` is available, as it
+    /// ensures consistency with the current time, which might differ from
+    /// [`std::time::Instant::now`] (e.g., when using simulated time instead of
+    /// real time).
+    pub fn add_event_data_now<F>(&self, f: F)
     where
         F: FnOnce() -> Option<qlog::events::EventData>,
     {
@@ -184,7 +205,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 +229,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}"),
         );
     }
 }
diff --git a/neqo-http3/src/qlog.rs b/neqo-http3/src/qlog.rs
@@ -10,8 +10,11 @@ use neqo_common::qlog::NeqoQlog;
 use neqo_transport::StreamId;
 use qlog::events::{DataRecipient, EventData};
 
+/// Uses [`NeqoQlog::add_event_data_now`] instead of
+/// [`NeqoQlog::add_event_data_with_instant`], given that `now` is not available
+/// on call-site. See docs on [`NeqoQlog::add_event_data_now`] for details.
 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,
@@ -25,8 +28,11 @@ pub fn h3_data_moved_up(qlog: &NeqoQlog, stream_id: StreamId, amount: usize) {
     });
 }
 
+/// Uses [`NeqoQlog::add_event_data_now`] instead of
+/// [`NeqoQlog::add_event_data_with_instant`], given that `now` is not available
+/// on call-site. See docs on [`NeqoQlog::add_event_data_now`] for details.
 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,

diff --git a/neqo-qpack/src/qlog.rs b/neqo-qpack/src/qlog.rs
@@ -12,8 +12,11 @@ use qlog::events::{
     EventData, RawInfo,
 };
 
+/// Uses [`NeqoQlog::add_event_data_now`] instead of
+/// [`NeqoQlog::add_event_data_with_instant`], given that `now` is not available
+/// on call-site. See docs on [`NeqoQlog::add_event_data_now`] for details.
 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,