feat(upgrade): introduce tracing as an optional unstable feature (hyp…

…erium#3326)

This change allow users to opt out of tracing via the `tracing` crate
by adding tracing as an optional feature. This change is part of the
effort, outlined in hyperium#2874, to reach hyper 1.0.

- Introduce several macros that act as wrappers around the `tracing`
module's macros to allow for more concise syntax for conditional
compilation of `tracing` macro calls. As `tracing` is unstable,
the new `trace` module will facilitate transitioning `tracing`
to an optional feature, as outlined in hyperium#2874 and hyperium#3326.
- Refactor code to utilize tracing macros from the new `trace` module.
- Add a `rustc` configuration flag (`hyper_unstable_tracing`) that must be passed
to the compiler when using the `tracing` feature. Throw a compiler error if `tracing`
is enabled without the flag. Part of the effort to transtition `tracing` to an
unstable dependecy. See hyperium#3326 and hyperium#2874.
- Modify `package.metadata.docs.rs` in `Cargo.toml` to include `tracing`
to list of `features` and `--cfg hyper_unstable_tracing` to the list of
`rustdoc-args`.
- Add unstable section to `lib.rs` detailing unstable features. Add information about `tracing`
and `ffi` to unstable features section.
- Log errors as a field rather than part of a formatted string.

Closes hyperium#3319

BREAKING CHANGES: tracing is disabled by default and requires users to
  opt in to an unstable feature to revert to previous behavior.

Signed-off-by: Sven Pfennig <[email protected]>

.github/workflows/CI.yml

@@ -144,7 +144,7 @@ jobs:
         uses: taiki-e/install-action@cargo-hack
 
       - name: check --feature-powerset
-        run: cargo hack check --feature-powerset --depth 2 --skip ffi -Z avoid-dev-deps
+        run: cargo hack check --feature-powerset --depth 2 --skip ffi,tracing -Z avoid-dev-deps
 
   ffi:
     name: Test C API (FFI)

Cargo.toml

@@ -33,7 +33,6 @@ http-body-util = { version = "=0.1.0-rc.3", optional = true }
 httparse = "1.8"
 h2_wasi = { version = "0.3.9", optional = true }
 itoa = "1"
-tracing = { version = "0.1", default-features = false, features = ["std"] }
 pin-project-lite = "0.2.4"
 tokio_wasi = { version = "1", features = ["sync"] }
 
@@ -42,6 +41,7 @@ tokio_wasi = { version = "1", features = ["sync"] }
 httpdate = { version = "1.0", optional = true }
 libc = { version = "0.2", optional = true }
 wasmedge_wasi_socket = {version = "0.4.2", optional = true }
+tracing = { version = "0.1", default-features = false, features = ["std"], optional = true }
 want = { version = "0.3", optional = true }
 
 [dev-dependencies]
@@ -88,12 +88,15 @@ server = ["dep:httpdate"]
 # C-API support (currently unstable (no semver))
 ffi = ["dep:libc", "dep:http-body-util"]
 
+# Utilize tracing (currently unstable)
+tracing = ["dep:tracing"]
+
 # internal features used in CI
 nightly = []
 
 [package.metadata.docs.rs]
-features = ["ffi", "full"]
-rustdoc-args = ["--cfg", "docsrs", "--cfg", "hyper_unstable_ffi"]
+features = ["ffi", "full", "tracing"]
+rustdoc-args = ["--cfg", "docsrs", "--cfg", "hyper_unstable_ffi", "--cfg", "hyper_unstable_tracing"]
 
 [package.metadata.playground]
 features = ["full"]

src/body/length.rs

@@ -50,8 +50,6 @@ impl DecodedLength {
     /// Checks the `u64` is within the maximum allowed for content-length.
     #[cfg(any(feature = "http1", feature = "http2"))]
     pub(crate) fn checked_new(len: u64) -> Result<Self, crate::error::Parse> {
-        use tracing::warn;
-
         if len <= MAX_LEN {
             Ok(DecodedLength(len))
         } else {

src/client/conn/http1.rs

@@ -191,8 +191,7 @@ where
                     Err(_canceled) => panic!("dispatch dropped without returning error"),
                 },
                 Err(_req) => {
-                    tracing::debug!("connection was not ready");
-
+                    debug!("connection was not ready");
                     Err(crate::Error::new_canceled().with("connection was not ready"))
                 }
             }
@@ -219,7 +218,7 @@ where
                 }))
             }
             Err(req) => {
-                tracing::debug!("connection was not ready");
+                debug!("connection was not ready");
                 let err = crate::Error::new_canceled().with("connection was not ready");
                 Either::Right(future::err((err, Some(req))))
             }
