Fix qlog issues to enable correct qvis rendering (mozilla#1544)

* Fix qlog issues that affect correct qvis rendering * Add tests * Log tparams with valid timestamp * Log ACTIVE_CONNECTION_ID_LIMIT and PREFERRED_ADDRESS to qlog. * Fix imports * More tests * Add clippy ignores * Restore fix to logging tparams with valid timestamp No idea how that got reverted * Interim commit * Progress * Enable qlog generation for some more tests * Update test-fixture/src/lib.rs Co-authored-by: Max Inden <[email protected]> * Update test-fixture/src/lib.rs Co-authored-by: Max Inden <[email protected]> * Update neqo-transport/src/qlog.rs Co-authored-by: Max Inden <[email protected]> * Update neqo-common/src/qlog.rs Co-authored-by: Max Inden <[email protected]> * Incorporate suggestions from @mxinden - thanks! * More readable JSON literals * Undo one suggestion per @martinthomson * Update neqo-common/src/qlog.rs Co-authored-by: Martin Thomson <[email protected]> * Update neqo-common/src/qlog.rs Co-authored-by: Martin Thomson <[email protected]> * Update neqo-common/src/qlog.rs Co-authored-by: Martin Thomson <[email protected]> * Suggestions from @martinthomson * Fix clippy. --------- Co-authored-by: Max Inden <[email protected]> Co-authored-by: Martin Thomson <[email protected]>
larseggert · Jan 17, 2024 · 70e3ac4 · 70e3ac4
1 parent 9d58e64
commit 70e3ac4
Show file tree

Hide file tree

Showing 8 changed files with 158 additions and 30 deletions.
diff --git a/neqo-common/Cargo.toml b/neqo-common/Cargo.toml
@@ -8,11 +8,14 @@ license = "MIT OR Apache-2.0"
 build = "build.rs"
 
 [dependencies]
-log = {version = "0.4.0", default-features = false}
-env_logger = {version = "0.10", default-features = false}
+log = { version = "0.4.0", default-features = false }
+env_logger = { version = "0.10", default-features = false }
 lazy_static = "1.3.0"
 qlog = "0.11.0"
-time = {version = "0.3", features = ["formatting"]}
+time = { version = "0.3", features = ["formatting"] }
+
+[dev-dependencies]
+test-fixture = { path = "../test-fixture" }
 
 [features]
 deny-warnings = []

diff --git a/neqo-common/src/qlog.rs b/neqo-common/src/qlog.rs
@@ -48,6 +48,11 @@ impl NeqoQlog {
         })
     }
 
+    #[must_use]
+    pub fn inner(&self) -> Rc<RefCell<Option<NeqoQlogShared>>> {
+        Rc::clone(&self.inner)
+    }
+
     /// Create a disabled `NeqoQlog` configuration.
     #[must_use]
     pub fn disabled() -> Self {
@@ -144,3 +149,39 @@ pub fn new_trace(role: Role) -> qlog::TraceSeq {
         }),
     }
 }
+
+#[cfg(test)]
+mod test {
+    use qlog::events::Event;
+    use test_fixture::EXPECTED_LOG_HEADER;
+
+    const EV_DATA: qlog::events::EventData =
+        qlog::events::EventData::SpinBitUpdated(qlog::events::connectivity::SpinBitUpdated {
+            state: true,
+        });
+
+    const EXPECTED_LOG_EVENT: &str = concat!(
+        "\u{1e}",
+        r#"{"time":0.0,"name":"connectivity:spin_bit_updated","data":{"state":true}}"#,
+        "\n"
+    );
+
+    #[test]
+    fn new_neqo_qlog() {
+        let (_log, contents) = test_fixture::new_neqo_qlog();
+        assert_eq!(contents.to_string(), EXPECTED_LOG_HEADER);
+    }
+
+    #[test]
+    fn add_event() {
+        let (mut log, contents) = test_fixture::new_neqo_qlog();
+        log.add_event(|| Some(Event::with_time(1.1, EV_DATA)));
+        assert_eq!(
+            contents.to_string(),
+            format!(
+                "{EXPECTED_LOG_HEADER}{e}",
+                e = EXPECTED_LOG_EVENT.replace("\"time\":0.0,", "\"time\":1.1,")
+            )
+        );
+    }
+}
diff --git a/neqo-transport/src/cid.rs b/neqo-transport/src/cid.rs
@@ -323,6 +323,10 @@ impl<SRT: Clone + PartialEq> ConnectionIdEntry<SRT> {
     pub fn connection_id(&self) -> &ConnectionId {
         &self.cid
     }
+
+    pub fn reset_token(&self) -> &SRT {
+        &self.srt
+    }
 }
 
 pub type RemoteConnectionIdEntry = ConnectionIdEntry<[u8; 16]>;

