add tracing instrumentation (#247)

* add tracing instrumentation

* add tracing features

.github/workflows/CI.yml

@@ -111,6 +111,7 @@ jobs:
       matrix:
         os: [ubuntu-latest]
         toolchain: [stable, beta]
+        features: [i-implement-a-third-party-backend-and-opt-into-breaking-changes, h3-tracing, 'h3-tracing,i-implement-a-third-party-backend-and-opt-into-breaking-changes']
     runs-on: ${{ matrix.os }}
     steps:
       - uses: actions/checkout@v3
@@ -125,6 +126,7 @@ jobs:
         uses: actions-rs/cargo@v1
         with:
           command: test
+          args: --features ${{ matrix.features }}
       - name: h3Spec
         run: ./ci/h3spec.sh
         if: matrix.toolchain == 'stable'

examples/Cargo.toml

@@ -10,8 +10,8 @@ edition = "2021"
 anyhow = "1.0"
 bytes = "1"
 futures = "0.3"
-h3 = { path = "../h3" }
-h3-quinn = { path = "../h3-quinn" }
+h3 = { path = "../h3", features = ["h3-tracing"] }
+h3-quinn = { path = "../h3-quinn", features = ["h3-quinn-tracing"] }
 h3-webtransport = { path = "../h3-webtransport" }
 http = "1"
 quinn = { version = "0.11", default-features = false, features = [
@@ -20,7 +20,11 @@ quinn = { version = "0.11", default-features = false, features = [
     "ring",
 ] }
 rcgen = { version = "0.13" }
-rustls = { version = "0.23", default-features = false, features = ["logging", "ring", "std"] }
+rustls = { version = "0.23", default-features = false, features = [
+    "logging",
+    "ring",
+    "std",
+] }
 rustls-native-certs = "0.7"
 structopt = "0.3"
 tokio = { version = "1.27", features = ["full"] }

h3-quinn/Cargo.toml

@@ -21,3 +21,7 @@ quinn = { version = "0.11", default-features = false, features = [
 tokio-util = { version = "0.7.9" }
 futures = { version = "0.3.28" }
 tokio = { version = "1", features = ["io-util"], default-features = false }
+tracing = { version = "0.1.40", optional = true }
+
+[features]
+h3-quinn-tracing = ["tracing"]

h3-quinn/src/lib.rs

@@ -28,6 +28,9 @@ use h3::{
 };
 use tokio_util::sync::ReusableBoxFuture;
 
+#[cfg(feature = "h3-quinn-tracing")]
+use tracing::instrument;
+
 /// A QUIC connection backed by Quinn
 ///
 /// Implements a [`quic::Connection`] backed by a [`quinn::Connection`].
@@ -155,6 +158,7 @@ where
     type OpenStreams = OpenStreams;
     type AcceptError = ConnectionError;
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_accept_bidi(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -169,6 +173,7 @@ where
         })))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_accept_recv(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -197,6 +202,7 @@ where
     type BidiStream = BidiStream<B>;
     type OpenError = ConnectionError;
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_open_bidi(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -215,6 +221,7 @@ where
         }))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_open_send(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -229,6 +236,7 @@ where
         Poll::Ready(Ok(Self::SendStream::new(send)))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn close(&mut self, code: h3::error::Code, reason: &[u8]) {
         self.conn.close(
             VarInt::from_u64(code.value()).expect("error code VarInt"),
@@ -243,6 +251,7 @@ where
 {
     type Error = SendDatagramError;
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn send_datagram(&mut self, data: Datagram<B>) -> Result<(), SendDatagramError> {
         // TODO investigate static buffer from known max datagram size
         let mut buf = BytesMut::new();
@@ -259,6 +268,7 @@ impl quic::RecvDatagramExt for Connection {
     type Error = ConnectionError;
 
     #[inline]
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_accept_datagram(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -289,6 +299,7 @@ where
     type BidiStream = BidiStream<B>;
     type OpenError = ConnectionError;
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_open_bidi(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -307,6 +318,7 @@ where
         }))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_open_send(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -321,6 +333,7 @@ where
         Poll::Ready(Ok(Self::SendStream::new(send)))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn close(&mut self, code: h3::error::Code, reason: &[u8]) {
         self.conn.close(
             VarInt::from_u64(code.value()).expect("error code VarInt"),
@@ -452,6 +465,7 @@ impl quic::RecvStream for RecvStream {
     type Buf = Bytes;
     type Error = ReadError;
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_data(
         &mut self,
         cx: &mut task::Context<'_>,
@@ -468,6 +482,7 @@ impl quic::RecvStream for RecvStream {
         Poll::Ready(Ok(chunk?.map(|c| c.bytes)))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn stop_sending(&mut self, error_code: u64) {
         self.stream
             .as_mut()
@@ -476,6 +491,7 @@ impl quic::RecvStream for RecvStream {
             .ok();
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn recv_id(&self) -> StreamId {
         self.stream
             .as_ref()
@@ -573,6 +589,7 @@ where
 {
     type Error = SendStreamError;
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_ready(&mut self, cx: &mut task::Context<'_>) -> Poll<Result<(), Self::Error>> {
         if let Some(ref mut data) = self.writing {
             while data.has_remaining() {
@@ -598,10 +615,12 @@ where
         Poll::Ready(Ok(()))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_finish(&mut self, _cx: &mut task::Context<'_>) -> Poll<Result<(), Self::Error>> {
         Poll::Ready(self.stream.as_mut().unwrap().finish().map_err(|e| e.into()))
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn reset(&mut self, reset_code: u64) {
         let _ = self
             .stream
@@ -610,6 +629,7 @@ where
             .reset(VarInt::from_u64(reset_code).unwrap_or(VarInt::MAX));
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn send_data<D: Into<WriteBuf<B>>>(&mut self, data: D) -> Result<(), Self::Error> {
         if self.writing.is_some() {
             return Err(Self::Error::NotReady);
@@ -618,6 +638,7 @@ where
         Ok(())
     }
 
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn send_id(&self) -> StreamId {
         self.stream
             .as_ref()
@@ -633,6 +654,7 @@ impl<B> quic::SendStreamUnframed<B> for SendStream<B>
 where
     B: Buf,
 {
+    #[cfg_attr(feature = "h3-quinn-tracing", instrument(skip_all))]
     fn poll_send<D: Buf>(
         &mut self,
         cx: &mut task::Context<'_>,

h3/Cargo.toml

@@ -21,14 +21,15 @@ categories = [
 
 [features]
 i-implement-a-third-party-backend-and-opt-into-breaking-changes = []
+h3-tracing = ["tracing"]
 
 [dependencies]
 bytes = "1"
 futures-util = { version = "0.3", default-features = false, features = ["io"] }
 http = "1"
 tokio = { version = "1", features = ["sync"] }
 pin-project-lite = { version = "0.2", default_features = false }
-tracing = "0.1.40"
+tracing = {version = "0.1.40", optional = true}
 fastrand = "2.0.1"
 
 [dev-dependencies]

h3/src/client/connection.rs

@@ -9,7 +9,9 @@ use std::{
 use bytes::{Buf, BytesMut};
 use futures_util::future;
 use http::request;
-use tracing::{info, trace};
+
+#[cfg(feature = "h3-tracing")]
+use tracing::{info, instrument, trace};
 
 use crate::{
     connection::{self, ConnectionInner, ConnectionState, SharedStateRef},
@@ -121,6 +123,7 @@ where
     B: Buf,
 {
     /// Send an HTTP/3 request to the server
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn send_request(
         &mut self,
         req: http::Request<()>,
@@ -346,17 +349,20 @@ where
     B: Buf,
 {
     /// Initiate a graceful shutdown, accepting `max_push` potentially in-flight server pushes
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn shutdown(&mut self, _max_push: usize) -> Result<(), Error> {
         // TODO: Calculate remaining pushes once server push is implemented.
         self.inner.shutdown(&mut self.sent_closing, PushId(0)).await
     }
 
     /// Wait until the connection is closed
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn wait_idle(&mut self) -> Result<(), Error> {
         future::poll_fn(|cx| self.poll_close(cx)).await
     }
 
     /// Maintain the connection state until it is closed
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub fn poll_close(&mut self, cx: &mut Context<'_>) -> Poll<Result<(), Error>> {
         while let Poll::Ready(result) = self.inner.poll_control(cx) {
             match result {
@@ -379,7 +385,12 @@ where
                 //= type=TODO
                 //# Once a server has provided new settings,
                 //# clients MUST comply with those values.
-                Ok(Frame::Settings(_)) => trace!("Got settings"),
+                Ok(Frame::Settings(_)) => {
+                    #[cfg(feature = "h3-tracing")]
+                    trace!("Got settings");
+                    ()
+                }
+
                 Ok(Frame::Goaway(id)) => {
                     //= https://www.rfc-editor.org/rfc/rfc9114#section-7.2.6
                     //# The GOAWAY frame is always sent on the control stream.  In the
@@ -395,6 +406,7 @@ where
                     }
                     self.inner.process_goaway(&mut self.recv_closing, id)?;
 
+                    #[cfg(feature = "h3-tracing")]
                     info!("Server initiated graceful shutdown, last: StreamId({})", id);
                 }
 

h3/src/client/stream.rs

@@ -1,6 +1,8 @@
 use bytes::Buf;
 use futures_util::future;
 use http::{HeaderMap, Response};
+#[cfg(feature = "h3-tracing")]
+use tracing::instrument;
 
 use crate::{
     connection::{self, ConnectionState, SharedStateRef},
@@ -82,6 +84,7 @@ where
     /// This should be called before trying to receive any data with [`recv_data()`].
     ///
     /// [`recv_data()`]: #method.recv_data
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn recv_response(&mut self) -> Result<Response<()>, Error> {
         let mut frame = future::poll_fn(|cx| self.inner.stream.poll_next(cx))
             .await
@@ -141,11 +144,13 @@ where
 
     /// Receive some of the request body.
     // TODO what if called before recv_response ?
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn recv_data(&mut self) -> Result<Option<impl Buf>, Error> {
         self.inner.recv_data().await
     }
 
     /// Receive an optional set of trailers for the response.
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn recv_trailers(&mut self) -> Result<Option<HeaderMap>, Error> {
         let res = self.inner.recv_trailers().await;
         if let Err(ref e) = res {
@@ -157,6 +162,7 @@ where
     }
 
     /// Tell the peer to stop sending into the underlying QUIC stream
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub fn stop_sending(&mut self, error_code: crate::error::Code) {
         // TODO take by value to prevent any further call as this request is cancelled
         // rename `cancel()` ?
@@ -170,6 +176,7 @@ where
     B: Buf,
 {
     /// Send some data on the request body.
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn send_data(&mut self, buf: B) -> Result<(), Error> {
         self.inner.send_data(buf).await
     }
@@ -179,6 +186,7 @@ where
     /// Either [`RequestStream::finish`] or
     /// [`RequestStream::send_trailers`] must be called to finalize a
     /// request.
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn send_trailers(&mut self, trailers: HeaderMap) -> Result<(), Error> {
         self.inner.send_trailers(trailers).await
     }
@@ -188,6 +196,7 @@ where
     /// Either [`RequestStream::finish`] or
     /// [`RequestStream::send_trailers`] must be called to finalize a
     /// request.
+    #[cfg_attr(feature = "h3-tracing", instrument(skip_all))]
     pub async fn finish(&mut self) -> Result<(), Error> {
         self.inner.finish().await
     }

h3/src/config.rs

@@ -105,7 +105,10 @@ impl TryFrom<Config> for frame::Settings {
             //# H3_SETTINGS_ERROR.
             match settings.insert(frame::SettingId::grease(), 0) {
                 Ok(_) => (),
-                Err(err) => tracing::warn!("Error when adding the grease Setting. Reason {}", err),
+                Err(_err) => {
+                    #[cfg(feature = "h3-tracing")]
+                    tracing::warn!("Error when adding the grease Setting. Reason {}", _err);
+                }
             }
         }