start adding tracing spans to internals (#478)

We've adopted `tracing` for diagnostics, but currently, it is just being
used as a drop-in replacement for the `log` crate. Ideally, we would
want to start emitting more structured diagnostics, using `tracing`'s
`Span`s and structured key-value fields.

A lot of the logging in `h2` is already written in a style that imitates
the formatting of structured key-value logs, but as textual log
messages. Migrating the logs to structured `tracing` events therefore is
pretty easy to do. I've also started adding spans, mostly in the read
path.

Finally, I've updated the tests to use `tracing` rather than
`env_logger`. The tracing setup happens in a macro, so that a span for
each test with the test's name can be generated and entered. This will
make the test output easier to read if multiple tests are run
concurrently with `--nocapture`.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Author: hawkw

Cargo.toml

@@ -48,6 +48,7 @@ tokio = { version = "0.2", features = ["io-util"] }
 bytes = "0.5.2"
 http = "0.2"
 tracing = { version = "0.1.13", default-features = false, features = ["std", "log"] }
+tracing-futures = { version = "0.2", default-features = false, features = ["std-future"]}
 fnv = "1.0.5"
 slab = "0.4.0"
 indexmap = "1.0"

src/client.rs

@@ -149,6 +149,7 @@ use std::task::{Context, Poll};
 use std::time::Duration;
 use std::usize;
 use tokio::io::{AsyncRead, AsyncWrite, AsyncWriteExt};
+use tracing_futures::Instrument;
 
 /// Initializes new HTTP/2.0 streams on a connection by sending a request.
 ///
@@ -1115,7 +1116,10 @@ where
     T: AsyncRead + AsyncWrite + Unpin,
 {
     let builder = Builder::new();
-    builder.handshake(io).await
+    builder
+        .handshake(io)
+        .instrument(tracing::trace_span!("client_handshake", io = %std::any::type_name::<T>()))
+        .await
 }
 
 // ===== impl Connection =====
@@ -1438,6 +1442,8 @@ impl Peer {
 impl proto::Peer for Peer {
     type Poll = Response<()>;
 
+    const NAME: &'static str = "Client";
+
     fn r#dyn() -> proto::DynPeer {
         proto::DynPeer::Client
     }

src/codec/framed_read.rs

@@ -61,6 +61,8 @@ impl<T> FramedRead<T> {
 
     fn decode_frame(&mut self, mut bytes: BytesMut) -> Result<Option<Frame>, RecvError> {
         use self::RecvError::*;
+        let span = tracing::trace_span!("FramedRead::decode_frame", offset = bytes.len());
+        let _e = span.enter();
 
         tracing::trace!("decoding frame from {}B", bytes.len());
 
@@ -74,7 +76,7 @@ impl<T> FramedRead<T> {
 
         let kind = head.kind();
 
-        tracing::trace!("    -> kind={:?}", kind);
+        tracing::trace!(frame.kind = ?kind);
 
         macro_rules! header_block {
             ($frame:ident, $head:ident, $bytes:ident) => ({
@@ -338,6 +340,8 @@ where
     type Item = Result<Frame, RecvError>;
 
     fn poll_next(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Option<Self::Item>> {
+        let span = tracing::trace_span!("FramedRead::poll_next");
+        let _e = span.enter();
         loop {
             tracing::trace!("poll");
             let bytes = match ready!(Pin::new(&mut self.inner).poll_next(cx)) {
@@ -346,9 +350,9 @@ where
                 None => return Poll::Ready(None),
             };
 
-            tracing::trace!("poll; bytes={}B", bytes.len());
+            tracing::trace!(read.bytes = bytes.len());
             if let Some(frame) = self.decode_frame(bytes)? {
-                tracing::debug!("received; frame={:?}", frame);
+                tracing::debug!(?frame, "received");
                 return Poll::Ready(Some(Ok(frame)));
             }
         }

src/codec/framed_write.rs

@@ -105,8 +105,10 @@ where
     pub fn buffer(&mut self, item: Frame<B>) -> Result<(), UserError> {
         // Ensure that we have enough capacity to accept the write.
         assert!(self.has_capacity());
+        let span = tracing::trace_span!("FramedWrite::buffer", frame = ?item);
+        let _e = span.enter();
 
-        tracing::debug!("send; frame={:?}", item);
+        tracing::debug!(frame = ?item, "send");
 
         match item {
             Frame::Data(mut v) => {
@@ -150,19 +152,19 @@ where
             }
             Frame::Settings(v) => {
                 v.encode(self.buf.get_mut());
-                tracing::trace!("encoded settings; rem={:?}", self.buf.remaining());
+                tracing::trace!(rem = self.buf.remaining(), "encoded settings");
             }
             Frame::GoAway(v) => {
                 v.encode(self.buf.get_mut());
-                tracing::trace!("encoded go_away; rem={:?}", self.buf.remaining());
+                tracing::trace!(rem = self.buf.remaining(), "encoded go_away");
             }
             Frame::Ping(v) => {
                 v.encode(self.buf.get_mut());
-                tracing::trace!("encoded ping; rem={:?}", self.buf.remaining());
+                tracing::trace!(rem = self.buf.remaining(), "encoded ping");
             }
             Frame::WindowUpdate(v) => {
                 v.encode(self.buf.get_mut());
-                tracing::trace!("encoded window_update; rem={:?}", self.buf.remaining());
+                tracing::trace!(rem = self.buf.remaining(), "encoded window_update");
             }
 
             Frame::Priority(_) => {
@@ -174,7 +176,7 @@ where
             }
             Frame::Reset(v) => {
                 v.encode(self.buf.get_mut());
-                tracing::trace!("encoded reset; rem={:?}", self.buf.remaining());
+                tracing::trace!(rem = self.buf.remaining(), "encoded reset");
             }
         }
 
@@ -183,18 +185,19 @@ where
 
     /// Flush buffered data to the wire
     pub fn flush(&mut self, cx: &mut Context) -> Poll<io::Result<()>> {
-        tracing::trace!("flush");
+        let span = tracing::trace_span!("FramedWrite::flush");
+        let _e = span.enter();
 
         loop {
             while !self.is_empty() {
                 match self.next {
                     Some(Next::Data(ref mut frame)) => {
-                        tracing::trace!("  -> queued data frame");
+                        tracing::trace!(queued_data_frame = true);
                         let mut buf = (&mut self.buf).chain(frame.payload_mut());
                         ready!(Pin::new(&mut self.inner).poll_write_buf(cx, &mut buf))?;
                     }
                     _ => {
-                        tracing::trace!("  -> not a queued data frame");
+                        tracing::trace!(queued_data_frame = false);
                         ready!(Pin::new(&mut self.inner).poll_write_buf(cx, &mut self.buf))?;
                     }
                 }

src/hpack/decoder.rs

@@ -183,6 +183,9 @@ impl Decoder {
             self.last_max_update = size;
         }
 
+        let span = tracing::trace_span!("hpack::decode");
+        let _e = span.enter();
+
         tracing::trace!("decode");
 
         while let Some(ty) = peek_u8(src) {
@@ -191,14 +194,14 @@ impl Decoder {
             // determined from the first byte.
             match Representation::load(ty)? {
                 Indexed => {
-                    tracing::trace!("    Indexed; rem={:?}", src.remaining());
+                    tracing::trace!(rem = src.remaining(), kind = %"Indexed");
                     can_resize = false;
                     let entry = self.decode_indexed(src)?;
                     consume(src);
                     f(entry);
                 }
                 LiteralWithIndexing => {
-                    tracing::trace!("    LiteralWithIndexing; rem={:?}", src.remaining());
+                    tracing::trace!(rem = src.remaining(), kind = %"LiteralWithIndexing");
                     can_resize = false;
                     let entry = self.decode_literal(src, true)?;
 
@@ -209,14 +212,14 @@ impl Decoder {
                     f(entry);
                 }
                 LiteralWithoutIndexing => {
-                    tracing::trace!("    LiteralWithoutIndexing; rem={:?}", src.remaining());
+                    tracing::trace!(rem = src.remaining(), kind = %"LiteralWithoutIndexing");
                     can_resize = false;
                     let entry = self.decode_literal(src, false)?;
                     consume(src);
                     f(entry);
                 }
                 LiteralNeverIndexed => {
-                    tracing::trace!("    LiteralNeverIndexed; rem={:?}", src.remaining());
+                    tracing::trace!(rem = src.remaining(), kind = %"LiteralNeverIndexed");
                     can_resize = false;
                     let entry = self.decode_literal(src, false)?;
                     consume(src);
@@ -226,7 +229,7 @@ impl Decoder {
                     f(entry);
                 }
                 SizeUpdate => {
-                    tracing::trace!("    SizeUpdate; rem={:?}", src.remaining());
+                    tracing::trace!(rem = src.remaining(), kind = %"SizeUpdate");
                     if !can_resize {
                         return Err(DecoderError::InvalidMaxDynamicSize);
                     }
@@ -249,9 +252,9 @@ impl Decoder {
         }
 
         tracing::debug!(
-            "Decoder changed max table size from {} to {}",
-            self.table.size(),
-            new_size
+            from = self.table.size(),
+            to = new_size,
+            "Decoder changed max table size"
         );
 
         self.table.set_max_size(new_size);
@@ -302,11 +305,7 @@ impl Decoder {
         let len = decode_int(buf, 7)?;
 
         if len > buf.remaining() {
-            tracing::trace!(
-                "decode_string underflow; len={}; remaining={}",
-                len,
-                buf.remaining()
-            );
+            tracing::trace!(len, remaining = buf.remaining(), "decode_string underflow",);
             return Err(DecoderError::NeedMore(NeedMore::StringUnderflow));
         }
 

src/hpack/encoder.rs

@@ -86,7 +86,11 @@ impl Encoder {
     where
         I: Iterator<Item = Header<Option<HeaderName>>>,
     {
+        let span = tracing::trace_span!("hpack::encode");
+        let _e = span.enter();
+
         let pos = position(dst);
+        tracing::trace!(pos, "encoding at");
 
         if let Err(e) = self.encode_size_updates(dst) {
             if e == EncoderError::BufferOverflow {

src/hpack/table.rs

@@ -597,7 +597,7 @@ impl Table {
                         }
 
                         assert!(dist <= their_dist,
-                                "could not find entry; actual={}; desired={};" +
+                                "could not find entry; actual={}; desired={}" +
                                 "probe={}, dist={}; their_dist={}; index={}; msg={}",
                                 actual, desired, probe, dist, their_dist,
                                 index.wrapping_sub(self.inserted), msg);

src/proto/connection.rs

@@ -44,6 +44,9 @@ where
     /// Stream state handler
     streams: Streams<B, P>,
 
+    /// A `tracing` span tracking the lifetime of the connection.
+    span: tracing::Span,
+
     /// Client or server
     _phantom: PhantomData<P>,
 }
@@ -100,6 +103,7 @@ where
             ping_pong: PingPong::new(),
             settings: Settings::new(config.settings),
             streams,
+            span: tracing::debug_span!("Connection", peer = %P::NAME),
             _phantom: PhantomData,
         }
     }
@@ -121,6 +125,9 @@ where
     /// Returns `RecvError` as this may raise errors that are caused by delayed
     /// processing of received frames.
     fn poll_ready(&mut self, cx: &mut Context) -> Poll<Result<(), RecvError>> {
+        let _e = self.span.enter();
+        let span = tracing::trace_span!("poll_ready");
+        let _e = span.enter();
         // The order of these calls don't really matter too much
         ready!(self.ping_pong.send_pending_pong(cx, &mut self.codec))?;
         ready!(self.ping_pong.send_pending_ping(cx, &mut self.codec))?;
@@ -200,9 +207,18 @@ where
 
     /// Advances the internal state of the connection.
     pub fn poll(&mut self, cx: &mut Context) -> Poll<Result<(), proto::Error>> {
+        // XXX(eliza): cloning the span is unfortunately necessary here in
+        // order to placate the borrow checker — `self` is mutably borrowed by
+        // `poll2`, which means that we can't borrow `self.span` to enter it.
+        // The clone is just an atomic ref bump.
+        let span = self.span.clone();
+        let _e = span.enter();
+        let span = tracing::trace_span!("poll");
+        let _e = span.enter();
         use crate::codec::RecvError::*;
 
         loop {
+            tracing::trace!(connection.state = ?self.state);
             // TODO: probably clean up this glob of code
             match self.state {
                 // When open, continue to poll a frame
@@ -230,7 +246,7 @@ where
                         // error. This is handled by setting a GOAWAY frame followed by
                         // terminating the connection.
                         Poll::Ready(Err(Connection(e))) => {
-                            tracing::debug!("Connection::poll; connection error={:?}", e);
+                            tracing::debug!(error = ?e, "Connection::poll; connection error");
 
                             // We may have already sent a GOAWAY for this error,
                             // if so, don't send another, just flush and close up.
@@ -250,15 +266,15 @@ where
                         // This is handled by resetting the frame then trying to read
                         // another frame.
                         Poll::Ready(Err(Stream { id, reason })) => {
-                            tracing::trace!("stream error; id={:?}; reason={:?}", id, reason);
+                            tracing::trace!(?id, ?reason, "stream error");
                             self.streams.send_reset(id, reason);
                         }
                         // Attempting to read a frame resulted in an I/O error. All
                         // active streams must be reset.
                         //
                         // TODO: Are I/O errors recoverable?
                         Poll::Ready(Err(Io(e))) => {
-                            tracing::debug!("Connection::poll; IO error={:?}", e);
+                            tracing::debug!(error = ?e, "Connection::poll; IO error");
                             let e = e.into();
 
                             // Reset all active streams
@@ -317,28 +333,28 @@ where
 
             match ready!(Pin::new(&mut self.codec).poll_next(cx)?) {
                 Some(Headers(frame)) => {
-                    tracing::trace!("recv HEADERS; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv HEADERS");
                     self.streams.recv_headers(frame)?;
                 }
                 Some(Data(frame)) => {
-                    tracing::trace!("recv DATA; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv DATA");
                     self.streams.recv_data(frame)?;
                 }
                 Some(Reset(frame)) => {
-                    tracing::trace!("recv RST_STREAM; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv RST_STREAM");
                     self.streams.recv_reset(frame)?;
                 }
                 Some(PushPromise(frame)) => {
-                    tracing::trace!("recv PUSH_PROMISE; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv PUSH_PROMISE");
                     self.streams.recv_push_promise(frame)?;
                 }
                 Some(Settings(frame)) => {
-                    tracing::trace!("recv SETTINGS; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv SETTINGS");
                     self.settings
                         .recv_settings(frame, &mut self.codec, &mut self.streams)?;
                 }
                 Some(GoAway(frame)) => {
-                    tracing::trace!("recv GOAWAY; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv GOAWAY");
                     // This should prevent starting new streams,
                     // but should allow continuing to process current streams
                     // until they are all EOS. Once they are, State should
@@ -347,7 +363,7 @@ where
                     self.error = Some(frame.reason());
                 }
                 Some(Ping(frame)) => {
-                    tracing::trace!("recv PING; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv PING");
                     let status = self.ping_pong.recv_ping(frame);
                     if status.is_shutdown() {
                         assert!(
@@ -360,11 +376,11 @@ where
                     }
                 }
                 Some(WindowUpdate(frame)) => {
-                    tracing::trace!("recv WINDOW_UPDATE; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv WINDOW_UPDATE");
                     self.streams.recv_window_update(frame)?;
                 }
                 Some(Priority(frame)) => {
-                    tracing::trace!("recv PRIORITY; frame={:?}", frame);
+                    tracing::trace!(?frame, "recv PRIORITY");
                     // TODO: handle
                 }
                 None => {

src/proto/peer.rs

@@ -11,6 +11,7 @@ use std::fmt;
 pub(crate) trait Peer {
     /// Message type polled from the transport
     type Poll: fmt::Debug;
+    const NAME: &'static str;
 
     fn r#dyn() -> Dyn;