From 0ad6542200d761b2e9247ec95c8f7696f4f9b71f Mon Sep 17 00:00:00 2001 From: lucas Date: Thu, 26 Mar 2020 17:32:56 +0000 Subject: [PATCH 1/2] qlog: update to v0.2.0 Previously, qlog API was designed to operate in a buffered mode. This required users to create a trace and hold it in memory, append events to it, and at the end serialize the whole thing. This change adds a streaming mode API that serializes qlog events immediately to a `Write` trait. A few quality-of-life changes have also been made. --- tools/qlog/Cargo.toml | 2 +- tools/qlog/README.md | 275 ++++++++--- tools/qlog/src/event.rs | 1 + tools/qlog/src/lib.rs | 976 ++++++++++++++++++++++++++++++++++------ 4 files changed, 1059 insertions(+), 195 deletions(-) diff --git a/tools/qlog/Cargo.toml b/tools/qlog/Cargo.toml index aa7e473766..8ba9433add 100644 --- a/tools/qlog/Cargo.toml +++ b/tools/qlog/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "qlog" -version = "0.1.0" +version = "0.2.0" authors = ["Lucas Pardue "] edition = "2018" description = "qlog data model for QUIC and HTTP/3" diff --git a/tools/qlog/README.md b/tools/qlog/README.md index 6da28aa64d..cc420a17d7 100644 --- a/tools/qlog/README.md +++ b/tools/qlog/README.md @@ -9,86 +9,118 @@ The crate uses Serde for conversion between Rust and JSON. [qlog QUIC and HTTP/3 events]: https://quiclog.github.io/internet-drafts/draft-marx-qlog-event-definitions-quic-h3 [TypeScript schema]: https://github.com/quiclog/qlog/blob/master/TypeScript/draft-01/QLog.ts -Getting Started ---------------- +Overview +-------- +qlog is a hierarchical logging format, with a rough structure of: + +* Log + * Trace(s) + * Event(s) + +In practice, a single QUIC connection maps to a single Trace file with one +or more Events. Applications can decide whether to combine Traces from +different connections into the same Log. + +## Traces + +A [`Trace`] contains metadata such as the [`VantagePoint`] of capture and +the [`Configuration`] of the `Trace`. -### Creating a trace +A very important part of the `Trace` is the definition of `event_fields`. A +qlog Event is a vector of [`EventField`]; this provides great flexibility to +log events with any number of `EventFields` in any order. The `event_fields` +property describes the format of event logging and it is important that +events comply with that format. Failing to do so it going to cause problems +for qlog analysis tools. For information is available at +https://tools.ietf.org/html/draft-marx-qlog-main-schema-01#section-3.3.4 -A typical application needs a single qlog trace that it appends QUIC and/or -HTTP/3 events to: +In order to make using qlog a bit easier, this crate expects a qlog Event to +consist of the following EventFields in the following order: +[`EventField::RelativeTime`], [`EventField::Category`], +[`EventField::Event`] and [`EventField::Data`]. A set of methods are +provided to assist in creating a Trace and appending events to it in this +format. + +## Writing out logs +As events occur during the connection, the application appends them to the +trace. The qlog crate supports two modes of writing logs: the buffered mode +stores everything in memory and requires the application to serialize and write +the output, the streaming mode progressively writes serialized JSON output to a +writer designated by the application. + +Buffered Mode +--------------- + +Create the trace: ```rust -let trace = Trace { - vantage_point: VantagePoint { - name: "Example client", - ty: VantagePointType::Client, +let mut trace = qlog::Trace::new( + qlog::VantagePoint { + name: Some("Example client".to_string()), + ty: qlog::VantagePointType::Client, flow: None, }, - title: Some("Example qlog trace".to_string()), - description: Some("Example qlog trace description".to_string()), - configuration: Some(Configuration { + Some("Example qlog trace".to_string()), + Some("Example qlog trace description".to_string()), + Some(qlog::Configuration { time_offset: Some("0".to_string()), - time_units: Some(TimeUnits::Ms), + time_units: Some(qlog::TimeUnits::Ms), original_uris: None, }), - common_fields: None, - event_fields: vec![ - "relative_time".to_string(), - "category".to_string(), - "event".to_string(), - "data".to_string(), - ], - events: Vec::new(), -}; - + None, +); ``` ### Adding events -Qlog Events are added to `qlog::Trace.events`. Utility method are provided for -the various types of QUIC and HTTP/3 events. The following example demonstrates -how to log a QUIC packet containing a single Crypto frame, it uses the -`push_transport_event()` and `QuicFrame::crypto()` methods to capture a +Qlog Events are added to `qlog::Trace.events`. + +It is recommended to use the provided utility methods to append semantically +valid events to a trace. However, there is nothing preventing you from +creating the events manually. + +The following example demonstrates how to log a QUIC packet +containing a single Crypto frame. It uses the [`QuicFrame::crypto()`], +[`packet_sent_min()`] and [`push_event()`] methods to create and log a PacketSent event and its EventData. ```rust -trace.push_transport_event( - "0".to_string(), - TransportEventType::PacketSent, - EventData::PacketSent { - raw_encrypted: None, - raw_decrypted: None, - packet_type: PacketType::Initial, - header: PacketHeader { - packet_number: "0".to_string(), - packet_size: Some(1251), - payload_length: Some(1224), - version: Some("0xff000018".to_string()), - scil: Some("8".to_string()), - dcil: Some("8".to_string()), - scid: Some("7e37e4dcc6682da8".to_string()), - dcid: Some("36ce104eee50101c".to_string()), - }, - frames: Some(vec![ - QuicFrame::crypto( - "0".to_string(), - "1000".to_string(), - ) - ]), - is_coalesced: None, - }, +let scid = [0x7e, 0x37, 0xe4, 0xdc, 0xc6, 0x68, 0x2d, 0xa8]; +let dcid = [0x36, 0xce, 0x10, 0x4e, 0xee, 0x50, 0x10, 0x1c]; + +let pkt_hdr = qlog::PacketHeader::new( + 0, + Some(1251), + Some(1224), + Some(0xff00001b), + Some(b"7e37e4dcc6682da8"), + Some(&dcid), +); + +let frames = + vec![qlog::QuicFrame::crypto("0".to_string(), "1000".to_string())]; + +let event = qlog::event::Event::packet_sent_min( + qlog::PacketType::Initial, + pkt_hdr, + Some(frames), ); + +trace.push_event(std::time::Duration::new(0, 0), event); ``` ### Serializing -Simply: +The qlog crate has only been tested with `serde_json`, however other serializer +targets might work. + +For example, serializing the trace created above: ```rust serde_json::to_string_pretty(&trace).unwrap(); ``` -which would generate the following: +would generate the following: ``` { @@ -119,7 +151,7 @@ which would generate the following: "packet_number": "0", "packet_size": 1251, "payload_length": 1224, - "version": "0xff000018", + "version": "0xff00001b", "scil": "8", "dcil": "8", "scid": "7e37e4dcc6682da8", @@ -137,3 +169,136 @@ which would generate the following: ] } ``` + +Streaming Mode +--------------- + +Create the trace: + +```rust +let mut trace = qlog::Trace::new( + qlog::VantagePoint { + name: Some("Example client".to_string()), + ty: qlog::VantagePointType::Client, + flow: None, + }, + Some("Example qlog trace".to_string()), + Some("Example qlog trace description".to_string()), + Some(qlog::Configuration { + time_offset: Some("0".to_string()), + time_units: Some(qlog::TimeUnits::Ms), + original_uris: None, + }), + None, +); +``` + +Create an object with the [`Write`] trait: + +```rust +let mut file = std::fs::File::create("foo.qlog").unwrap(); +``` + +Create a [`QlogStreamer`] and start serialization to foo.qlog +using [`start_log()`]: + +```rust +let mut streamer = qlog::QlogStreamer::new( + qlog::QLOG_VERSION.to_string(), + Some("Example qlog".to_string()), + Some("Example qlog description".to_string()), + None, + std::time::Instant::now(), + trace, + Box::new(file), +); + +streamer.start_log().ok(); + +``` + +### Adding simple events + +Once logging has started you can stream events. Simple events can be written in +one step using [`add_event()`]: + +```rust +let event = qlog::event::Event::metrics_updated_min(); +streamer.add_event(event).ok(); +``` + +### Adding events with frames +Some events contain optional arrays of QUIC frames. If the event has +`Some(Vec)`, even if it is empty, the streamer enters a frame +serializing mode that must be finalized before other events can be logged. + +In this example, a PacketSent event is created with an empty frame array and +frames are written out later: + +```rust +let qlog_pkt_hdr = qlog::PacketHeader::with_type( + qlog::PacketType::OneRtt, + 0, + Some(1251), + Some(1224), + Some(0xff00001b), + Some(b"7e37e4dcc6682da8"), + Some(b"36ce104eee50101c"), +); + +let event = qlog::event::Event::packet_sent_min( + qlog::PacketType::OneRtt, + qlog_pkt_hdr, + Some(Vec::new()), +); + +streamer.add_event(event).ok(); + +``` + +In this example, the frames contained in the QUIC packet +are PING and PADDING. Each frame is written using the +[`add_frame()`] method. Frame writing is concluded with +[`finish_frames()`]. + +```rust +let ping = qlog::QuicFrame::ping(); +let padding = qlog::QuicFrame::padding(); + +streamer.add_frame(ping, false).ok(); +streamer.add_frame(padding, false).ok(); + +streamer.finish_frames().ok(); +``` + +Once all events have have been written, the log +can be finalized with [`finish_log()`]: + +```rust +streamer.finish_log().ok(); +``` + +### Serializing + +Serialization to JSON occurs as methods on the [`QlogStreamer`] +are called. No additional steps are required. + +[`Trace`]: struct.Trace.html +[`VantagePoint`]: struct.VantagePoint.html +[`Configuration`]: struct.Configuration.html +[`EventField`]: enum.EventField.html +[`EventField::RelativeTime`]: enum.EventField.html#variant.RelativeTime +[`EventField::Category`]: enum.EventField.html#variant.Category +[`EventField::Type`]: enum.EventField.html#variant.Type +[`EventField::Data`]: enum.EventField.html#variant.Data +[`qlog::Trace.events`]: struct.Trace.html#structfield.events +[`push_event()`]: struct.Trace.html#method.push_event +[`packet_sent_min()`]: event/struct.Event.html#method.packet_sent_min +[`QuicFrame::crypto()`]: enum.QuicFrame.html#variant.Crypto +[`QlogStreamer`]: struct.QlogStreamer.html +[`Write`]: https://doc.rust-lang.org/std/io/trait.Write.html +[`start_log()`]: struct.QlogStreamer.html#method.start_log +[`add_event()`]: struct.QlogStreamer.html#method.add_event +[`add_frame()`]: struct.QlogStreamer.html#method.add_frame +[`finish_frames()`]: struct.QlogStreamer.html#method.finish_frames +[`finish_log()`]: struct.QlogStreamer.html#method.finish_log \ No newline at end of file diff --git a/tools/qlog/src/event.rs b/tools/qlog/src/event.rs index 316857df53..beb74f4898 100644 --- a/tools/qlog/src/event.rs +++ b/tools/qlog/src/event.rs @@ -40,6 +40,7 @@ use super::*; /// of several optional fields, so minimal versions of these functions are /// provided, which accept only mandatory qlog parameters. Minimal functions are /// identified by a `_min` suffix. +#[derive(Clone)] pub struct Event { pub category: EventCategory, pub ty: EventType, diff --git a/tools/qlog/src/lib.rs b/tools/qlog/src/lib.rs index 859296203b..f8788c6516 100644 --- a/tools/qlog/src/lib.rs +++ b/tools/qlog/src/lib.rs @@ -38,7 +38,7 @@ //! [TypeScript schema]: //! https://github.com/quiclog/qlog/blob/master/TypeScript/draft-01/QLog.ts //! -//! Getting Started +//! Overview //! --------------- //! qlog is a hierarchical logging format, with a rough structure of: //! @@ -70,6 +70,13 @@ //! provided to assist in creating a Trace and appending events to it in this //! format. //! +//! ## Writing out logs +//! As events occur during the connection, the application appends them to the +//! trace. The qlog crate supports two modes of writing logs: the buffered mode +//! stores everything in memory and requires the application to serialize and write +//! the output, the streaming mode progressively writes serialized JSON output to a +//! writer designated by the application. +//! //! ### Creating a Trace //! //! A typical application needs a single qlog [`Trace`] that it appends QUIC @@ -125,16 +132,19 @@ //! //! let scid = [0x7e, 0x37, 0xe4, 0xdc, 0xc6, 0x68, 0x2d, 0xa8]; //! let dcid = [0x36, 0xce, 0x10, 0x4e, 0xee, 0x50, 0x10, 0x1c]; +//! //! let pkt_hdr = qlog::PacketHeader::new( //! 0, //! Some(1251), //! Some(1224), -//! Some(0xff000018), -//! Some(&scid), +//! Some(0xff00001b), +//! Some(b"7e37e4dcc6682da8"), //! Some(&dcid), //! ); +//! //! let frames = //! vec![qlog::QuicFrame::crypto("0".to_string(), "1000".to_string())]; +//! //! let event = qlog::event::Event::packet_sent_min( //! qlog::PacketType::Initial, //! pkt_hdr, @@ -146,7 +156,10 @@ //! //! ### Serializing //! -//! Simply: +//! The qlog crate has only been tested with `serde_json`, however +//! other serializer targets might work. +//! +//! For example, serializing the trace created above: //! //! ``` //! # let mut trace = qlog::Trace::new ( @@ -198,7 +211,7 @@ //! "packet_number": "0", //! "packet_size": 1251, //! "payload_length": 1224, -//! "version": "ff000018", +//! "version": "ff00001b", //! "scil": "8", //! "dcil": "8", //! "scid": "7e37e4dcc6682da8", @@ -216,6 +229,237 @@ //! ] //! } //! ``` +//! +//! Streaming Mode +//! -------------- +//! +//! Create the trace: +//! +//! ``` +//! let mut trace = qlog::Trace::new( +//! qlog::VantagePoint { +//! name: Some("Example client".to_string()), +//! ty: qlog::VantagePointType::Client, +//! flow: None, +//! }, +//! Some("Example qlog trace".to_string()), +//! Some("Example qlog trace description".to_string()), +//! Some(qlog::Configuration { +//! time_offset: Some("0".to_string()), +//! time_units: Some(qlog::TimeUnits::Ms), +//! original_uris: None, +//! }), +//! None, +//! ); +//! ``` +//! Create an object with the [`Write`] trait: +//! +//! ``` +//! let mut file = std::fs::File::create("foo.qlog").unwrap(); +//! ``` +//! +//! Create a [`QlogStreamer`] and start serialization to foo.qlog +//! using [`start_log()`]: +//! +//! ``` +//! # let mut trace = qlog::Trace::new( +//! # qlog::VantagePoint { +//! # name: Some("Example client".to_string()), +//! # ty: qlog::VantagePointType::Client, +//! # flow: None, +//! # }, +//! # Some("Example qlog trace".to_string()), +//! # Some("Example qlog trace description".to_string()), +//! # Some(qlog::Configuration { +//! # time_offset: Some("0".to_string()), +//! # time_units: Some(qlog::TimeUnits::Ms), +//! # original_uris: None, +//! # }), +//! # None, +//! # ); +//! # let mut file = std::fs::File::create("foo.qlog").unwrap(); +//! let mut streamer = qlog::QlogStreamer::new( +//! qlog::QLOG_VERSION.to_string(), +//! Some("Example qlog".to_string()), +//! Some("Example qlog description".to_string()), +//! None, +//! std::time::Instant::now(), +//! trace, +//! Box::new(file), +//! ); +//! +//! streamer.start_log().ok(); +//! ``` +//! +//! ### Adding simple events +//! +//! Once logging has started you can stream events. Simple events +//! can be written in one step using [`add_event()`]: +//! +//! ``` +//! # let mut trace = qlog::Trace::new( +//! # qlog::VantagePoint { +//! # name: Some("Example client".to_string()), +//! # ty: qlog::VantagePointType::Client, +//! # flow: None, +//! # }, +//! # Some("Example qlog trace".to_string()), +//! # Some("Example qlog trace description".to_string()), +//! # Some(qlog::Configuration { +//! # time_offset: Some("0".to_string()), +//! # time_units: Some(qlog::TimeUnits::Ms), +//! # original_uris: None, +//! # }), +//! # None, +//! # ); +//! # let mut file = std::fs::File::create("foo.qlog").unwrap(); +//! # let mut streamer = qlog::QlogStreamer::new( +//! # qlog::QLOG_VERSION.to_string(), +//! # Some("Example qlog".to_string()), +//! # Some("Example qlog description".to_string()), +//! # None, +//! # std::time::Instant::now(), +//! # trace, +//! # Box::new(file), +//! # ); +//! let event = qlog::event::Event::metrics_updated_min(); +//! streamer.add_event(event).ok(); +//! ``` +//! +//! ### Adding events with frames +//! Some events contain optional arrays of QUIC frames. If the +//! event has `Some(Vec)`, even if it is empty, the +//! streamer enters a frame serializing mode that must be +//! finalized before other events can be logged. +//! +//! In this example, a `PacketSent` event is created with an +//! empty frame array and frames are written out later: +//! +//! ``` +//! # let mut trace = qlog::Trace::new( +//! # qlog::VantagePoint { +//! # name: Some("Example client".to_string()), +//! # ty: qlog::VantagePointType::Client, +//! # flow: None, +//! # }, +//! # Some("Example qlog trace".to_string()), +//! # Some("Example qlog trace description".to_string()), +//! # Some(qlog::Configuration { +//! # time_offset: Some("0".to_string()), +//! # time_units: Some(qlog::TimeUnits::Ms), +//! # original_uris: None, +//! # }), +//! # None, +//! # ); +//! # let mut file = std::fs::File::create("foo.qlog").unwrap(); +//! # let mut streamer = qlog::QlogStreamer::new( +//! # qlog::QLOG_VERSION.to_string(), +//! # Some("Example qlog".to_string()), +//! # Some("Example qlog description".to_string()), +//! # None, +//! # std::time::Instant::now(), +//! # trace, +//! # Box::new(file), +//! # ); +//! let qlog_pkt_hdr = qlog::PacketHeader::with_type( +//! qlog::PacketType::OneRtt, +//! 0, +//! Some(1251), +//! Some(1224), +//! Some(0xff00001b), +//! Some(b"7e37e4dcc6682da8"), +//! Some(b"36ce104eee50101c"), +//! ); +//! +//! let event = qlog::event::Event::packet_sent_min( +//! qlog::PacketType::OneRtt, +//! qlog_pkt_hdr, +//! Some(Vec::new()), +//! ); +//! +//! streamer.add_event(event).ok(); +//! +//! ``` +//! +//! In this example, the frames contained in the QUIC packet +//! are PING and PADDING. Each frame is written using the +//! [`add_frame()`] method. Frame writing is concluded with +//! [`finish_frames()`]. +//! +//! ``` +//! # let mut trace = qlog::Trace::new( +//! # qlog::VantagePoint { +//! # name: Some("Example client".to_string()), +//! # ty: qlog::VantagePointType::Client, +//! # flow: None, +//! # }, +//! # Some("Example qlog trace".to_string()), +//! # Some("Example qlog trace description".to_string()), +//! # Some(qlog::Configuration { +//! # time_offset: Some("0".to_string()), +//! # time_units: Some(qlog::TimeUnits::Ms), +//! # original_uris: None, +//! # }), +//! # None, +//! # ); +//! # let mut file = std::fs::File::create("foo.qlog").unwrap(); +//! # let mut streamer = qlog::QlogStreamer::new( +//! # qlog::QLOG_VERSION.to_string(), +//! # Some("Example qlog".to_string()), +//! # Some("Example qlog description".to_string()), +//! # None, +//! # std::time::Instant::now(), +//! # trace, +//! # Box::new(file), +//! # ); +//! +//! let ping = qlog::QuicFrame::ping(); +//! let padding = qlog::QuicFrame::padding(); +//! +//! streamer.add_frame(ping, false).ok(); +//! streamer.add_frame(padding, false).ok(); +//! +//! streamer.finish_frames().ok(); +//! +//! ``` +//! +//! Once all events have have been written, the log +//! can be finalized with [`finish_log()`]: +//! +//! ``` +//! # let mut trace = qlog::Trace::new( +//! # qlog::VantagePoint { +//! # name: Some("Example client".to_string()), +//! # ty: qlog::VantagePointType::Client, +//! # flow: None, +//! # }, +//! # Some("Example qlog trace".to_string()), +//! # Some("Example qlog trace description".to_string()), +//! # Some(qlog::Configuration { +//! # time_offset: Some("0".to_string()), +//! # time_units: Some(qlog::TimeUnits::Ms), +//! # original_uris: None, +//! # }), +//! # None, +//! # ); +//! # let mut file = std::fs::File::create("foo.qlog").unwrap(); +//! # let mut streamer = qlog::QlogStreamer::new( +//! # qlog::QLOG_VERSION.to_string(), +//! # Some("Example qlog".to_string()), +//! # Some("Example qlog description".to_string()), +//! # None, +//! # std::time::Instant::now(), +//! # trace, +//! # Box::new(file), +//! # ); +//! streamer.finish_log().ok(); +//! ``` +//! +//! ### Serializing +//! +//! Serialization to JSON occurs as methods on the [`QlogStreamer`] +//! are called. No additional steps are required. +//! //! [`Trace`]: struct.Trace.html //! [`VantagePoint`]: struct.VantagePoint.html //! [`Configuration`]: struct.Configuration.html @@ -228,13 +472,60 @@ //! [`push_event()`]: struct.Trace.html#method.push_event //! [`packet_sent_min()`]: event/struct.Event.html#method.packet_sent_min //! [`QuicFrame::crypto()`]: enum.QuicFrame.html#variant.Crypto +//! [`QlogStreamer`]: struct.QlogStreamer.html +//! [`Write`]: https://doc.rust-lang.org/std/io/trait.Write.html +//! [`start_log()`]: struct.QlogStreamer.html#method.start_log +//! [`add_event()`]: struct.QlogStreamer.html#method.add_event +//! [`add_frame()`]: struct.QlogStreamer.html#method.add_frame +//! [`finish_frames()`]: struct.QlogStreamer.html#method.finish_frames +//! [`finish_log()`]: struct.QlogStreamer.html#method.finish_log use serde::{ Deserialize, Serialize, }; +/// A quiche qlog error. +#[derive(Debug)] +pub enum Error { + /// There is no more work to do. + Done, + + /// The operation cannot be completed because it was attempted + /// in an invalid state. + InvalidState, + + /// I/O error. + IoError(std::io::Error), +} + +impl std::fmt::Display for Error { + fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + write!(f, "{:?}", self) + } +} + +impl std::error::Error for Error { + fn source(&self) -> Option<&(dyn std::error::Error + 'static)> { + None + } +} + +impl std::convert::From for Error { + fn from(err: std::io::Error) -> Self { + Error::IoError(err) + } +} + pub const QLOG_VERSION: &str = "draft-01"; +/// A specialized [`Result`] type for quiche qlog operations. +/// +/// This type is used throughout the public API for any operation that +/// can produce an error. +/// +/// [`Result`]: https://doc.rust-lang.org/std/result/enum.Result.html +pub type Result = std::result::Result; + #[serde_with::skip_serializing_none] #[derive(Serialize, Clone)] pub struct Qlog { @@ -258,6 +549,252 @@ impl Default for Qlog { } } +#[derive(PartialEq)] +pub enum StreamerState { + Initial, + Ready, + WritingFrames, + Finished, +} + +/// A helper object specialized for streaming JSON-serialized qlog to a +/// [`Write`] trait. +/// +/// The object is responsible for the `Qlog` object that contains the provided +/// `Trace`. +/// +/// Serialization is progressively driven by method calls; once log streaming is +/// started, `event::Events` can be written using `add_event()`. Some events +/// can contain an array of `QuicFrame`s, when writing such an event, the +/// streamer enters a frame-serialization mode where frames are be progressively +/// written using `add_frame()`. This mode is concluded using +/// `finished_frames()`. While serializing frames, any attempts to log +/// additional events are ignored. +/// +/// [`Write`]: https://doc.rust-lang.org/std/io/trait.Write.html +pub struct QlogStreamer { + start_time: std::time::Instant, + writer: Box, + qlog: Qlog, + state: StreamerState, + first_event: bool, + first_frame: bool, +} + +impl QlogStreamer { + /// Creates a QlogStreamer object. + /// + /// It owns a `Qlog` object that contains the provided `Trace`, which must + /// have the following ordered-set of names EventFields: + /// + /// ["relative_time", "category", "event".to_string(), "data"] + /// + /// All serialization will be written to the provided `Write`. + pub fn new( + qlog_version: String, title: Option, description: Option, + summary: Option, start_time: std::time::Instant, trace: Trace, + writer: Box, + ) -> Self { + let qlog = Qlog { + qlog_version, + title, + description, + summary, + traces: vec![trace], + }; + + QlogStreamer { + start_time, + writer, + qlog, + state: StreamerState::Initial, + first_event: true, + first_frame: false, + } + } + + /// Starts qlog streaming serialization. + /// + /// This writes out the JSON-serialized form of all information up to qlog + /// `Trace`'s array of `EventField`s. EventFields are separately appended + /// using functions that accept and `event::Event`. + pub fn start_log(&mut self) -> Result<()> { + if self.state != StreamerState::Initial { + return Err(Error::Done); + } + + // A qlog contains a trace holding a vector of events that we want to + // serialize in a streaming manner. So at the start of serialization, + // take off all closing delimiters, and leave us in a state to accept + // new events. + match serde_json::to_string(&self.qlog) { + Ok(mut out) => { + out.truncate(out.len() - 4); + + self.writer.as_mut().write_all(out.as_bytes())?; + + self.state = StreamerState::Ready; + + self.first_event = self.qlog.traces[0].events.is_empty(); + }, + + _ => return Err(Error::Done), + } + + Ok(()) + } + + /// Finishes qlog streaming serialization. + /// + /// The JSON-serialized output has remaining close delimiters added. + /// After this is called, no more serialization will occur. + pub fn finish_log(&mut self) -> Result<()> { + if self.state == StreamerState::Initial || + self.state == StreamerState::Finished + { + return Err(Error::InvalidState); + } + + self.writer.as_mut().write_all(b"]}]}")?; + + self.state = StreamerState::Finished; + + self.writer.as_mut().flush()?; + + Ok(()) + } + + /// Writes a JSON-serialized `EventField`s. + /// + /// Some qlog events can contain `QuicFrames`. If this is detected `true` is + /// returned and the streamer enters a frame-serialization mode that is only + /// concluded by `finish_frames()`. In this mode, attempts to log additional + /// events are ignored. + /// + /// If the event contains no array of `QuicFrames` return `false`. + pub fn add_event(&mut self, event: event::Event) -> Result { + if self.state != StreamerState::Ready { + return Err(Error::InvalidState); + } + + let event_time = self.start_time.elapsed(); + + let rel = match &self.qlog.traces[0].configuration { + Some(conf) => match conf.time_units { + Some(TimeUnits::Ms) => event_time.as_millis().to_string(), + + Some(TimeUnits::Us) => event_time.as_micros().to_string(), + + None => String::from(""), + }, + + None => String::from(""), + }; + + let (ev_data, contains_frames) = match serde_json::to_string(&event.data) + { + Ok(mut ev_data_out) => + if let Some(f) = event.data.contains_quic_frames() { + ev_data_out.truncate(ev_data_out.len() - 2); + + if f == 0 { + self.first_frame = true; + } + + (ev_data_out, true) + } else { + (ev_data_out, false) + }, + + _ => return Err(Error::Done), + }; + + let maybe_comma = if self.first_event { + self.first_event = false; + "" + } else { + "," + }; + + let maybe_terminate = if contains_frames { "" } else { "]" }; + + let ev_time = serde_json::to_string(&EventField::RelativeTime(rel)).ok(); + let ev_cat = + serde_json::to_string(&EventField::Category(event.category)).ok(); + let ev_ty = serde_json::to_string(&EventField::Event(event.ty)).ok(); + + if let (Some(ev_time), Some(ev_cat), Some(ev_ty)) = + (ev_time, ev_cat, ev_ty) + { + let out = format!( + "{}[{},{},{},{}{}", + maybe_comma, ev_time, ev_cat, ev_ty, ev_data, maybe_terminate + ); + + self.writer.as_mut().write_all(out.as_bytes())?; + + if contains_frames { + self.state = StreamerState::WritingFrames + } else { + self.state = StreamerState::Ready + }; + + return Ok(contains_frames); + } + + Err(Error::Done) + } + + /// Writes a JSON-serialized `QuicFrame`. + /// + /// Only valid while in the frame-serialization mode. + pub fn add_frame(&mut self, frame: QuicFrame, last: bool) -> Result<()> { + if self.state != StreamerState::WritingFrames { + return Err(Error::InvalidState); + } + + match serde_json::to_string(&frame) { + Ok(mut out) => { + if !self.first_frame { + out.insert(0, ','); + } else { + self.first_frame = false; + } + + self.writer.as_mut().write_all(out.as_bytes())?; + + if last { + self.finish_frames()?; + } + }, + + _ => return Err(Error::Done), + } + + Ok(()) + } + + /// Concludes `QuicFrame` streaming serialization. + /// + /// Only valid while in the frame-serialization mode. + pub fn finish_frames(&mut self) -> Result<()> { + if self.state != StreamerState::WritingFrames { + return Err(Error::InvalidState); + } + + self.writer.as_mut().write_all(b"]}]")?; + self.state = StreamerState::Ready; + + Ok(()) + } + + /// Returns the writer. + #[allow(clippy::borrowed_box)] + pub fn writer(&self) -> &Box { + &self.writer + } +} + #[serde_with::skip_serializing_none] #[derive(Serialize, Clone)] pub struct Trace { @@ -1027,6 +1564,29 @@ pub enum EventData { }, } +impl EventData { + /// Returns size of `EventData` array of `QuicFrame`s if it exists. + pub fn contains_quic_frames(&self) -> Option { + // For some EventData variants, the frame array is optional + // but for others it is mandatory. + match self { + EventData::PacketSent { frames, .. } | + EventData::PacketReceived { frames, .. } => + if let Some(f) = frames { + Some(f.len()) + } else { + None + }, + + EventData::PacketLost { frames, .. } | + EventData::MarkedForRetransmit { frames } | + EventData::FramesProcessed { frames } => Some(frames.len()), + + _ => None, + } + } +} + #[derive(Serialize, Clone)] #[serde(rename_all = "snake_case")] pub enum PacketType { @@ -1108,6 +1668,7 @@ pub struct PacketHeader { } impl PacketHeader { + /// Creates a new PacketHeader. pub fn new( packet_number: u64, packet_size: Option, payload_length: Option, version: Option, scid: Option<&[u8]>, @@ -1148,6 +1709,37 @@ impl PacketHeader { dcid, } } + + /// Creates a new PacketHeader. + /// + /// Once a QUIC connection has formed, version, dcid and scid are stable, so + /// there are space benefits to not logging them in every packet, especially + /// PacketType::OneRtt. + pub fn with_type( + ty: PacketType, packet_number: u64, packet_size: Option, + payload_length: Option, version: Option, scid: Option<&[u8]>, + dcid: Option<&[u8]>, + ) -> Self { + match ty { + PacketType::OneRtt => PacketHeader::new( + packet_number, + packet_size, + payload_length, + None, + None, + None, + ), + + _ => PacketHeader::new( + packet_number, + packet_size, + payload_length, + version, + scid, + dcid, + ), + } + } } #[derive(Serialize, Clone)] @@ -1865,24 +2457,50 @@ impl<'a> std::fmt::Display for HexSlice<'a> { } #[doc(hidden)] -pub mod testing {} - -#[cfg(test)] -mod tests { +pub mod testing { use super::*; - #[test] - fn packet_header() { + pub fn make_pkt_hdr() -> PacketHeader { let scid = [0x7e, 0x37, 0xe4, 0xdc, 0xc6, 0x68, 0x2d, 0xa8]; let dcid = [0x36, 0xce, 0x10, 0x4e, 0xee, 0x50, 0x10, 0x1c]; - let pkt_hdr = PacketHeader::new( + + PacketHeader::new( 0, Some(1251), Some(1224), - Some(0xff000018), + Some(0xff00_0018), Some(&scid), Some(&dcid), - ); + ) + } + + pub fn make_trace() -> Trace { + Trace::new( + VantagePoint { + name: None, + ty: VantagePointType::Server, + flow: None, + }, + Some("Quiche qlog trace".to_string()), + Some("Quiche qlog trace description".to_string()), + Some(Configuration { + time_offset: Some("0".to_string()), + time_units: Some(TimeUnits::Ms), + original_uris: None, + }), + None, + ) + } +} + +#[cfg(test)] +mod tests { + use super::*; + use testing::*; + + #[test] + fn packet_header() { + let pkt_hdr = make_pkt_hdr(); let log_string = r#"{ "packet_number": "0", @@ -1906,7 +2524,7 @@ mod tests { "packet_number": "0", "packet_size": 1251, "payload_length": 1224, - "version": "ff000018", + "version": "ff00001b", "scil": "8", "dcil": "8", "scid": "7e37e4dcc6682da8", @@ -1920,7 +2538,7 @@ mod tests { 0, Some(1251), Some(1224), - Some(0xff000018), + Some(0xff00001b), Some(&scid), Some(&dcid), ); @@ -1971,16 +2589,7 @@ mod tests { ] }"#; - let scid = [0x7e, 0x37, 0xe4, 0xdc, 0xc6, 0x68, 0x2d, 0xa8]; - let dcid = [0x36, 0xce, 0x10, 0x4e, 0xee, 0x50, 0x10, 0x1c]; - let pkt_hdr = PacketHeader::new( - 0, - Some(1251), - Some(1224), - Some(0xff000018), - Some(&scid), - Some(&dcid), - ); + let pkt_hdr = make_pkt_hdr(); let mut frames = Vec::new(); frames.push(QuicFrame::padding()); @@ -2031,29 +2640,14 @@ mod tests { "events": [] }"#; - let trace = Trace::new( - VantagePoint { - name: None, - ty: VantagePointType::Server, - flow: None, - }, - Some("Quiche qlog trace".to_string()), - Some("Quiche qlog trace description".to_string()), - Some(Configuration { - time_offset: Some("0".to_string()), - time_units: Some(TimeUnits::Ms), - original_uris: None, - }), - None, - ); + let trace = make_trace(); assert_eq!(serde_json::to_string_pretty(&trace).unwrap(), log_string); } -} -#[test] -fn trace_single_transport_event() { - let log_string = r#"{ + #[test] + fn trace_single_transport_event() { + let log_string = r#"{ "vantage_point": { "type": "server" }, @@ -2100,109 +2694,213 @@ fn trace_single_transport_event() { ] }"#; - let mut trace = Trace::new( - VantagePoint { - name: None, - ty: VantagePointType::Server, - flow: None, - }, - Some("Quiche qlog trace".to_string()), - Some("Quiche qlog trace description".to_string()), - Some(Configuration { - time_offset: Some("0".to_string()), - time_units: Some(TimeUnits::Ms), - original_uris: None, - }), - None, - ); - - let scid = [0x7e, 0x37, 0xe4, 0xdc, 0xc6, 0x68, 0x2d, 0xa8]; - let dcid = [0x36, 0xce, 0x10, 0x4e, 0xee, 0x50, 0x10, 0x1c]; - let pkt_hdr = PacketHeader::new( - 0, - Some(1251), - Some(1224), - Some(0xff000018), - Some(&scid), - Some(&dcid), - ); - let frames = vec![QuicFrame::stream( - "0".to_string(), - "0".to_string(), - "100".to_string(), - true, - None, - )]; - let event = - event::Event::packet_sent_min(PacketType::Initial, pkt_hdr, Some(frames)); - - trace.push_event(std::time::Duration::new(0, 0), event); - - assert_eq!(serde_json::to_string_pretty(&trace).unwrap(), log_string); -} - -#[test] -fn test_event_validity() { - // Test a single event in each category - - let ev = event::Event::server_listening_min(443, 443); - assert!(ev.is_valid()); - - let ev = event::Event::transport_parameters_set_min(); - assert!(ev.is_valid()); - - let ev = event::Event::recovery_parameters_set_min(); - assert!(ev.is_valid()); - - let ev = event::Event::h3_parameters_set_min(); - assert!(ev.is_valid()); - - let ev = event::Event::qpack_state_updated_min(); - assert!(ev.is_valid()); - - let ev = event::Event { - category: EventCategory::Error, - ty: EventType::GenericEventType(GenericEventType::ConnectionError), - data: EventData::ConnectionError { - code: None, - description: None, - }, - }; + let mut trace = make_trace(); - assert!(ev.is_valid()); -} + let pkt_hdr = make_pkt_hdr(); -#[test] -fn test_bogus_event_validity() { - // Test a single event in each category + let frames = vec![QuicFrame::stream( + "0".to_string(), + "0".to_string(), + "100".to_string(), + true, + None, + )]; + let event = event::Event::packet_sent_min( + PacketType::Initial, + pkt_hdr, + Some(frames), + ); + + trace.push_event(std::time::Duration::new(0, 0), event); - let mut ev = event::Event::server_listening_min(443, 443); - ev.category = EventCategory::Simulation; - assert!(!ev.is_valid()); + assert_eq!(serde_json::to_string_pretty(&trace).unwrap(), log_string); + } + + #[test] + fn test_event_validity() { + // Test a single event in each category - let mut ev = event::Event::transport_parameters_set_min(); - ev.category = EventCategory::Simulation; - assert!(!ev.is_valid()); + let ev = event::Event::server_listening_min(443, 443); + assert!(ev.is_valid()); - let mut ev = event::Event::recovery_parameters_set_min(); - ev.category = EventCategory::Simulation; - assert!(!ev.is_valid()); + let ev = event::Event::transport_parameters_set_min(); + assert!(ev.is_valid()); - let mut ev = event::Event::h3_parameters_set_min(); - ev.category = EventCategory::Simulation; - assert!(!ev.is_valid()); + let ev = event::Event::recovery_parameters_set_min(); + assert!(ev.is_valid()); - let mut ev = event::Event::qpack_state_updated_min(); - ev.category = EventCategory::Simulation; - assert!(!ev.is_valid()); + let ev = event::Event::h3_parameters_set_min(); + assert!(ev.is_valid()); - let ev = event::Event { - category: EventCategory::Error, - ty: EventType::GenericEventType(GenericEventType::ConnectionError), - data: EventData::FramesProcessed { frames: Vec::new() }, - }; + let ev = event::Event::qpack_state_updated_min(); + assert!(ev.is_valid()); - assert!(!ev.is_valid()); + let ev = event::Event { + category: EventCategory::Error, + ty: EventType::GenericEventType(GenericEventType::ConnectionError), + data: EventData::ConnectionError { + code: None, + description: None, + }, + }; + + assert!(ev.is_valid()); + } + + #[test] + fn bogus_event_validity() { + // Test a single event in each category + + let mut ev = event::Event::server_listening_min(443, 443); + ev.category = EventCategory::Simulation; + assert!(!ev.is_valid()); + + let mut ev = event::Event::transport_parameters_set_min(); + ev.category = EventCategory::Simulation; + assert!(!ev.is_valid()); + + let mut ev = event::Event::recovery_parameters_set_min(); + ev.category = EventCategory::Simulation; + assert!(!ev.is_valid()); + + let mut ev = event::Event::h3_parameters_set_min(); + ev.category = EventCategory::Simulation; + assert!(!ev.is_valid()); + + let mut ev = event::Event::qpack_state_updated_min(); + ev.category = EventCategory::Simulation; + assert!(!ev.is_valid()); + + let ev = event::Event { + category: EventCategory::Error, + ty: EventType::GenericEventType(GenericEventType::ConnectionError), + data: EventData::FramesProcessed { frames: Vec::new() }, + }; + + assert!(!ev.is_valid()); + } + + #[test] + fn serialization_states() { + let v: Vec = Vec::new(); + let buff = std::io::Cursor::new(v); + let writer = Box::new(buff); + + let mut trace = make_trace(); + let pkt_hdr = make_pkt_hdr(); + + let frame1 = QuicFrame::stream( + "40".to_string(), + "40".to_string(), + "400".to_string(), + true, + None, + ); + + let event1 = event::Event::packet_sent_min( + PacketType::Handshake, + pkt_hdr.clone(), + Some(vec![frame1]), + ); + + trace.push_event(std::time::Duration::new(0, 0), event1); + + let frame2 = QuicFrame::stream( + "0".to_string(), + "0".to_string(), + "100".to_string(), + true, + None, + ); + + let event2 = event::Event::packet_sent_min( + PacketType::Initial, + pkt_hdr, + Some(Vec::new()), + ); + + let mut s = QlogStreamer::new( + "version".to_string(), + Some("title".to_string()), + Some("description".to_string()), + None, + std::time::Instant::now(), + trace, + writer, + ); + + // Before the log is started all other operations should fail. + assert!(match s.add_event(event2.clone()) { + Err(Error::InvalidState) => true, + _ => false, + }); + assert!(match s.add_frame(frame2.clone(), false) { + Err(Error::InvalidState) => true, + _ => false, + }); + assert!(match s.finish_frames() { + Err(Error::InvalidState) => true, + _ => false, + }); + assert!(match s.finish_log() { + Err(Error::InvalidState) => true, + _ => false, + }); + + // Once a log is started, can't write frames before an event. + assert!(match s.start_log() { + Ok(()) => true, + _ => false, + }); + assert!(match s.add_frame(frame2.clone(), true) { + Err(Error::InvalidState) => true, + _ => false, + }); + assert!(match s.finish_frames() { + Err(Error::InvalidState) => true, + _ => false, + }); + + // Some events hold frames, can't write any more events until frame + // writing is concluded. + assert!(match s.add_event(event2.clone()) { + Ok(true) => true, + _ => false, + }); + assert!(match s.add_event(event2.clone()) { + Err(Error::InvalidState) => true, + _ => false, + }); + + // While writing frames, can't write events. + assert!(match s.add_frame(frame2.clone(), false) { + Ok(()) => true, + _ => false, + }); + assert!(match s.add_event(event2.clone()) { + Err(Error::InvalidState) => true, + _ => false, + }); + + // Finish logging + assert!(match s.finish_frames() { + Ok(()) => true, + _ => false, + }); + assert!(match s.finish_log() { + Ok(()) => true, + _ => false, + }); + + let r = s.writer(); + let w: &Box>> = unsafe { std::mem::transmute(r) }; + + let log_string = r#"{"qlog_version":"version","title":"title","description":"description","traces":[{"vantage_point":{"type":"server"},"title":"Quiche qlog trace","description":"Quiche qlog trace description","configuration":{"time_units":"ms","time_offset":"0"},"event_fields":["relative_time","category","event","data"],"events":[["0","transport","packet_sent",{"packet_type":"handshake","header":{"packet_number":"0","packet_size":1251,"payload_length":1224,"version":"ff000018","scil":"8","dcil":"8","scid":"7e37e4dcc6682da8","dcid":"36ce104eee50101c"},"frames":[{"frame_type":"stream","stream_id":"40","offset":"40","length":"400","fin":true}]}],["0","transport","packet_sent",{"packet_type":"initial","header":{"packet_number":"0","packet_size":1251,"payload_length":1224,"version":"ff000018","scil":"8","dcil":"8","scid":"7e37e4dcc6682da8","dcid":"36ce104eee50101c"},"frames":[{"frame_type":"stream","stream_id":"0","offset":"0","length":"100","fin":true}]}]]}]}"#; + + let written_string = std::str::from_utf8(w.as_ref().get_ref()).unwrap(); + + assert_eq!(log_string, written_string); + } } pub mod event; From 1646345b709d783b1b27069d86a36877c1427a32 Mon Sep 17 00:00:00 2001 From: lucas Date: Thu, 26 Mar 2020 17:53:08 +0000 Subject: [PATCH 2/2] libs/apps: add qlog support This change introduces qlog support into the quiche library as a new optional feature that is disabled by default. qlog occurs in addition to conventional Rust logging. To build quiche with qlog support do: cargo build --features qlog Rust applications can enable qlog on a per-connection basis via the `set_qlog()` method. C applications can use `quiche_conn_set_qlog_fd()`. Once qlog is enabled, qlog events are seralized in a streaming fashion to the target Write trait or file descriptor. --- Cargo.toml | 1 + clippy.toml | 2 +- include/quiche.h | 4 + src/ffi.rs | 22 +++ src/frame.rs | 148 ++++++++++++++++++ src/lib.rs | 231 ++++++++++++++++++++++++++++ src/packet.rs | 17 ++ src/ranges.rs | 15 +- src/recovery.rs | 22 +++ tools/apps/Cargo.toml | 3 +- tools/apps/src/bin/quiche-client.rs | 15 ++ tools/apps/src/bin/quiche-server.rs | 18 ++- tools/apps/src/lib.rs | 24 ++- 13 files changed, 512 insertions(+), 10 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 7e2f874ad1..e0472265b7 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -62,6 +62,7 @@ libc = "0.2" ring = "0.16" criterion = { version = "0.3", optional = true } lazy_static = "1" +qlog = { version = "0.2", optional = true } [target."cfg(windows)".dependencies] winapi = { version = "0.3", features = ["wincrypt"] } diff --git a/clippy.toml b/clippy.toml index d2939b9f95..1069540c83 100644 --- a/clippy.toml +++ b/clippy.toml @@ -1 +1 @@ -cognitive-complexity-threshold = 70 +cognitive-complexity-threshold = 72 diff --git a/include/quiche.h b/include/quiche.h index 7a15e0ce63..65228e8671 100644 --- a/include/quiche.h +++ b/include/quiche.h @@ -214,6 +214,10 @@ quiche_conn *quiche_conn_new_with_tls(const uint8_t *scid, size_t scid_len, quiche_config *config, void *ssl, bool is_server); +// Enables qlog to the specified file descriptor. Unix only. +void quiche_conn_set_qlog_fd(quiche_conn *conn, int fd, const char * log_title, + const char * log_desc); + // Processes QUIC packets received from the peer. ssize_t quiche_conn_recv(quiche_conn *conn, uint8_t *buf, size_t buf_len); diff --git a/src/ffi.rs b/src/ffi.rs index 00931123b0..a43990d4aa 100644 --- a/src/ffi.rs +++ b/src/ffi.rs @@ -29,6 +29,9 @@ use std::ptr; use std::slice; use std::sync::atomic; +#[cfg(all(unix, feature = "qlog"))] +use std::os::unix::io::FromRawFd; + use libc::c_char; use libc::c_int; use libc::c_void; @@ -231,6 +234,25 @@ pub extern fn quiche_config_set_cc_algorithm( config.set_cc_algorithm(algo); } +#[no_mangle] +#[cfg(all(unix, feature = "qlog"))] +pub extern fn quiche_conn_set_qlog_fd( + conn: &mut Connection, fd: c_int, log_title: *const c_char, + log_desc: *const c_char, +) { + let f = unsafe { std::fs::File::from_raw_fd(fd) }; + let writer = std::io::BufWriter::new(f); + + let title = unsafe { ffi::CStr::from_ptr(log_title).to_str().unwrap() }; + let description = unsafe { ffi::CStr::from_ptr(log_desc).to_str().unwrap() }; + + conn.set_qlog( + std::boxed::Box::new(writer), + title.to_string(), + format!("{} id={}", description, conn.trace_id), + ); +} + #[no_mangle] pub extern fn quiche_config_free(config: *mut Config) { unsafe { Box::from_raw(config) }; diff --git a/src/frame.rs b/src/frame.rs index 744fc98cec..cbac38a014 100644 --- a/src/frame.rs +++ b/src/frame.rs @@ -689,6 +689,154 @@ impl Frame { _ => true, } } + + #[cfg(feature = "qlog")] + pub fn to_qlog(&self) -> qlog::QuicFrame { + match self { + Frame::Padding { .. } => qlog::QuicFrame::padding(), + + Frame::Ping { .. } => qlog::QuicFrame::ping(), + + Frame::ACK { ack_delay, ranges } => { + let ack_ranges = + ranges.iter().map(|r| (r.start, r.end - 1)).collect(); + qlog::QuicFrame::ack( + Some(ack_delay.to_string()), + Some(ack_ranges), + None, + None, + None, + ) + }, + + Frame::ResetStream { + stream_id, + error_code, + final_size, + } => qlog::QuicFrame::reset_stream( + stream_id.to_string(), + *error_code, + final_size.to_string(), + ), + + Frame::StopSending { + stream_id, + error_code, + } => + qlog::QuicFrame::stop_sending(stream_id.to_string(), *error_code), + + Frame::Crypto { data } => qlog::QuicFrame::crypto( + data.off().to_string(), + data.len().to_string(), + ), + + Frame::NewToken { token } => qlog::QuicFrame::new_token( + token.len().to_string(), + "TODO: https://github.com/quiclog/internet-drafts/issues/36" + .to_string(), + ), + + Frame::Stream { stream_id, data } => qlog::QuicFrame::stream( + stream_id.to_string(), + data.off().to_string(), + data.len().to_string(), + data.fin(), + None, + ), + + Frame::MaxData { max } => qlog::QuicFrame::max_data(max.to_string()), + + Frame::MaxStreamData { stream_id, max } => + qlog::QuicFrame::max_stream_data( + stream_id.to_string(), + max.to_string(), + ), + + Frame::MaxStreamsBidi { max } => qlog::QuicFrame::max_streams( + qlog::StreamType::Bidirectional, + max.to_string(), + ), + + Frame::MaxStreamsUni { max } => qlog::QuicFrame::max_streams( + qlog::StreamType::Unidirectional, + max.to_string(), + ), + + Frame::DataBlocked { limit } => + qlog::QuicFrame::data_blocked(limit.to_string()), + + Frame::StreamDataBlocked { stream_id, limit } => + qlog::QuicFrame::stream_data_blocked( + stream_id.to_string(), + limit.to_string(), + ), + + Frame::StreamsBlockedBidi { limit } => + qlog::QuicFrame::streams_blocked( + qlog::StreamType::Bidirectional, + limit.to_string(), + ), + + Frame::StreamsBlockedUni { limit } => + qlog::QuicFrame::streams_blocked( + qlog::StreamType::Unidirectional, + limit.to_string(), + ), + + Frame::NewConnectionId { + seq_num, + retire_prior_to, + conn_id, + .. + } => qlog::QuicFrame::new_connection_id( + seq_num.to_string(), + retire_prior_to.to_string(), + conn_id.len() as u64, + "TODO: https://github.com/quiclog/internet-drafts/issues/36" + .to_string(), + "TODO: https://github.com/quiclog/internet-drafts/issues/36" + .to_string(), + ), + + Frame::RetireConnectionId { seq_num } => + qlog::QuicFrame::retire_connection_id(seq_num.to_string()), + + Frame::PathChallenge { .. } => qlog::QuicFrame::path_challenge(Some( + "TODO: https://github.com/quiclog/internet-drafts/issues/36" + .to_string(), + )), + + Frame::PathResponse { .. } => qlog::QuicFrame::path_response(Some( + "TODO: https://github.com/quiclog/internet-drafts/issues/36" + .to_string(), + )), + + Frame::ConnectionClose { + error_code, reason, .. + } => qlog::QuicFrame::connection_close( + qlog::ErrorSpace::TransportError, + *error_code, + *error_code, + String::from_utf8(reason.clone()).unwrap(), + Some( + "TODO: https://github.com/quiclog/internet-drafts/issues/36" + .to_string(), + ), + ), + + Frame::ApplicationClose { error_code, reason } => + qlog::QuicFrame::connection_close( + qlog::ErrorSpace::ApplicationError, + *error_code, + *error_code, + String::from_utf8(reason.clone()).unwrap(), + None, /* Application variant of the frame has no trigger + * frame type */ + ), + + _ => qlog::QuicFrame::unknown(std::u64::MAX), + } + } } impl std::fmt::Debug for Frame { diff --git a/src/lib.rs b/src/lib.rs index 8b468b165e..8270f0a3eb 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -271,6 +271,9 @@ use std::time; use std::pin::Pin; use std::str::FromStr; +#[cfg(feature = "qlog")] +use qlog::event::Event; + /// The current QUIC wire version. pub const PROTOCOL_VERSION: u32 = PROTOCOL_VERSION_DRAFT27; @@ -850,6 +853,14 @@ pub struct Connection { /// Whether to send GREASE. grease: bool, + + /// Qlog streaming output. + #[cfg(feature = "qlog")] + qlog_streamer: Option, + + /// Whether peer transport parameters were qlogged. + #[cfg(feature = "qlog")] + qlogged_peer_params: bool, } /// Creates a new server-side connection. @@ -1029,6 +1040,21 @@ macro_rules! push_frame_to_pkt { }}; } +/// Conditional qlog action. +/// +/// Executes the provided body if the qlog feature is enabled and quiche +/// has been condifigured with a log writer. +macro_rules! qlog_with { + ($qlog_streamer:expr, $qlog_streamer_ref:ident, $body:block) => {{ + #[cfg(feature = "qlog")] + { + if let Some($qlog_streamer_ref) = &mut $qlog_streamer { + $body + } + } + }}; +} + impl Connection { fn new( scid: &[u8], odcid: Option<&[u8]>, config: &mut Config, is_server: bool, @@ -1126,6 +1152,12 @@ impl Connection { closed: false, grease: config.grease, + + #[cfg(feature = "qlog")] + qlog_streamer: None, + + #[cfg(feature = "qlog")] + qlogged_peer_params: false, }); if let Some(odcid) = odcid { @@ -1157,6 +1189,60 @@ impl Connection { Ok(conn) } + /// Sets qlog output to the designated [`Writer`]. + /// + /// [`Writer`]: https://doc.rust-lang.org/std/io/trait.Write.html + #[cfg(feature = "qlog")] + pub fn set_qlog( + &mut self, writer: Box, title: String, + description: String, + ) { + let vp = if self.is_server { + qlog::VantagePointType::Server + } else { + qlog::VantagePointType::Client + }; + + let trace = qlog::Trace::new( + qlog::VantagePoint { + name: None, + ty: vp, + flow: None, + }, + Some(title.to_string()), + Some(description.to_string()), + Some(qlog::Configuration { + time_offset: Some("0".to_string()), + time_units: Some(qlog::TimeUnits::Ms), + original_uris: None, + }), + None, + ); + + let mut streamer = qlog::QlogStreamer::new( + qlog::QLOG_VERSION.to_string(), + Some(title), + Some(description), + None, + std::time::Instant::now(), + trace, + writer, + ); + + streamer.start_log().ok(); + + let ev = self.peer_transport_params.to_qlog( + qlog::TransportOwner::Local, + self.version, + self.handshake.alpn_protocol(), + self.handshake.cipher(), + ); + + streamer.add_event(ev).ok(); + + self.qlog_streamer = Some(streamer); + } + /// Processes QUIC packets received from the peer. /// /// On success the number of bytes processed from the input buffer is @@ -1501,6 +1587,30 @@ impl Connection { pn ); + qlog_with!(self.qlog_streamer, q, { + let packet_size = b.len(); + + let qlog_pkt_hdr = qlog::PacketHeader::with_type( + hdr.ty.to_qlog(), + pn, + Some(packet_size as u64), + Some(payload_len as u64), + Some(hdr.version), + Some(&hdr.scid), + Some(&hdr.dcid), + ); + + q.add_event(Event::packet_received( + hdr.ty.to_qlog(), + qlog_pkt_hdr, + Some(Vec::new()), + None, + None, + None, + )) + .ok(); + }); + let mut payload = packet::decrypt_pkt(&mut b, pn, pn_len, payload_len, &aead).map_err( |e| drop_pkt_on_err(e, self.recv_count, &self.trace_id), @@ -1520,6 +1630,10 @@ impl Connection { while payload.cap() > 0 { let frame = frame::Frame::from_bytes(&mut payload, hdr.ty)?; + qlog_with!(self.qlog_streamer, q, { + q.add_frame(frame.to_qlog(), false).ok(); + }); + if frame.ack_eliciting() { ack_elicited = true; } @@ -1527,6 +1641,36 @@ impl Connection { self.process_frame(frame, epoch, now)?; } + qlog_with!(self.qlog_streamer, q, { + // always conclude frame writing + q.finish_frames().ok(); + }); + + // Only log the remote transport parameters once the connection is + // established (i.e. after frames have been fully parsed) and only + // once per connection. + if self.is_established() { + qlog_with!(self.qlog_streamer, q, { + // Always conclude frame writing. + q.finish_frames().ok(); + + if !self.qlogged_peer_params { + let ev = self.peer_transport_params.to_qlog( + qlog::TransportOwner::Remote, + self.version, + self.handshake.alpn_protocol(), + self.handshake.cipher(), + ); + + if let Some(qlog_streamer) = self.qlog_streamer.as_mut() { + qlog_streamer.add_event(ev).unwrap(); + } + + self.qlogged_peer_params = true; + } + }); + } + // Process acked frames. for acked in self.recovery.acked[epoch].drain(..) { match acked { @@ -2115,13 +2259,41 @@ impl Connection { pn ); + qlog_with!(self.qlog_streamer, q, { + let qlog_pkt_hdr = qlog::PacketHeader::with_type( + hdr.ty.to_qlog(), + pn, + Some(payload_len as u64 + payload_offset as u64), + Some(payload_len as u64), + Some(hdr.version), + Some(&hdr.scid), + Some(&hdr.dcid), + ); + + let packet_sent_ev = Event::packet_sent_min( + hdr.ty.to_qlog(), + qlog_pkt_hdr, + Some(Vec::new()), + ); + + q.add_event(packet_sent_ev).ok(); + }); + // Encode frames into the output packet. for frame in &frames { trace!("{} tx frm {:?}", self.trace_id, frame); frame.to_bytes(&mut b)?; + + qlog_with!(self.qlog_streamer, q, { + q.add_frame(frame.to_qlog(), false).ok(); + }); } + qlog_with!(self.qlog_streamer, q, { + q.finish_frames().ok(); + }); + let aead = match self.pkt_num_spaces[epoch].crypto_seal { Some(ref v) => v, None => return Err(Error::InvalidState), @@ -2157,6 +2329,11 @@ impl Connection { &self.trace_id, ); + qlog_with!(self.qlog_streamer, q, { + let ev = self.recovery.to_qlog(); + q.add_event(ev).ok(); + }); + self.pkt_num_spaces[epoch].next_pkt_num += 1; self.sent_count += 1; @@ -2568,6 +2745,10 @@ impl Connection { if draining_timer <= now { trace!("{} draining timeout expired", self.trace_id); + qlog_with!(self.qlog_streamer, q, { + q.finish_log().ok(); + }); + self.closed = true; } @@ -2581,6 +2762,10 @@ impl Connection { if timer <= now { trace!("{} idle timeout expired", self.trace_id); + qlog_with!(self.qlog_streamer, q, { + q.finish_log().ok(); + }); + self.closed = true; return; } @@ -2596,6 +2781,11 @@ impl Connection { &self.trace_id, ); + qlog_with!(self.qlog_streamer, q, { + let ev = self.recovery.to_qlog(); + q.add_event(ev).ok(); + }); + return; } } @@ -2854,6 +3044,11 @@ impl Connection { &self.trace_id, )?; + qlog_with!(self.qlog_streamer, q, { + let ev = self.recovery.to_qlog(); + q.add_event(ev).ok(); + }); + // When we receive an ACK for a 1-RTT packet after handshake // completion, it means the handshake has been confirmed. if epoch == packet::EPOCH_APPLICATION && self.is_established() { @@ -3573,6 +3768,42 @@ impl TransportParams { Ok(&mut out[..out_len]) } + + /// Creates a qlog event for connection transport parameters and TLS fields + #[cfg(feature = "qlog")] + pub fn to_qlog( + &self, owner: qlog::TransportOwner, version: u32, alpn: &[u8], + cipher: Option, + ) -> qlog::event::Event { + let ocid = + qlog::HexSlice::maybe_string(self.original_connection_id.as_ref()); + let stateless_reset_token = + qlog::HexSlice::maybe_string(self.stateless_reset_token.as_ref()); + + Event::transport_parameters_set( + Some(owner), + None, // resumption + None, // early data + String::from_utf8(alpn.to_vec()).ok(), + Some(format!("{:x?}", version)), + Some(format!("{:?}", cipher)), + ocid, + stateless_reset_token, + Some(self.disable_active_migration), + Some(self.max_idle_timeout), + Some(self.max_packet_size), + Some(self.ack_delay_exponent), + Some(self.max_ack_delay), + Some(self.active_conn_id_limit), + Some(self.initial_max_data.to_string()), + Some(self.initial_max_stream_data_bidi_local.to_string()), + Some(self.initial_max_stream_data_bidi_remote.to_string()), + Some(self.initial_max_stream_data_uni.to_string()), + Some(self.initial_max_streams_bidi.to_string()), + Some(self.initial_max_streams_uni.to_string()), + None, // preferred address + ) + } } #[doc(hidden)] diff --git a/src/packet.rs b/src/packet.rs index c9a78ac5c6..c97dc6a4a7 100644 --- a/src/packet.rs +++ b/src/packet.rs @@ -109,6 +109,23 @@ impl Type { _ => Err(Error::InvalidPacket), } } + + #[cfg(feature = "qlog")] + pub(crate) fn to_qlog(self) -> qlog::PacketType { + match self { + Type::Initial => qlog::PacketType::Initial, + + Type::Retry => qlog::PacketType::Retry, + + Type::Handshake => qlog::PacketType::Handshake, + + Type::ZeroRTT => qlog::PacketType::ZeroRtt, + + Type::VersionNegotiation => qlog::PacketType::VersionNegotiation, + + Type::Short => qlog::PacketType::OneRtt, + } + } } /// A QUIC packet's header. diff --git a/src/ranges.rs b/src/ranges.rs index 3d1f718341..b61535f201 100644 --- a/src/ranges.rs +++ b/src/ranges.rs @@ -244,7 +244,8 @@ mod tests { fn insert_non_overlapping() { let mut r = RangeSet::default(); assert_eq!(r.inner.len(), 0); - assert_eq!(&r.flatten().collect::>(), &[]); + let empty: &[u64] = &[]; + assert_eq!(&r.flatten().collect::>(), &empty); r.insert(4..7); assert_eq!(r.inner.len(), 1); @@ -432,7 +433,9 @@ mod tests { fn flatten_rev() { let mut r = RangeSet::default(); assert_eq!(r.inner.len(), 0); - assert_eq!(&r.flatten().collect::>(), &[]); + + let empty: &[u64] = &[]; + assert_eq!(&r.flatten().collect::>(), &empty); r.insert(4..7); assert_eq!(r.inner.len(), 1); @@ -451,7 +454,9 @@ mod tests { fn flatten_one() { let mut r = RangeSet::default(); assert_eq!(r.inner.len(), 0); - assert_eq!(&r.flatten().collect::>(), &[]); + + let empty: &[u64] = &[]; + assert_eq!(&r.flatten().collect::>(), &empty); r.insert(0..1); assert_eq!(r.inner.len(), 1); @@ -496,7 +501,9 @@ mod tests { assert_eq!(&r.flatten().collect::>(), &[19]); r.remove_until(20); - assert_eq!(&r.flatten().collect::>(), &[]); + + let empty: &[u64] = &[]; + assert_eq!(&r.flatten().collect::>(), &empty); } #[test] diff --git a/src/recovery.rs b/src/recovery.rs index e59de3e04a..4ad976e45d 100644 --- a/src/recovery.rs +++ b/src/recovery.rs @@ -33,6 +33,9 @@ use std::time::Instant; use std::collections::BTreeMap; +#[cfg(feature = "qlog")] +use qlog::event::Event; + use crate::Config; use crate::Error; use crate::Result; @@ -728,6 +731,25 @@ impl Recovery { self.app_limited_at_pkt = if limited > 0 { limited } else { 1 }; } } + + #[cfg(feature = "qlog")] + pub fn to_qlog(&self) -> qlog::event::Event { + // QVis can't use all these fields and they can be large. + Event::metrics_updated( + Some(self.min_rtt.as_millis() as u64), + Some(self.rtt().as_millis() as u64), + Some(self.latest_rtt.as_millis() as u64), + Some(self.rttvar.as_millis() as u64), + None, // delay + None, // probe_count + Some(self.cwnd() as u64), + Some(self.bytes_in_flight as u64), + None, // ssthresh + None, // packets_in_flight + None, // in_recovery + None, // pacing_rate + ) + } } /// Available congestion control algorithms. diff --git a/tools/apps/Cargo.toml b/tools/apps/Cargo.toml index 6c9aed0be9..6dd81ebd39 100644 --- a/tools/apps/Cargo.toml +++ b/tools/apps/Cargo.toml @@ -16,7 +16,8 @@ mio = "0.6" url = "1" log = "0.4" ring = "0.16" -quiche = { path = "../../" } +quiche = { path = "../../", features=["qlog"] } +qlog = { version = "0.2", optional = true } [profile.release] debug = true diff --git a/tools/apps/src/bin/quiche-client.rs b/tools/apps/src/bin/quiche-client.rs index cb8812dd07..c8c61a2479 100644 --- a/tools/apps/src/bin/quiche-client.rs +++ b/tools/apps/src/bin/quiche-client.rs @@ -139,6 +139,21 @@ fn main() { let mut conn = quiche::connect(connect_url.domain(), &scid, &mut config).unwrap(); + // Only bother with qlog if the user specified it. + #[cfg(feature = "qlog")] + { + if let Some(dir) = std::env::var_os("QLOGDIR") { + let id = hex_dump(&scid); + let writer = make_qlog_writer(&dir, "client", &id); + + conn.set_qlog( + std::boxed::Box::new(writer), + "quiche-client qlog".to_string(), + format!("{} id={}", "quiche-client qlog", id), + ); + } + } + info!( "connecting to {:} from {:} with scid {}", peer_addr, diff --git a/tools/apps/src/bin/quiche-server.rs b/tools/apps/src/bin/quiche-server.rs index ab9e2138ec..1d2d41d081 100644 --- a/tools/apps/src/bin/quiche-server.rs +++ b/tools/apps/src/bin/quiche-server.rs @@ -287,7 +287,23 @@ fn main() { hex_dump(&scid) ); - let conn = quiche::accept(&scid, odcid, &mut config).unwrap(); + #[allow(unused_mut)] + let mut conn = quiche::accept(&scid, odcid, &mut config).unwrap(); + + // Only bother with qlog if the user specified it. + #[cfg(feature = "qlog")] + { + if let Some(dir) = std::env::var_os("QLOGDIR") { + let id = hex_dump(&scid); + let writer = make_qlog_writer(&dir, "server", &id); + + conn.set_qlog( + std::boxed::Box::new(writer), + "quiche-server qlog".to_string(), + format!("{} id={}", "quiche-server qlog", id), + ); + } + } let client = Client { conn, diff --git a/tools/apps/src/lib.rs b/tools/apps/src/lib.rs index 3b82e49ece..db229a691d 100644 --- a/tools/apps/src/lib.rs +++ b/tools/apps/src/lib.rs @@ -176,7 +176,7 @@ pub type ClientMap = HashMap, (net::SocketAddr, Client)>; /// Multiple requests for the same URL are indicated by the value of `cardinal`, /// any value "N" greater than 1, will cause ".N" to be appended to the /// filename. -fn make_writer( +fn make_resource_writer( url: &url::Url, target_path: &Option, cardinal: u64, ) -> Option> { if let Some(tp) = target_path { @@ -213,6 +213,24 @@ fn autoindex(path: path::PathBuf, index: &str) -> path::PathBuf { path } +/// Makes a buffered writer for a qlog. +pub fn make_qlog_writer( + dir: &std::ffi::OsStr, role: &str, id: &str, +) -> std::io::BufWriter { + let mut path = std::path::PathBuf::from(dir); + let filename = format!("{}-{}.qlog", role, id); + path.push(filename); + + match std::fs::File::create(&path) { + Ok(f) => std::io::BufWriter::new(f), + + Err(e) => panic!( + "Error creating qlog file attempted path was {:?}: {}", + path, e + ), + } +} + pub trait HttpConn { fn send_requests( &mut self, conn: &mut quiche::Connection, target_path: &Option, @@ -320,7 +338,7 @@ impl HttpConn for Http09Conn { req.stream_id = Some(self.stream_id); req.response_writer = - make_writer(&req.url, target_path, req.cardinal); + make_resource_writer(&req.url, target_path, req.cardinal); self.stream_id += 4; @@ -734,7 +752,7 @@ impl HttpConn for Http3Conn { req.stream_id = Some(s); req.response_writer = - make_writer(&req.url, target_path, req.cardinal); + make_resource_writer(&req.url, target_path, req.cardinal); if let Some(body) = &self.body { if let Err(e) = self.h3_conn.send_body(conn, s, body, true) {