From 70e3ac44014af65eb7792013ceb5829693b50992 Mon Sep 17 00:00:00 2001 From: Lars Eggert Date: Wed, 17 Jan 2024 12:40:39 +0200 Subject: [PATCH] Fix qlog issues to enable correct qvis rendering (#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 * Update test-fixture/src/lib.rs Co-authored-by: Max Inden * Update neqo-transport/src/qlog.rs Co-authored-by: Max Inden * Update neqo-common/src/qlog.rs Co-authored-by: Max Inden * 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 * Update neqo-common/src/qlog.rs Co-authored-by: Martin Thomson * Update neqo-common/src/qlog.rs Co-authored-by: Martin Thomson * Suggestions from @martinthomson * Fix clippy. --------- Co-authored-by: Max Inden Co-authored-by: Martin Thomson --- neqo-common/Cargo.toml | 9 ++- neqo-common/src/qlog.rs | 41 ++++++++++ neqo-transport/src/cid.rs | 4 + .../src/connection/tests/migration.rs | 4 +- neqo-transport/src/connection/tests/mod.rs | 13 +++- neqo-transport/src/qlog.rs | 38 ++++++---- test-fixture/Cargo.toml | 5 +- test-fixture/src/lib.rs | 74 ++++++++++++++++++- 8 files changed, 158 insertions(+), 30 deletions(-) diff --git a/neqo-common/Cargo.toml b/neqo-common/Cargo.toml index 25d72980ca..ca209328e5 100644 --- 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 index ac03ecfcb0..5ff74750b0 100644 --- 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>> { + 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 index 70e327a296..eefc3104a9 100644 --- a/neqo-transport/src/cid.rs +++ b/neqo-transport/src/cid.rs @@ -323,6 +323,10 @@ impl ConnectionIdEntry { 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 index 056aa0247f..b7e5392903 100644 --- 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 index a244efca53..b722feff78 100644 --- 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,15 +109,18 @@ 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, @@ -124,6 +128,7 @@ pub fn new_server(params: ConnectionParameters) -> Connection { 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 index f5ca21ca40..021367d8da 100644 --- 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(hawkinsw@obs.cr): 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(hawkinsw@obs.cr): 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 index 99bdd41cb5..dddabfbc2d 100644 --- 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 index 5ddba24814..fa9276bf5c 100644 --- 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,7 +178,7 @@ pub fn default_server_h3() -> Connection { #[must_use] pub fn new_server(alpn: &[impl AsRef], params: ConnectionParameters) -> Connection { fixture_init(); - + let (log, _contents) = new_neqo_qlog(); let mut c = Connection::new_server( DEFAULT_KEYS, alpn, @@ -174,6 +186,7 @@ pub fn new_server(alpn: &[impl AsRef], params: ConnectionParameters) -> Con 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) { b.map(|b| Datagram::new(d.source(), d.destination(), b)), ) } + +#[derive(Clone)] +pub struct SharedVec { + buf: Arc>>>, +} + +impl Write for SharedVec { + fn write(&mut self, buf: &[u8]) -> Result { + 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 together with a +/// `Cursor>` 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" +);