diff --git a/neqo-transport/src/connection/tests/migration.rs b/neqo-transport/src/connection/tests/migration.rs
@@ -30,7 +30,7 @@ use std::{
 use test_fixture::{
     self, addr, addr_v4,
     assertions::{assert_v4_path, assert_v6_path},
-    fixture_init, now,
+    fixture_init, new_neqo_qlog, now,
 };
 
 /// This should be a valid-seeming transport parameter.
@@ -498,6 +498,7 @@ fn preferred_address(hs_client: SocketAddr, hs_server: SocketAddr, preferred: So
     };
 
     fixture_init();
+    let (log, _contents) = new_neqo_qlog();
     let mut client = Connection::new_client(
         test_fixture::DEFAULT_SERVER_NAME,
         test_fixture::DEFAULT_ALPN,
@@ -508,6 +509,7 @@ fn preferred_address(hs_client: SocketAddr, hs_server: SocketAddr, preferred: So
         now(),
     )
     .unwrap();
+    client.set_qlog(log);
     let spa = match preferred {
         SocketAddr::V6(v6) => PreferredAddress::new(None, Some(v6)),
         SocketAddr::V4(v4) => PreferredAddress::new(Some(v4), None),

diff --git a/neqo-transport/src/connection/tests/mod.rs b/neqo-transport/src/connection/tests/mod.rs
@@ -30,7 +30,7 @@ use std::{
 
 use neqo_common::{event::Provider, qdebug, qtrace, Datagram, Decoder, Role};
 use neqo_crypto::{random, AllowZeroRtt, AuthenticationStatus, ResumptionToken};
-use test_fixture::{self, addr, fixture_init, now};
+use test_fixture::{self, addr, fixture_init, new_neqo_qlog, now};
 
 // All the tests.
 mod ackrate;
@@ -99,7 +99,8 @@ impl ConnectionIdGenerator for CountingConnectionIdGenerator {
 // These are a direct copy of those functions.
 pub fn new_client(params: ConnectionParameters) -> Connection {
     fixture_init();
-    Connection::new_client(
+    let (log, _contents) = new_neqo_qlog();
+    let mut client = Connection::new_client(
         test_fixture::DEFAULT_SERVER_NAME,
         test_fixture::DEFAULT_ALPN,
         Rc::new(RefCell::new(CountingConnectionIdGenerator::default())),
@@ -108,22 +109,26 @@ pub fn new_client(params: ConnectionParameters) -> Connection {
         params,
         now(),
     )
-    .expect("create a default client")
+    .expect("create a default client");
+    client.set_qlog(log);
+    client
 }
+
 pub fn default_client() -> Connection {
     new_client(ConnectionParameters::default())
 }
 
 pub fn new_server(params: ConnectionParameters) -> Connection {
     fixture_init();
-
+    let (log, _contents) = new_neqo_qlog();
     let mut c = Connection::new_server(
         test_fixture::DEFAULT_KEYS,
         test_fixture::DEFAULT_ALPN,
         Rc::new(RefCell::new(CountingConnectionIdGenerator::default())),
         params,
     )
     .expect("create a default server");
+    c.set_qlog(log);
     c.server_enable_0rtt(&test_fixture::anti_replay(), AllowZeroRtt {})
         .expect("enable 0-RTT");
     c

diff --git a/neqo-transport/src/qlog.rs b/neqo-transport/src/qlog.rs
@@ -19,7 +19,7 @@ use qlog::events::{
         AckedRanges, ErrorSpace, MetricsUpdated, PacketDropped, PacketHeader, PacketLost,
         PacketReceived, PacketSent, QuicFrame, StreamType, VersionInformation,
     },
-    Event, EventData, RawInfo,
+    EventData, RawInfo,
 };
 
 use neqo_common::{hex, qinfo, qlog::NeqoQlog, Decoder};
@@ -37,7 +37,7 @@ use crate::{
 };
 
 pub fn connection_tparams_set(qlog: &mut NeqoQlog, tph: &TransportParametersHandler) {
-    qlog.add_event(|| {
+    qlog.add_event_data(|| {
         let remote = tph.remote();
         let ev_data = EventData::TransportParametersSet(
             qlog::events::quic::TransportParametersSet {
@@ -61,20 +61,26 @@ pub fn connection_tparams_set(qlog: &mut NeqoQlog, tph: &TransportParametersHand
                 max_udp_payload_size: Some(remote.get_integer(tparams::MAX_UDP_PAYLOAD_SIZE) as u32),
                 ack_delay_exponent: Some(remote.get_integer(tparams::ACK_DELAY_EXPONENT) as u16),
                 max_ack_delay: Some(remote.get_integer(tparams::MAX_ACK_DELAY) as u16),
-                // TODO([email protected]): We do not yet handle ACTIVE_CONNECTION_ID_LIMIT in tparams yet.
-                active_connection_id_limit: None,
+                active_connection_id_limit: Some(remote.get_integer(tparams::ACTIVE_CONNECTION_ID_LIMIT) as u32),
                 initial_max_data: Some(remote.get_integer(tparams::INITIAL_MAX_DATA)),
                 initial_max_stream_data_bidi_local: Some(remote.get_integer(tparams::INITIAL_MAX_STREAM_DATA_BIDI_LOCAL)),
                 initial_max_stream_data_bidi_remote: Some(remote.get_integer(tparams::INITIAL_MAX_STREAM_DATA_BIDI_REMOTE)),
                 initial_max_stream_data_uni: Some(remote.get_integer(tparams::INITIAL_MAX_STREAM_DATA_UNI)),
                 initial_max_streams_bidi: Some(remote.get_integer(tparams::INITIAL_MAX_STREAMS_BIDI)),
                 initial_max_streams_uni: Some(remote.get_integer(tparams::INITIAL_MAX_STREAMS_UNI)),
-                // TODO([email protected]): We do not yet handle PREFERRED_ADDRESS in tparams yet.
-                preferred_address: None,
+                preferred_address: remote.get_preferred_address().and_then(|(paddr, cid)| {
+                    Some(qlog::events::quic::PreferredAddress {
+                        ip_v4: paddr.ipv4()?.ip().to_string(),
+                        ip_v6: paddr.ipv6()?.ip().to_string(),
+                        port_v4: paddr.ipv4()?.port(),
+                        port_v6: paddr.ipv6()?.port(),
+                        connection_id: cid.connection_id().to_string(),
+                        stateless_reset_token: hex(cid.reset_token()),
+                    })
+                }),
             });
 
-        // This event occurs very early, so just mark the time as 0.0.
-        Some(Event::with_time(0.0, ev_data))
+        Some(ev_data)
     });
 }
 
@@ -194,8 +200,8 @@ pub fn packet_sent(
         let mut d = Decoder::from(body);
         let header = PacketHeader::with_type(to_qlog_pkt_type(pt), Some(pn), None, None, None);
         let raw = RawInfo {
-            length: None,
-            payload_length: Some(plen as u64),
+            length: Some(plen as u64),
+            payload_length: None,
             data: None,
         };
 
@@ -229,18 +235,18 @@ pub fn packet_sent(
     });
 }
 
-pub fn packet_dropped(qlog: &mut NeqoQlog, payload: &PublicPacket) {
+pub fn packet_dropped(qlog: &mut NeqoQlog, public_packet: &PublicPacket) {
     qlog.add_event_data(|| {
         let header = PacketHeader::with_type(
-            to_qlog_pkt_type(payload.packet_type()),
+            to_qlog_pkt_type(public_packet.packet_type()),
             None,
             None,
             None,
             None,
         );
         let raw = RawInfo {
-            length: None,
-            payload_length: Some(payload.len() as u64),
+            length: Some(public_packet.len() as u64),
+            payload_length: None,
             data: None,
         };
 
@@ -290,8 +296,8 @@ pub fn packet_received(
             None,
         );
         let raw = RawInfo {
-            length: None,
-            payload_length: Some(public_packet.len() as u64),
+            length: Some(public_packet.len() as u64),
+            payload_length: None,
             data: None,
         };
 

diff --git a/test-fixture/Cargo.toml b/test-fixture/Cargo.toml
@@ -7,13 +7,14 @@ rust-version = "1.70.0"
 license = "MIT OR Apache-2.0"
 
 [dependencies]
+lazy_static = "1.3.0"
+log = {version = "0.4.0", default-features = false}
 neqo-common = { path = "../neqo-common" }
 neqo-crypto = { path = "../neqo-crypto" }
 neqo-http3 = { path = "../neqo-http3" }
 neqo-qpack = { path = "../neqo-qpack" }
 neqo-transport = { path = "../neqo-transport" }
-log = {version = "0.4.0", default-features = false}
-lazy_static = "1.3.0"
+qlog = "0.11.0"
 
 [features]
 deny-warnings = []
diff --git a/test-fixture/src/lib.rs b/test-fixture/src/lib.rs
@@ -7,7 +7,12 @@
 #![cfg_attr(feature = "deny-warnings", deny(warnings))]
 #![warn(clippy::pedantic)]
 
-use neqo_common::{event::Provider, hex, qtrace, Datagram, Decoder};
+use neqo_common::{
+    event::Provider,
+    hex,
+    qlog::{new_trace, NeqoQlog},
+    qtrace, Datagram, Decoder, Role,
+};
 
 use neqo_crypto::{init_db, random, AllowZeroRtt, AntiReplay, AuthenticationStatus};
 use neqo_http3::{Http3Client, Http3Parameters, Http3Server};
@@ -16,13 +21,17 @@ use neqo_transport::{
     ConnectionIdGenerator, ConnectionIdRef, ConnectionParameters, State, Version,
 };
 
+use qlog::{events::EventImportance, streamer::QlogStreamer};
+
 use std::{
     cell::RefCell,
     cmp::max,
     convert::TryFrom,
+    io::{Cursor, Result, Write},
     mem,
     net::{IpAddr, Ipv4Addr, Ipv6Addr, SocketAddr},
     rc::Rc,
+    sync::{Arc, Mutex},
     time::{Duration, Instant},
 };
 
@@ -130,7 +139,8 @@ impl ConnectionIdGenerator for CountingConnectionIdGenerator {
 #[must_use]
 pub fn new_client(params: ConnectionParameters) -> Connection {
     fixture_init();
-    Connection::new_client(
+    let (log, _contents) = new_neqo_qlog();
+    let mut client = Connection::new_client(
         DEFAULT_SERVER_NAME,
         DEFAULT_ALPN,
         Rc::new(RefCell::new(CountingConnectionIdGenerator::default())),
@@ -139,7 +149,9 @@ pub fn new_client(params: ConnectionParameters) -> Connection {
         params.ack_ratio(255), // Tests work better with this set this way.
         now(),
     )
-    .expect("create a client")
+    .expect("create a client");
+    client.set_qlog(log);
+    client
 }
 
 /// Create a transport client with default configuration.
@@ -166,14 +178,15 @@ pub fn default_server_h3() -> Connection {
 #[must_use]
 pub fn new_server(alpn: &[impl AsRef<str>], params: ConnectionParameters) -> Connection {
     fixture_init();
-
+    let (log, _contents) = new_neqo_qlog();
     let mut c = Connection::new_server(
         DEFAULT_KEYS,
         alpn,
         Rc::new(RefCell::new(CountingConnectionIdGenerator::default())),
         params.ack_ratio(255),
     )
     .expect("create a server");
+    c.set_qlog(log);
     c.server_enable_0rtt(&anti_replay(), AllowZeroRtt {})
         .expect("enable 0-RTT");
     c
@@ -323,3 +336,56 @@ pub fn split_datagram(d: &Datagram) -> (Datagram, Option<Datagram>) {
         b.map(|b| Datagram::new(d.source(), d.destination(), b)),
     )
 }
+
+#[derive(Clone)]
+pub struct SharedVec {
+    buf: Arc<Mutex<Cursor<Vec<u8>>>>,
+}
+
+impl Write for SharedVec {
+    fn write(&mut self, buf: &[u8]) -> Result<usize> {
+        self.buf.lock().unwrap().write(buf)
+    }
+    fn flush(&mut self) -> Result<()> {
+        self.buf.lock().unwrap().flush()
+    }
+}
+
+impl ToString for SharedVec {
+    fn to_string(&self) -> String {
+        String::from_utf8(self.buf.lock().unwrap().clone().into_inner()).unwrap()
+    }
+}
+
+/// Returns a pair of new enabled `NeqoQlog` that is backed by a Vec<u8> together with a
+/// `Cursor<Vec<u8>>` that can be used to read the contents of the log.
+/// # Panics
+/// Panics if the log cannot be created.
+#[must_use]
+pub fn new_neqo_qlog() -> (NeqoQlog, SharedVec) {
+    let mut trace = new_trace(Role::Client);
+    // Set reference time to 0.0 for testing.
+    trace.common_fields.as_mut().unwrap().reference_time = Some(0.0);
+    let buf = SharedVec {
+        buf: Arc::default(),
+    };
+    let contents = buf.clone();
+    let streamer = QlogStreamer::new(
+        qlog::QLOG_VERSION.to_string(),
+        None,
+        None,
+        None,
+        std::time::Instant::now(),
+        trace,
+        EventImportance::Base,
+        Box::new(buf),
+    );
+    let log = NeqoQlog::enabled(streamer, "");
+    (log.expect("to be able to write to new log"), contents)
+}
+
+pub const EXPECTED_LOG_HEADER: &str = concat!(
+    "\u{1e}",
+    r#"{"qlog_version":"0.3","qlog_format":"JSON-SEQ","trace":{"vantage_point":{"name":"neqo-Client","type":"client"},"title":"neqo-Client trace","description":"Example qlog trace description","configuration":{"time_offset":0.0},"common_fields":{"reference_time":0.0,"time_format":"relative"}}}"#,
+    "\n"
+);