@@ -478,7 +477,7 @@ impl Builder {
         let opts = self.clone();
 
         async move {
-            tracing::trace!("client handshake HTTP/1");
+            trace!("client handshake HTTP/1");
 
             let (tx, rx) = dispatch::channel();
             let mut conn = proto::Conn::new(io);

src/client/conn/http2.rs

@@ -146,7 +146,7 @@ where
                     Err(_canceled) => panic!("dispatch dropped without returning error"),
                 },
                 Err(_req) => {
-                    tracing::debug!("connection was not ready");
+                    debug!("connection was not ready");
 
                     Err(crate::Error::new_canceled().with("connection was not ready"))
                 }
@@ -174,7 +174,7 @@ where
                 }))
             }
             Err(req) => {
-                tracing::debug!("connection was not ready");
+                debug!("connection was not ready");
                 let err = crate::Error::new_canceled().with("connection was not ready");
                 Either::Right(future::err((err, Some(req))))
             }
@@ -407,7 +407,7 @@ where
         let opts = self.clone();
 
         async move {
-            tracing::trace!("client handshake HTTP/1");
+            trace!("client handshake HTTP/1");
 
             let (tx, rx) = dispatch::channel();
             let h2 = proto::h2::client::handshake(io, rx, &opts.h2_builder, opts.exec, opts.timer)

src/client/dispatch.rs

@@ -5,7 +5,6 @@ use http::{Request, Response};
 use http_body::Body;
 use pin_project_lite::pin_project;
 use tokio::sync::{mpsc, oneshot};
-use tracing::trace;
 
 use crate::{
     body::Incoming,

src/lib.rs

@@ -51,7 +51,20 @@
 //! - `server`: Enables the HTTP `server`.
 //!
 //! [feature flags]: https://doc.rust-lang.org/cargo/reference/manifest.html#the-features-section
-
+//!
+//! # Unstable Features
+//! hyper includes a set of unstable optional features that can be enabled through the use of a
+//! feature flag and a [configuration flag].
+//!
+//! The following is a list of feature flags and their corresponding `RUSTFLAG`:
+//! - `ffi`: Enables C API for hyper `hyper_unstable_ffi`.
+//! - `tracing`: Enables debug logging with `hyper_unstable_tracing`.
+//!
+//! Enabling an unstable feature is possible with the following `cargo` command, as of version `1.64.0`:
+//! ```notrust
+//! RUSTFLAGS="--cfg hyper_unstable_tracing" cargo rustc --features client,http1,http2,tracing --crate-type cdylib
+//!```
+//! [configuration flag]: https://doc.rust-lang.org/reference/conditional-compilation.html
 #[doc(hidden)]
 pub use http;
 
@@ -67,6 +80,10 @@ pub use crate::error::{Error, Result};
 
 #[macro_use]
 mod cfg;
+
+#[macro_use]
+mod trace;
+
 #[macro_use]
 mod common;
 pub mod body;

src/proto/h1/conn.rs

@@ -9,7 +9,6 @@ use bytes::{Buf, Bytes};
 use http::header::{HeaderValue, CONNECTION};
 use http::{HeaderMap, Method, Version};
 use httparse::ParserConfig;
-use tracing::{debug, error, trace};
 
 use super::io::Buffered;
 use super::{Decoder, Encode, EncodedBuf, Encoder, Http1Transaction, ParseContext, Wants};
@@ -439,7 +438,7 @@ where
 
         let result = ready!(self.io.poll_read_from_io(cx));
         Poll::Ready(result.map_err(|e| {
-            trace!("force_io_read; io error = {:?}", e);
+            trace!(error = %e, "force_io_read; io error");
             self.state.close();
             e
         }))
@@ -749,7 +748,9 @@ where
 
         // If still in Reading::Body, just give up
         match self.state.reading {
-            Reading::Init | Reading::KeepAlive => trace!("body drained"),
+            Reading::Init | Reading::KeepAlive => {
+                trace!("body drained")
+            }
             _ => self.close_read(),
         }
     }

src/proto/h1/decode.rs

@@ -4,7 +4,6 @@ use std::io;
 use std::usize;
 
 use bytes::Bytes;
-use tracing::{debug, trace};
 
 use crate::common::{task, Poll};
 

src/proto/h1/dispatch.rs

@@ -3,7 +3,6 @@ use std::error::Error as StdError;
 use crate::rt::{Read, Write};
 use bytes::{Buf, Bytes};
 use http::Request;
-use tracing::{debug, trace};
 
 use super::{Http1Transaction, Wants};
 use crate::body::{Body, DecodedLength, Incoming as IncomingBody};

src/proto/h1/encode.rs

@@ -3,7 +3,6 @@ use std::io::IoSlice;
 
 use bytes::buf::{Chain, Take};
 use bytes::Buf;
-use tracing::trace;
 
 use super::io::WriteBuf;
 

src/proto/h1/io.rs

@@ -8,7 +8,6 @@ use std::mem::MaybeUninit;
 
 use crate::rt::{Read, ReadBuf, Write};
 use bytes::{Buf, BufMut, Bytes, BytesMut};
-use tracing::{debug, trace};
 
 use super::{Http1Transaction, ParseContext, ParsedMessage};
 use crate::common::buf::BufList;
@@ -224,7 +223,7 @@ where
                             if Pin::new(h1_header_read_timeout_fut).poll(cx).is_ready() {
                                 *parse_ctx.h1_header_read_timeout_running = false;
 
-                                tracing::warn!("read header from client timeout");
+                                warn!("read header from client timeout");
                                 return Poll::Ready(Err(crate::Error::new_header_timeout()));
                             }
                         }

src/proto/h1/role.rs

@@ -9,7 +9,6 @@ use bytes::BytesMut;
 use http::header::ValueIter;
 use http::header::{self, Entry, HeaderName, HeaderValue};
 use http::{HeaderMap, Method, StatusCode, Version};
-use tracing::{debug, error, trace, trace_span, warn};
 
 use crate::body::DecodedLength;
 #[cfg(feature = "server")]
@@ -72,8 +71,7 @@ where
         return Ok(None);
     }
 
-    let span = trace_span!("parse_headers");
-    let _s = span.enter();
+    let _entered = trace_span!("parse_headers");
 
     #[cfg(feature = "server")]
     if !*ctx.h1_header_read_timeout_running {
@@ -103,8 +101,7 @@ pub(super) fn encode_headers<T>(
 where
     T: Http1Transaction,
 {
-    let span = trace_span!("encode_headers");
-    let _s = span.enter();
+    let _entered = trace_span!("encode_headers");
     T::encode(enc, dst)
 }
 

src/proto/h2/client.rs

@@ -12,7 +12,6 @@ use h2::client::{Builder, Connection, SendRequest};
 use h2::SendStream;
 use http::{Method, StatusCode};
 use pin_project_lite::pin_project;
-use tracing::{debug, trace, warn};
 
 use super::ping::{Ponger, Recorder};
 use super::{ping, H2Upgraded, PipeToSendStream, SendBuf};
@@ -243,7 +242,9 @@ where
         if polled.is_ready() {
             *this.is_terminated = true;
         }
-        polled.map_err(|e| debug!("connection error: {}", e))
+        polled.map_err(|_e| {
+            debug!(error = %_e, "connection error");
+        })
     }
 }
 
@@ -441,8 +442,8 @@ where
 
         match this.pipe.poll_unpin(cx) {
             Poll::Ready(result) => {
-                if let Err(e) = result {
-                    debug!("client request body error: {}", e);
+                if let Err(_e) = result {
+                    debug!("client request body error: {}", _e);
                 }
                 drop(this.conn_drop_ref.take().expect("Future polled twice"));
                 drop(this.ping.take().expect("Future polled twice"));

src/proto/h2/mod.rs

@@ -8,7 +8,6 @@ use std::error::Error as StdError;
 use std::io::{Cursor, IoSlice};
 use std::mem;
 use std::task::Context;
-use tracing::{debug, trace, warn};
 
 use crate::body::Body;
 use crate::common::{task, Future, Pin, Poll};

src/proto/h2/ping.rs

@@ -26,7 +26,6 @@ use std::task::{self, Poll};
 use std::time::{Duration, Instant};
 
 use h2::{Ping, PingPong};
-use tracing::{debug, trace};
 
 use crate::common::time::Time;
 use crate::rt::Sleep;
@@ -300,8 +299,8 @@ impl Ponger {
                     }
                 }
             }
-            Poll::Ready(Err(e)) => {
-                debug!("pong error: {}", e);
+            Poll::Ready(Err(_e)) => {
+                debug!("pong error: {}", _e);
             }
             Poll::Pending => {
                 if let Some(ref mut ka) = self.keep_alive {
@@ -332,8 +331,8 @@ impl Shared {
                 self.ping_sent_at = Some(Instant::now());
                 trace!("sent ping");
             }
-            Err(err) => {
-                debug!("error sending ping: {}", err);
+            Err(_err) => {
+                debug!("error sending ping: {}", _err);
             }
         }
     }

src/proto/h2/server.rs

@@ -9,7 +9,6 @@ use h2::server::{Connection, Handshake, SendResponse};
 use h2::{Reason, RecvStream};
 use http::{Method, Request};
 use pin_project_lite::pin_project;
-use tracing::{debug, trace, warn};
 
 use super::{ping, PipeToSendStream, SendBuf};
 use crate::body::{Body, Incoming as IncomingBody};
@@ -508,8 +507,8 @@ where
 
     fn poll(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll<Self::Output> {
         self.poll2(cx).map(|res| {
-            if let Err(e) = res {
-                debug!("stream error: {}", e);
+            if let Err(_e) = res {
+                debug!("stream error: {}", _e);
             }
         })
     }