From a2f89d0fa95f44e6c6fdb3ecb53885c37d2859b9 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Wed, 27 Sep 2023 10:46:49 +0100 Subject: [PATCH 01/13] feat(upgrade): introduce tracing as an optional unstable feature 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 #2874, to reach hyper 1.0. Closes #3319 BREAKING CHANGES: tracing is disabled by default and requires users to opt in to revert to previous behavior. --- Cargo.toml | 5 ++++- src/body/length.rs | 2 ++ src/client/conn/http1.rs | 3 +++ src/client/conn/http2.rs | 3 +++ src/client/dispatch.rs | 2 ++ src/proto/h1/conn.rs | 35 ++++++++++++++++++++++++++++- src/proto/h1/decode.rs | 10 +++++++++ src/proto/h1/dispatch.rs | 15 +++++++++++++ src/proto/h1/encode.rs | 7 ++++++ src/proto/h1/io.rs | 12 ++++++++++ src/proto/h1/role.rs | 48 ++++++++++++++++++++++++++++++++++++---- src/proto/h2/client.rs | 17 +++++++++++++- src/proto/h2/mod.rs | 10 +++++++++ src/proto/h2/ping.rs | 10 +++++++++ src/proto/h2/server.rs | 11 +++++++++ src/upgrade.rs | 4 +++- 16 files changed, 186 insertions(+), 8 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 961b50e7ad..cac55da78c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -30,7 +30,6 @@ httpdate = "1.0" httparse = "1.8" h2 = { version = "0.3.9", optional = true } itoa = "1" -tracing = { version = "0.1", default-features = false, features = ["std"] } pin-project-lite = "0.2.4" tokio = { version = "1", features = ["sync"] } want = "0.3" @@ -38,6 +37,7 @@ want = "0.3" # Optional libc = { version = "0.2", optional = true } +tracing = { version = "0.1", default-features = false, features = ["std"], optional = true } [dev-dependencies] futures-util = { version = "0.3", default-features = false, features = ["alloc"] } @@ -84,6 +84,9 @@ server = [] # 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 = [] diff --git a/src/body/length.rs b/src/body/length.rs index e2bbee8039..dea90d58f5 100644 --- a/src/body/length.rs +++ b/src/body/length.rs @@ -50,11 +50,13 @@ 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 { + #[cfg(feature = "tracing")] use tracing::warn; if len <= MAX_LEN { Ok(DecodedLength(len)) } else { + #[cfg(feature = "tracing")] warn!("content-length bigger than maximum: {} > {}", len, MAX_LEN); Err(crate::error::Parse::TooLarge) } diff --git a/src/client/conn/http1.rs b/src/client/conn/http1.rs index 2034f0f2a6..7bbc4e79e8 100644 --- a/src/client/conn/http1.rs +++ b/src/client/conn/http1.rs @@ -191,6 +191,7 @@ where Err(_canceled) => panic!("dispatch dropped without returning error"), }, Err(_req) => { + #[cfg(feature = "tracing")] tracing::debug!("connection was not ready"); Err(crate::Error::new_canceled().with("connection was not ready")) @@ -219,6 +220,7 @@ where })) } Err(req) => { + #[cfg(feature = "tracing")] tracing::debug!("connection was not ready"); let err = crate::Error::new_canceled().with("connection was not ready"); Either::Right(future::err((err, Some(req)))) @@ -478,6 +480,7 @@ impl Builder { let opts = self.clone(); async move { + #[cfg(feature = "tracing")] tracing::trace!("client handshake HTTP/1"); let (tx, rx) = dispatch::channel(); diff --git a/src/client/conn/http2.rs b/src/client/conn/http2.rs index e9686347b3..cafa2e1dd7 100644 --- a/src/client/conn/http2.rs +++ b/src/client/conn/http2.rs @@ -146,6 +146,7 @@ where Err(_canceled) => panic!("dispatch dropped without returning error"), }, Err(_req) => { + #[cfg(feature = "tracing")] tracing::debug!("connection was not ready"); Err(crate::Error::new_canceled().with("connection was not ready")) @@ -174,6 +175,7 @@ where })) } Err(req) => { + #[cfg(feature = "tracing")] tracing::debug!("connection was not ready"); let err = crate::Error::new_canceled().with("connection was not ready"); Either::Right(future::err((err, Some(req)))) @@ -407,6 +409,7 @@ where let opts = self.clone(); async move { + #[cfg(feature = "tracing")] tracing::trace!("client handshake HTTP/1"); let (tx, rx) = dispatch::channel(); diff --git a/src/client/dispatch.rs b/src/client/dispatch.rs index 40cb554917..0ed4d39ff9 100644 --- a/src/client/dispatch.rs +++ b/src/client/dispatch.rs @@ -5,6 +5,7 @@ use http::{Request, Response}; use http_body::Body; use pin_project_lite::pin_project; use tokio::sync::{mpsc, oneshot}; +#[cfg(feature = "tracing")] use tracing::trace; use crate::{ @@ -316,6 +317,7 @@ where return std::task::Poll::Pending; } }; + #[cfg(feature = "tracing")] trace!("send_when canceled"); Poll::Ready(()) } diff --git a/src/proto/h1/conn.rs b/src/proto/h1/conn.rs index 04f25ef085..843d0f5267 100644 --- a/src/proto/h1/conn.rs +++ b/src/proto/h1/conn.rs @@ -9,6 +9,7 @@ use bytes::{Buf, Bytes}; use http::header::{HeaderValue, CONNECTION}; use http::{HeaderMap, Method, Version}; use httparse::ParserConfig; +#[cfg(feature = "tracing")] use tracing::{debug, error, trace}; use super::io::Buffered; @@ -197,6 +198,7 @@ where cx: &mut task::Context<'_>, ) -> Poll, DecodedLength, Wants)>>> { debug_assert!(self.can_read_head()); + #[cfg(feature = "tracing")] trace!("Conn::read_head"); let msg = match ready!(self.io.parse::( @@ -228,6 +230,7 @@ where // Note: don't deconstruct `msg` into local variables, it appears // the optimizer doesn't remove the extra copies. + #[cfg(feature = "tracing")] debug!("incoming body is {}", msg.decode); // Prevent accepting HTTP/0.9 responses after the initial one, if any. @@ -250,6 +253,7 @@ where }; if msg.decode == DecodedLength::ZERO { + #[cfg(feature = "tracing")] if msg.expect_continue { debug!("ignoring expect-continue since body is empty"); } @@ -277,6 +281,7 @@ where let was_mid_parse = e.is_parse() || !self.io.read_buf().is_empty(); if was_mid_parse || must_error { // We check if the buf contains the h2 Preface + #[cfg(feature = "tracing")] debug!( "parse error ({}) with {} bytes", e, @@ -287,6 +292,7 @@ where Err(e) => Poll::Ready(Some(Err(e))), } } else { + #[cfg(feature = "tracing")] debug!("read eof"); self.close_write(); Poll::Ready(None) @@ -304,6 +310,7 @@ where match ready!(decoder.decode(cx, &mut self.io)) { Ok(slice) => { let (reading, chunk) = if decoder.is_eof() { + #[cfg(feature = "tracing")] debug!("incoming body completed"); ( Reading::KeepAlive, @@ -314,6 +321,7 @@ where }, ) } else if slice.is_empty() { + #[cfg(feature = "tracing")] error!("incoming body unexpectedly ended"); // This should be unreachable, since all 3 decoders // either set eof=true or return an Err when reading @@ -325,6 +333,7 @@ where (reading, Poll::Ready(chunk)) } Err(e) => { + #[cfg(feature = "tracing")] debug!("incoming body decode error: {}", e); (Reading::Closed, Poll::Ready(Some(Err(e)))) } @@ -333,6 +342,7 @@ where Reading::Continue(ref decoder) => { // Write the 100 Continue if not already responded... if let Writing::Init = self.state.writing { + #[cfg(feature = "tracing")] trace!("automatically sending 100 Continue"); let cont = b"HTTP/1.1 100 Continue\r\n\r\n"; self.io.headers_buf().extend_from_slice(cont); @@ -388,6 +398,7 @@ where debug_assert!(T::is_client()); if !self.io.read_buf().is_empty() { + #[cfg(feature = "tracing")] debug!("received an unexpected {} bytes", self.io.read_buf().len()); return Poll::Ready(Err(crate::Error::new_unexpected_message())); } @@ -396,9 +407,11 @@ where if num_read == 0 { let ret = if self.should_error_on_eof() { + #[cfg(feature = "tracing")] trace!("found unexpected EOF on busy connection: {:?}", self.state); Poll::Ready(Err(crate::Error::new_incomplete())) } else { + #[cfg(feature = "tracing")] trace!("found EOF on idle connection, closing"); Poll::Ready(Ok(())) }; @@ -408,6 +421,7 @@ where return ret; } + #[cfg(feature = "tracing")] debug!( "received unexpected {} bytes on an idle connection", num_read @@ -426,6 +440,7 @@ where let num_read = ready!(self.force_io_read(cx)).map_err(crate::Error::new_io)?; if num_read == 0 { + #[cfg(feature = "tracing")] trace!("found unexpected EOF on busy connection: {:?}", self.state); self.state.close_read(); Poll::Ready(Err(crate::Error::new_incomplete())) @@ -439,6 +454,7 @@ where let result = ready!(self.io.poll_read_from_io(cx)); Poll::Ready(result.map_err(|e| { + #[cfg(feature = "tracing")] trace!("force_io_read; io error = {:?}", e); self.state.close(); e @@ -468,6 +484,7 @@ where match self.io.poll_read_from_io(cx) { Poll::Ready(Ok(n)) => { if n == 0 { + #[cfg(feature = "tracing")] trace!("maybe_notify; read eof"); if self.state.is_idle() { self.state.close(); @@ -478,10 +495,12 @@ where } } Poll::Pending => { + #[cfg(feature = "tracing")] trace!("maybe_notify; read_from_io blocked"); return; } Poll::Ready(Err(e)) => { + #[cfg(feature = "tracing")] trace!("maybe_notify; read_from_io error: {}", e); self.state.close(); self.state.error = Some(crate::Error::new_io(e)); @@ -720,6 +739,7 @@ where pub(crate) fn poll_flush(&mut self, cx: &mut task::Context<'_>) -> Poll> { ready!(Pin::new(&mut self.io).poll_flush(cx))?; self.try_keep_alive(cx); + #[cfg(feature = "tracing")] trace!("flushed({}): {:?}", T::LOG, self.state); Poll::Ready(Ok(())) } @@ -727,10 +747,12 @@ where pub(crate) fn poll_shutdown(&mut self, cx: &mut task::Context<'_>) -> Poll> { match ready!(Pin::new(self.io.io_mut()).poll_shutdown(cx)) { Ok(()) => { + #[cfg(feature = "tracing")] trace!("shut down IO complete"); Poll::Ready(Ok(())) } Err(e) => { + #[cfg(feature = "tracing")] debug!("error shutting down IO: {}", e); Poll::Ready(Err(e)) } @@ -749,7 +771,10 @@ where // If still in Reading::Body, just give up match self.state.reading { - Reading::Init | Reading::KeepAlive => trace!("body drained"), + Reading::Init | Reading::KeepAlive => { + #[cfg(feature = "tracing")] + trace!("body drained") + } _ => self.close_read(), } } @@ -765,9 +790,11 @@ where #[cfg(feature = "server")] pub(crate) fn disable_keep_alive(&mut self) { if self.state.is_idle() { + #[cfg(feature = "tracing")] trace!("disable_keep_alive; closing idle connection"); self.state.close(); } else { + #[cfg(feature = "tracing")] trace!("disable_keep_alive; in-progress connection"); self.state.disable_keep_alive(); } @@ -782,6 +809,7 @@ where } pub(super) fn on_upgrade(&mut self) -> crate::upgrade::OnUpgrade { + #[cfg(feature = "tracing")] trace!("{}: prepare possible HTTP upgrade", T::LOG); self.state.prepare_upgrade() } @@ -898,6 +926,7 @@ impl fmt::Debug for Writing { impl std::ops::BitAndAssign for KA { fn bitand_assign(&mut self, enabled: bool) { if !enabled { + #[cfg(feature = "tracing")] trace!("remote disabling keep-alive"); *self = KA::Disabled; } @@ -937,6 +966,7 @@ impl KA { impl State { fn close(&mut self) { + #[cfg(feature = "tracing")] trace!("State::close()"); self.reading = Reading::Closed; self.writing = Writing::Closed; @@ -944,12 +974,14 @@ impl State { } fn close_read(&mut self) { + #[cfg(feature = "tracing")] trace!("State::close_read()"); self.reading = Reading::Closed; self.keep_alive.disable(); } fn close_write(&mut self) { + #[cfg(feature = "tracing")] trace!("State::close_write()"); self.writing = Writing::Closed; self.keep_alive.disable(); @@ -969,6 +1001,7 @@ impl State { if let KA::Busy = self.keep_alive.status() { self.idle::(); } else { + #[cfg(feature = "tracing")] trace!( "try_keep_alive({}): could keep-alive, but status = {:?}", T::LOG, diff --git a/src/proto/h1/decode.rs b/src/proto/h1/decode.rs index 47d9bbd081..2290eec394 100644 --- a/src/proto/h1/decode.rs +++ b/src/proto/h1/decode.rs @@ -4,6 +4,7 @@ use std::io; use std::usize; use bytes::Bytes; +#[cfg(feature = "tracing")] use tracing::{debug, trace}; use crate::common::{task, Poll}; @@ -106,6 +107,7 @@ impl Decoder { cx: &mut task::Context<'_>, body: &mut R, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("decode; state={:?}", self.kind); match self.kind { Length(ref mut remaining) => { @@ -134,6 +136,7 @@ impl Decoder { // advances the chunked state *state = ready!(state.step(cx, body, size, &mut buf))?; if *state == ChunkedState::End { + #[cfg(feature = "tracing")] trace!("end of chunked"); return Poll::Ready(Ok(Bytes::new())); } @@ -211,6 +214,7 @@ impl ChunkedState { rdr: &mut R, size: &mut u64, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("Read chunk hex size"); macro_rules! or_overflow { @@ -255,6 +259,7 @@ impl ChunkedState { cx: &mut task::Context<'_>, rdr: &mut R, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("read_size_lws"); match byte!(rdr, cx) { // LWS can follow the chunk size, but no more digits can come @@ -271,6 +276,7 @@ impl ChunkedState { cx: &mut task::Context<'_>, rdr: &mut R, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("read_extension"); // We don't care about extensions really at all. Just ignore them. // They "end" at the next CRLF. @@ -292,12 +298,14 @@ impl ChunkedState { rdr: &mut R, size: u64, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("Chunk size is {:?}", size); match byte!(rdr, cx) { b'\n' => { if size == 0 { Poll::Ready(Ok(ChunkedState::EndCr)) } else { + #[cfg(feature = "tracing")] debug!("incoming chunked header: {0:#X} ({0} bytes)", size); Poll::Ready(Ok(ChunkedState::Body)) } @@ -315,6 +323,7 @@ impl ChunkedState { rem: &mut u64, buf: &mut Option, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("Chunked read, remaining={:?}", rem); // cap remaining bytes at the max capacity of usize @@ -372,6 +381,7 @@ impl ChunkedState { cx: &mut task::Context<'_>, rdr: &mut R, ) -> Poll> { + #[cfg(feature = "tracing")] trace!("read_trailer"); match byte!(rdr, cx) { b'\r' => Poll::Ready(Ok(ChunkedState::TrailerLf)), diff --git a/src/proto/h1/dispatch.rs b/src/proto/h1/dispatch.rs index eea31a1105..1baaa0eb00 100644 --- a/src/proto/h1/dispatch.rs +++ b/src/proto/h1/dispatch.rs @@ -3,6 +3,7 @@ use std::error::Error as StdError; use crate::rt::{Read, Write}; use bytes::{Buf, Bytes}; use http::Request; +#[cfg(feature = "tracing")] use tracing::{debug, trace}; use super::{Http1Transaction, Wants}; @@ -182,6 +183,7 @@ where } } + #[cfg(feature = "tracing")] trace!("poll_loop yielding (self = {:p})", self); task::yield_now(cx).map(|never| match never {}) @@ -204,6 +206,7 @@ where Poll::Ready(Err(_canceled)) => { // user doesn't care about the body // so we should stop reading + #[cfg(feature = "tracing")] trace!("body receiver dropped before eof, draining or closing"); self.conn.poll_drain_or_close_read(cx); continue; @@ -216,6 +219,7 @@ where } Err(_canceled) => { if self.conn.can_read_body() { + #[cfg(feature = "tracing")] trace!("body receiver dropped before eof, closing"); self.conn.close_read(); } @@ -246,6 +250,7 @@ where match ready!(self.dispatch.poll_ready(cx)) { Ok(()) => (), Err(()) => { + #[cfg(feature = "tracing")] trace!("dispatch no longer receiving messages"); self.close(); return Poll::Ready(Ok(())); @@ -277,6 +282,7 @@ where Poll::Ready(Ok(())) } Some(Err(err)) => { + #[cfg(feature = "tracing")] debug!("read_head error: {}", err); self.dispatch.recv_msg(Err(err))?; // if here, the dispatcher gave the user the error @@ -335,6 +341,7 @@ where { debug_assert!(!*clear_body, "opt guard defaults to keeping body"); if !self.conn.can_write_body() { + #[cfg(feature = "tracing")] trace!( "no more write body allowed, user body is_end_stream = {}", body.is_end_stream(), @@ -352,6 +359,7 @@ where let chunk = if let Ok(data) = frame.into_data() { data } else { + #[cfg(feature = "tracing")] trace!("discarding non-data frame"); continue; }; @@ -359,6 +367,7 @@ where if eos { *clear_body = true; if chunk.remaining() == 0 { + #[cfg(feature = "tracing")] trace!("discarding empty chunk"); self.conn.end_body()?; } else { @@ -366,6 +375,7 @@ where } } else { if chunk.remaining() == 0 { + #[cfg(feature = "tracing")] trace!("discarding empty chunk"); continue; } @@ -389,6 +399,7 @@ where fn poll_flush(&mut self, cx: &mut task::Context<'_>) -> Poll> { self.conn.poll_flush(cx).map_err(|err| { + #[cfg(feature = "tracing")] debug!("error writing: {}", err); crate::Error::new_body_write(err) }) @@ -580,6 +591,7 @@ cfg_client! { // check that future hasn't been canceled already match cb.poll_canceled(cx) { Poll::Ready(()) => { + #[cfg(feature = "tracing")] trace!("request canceled"); Poll::Ready(None) } @@ -598,6 +610,7 @@ cfg_client! { } Poll::Ready(None) => { // user has dropped sender handle + #[cfg(feature = "tracing")] trace!("client tx closed"); this.rx_closed = true; Poll::Ready(None) @@ -627,6 +640,7 @@ cfg_client! { } else if !self.rx_closed { self.rx.close(); if let Some((req, cb)) = self.rx.try_recv() { + #[cfg(feature = "tracing")] trace!("canceling queued request with connection error: {}", err); // in this case, the message was never even started, so it's safe to tell // the user that the request was completely canceled @@ -646,6 +660,7 @@ cfg_client! { match self.callback { Some(ref mut cb) => match cb.poll_canceled(cx) { Poll::Ready(()) => { + #[cfg(feature = "tracing")] trace!("callback receiver has dropped"); Poll::Ready(Err(())) } diff --git a/src/proto/h1/encode.rs b/src/proto/h1/encode.rs index cb4a7841fe..d65dc59fd5 100644 --- a/src/proto/h1/encode.rs +++ b/src/proto/h1/encode.rs @@ -3,6 +3,7 @@ use std::io::IoSlice; use bytes::buf::{Chain, Take}; use bytes::Buf; +#[cfg(feature = "tracing")] use tracing::trace; use super::io::WriteBuf; @@ -111,6 +112,7 @@ impl Encoder { let kind = match self.kind { Kind::Chunked => { + #[cfg(feature = "tracing")] trace!("encoding chunked {}B", len); let buf = ChunkSize::new(len) .chain(msg) @@ -118,6 +120,7 @@ impl Encoder { BufKind::Chunked(buf) } Kind::Length(ref mut remaining) => { + #[cfg(feature = "tracing")] trace!("sized write, len = {}", len); if len as u64 > *remaining { let limit = *remaining as usize; @@ -130,6 +133,7 @@ impl Encoder { } #[cfg(feature = "server")] Kind::CloseDelimited => { + #[cfg(feature = "tracing")] trace!("close delimited write {}B", len); BufKind::Exact(msg) } @@ -146,6 +150,7 @@ impl Encoder { match self.kind { Kind::Chunked => { + #[cfg(feature = "tracing")] trace!("encoding chunked {}B", len); let buf = ChunkSize::new(len) .chain(msg) @@ -156,6 +161,7 @@ impl Encoder { Kind::Length(remaining) => { use std::cmp::Ordering; + #[cfg(feature = "tracing")] trace!("sized write, len = {}", len); match (len as u64).cmp(&remaining) { Ordering::Equal => { @@ -174,6 +180,7 @@ impl Encoder { } #[cfg(feature = "server")] Kind::CloseDelimited => { + #[cfg(feature = "tracing")] trace!("close delimited write {}B", len); dst.buffer(msg); false diff --git a/src/proto/h1/io.rs b/src/proto/h1/io.rs index b49cda3dd3..8c16f267e0 100644 --- a/src/proto/h1/io.rs +++ b/src/proto/h1/io.rs @@ -8,6 +8,7 @@ use std::mem::MaybeUninit; use crate::rt::{Read, ReadBuf, Write}; use bytes::{Buf, BufMut, Bytes, BytesMut}; +#[cfg(feature = "tracing")] use tracing::{debug, trace}; use super::{Http1Transaction, ParseContext, ParsedMessage}; @@ -200,6 +201,7 @@ where }, )? { Some(msg) => { + #[cfg(feature = "tracing")] debug!("parsed {} headers", msg.head.headers.len()); #[cfg(feature = "server")] @@ -212,6 +214,7 @@ where None => { let max = self.read_buf_strategy.max(); if self.read_buf.len() >= max { + #[cfg(feature = "tracing")] debug!("max_buf_size ({}) reached, closing", max); return Poll::Ready(Err(crate::Error::new_too_large())); } @@ -224,6 +227,7 @@ where if Pin::new(h1_header_read_timeout_fut).poll(cx).is_ready() { *parse_ctx.h1_header_read_timeout_running = false; + #[cfg(feature = "tracing")] tracing::warn!("read header from client timeout"); return Poll::Ready(Err(crate::Error::new_header_timeout())); } @@ -232,6 +236,7 @@ where } } if ready!(self.poll_read_from_io(cx)).map_err(crate::Error::new_io)? == 0 { + #[cfg(feature = "tracing")] trace!("parse eof"); return Poll::Ready(Err(crate::Error::new_incomplete())); } @@ -254,6 +259,7 @@ where match Pin::new(&mut self.io).poll_read(cx, buf.unfilled()) { Poll::Ready(Ok(_)) => { let n = buf.filled().len(); + #[cfg(feature = "tracing")] trace!("received {} bytes", n); unsafe { // Safety: we just read that many bytes into the @@ -305,10 +311,12 @@ where // `poll_write_buf` doesn't exist in Tokio 0.3 yet...when // `poll_write_buf` comes back, the manual advance will need to leave! self.write_buf.advance(n); + #[cfg(feature = "tracing")] debug!("flushed {} bytes", n); if self.write_buf.remaining() == 0 { break; } else if n == 0 { + #[cfg(feature = "tracing")] trace!( "write returned zero, but {} bytes remaining", self.write_buf.remaining() @@ -327,12 +335,14 @@ where fn poll_flush_flattened(&mut self, cx: &mut task::Context<'_>) -> Poll> { loop { let n = ready!(Pin::new(&mut self.io).poll_write(cx, self.write_buf.headers.chunk()))?; + #[cfg(feature = "tracing")] debug!("flushed {} bytes", n); self.write_buf.headers.advance(n); if self.write_buf.headers.remaining() == 0 { self.write_buf.headers.reset(); break; } else if n == 0 { + #[cfg(feature = "tracing")] trace!( "write returned zero, but {} bytes remaining", self.write_buf.remaining() @@ -562,6 +572,7 @@ where let head = self.headers_mut(); head.maybe_unshift(buf.remaining()); + #[cfg(feature = "tracing")] trace!( self.len = head.remaining(), buf.len = buf.remaining(), @@ -582,6 +593,7 @@ where } } WriteStrategy::Queue => { + #[cfg(feature = "tracing")] trace!( self.len = self.remaining(), buf.len = buf.remaining(), diff --git a/src/proto/h1/role.rs b/src/proto/h1/role.rs index daf41c719c..264b6f2ffa 100644 --- a/src/proto/h1/role.rs +++ b/src/proto/h1/role.rs @@ -9,6 +9,7 @@ use bytes::BytesMut; use http::header::ValueIter; use http::header::{self, Entry, HeaderName, HeaderValue}; use http::{HeaderMap, Method, StatusCode, Version}; +#[cfg(feature = "tracing")] use tracing::{debug, error, trace, trace_span, warn}; use crate::body::DecodedLength; @@ -54,6 +55,7 @@ macro_rules! maybe_panic { if cfg!(debug_assertions) { panic!("{:?}", _err); } else { + #[cfg(feature = "tracing")] error!("Internal Hyper error, please report {:?}", _err); return Err(Parse::Internal) } @@ -72,8 +74,11 @@ where return Ok(None); } - let span = trace_span!("parse_headers"); - let _s = span.enter(); + #[cfg(feature = "tracing")] + { + let span = trace_span!("parse_headers"); + let _s = span.enter(); + } #[cfg(feature = "server")] if !*ctx.h1_header_read_timeout_running { @@ -82,10 +87,12 @@ where *ctx.h1_header_read_timeout_running = true; match ctx.h1_header_read_timeout_fut { Some(h1_header_read_timeout_fut) => { + #[cfg(feature = "tracing")] debug!("resetting h1 header read timeout timer"); ctx.timer.reset(h1_header_read_timeout_fut, deadline); } None => { + #[cfg(feature = "tracing")] debug!("setting h1 header read timeout timer"); *ctx.h1_header_read_timeout_fut = Some(ctx.timer.sleep_until(deadline)); } @@ -103,8 +110,11 @@ pub(super) fn encode_headers( where T: Http1Transaction, { - let span = trace_span!("encode_headers"); - let _s = span.enter(); + #[cfg(feature = "tracing")] + { + let span = trace_span!("encode_headers"); + let _s = span.enter(); + } T::encode(enc, dst) } @@ -144,11 +154,13 @@ impl Http1Transaction for Server { /* SAFETY: it is safe to go from MaybeUninit array to array of MaybeUninit */ let mut headers: [MaybeUninit>; MAX_HEADERS] = unsafe { MaybeUninit::uninit().assume_init() }; + #[cfg(feature = "tracing")] trace!(bytes = buf.len(), "Request.parse"); let mut req = httparse::Request::new(&mut []); let bytes = buf.as_ref(); match req.parse_with_uninit_headers(bytes, &mut headers) { Ok(httparse::Status::Complete(parsed_len)) => { + #[cfg(feature = "tracing")] trace!("Request.parse Complete({})", parsed_len); len = parsed_len; let uri = req.path.unwrap(); @@ -238,6 +250,7 @@ impl Http1Transaction for Server { // not the final encoding, and this is a Request, then it is // malformed. A server should respond with 400 Bad Request. if !is_http_11 { + #[cfg(feature = "tracing")] debug!("HTTP/1.0 cannot have Transfer-Encoding header"); return Err(Parse::transfer_encoding_unexpected()); } @@ -257,6 +270,7 @@ impl Http1Transaction for Server { .ok_or_else(Parse::content_length_invalid)?; if let Some(prev) = con_len { if prev != len { + #[cfg(feature = "tracing")] debug!( "multiple Content-Length headers with different values: [{}, {}]", prev, len, @@ -306,6 +320,7 @@ impl Http1Transaction for Server { } if is_te && !is_te_chunked { + #[cfg(feature = "tracing")] debug!("request with transfer-encoding header, but not chunked, bad request"); return Err(Parse::transfer_encoding_invalid()); } @@ -338,6 +353,7 @@ impl Http1Transaction for Server { } fn encode(mut msg: Encode<'_, Self::Outgoing>, dst: &mut Vec) -> crate::Result { + #[cfg(feature = "tracing")] trace!( "Server::encode status={:?}, body={:?}, req_method={:?}", msg.head.subject, @@ -359,6 +375,7 @@ impl Http1Transaction for Server { wrote_len = true; (Ok(()), true) } else if msg.head.subject.is_informational() { + #[cfg(feature = "tracing")] warn!("response with 1xx status code not supported"); *msg.head = MessageHead::default(); msg.head.subject = StatusCode::INTERNAL_SERVER_ERROR; @@ -388,6 +405,7 @@ impl Http1Transaction for Server { Version::HTTP_10 => extend(dst, b"HTTP/1.0 "), Version::HTTP_11 => extend(dst, b"HTTP/1.1 "), Version::HTTP_2 => { + #[cfg(feature = "tracing")] debug!("response with HTTP2 version coerced to HTTP/1.1"); extend(dst, b"HTTP/1.1 "); } @@ -451,6 +469,7 @@ impl Http1Transaction for Server { _ => return None, }; + #[cfg(feature = "tracing")] debug!("sending automatic response ({}) for parse error", status); let mut msg = MessageHead::default(); msg.subject = status; @@ -666,6 +685,7 @@ impl Server { match *name { header::CONTENT_LENGTH => { if wrote_len && !is_name_written { + #[cfg(feature = "tracing")] warn!("unexpected content-length found, canceling"); rewind(dst); return Err(crate::Error::new_user_header()); @@ -713,6 +733,7 @@ impl Server { if let Some(len) = headers::content_length_parse(&value) { if let Some(prev) = prev_con_len { if prev != len { + #[cfg(feature = "tracing")] warn!( "multiple Content-Length values found: [{}, {}]", prev, len @@ -737,6 +758,7 @@ impl Server { continue 'headers; } } else { + #[cfg(feature = "tracing")] warn!("illegal Content-Length value: {:?}", value); rewind(dst); return Err(crate::Error::new_user_header()); @@ -753,6 +775,7 @@ impl Server { debug_assert_eq!(encoder, Encoder::length(0)); } else { if value.as_bytes() != b"0" { + #[cfg(feature = "tracing")] warn!( "content-length value found, but empty body provided: {:?}", value @@ -766,6 +789,7 @@ impl Server { } header::TRANSFER_ENCODING => { if wrote_len && !is_name_written { + #[cfg(feature = "tracing")] warn!("unexpected transfer-encoding found, canceling"); rewind(dst); return Err(crate::Error::new_user_header()); @@ -883,6 +907,7 @@ impl Server { } if !Server::can_have_body(msg.req_method, msg.head.subject) { + #[cfg(feature = "tracing")] trace!( "server body forced to 0; method={:?}, status={:?}", msg.req_method, @@ -942,6 +967,7 @@ impl Http1Transaction for Client { // SAFETY: We can go safely from MaybeUninit array to array of MaybeUninit let mut headers: [MaybeUninit>; MAX_HEADERS] = unsafe { MaybeUninit::uninit().assume_init() }; + #[cfg(feature = "tracing")] trace!(bytes = buf.len(), "Response.parse"); let mut res = httparse::Response::new(&mut []); let bytes = buf.as_ref(); @@ -951,6 +977,7 @@ impl Http1Transaction for Client { &mut headers, ) { Ok(httparse::Status::Complete(len)) => { + #[cfg(feature = "tracing")] trace!("Response.parse Complete({})", len); let status = StatusCode::from_u16(res.code.unwrap())?; @@ -975,6 +1002,7 @@ impl Http1Transaction for Client { } Ok(httparse::Status::Partial) => return Ok(None), Err(httparse::Error::Version) if ctx.h09_responses => { + #[cfg(feature = "tracing")] trace!("Response.parse accepted HTTP/0.9 response"); (0, StatusCode::OK, None, Version::HTTP_09, 0) @@ -1097,6 +1125,7 @@ impl Http1Transaction for Client { } fn encode(msg: Encode<'_, Self::Outgoing>, dst: &mut Vec) -> crate::Result { + #[cfg(feature = "tracing")] trace!( "Client::encode method={:?}, body={:?}", msg.head.subject.0, @@ -1119,6 +1148,7 @@ impl Http1Transaction for Client { Version::HTTP_10 => extend(dst, b"HTTP/1.0"), Version::HTTP_11 => extend(dst, b"HTTP/1.1"), Version::HTTP_2 => { + #[cfg(feature = "tracing")] debug!("request with HTTP2 version coerced to HTTP/1.1"); extend(dst, b"HTTP/1.1"); } @@ -1178,6 +1208,7 @@ impl Client { return Ok(Some((DecodedLength::ZERO, true))); } 100 | 102..=199 => { + #[cfg(feature = "tracing")] trace!("ignoring informational response: {}", inc.subject.as_u16()); return Ok(None); } @@ -1195,6 +1226,7 @@ impl Client { } Some(_) => {} None => { + #[cfg(feature = "tracing")] trace!("Client::decoder is missing the Method"); } } @@ -1205,20 +1237,24 @@ impl Client { // not the final encoding, and this is a Request, then it is // malformed. A server should respond with 400 Bad Request. if inc.version == Version::HTTP_10 { + #[cfg(feature = "tracing")] debug!("HTTP/1.0 cannot have Transfer-Encoding header"); Err(Parse::transfer_encoding_unexpected()) } else if headers::transfer_encoding_is_chunked(&inc.headers) { Ok(Some((DecodedLength::CHUNKED, false))) } else { + #[cfg(feature = "tracing")] trace!("not chunked, read till eof"); Ok(Some((DecodedLength::CLOSE_DELIMITED, false))) } } else if let Some(len) = headers::content_length_parse_all(&inc.headers) { Ok(Some((DecodedLength::checked_new(len)?, false))) } else if inc.headers.contains_key(header::CONTENT_LENGTH) { + #[cfg(feature = "tracing")] debug!("illegal Content-Length header"); Err(Parse::content_length_invalid()) } else { + #[cfg(feature = "tracing")] trace!("neither Transfer-Encoding nor Content-Length"); Ok(Some((DecodedLength::CLOSE_DELIMITED, false))) } @@ -1248,6 +1284,7 @@ impl Client { if !can_chunked { // Chunked isn't legal, so if it is set, we need to remove it. if headers.remove(header::TRANSFER_ENCODING).is_some() { + #[cfg(feature = "tracing")] trace!("removing illegal transfer-encoding header"); } @@ -1270,6 +1307,7 @@ impl Client { if headers::is_chunked(te.iter()) { Some(Encoder::chunked()) } else { + #[cfg(feature = "tracing")] warn!("user provided transfer-encoding does not end in 'chunked'"); // There's a Transfer-Encoding, but it doesn't end in 'chunked'! @@ -1412,6 +1450,7 @@ fn set_content_length(headers: &mut HeaderMap, len: u64) -> Encoder { // Uh oh, the user set `Content-Length` headers, but set bad ones. // This would be an illegal message anyways, so let's try to repair // with our known good length. + #[cfg(feature = "tracing")] error!("user provided content-length header was invalid"); cl.insert(HeaderValue::from(len)); @@ -1443,6 +1482,7 @@ fn record_header_indices( for (header, indices) in headers.iter().zip(indices.iter_mut()) { if header.name.len() >= (1 << 16) { + #[cfg(feature = "tracing")] debug!("header name larger than 64kb: {:?}", header.name); return Err(crate::error::Parse::TooLarge); } diff --git a/src/proto/h2/client.rs b/src/proto/h2/client.rs index 7226c98bf5..96cae99fb2 100644 --- a/src/proto/h2/client.rs +++ b/src/proto/h2/client.rs @@ -12,6 +12,7 @@ use h2::client::{Builder, Connection, SendRequest}; use h2::SendStream; use http::{Method, StatusCode}; use pin_project_lite::pin_project; +#[cfg(feature = "tracing")] use tracing::{debug, trace, warn}; use super::ping::{Ponger, Recorder}; @@ -201,6 +202,7 @@ where this.conn.set_initial_window_size(wnd)?; } Poll::Ready(ping::Ponged::KeepAliveTimedOut) => { + #[cfg(feature = "tracing")] debug!("connection keep-alive timed out"); return Poll::Ready(Ok(())); } @@ -243,7 +245,10 @@ where if polled.is_ready() { *this.is_terminated = true; } - polled.map_err(|e| debug!("connection error: {}", e)) + polled.map_err(|e| { + #[cfg(feature = "tracing")] + debug!("connection error: {}", e) + }) } } @@ -314,6 +319,7 @@ where // mpsc has been dropped, hopefully polling // the connection some more should start shutdown // and then close. + #[cfg(feature = "tracing")] trace!("send_request dropped, starting conn shutdown"); drop(this.cancel_tx.take().expect("ConnTask Future polled twice")); } @@ -442,6 +448,7 @@ where match this.pipe.poll_unpin(cx) { Poll::Ready(result) => { if let Err(e) = result { + #[cfg(feature = "tracing")] debug!("client request body error: {}", e); } drop(this.conn_drop_ref.take().expect("Future polled twice")); @@ -547,6 +554,7 @@ where let content_length = headers::content_length_parse_all(res.headers()); if let (Some(mut send_stream), StatusCode::OK) = (send_stream, res.status()) { if content_length.map_or(false, |len| len != 0) { + #[cfg(feature = "tracing")] warn!("h2 connect response with non-zero body not supported"); send_stream.send_reset(h2::Reason::INTERNAL_ERROR); @@ -582,6 +590,7 @@ where Err(err) => { ping.ensure_not_timed_out().map_err(|e| (e, None))?; + #[cfg(feature = "tracing")] debug!("client response error: {}", err); Poll::Ready(Err((crate::Error::new_h2(err), None::>))) } @@ -606,6 +615,7 @@ where Err(err) => { self.ping.ensure_not_timed_out()?; return if err.reason() == Some(::h2::Reason::NO_ERROR) { + #[cfg(feature = "tracing")] trace!("connection gracefully shutdown"); Poll::Ready(Ok(Dispatched::Shutdown)) } else { @@ -628,6 +638,7 @@ where Poll::Ready(Some((req, cb))) => { // check that future hasn't been canceled already if cb.is_canceled() { + #[cfg(feature = "tracing")] trace!("request callback is canceled"); continue; } @@ -647,6 +658,7 @@ where if headers::content_length_parse_all(req.headers()) .map_or(false, |len| len != 0) { + #[cfg(feature = "tracing")] warn!("h2 connect request with non-zero body not supported"); cb.send(Err(( crate::Error::new_h2(h2::Reason::INTERNAL_ERROR.into()), @@ -663,6 +675,7 @@ where let (fut, body_tx) = match self.h2_tx.send_request(req, !is_connect && eos) { Ok(ok) => ok, Err(err) => { + #[cfg(feature = "tracing")] debug!("client send request error: {}", err); cb.send(Err((crate::Error::new_h2(err), None))); continue; @@ -698,6 +711,7 @@ where } Poll::Ready(None) => { + #[cfg(feature = "tracing")] trace!("client::dispatch::Sender dropped"); return Poll::Ready(Ok(Dispatched::Shutdown)); } @@ -705,6 +719,7 @@ where Poll::Pending => match ready!(Pin::new(&mut self.conn_eof).poll(cx)) { Ok(never) => match never {}, Err(_conn_is_eof) => { + #[cfg(feature = "tracing")] trace!("connection task is closed, closing dispatch task"); return Poll::Ready(Ok(Dispatched::Shutdown)); } diff --git a/src/proto/h2/mod.rs b/src/proto/h2/mod.rs index 2002edeb13..191030ffd6 100644 --- a/src/proto/h2/mod.rs +++ b/src/proto/h2/mod.rs @@ -8,6 +8,7 @@ use std::error::Error as StdError; use std::io::{Cursor, IoSlice}; use std::mem; use std::task::Context; +#[cfg(feature = "tracing")] use tracing::{debug, trace, warn}; use crate::body::Body; @@ -45,6 +46,7 @@ const CONNECTION_HEADERS: [HeaderName; 5] = [ fn strip_connection_headers(headers: &mut HeaderMap, is_request: bool) { for header in &CONNECTION_HEADERS { if headers.remove(header).is_some() { + #[cfg(feature = "tracing")] warn!("Connection header illegal in HTTP/2: {}", header.as_str()); } } @@ -55,14 +57,17 @@ fn strip_connection_headers(headers: &mut HeaderMap, is_request: bool) { .map(|te_header| te_header != "trailers") .unwrap_or(false) { + #[cfg(feature = "tracing")] warn!("TE headers not set to \"trailers\" are illegal in HTTP/2 requests"); headers.remove(TE); } } else if headers.remove(TE).is_some() { + #[cfg(feature = "tracing")] warn!("TE headers illegal in HTTP/2 responses"); } if let Some(header) = headers.remove(CONNECTION) { + #[cfg(feature = "tracing")] warn!( "Connection header illegal in HTTP/2: {}", CONNECTION.as_str() @@ -145,6 +150,7 @@ where .poll_reset(cx) .map_err(crate::Error::new_body_write)? { + #[cfg(feature = "tracing")] debug!("stream received RST_STREAM: {:?}", reason); return Poll::Ready(Err(crate::Error::new_body_write(::h2::Error::from(reason)))); } @@ -154,6 +160,7 @@ where if frame.is_data() { let chunk = frame.into_data().unwrap_or_else(|_| unreachable!()); let is_eos = me.stream.is_end_stream(); + #[cfg(feature = "tracing")] trace!( "send body chunk: {} bytes, eos={}", chunk.remaining(), @@ -176,6 +183,7 @@ where .map_err(crate::Error::new_body_write)?; return Poll::Ready(Ok(())); } else { + #[cfg(feature = "tracing")] trace!("discarding unknown frame"); // loop again } @@ -205,12 +213,14 @@ impl SendStreamExt for SendStream> { E: Into>, { let err = crate::Error::new_user_body(err); + #[cfg(feature = "tracing")] debug!("send body user stream error: {}", err); self.send_reset(err.h2_reason()); err } fn send_eos_frame(&mut self) -> crate::Result<()> { + #[cfg(feature = "tracing")] trace!("send body eos"); self.send_data(SendBuf::None, true) .map_err(crate::Error::new_body_write) diff --git a/src/proto/h2/ping.rs b/src/proto/h2/ping.rs index 297e0c7876..21201189ea 100644 --- a/src/proto/h2/ping.rs +++ b/src/proto/h2/ping.rs @@ -26,6 +26,7 @@ use std::task::{self, Poll}; use std::time::{Duration, Instant}; use h2::{Ping, PingPong}; +#[cfg(feature = "tracing")] use tracing::{debug, trace}; use crate::common::time::Time; @@ -280,6 +281,7 @@ impl Ponger { .expect("pong received implies ping_sent_at"); locked.ping_sent_at = None; let rtt = now - start; + #[cfg(feature = "tracing")] trace!("recv pong"); if let Some(ref mut ka) = self.keep_alive { @@ -291,6 +293,7 @@ impl Ponger { if let Some(ref mut bdp) = self.bdp { let bytes = locked.bytes.expect("bdp enabled implies bytes"); locked.bytes = Some(0); // reset + #[cfg(feature = "tracing")] trace!("received BDP ack; bytes = {}, rtt = {:?}", bytes, rtt); let update = bdp.calculate(bytes, rtt); @@ -301,6 +304,7 @@ impl Ponger { } } Poll::Ready(Err(e)) => { + #[cfg(feature = "tracing")] debug!("pong error: {}", e); } Poll::Pending => { @@ -330,9 +334,11 @@ impl Shared { match self.ping_pong.send_ping(Ping::opaque()) { Ok(()) => { self.ping_sent_at = Some(Instant::now()); + #[cfg(feature = "tracing")] trace!("sent ping"); } Err(err) => { + #[cfg(feature = "tracing")] debug!("error sending ping: {}", err); } } @@ -378,6 +384,7 @@ impl Bdp { // calculate the current bandwidth let bw = (bytes as f64) / (self.rtt * 1.5); + #[cfg(feature = "tracing")] trace!("current bandwidth = {:.1}B/s", bw); if bw < self.max_bandwidth { @@ -392,6 +399,7 @@ impl Bdp { // bdp, increase to double the current sample. if bytes >= self.bdp as usize * 2 / 3 { self.bdp = (bytes * 2).min(BDP_LIMIT) as WindowSize; + #[cfg(feature = "tracing")] trace!("BDP increased to {}", self.bdp); self.stable_count = 0; @@ -461,6 +469,7 @@ impl KeepAlive { cx.waker().wake_by_ref(); // schedule us again return; } + #[cfg(feature = "tracing")] trace!("keep-alive interval ({:?}) reached", self.interval); shared.send_ping(); self.state = KeepAliveState::PingSent; @@ -477,6 +486,7 @@ impl KeepAlive { if Pin::new(&mut self.sleep).poll(cx).is_pending() { return Ok(()); } + #[cfg(feature = "tracing")] trace!("keep-alive timeout ({:?}) reached", self.timeout); Err(KeepAliveTimedOut) } diff --git a/src/proto/h2/server.rs b/src/proto/h2/server.rs index 0913f314c9..f03169148c 100644 --- a/src/proto/h2/server.rs +++ b/src/proto/h2/server.rs @@ -9,6 +9,7 @@ use h2::server::{Connection, Handshake, SendResponse}; use h2::{Reason, RecvStream}; use http::{Method, Request}; use pin_project_lite::pin_project; +#[cfg(feature = "tracing")] use tracing::{debug, trace, warn}; use super::{ping, PipeToSendStream, SendBuf}; @@ -161,6 +162,7 @@ where } pub(crate) fn graceful_shutdown(&mut self) { + #[cfg(feature = "tracing")] trace!("graceful_shutdown"); match self.state { State::Handshaking { .. } => { @@ -248,6 +250,7 @@ where match ready!(self.conn.poll_accept(cx)) { Some(Ok((req, mut respond))) => { + #[cfg(feature = "tracing")] trace!("incoming request"); let content_length = headers::content_length_parse_all(req.headers()); let ping = self @@ -271,6 +274,7 @@ where ) } else { if content_length.map_or(false, |len| len != 0) { + #[cfg(feature = "tracing")] warn!("h2 connect request with non-zero body not supported"); respond.send_reset(h2::Reason::INTERNAL_ERROR); return Poll::Ready(Ok(())); @@ -304,6 +308,7 @@ where ping.ensure_not_timed_out()?; } + #[cfg(feature = "tracing")] trace!("incoming connection complete"); return Poll::Ready(Ok(())); } @@ -329,6 +334,7 @@ where let _ = self.conn.set_initial_window_size(wnd); } Poll::Ready(ping::Ponged::KeepAliveTimedOut) => { + #[cfg(feature = "tracing")] debug!("keep-alive timed out, closing connection"); self.conn.abrupt_shutdown(h2::Reason::NO_ERROR); } @@ -395,6 +401,7 @@ macro_rules! reply { match $me.reply.send_response($res, $eos) { Ok(tx) => tx, Err(e) => { + #[cfg(feature = "tracing")] debug!("send response error: {}", e); $me.reply.send_reset(Reason::INTERNAL_ERROR); return Poll::Ready(Err(crate::Error::new_h2(e))); @@ -427,6 +434,7 @@ where if let Poll::Ready(reason) = me.reply.poll_reset(cx).map_err(crate::Error::new_h2)? { + #[cfg(feature = "tracing")] debug!("stream received RST_STREAM: {:?}", reason); return Poll::Ready(Err(crate::Error::new_h2(reason.into()))); } @@ -434,6 +442,7 @@ where } Poll::Ready(Err(e)) => { let err = crate::Error::new_user_service(e); + #[cfg(feature = "tracing")] warn!("http2 service errored: {}", err); me.reply.send_reset(err.h2_reason()); return Poll::Ready(Err(err)); @@ -454,6 +463,7 @@ where if headers::content_length_parse_all(res.headers()) .map_or(false, |len| len != 0) { + #[cfg(feature = "tracing")] warn!("h2 successful response to CONNECT request with body not supported"); me.reply.send_reset(h2::Reason::INTERNAL_ERROR); return Poll::Ready(Err(crate::Error::new_user_header())); @@ -509,6 +519,7 @@ where fn poll(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll { self.poll2(cx).map(|res| { if let Err(e) = res { + #[cfg(feature = "tracing")] debug!("stream error: {}", e); } }) diff --git a/src/upgrade.rs b/src/upgrade.rs index 231578f913..56f7ccabcf 100644 --- a/src/upgrade.rs +++ b/src/upgrade.rs @@ -48,7 +48,7 @@ use std::marker::Unpin; use crate::rt::{Read, ReadBufCursor, Write}; use bytes::Bytes; use tokio::sync::oneshot; -#[cfg(any(feature = "http1", feature = "http2"))] +#[cfg(all(any(feature = "http1", feature = "http2"), feature = "tracing"))] use tracing::trace; use crate::common::io::Rewind; @@ -233,6 +233,7 @@ impl fmt::Debug for OnUpgrade { #[cfg(any(feature = "http1", feature = "http2"))] impl Pending { pub(super) fn fulfill(self, upgraded: Upgraded) { + #[cfg(feature = "tracing")] trace!("pending upgrade fulfill"); let _ = self.tx.send(Ok(upgraded)); } @@ -241,6 +242,7 @@ impl Pending { /// Don't fulfill the pending Upgrade, but instead signal that /// upgrades are handled manually. pub(super) fn manual(self) { + #[cfg(feature = "tracing")] trace!("pending upgrade handled manually"); let _ = self.tx.send(Err(crate::Error::new_user_manual_upgrade())); } From 6bc791e4f8c705abc40643f0234d632af67fb312 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Wed, 27 Sep 2023 21:48:21 +0100 Subject: [PATCH 02/13] feat(trace): add internal tracing macro module 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 #2874 and #3326. BREAKING CHANGES: Integration of macros requires the replacement of uses of `trace` macros. --- src/lib.rs | 2 + src/trace.rs | 107 +++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 109 insertions(+) create mode 100644 src/trace.rs diff --git a/src/lib.rs b/src/lib.rs index 7de04debc3..319ddc9c07 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -68,6 +68,8 @@ pub use crate::error::{Error, Result}; #[macro_use] mod cfg; #[macro_use] +mod trace; +#[macro_use] mod common; pub mod body; mod error; diff --git a/src/trace.rs b/src/trace.rs new file mode 100644 index 0000000000..c001e4092f --- /dev/null +++ b/src/trace.rs @@ -0,0 +1,107 @@ +#![allow(unused_macros)] + +macro_rules! debug { + ($($arg:tt)+) => { + #[cfg(feature = "tracing")] + { + println!($($arg)+); + tracing::debug!($($arg)+); + } + } +} + +macro_rules! debug_span { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + let span = tracing::debug_span!($($arg)+); + let _ = span.enter(); + } + } +} + +macro_rules! error { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + tracing::error!($($arg)+); + } + } +} + +macro_rules! error_span { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + let span = tracing::error_span!($($arg)+); + let _ = span.enter(); + } + } +} + +macro_rules! info { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + tracing::info!($($arg)+); + } + } +} + +macro_rules! info_span { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + let span = tracing::info_span!($($arg)+); + let _ = span.enter(); + } + } +} + +macro_rules! trace { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + tracing::trace!($($arg)+); + } + } +} + +macro_rules! trace_span { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + let span = tracing::trace_span!($($arg)+); + let _ = span.enter(); + } + } +} + +macro_rules! span { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + let span = tracing::span!($($arg)+); + let _ = span.enter(); + } + } +} + +macro_rules! warn { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + tracing::warn!($($arg)+); + } + } +} + +macro_rules! warn_span { + ($($arg:tt)*) => { + #[cfg(feature = "tracing")] + { + let span = tracing::warn_span!($($arg)+); + let _ = span.enter(); + } + } +} From d01afc3228d50b4ac9e1315c109601f5efc6f59a Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Thu, 28 Sep 2023 01:01:30 +0100 Subject: [PATCH 03/13] refactor(multiple): subsitute calls to tracing macros with new internal trace module Refactor code to utilize tracing macros from the new `trace` module and fix breaking changes described in commit aba2a35. Part of the effort to transition `tracing` to an unstable feature #3326 ##2874. --- src/body/length.rs | 4 ---- src/client/conn/http1.rs | 10 +++----- src/client/conn/http2.rs | 9 +++----- src/client/dispatch.rs | 3 --- src/proto/h1/conn.rs | 32 -------------------------- src/proto/h1/decode.rs | 11 --------- src/proto/h1/dispatch.rs | 16 ------------- src/proto/h1/encode.rs | 8 ------- src/proto/h1/io.rs | 15 +----------- src/proto/h1/role.rs | 49 +++------------------------------------- src/proto/h2/client.rs | 16 +------------ src/proto/h2/mod.rs | 11 --------- src/proto/h2/ping.rs | 11 --------- src/proto/h2/server.rs | 12 ---------- src/upgrade.rs | 6 ++--- 15 files changed, 13 insertions(+), 200 deletions(-) diff --git a/src/body/length.rs b/src/body/length.rs index dea90d58f5..2e46e4b309 100644 --- a/src/body/length.rs +++ b/src/body/length.rs @@ -50,13 +50,9 @@ 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 { - #[cfg(feature = "tracing")] - use tracing::warn; - if len <= MAX_LEN { Ok(DecodedLength(len)) } else { - #[cfg(feature = "tracing")] warn!("content-length bigger than maximum: {} > {}", len, MAX_LEN); Err(crate::error::Parse::TooLarge) } diff --git a/src/client/conn/http1.rs b/src/client/conn/http1.rs index 7bbc4e79e8..4887f86663 100644 --- a/src/client/conn/http1.rs +++ b/src/client/conn/http1.rs @@ -191,9 +191,7 @@ where Err(_canceled) => panic!("dispatch dropped without returning error"), }, Err(_req) => { - #[cfg(feature = "tracing")] - tracing::debug!("connection was not ready"); - + debug!("connection was not ready"); Err(crate::Error::new_canceled().with("connection was not ready")) } } @@ -220,8 +218,7 @@ where })) } Err(req) => { - #[cfg(feature = "tracing")] - 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)))) } @@ -480,8 +477,7 @@ impl Builder { let opts = self.clone(); async move { - #[cfg(feature = "tracing")] - tracing::trace!("client handshake HTTP/1"); + trace!("client handshake HTTP/1"); let (tx, rx) = dispatch::channel(); let mut conn = proto::Conn::new(io); diff --git a/src/client/conn/http2.rs b/src/client/conn/http2.rs index cafa2e1dd7..edb99cfeff 100644 --- a/src/client/conn/http2.rs +++ b/src/client/conn/http2.rs @@ -146,8 +146,7 @@ where Err(_canceled) => panic!("dispatch dropped without returning error"), }, Err(_req) => { - #[cfg(feature = "tracing")] - tracing::debug!("connection was not ready"); + debug!("connection was not ready"); Err(crate::Error::new_canceled().with("connection was not ready")) } @@ -175,8 +174,7 @@ where })) } Err(req) => { - #[cfg(feature = "tracing")] - 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)))) } @@ -409,8 +407,7 @@ where let opts = self.clone(); async move { - #[cfg(feature = "tracing")] - 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) diff --git a/src/client/dispatch.rs b/src/client/dispatch.rs index 0ed4d39ff9..ef9bce181c 100644 --- a/src/client/dispatch.rs +++ b/src/client/dispatch.rs @@ -5,8 +5,6 @@ use http::{Request, Response}; use http_body::Body; use pin_project_lite::pin_project; use tokio::sync::{mpsc, oneshot}; -#[cfg(feature = "tracing")] -use tracing::trace; use crate::{ body::Incoming, @@ -317,7 +315,6 @@ where return std::task::Poll::Pending; } }; - #[cfg(feature = "tracing")] trace!("send_when canceled"); Poll::Ready(()) } diff --git a/src/proto/h1/conn.rs b/src/proto/h1/conn.rs index 843d0f5267..45fcf69915 100644 --- a/src/proto/h1/conn.rs +++ b/src/proto/h1/conn.rs @@ -9,8 +9,6 @@ use bytes::{Buf, Bytes}; use http::header::{HeaderValue, CONNECTION}; use http::{HeaderMap, Method, Version}; use httparse::ParserConfig; -#[cfg(feature = "tracing")] -use tracing::{debug, error, trace}; use super::io::Buffered; use super::{Decoder, Encode, EncodedBuf, Encoder, Http1Transaction, ParseContext, Wants}; @@ -198,7 +196,6 @@ where cx: &mut task::Context<'_>, ) -> Poll, DecodedLength, Wants)>>> { debug_assert!(self.can_read_head()); - #[cfg(feature = "tracing")] trace!("Conn::read_head"); let msg = match ready!(self.io.parse::( @@ -230,7 +227,6 @@ where // Note: don't deconstruct `msg` into local variables, it appears // the optimizer doesn't remove the extra copies. - #[cfg(feature = "tracing")] debug!("incoming body is {}", msg.decode); // Prevent accepting HTTP/0.9 responses after the initial one, if any. @@ -253,7 +249,6 @@ where }; if msg.decode == DecodedLength::ZERO { - #[cfg(feature = "tracing")] if msg.expect_continue { debug!("ignoring expect-continue since body is empty"); } @@ -281,7 +276,6 @@ where let was_mid_parse = e.is_parse() || !self.io.read_buf().is_empty(); if was_mid_parse || must_error { // We check if the buf contains the h2 Preface - #[cfg(feature = "tracing")] debug!( "parse error ({}) with {} bytes", e, @@ -292,7 +286,6 @@ where Err(e) => Poll::Ready(Some(Err(e))), } } else { - #[cfg(feature = "tracing")] debug!("read eof"); self.close_write(); Poll::Ready(None) @@ -310,7 +303,6 @@ where match ready!(decoder.decode(cx, &mut self.io)) { Ok(slice) => { let (reading, chunk) = if decoder.is_eof() { - #[cfg(feature = "tracing")] debug!("incoming body completed"); ( Reading::KeepAlive, @@ -321,7 +313,6 @@ where }, ) } else if slice.is_empty() { - #[cfg(feature = "tracing")] error!("incoming body unexpectedly ended"); // This should be unreachable, since all 3 decoders // either set eof=true or return an Err when reading @@ -333,7 +324,6 @@ where (reading, Poll::Ready(chunk)) } Err(e) => { - #[cfg(feature = "tracing")] debug!("incoming body decode error: {}", e); (Reading::Closed, Poll::Ready(Some(Err(e)))) } @@ -342,7 +332,6 @@ where Reading::Continue(ref decoder) => { // Write the 100 Continue if not already responded... if let Writing::Init = self.state.writing { - #[cfg(feature = "tracing")] trace!("automatically sending 100 Continue"); let cont = b"HTTP/1.1 100 Continue\r\n\r\n"; self.io.headers_buf().extend_from_slice(cont); @@ -398,7 +387,6 @@ where debug_assert!(T::is_client()); if !self.io.read_buf().is_empty() { - #[cfg(feature = "tracing")] debug!("received an unexpected {} bytes", self.io.read_buf().len()); return Poll::Ready(Err(crate::Error::new_unexpected_message())); } @@ -407,11 +395,9 @@ where if num_read == 0 { let ret = if self.should_error_on_eof() { - #[cfg(feature = "tracing")] trace!("found unexpected EOF on busy connection: {:?}", self.state); Poll::Ready(Err(crate::Error::new_incomplete())) } else { - #[cfg(feature = "tracing")] trace!("found EOF on idle connection, closing"); Poll::Ready(Ok(())) }; @@ -421,7 +407,6 @@ where return ret; } - #[cfg(feature = "tracing")] debug!( "received unexpected {} bytes on an idle connection", num_read @@ -440,7 +425,6 @@ where let num_read = ready!(self.force_io_read(cx)).map_err(crate::Error::new_io)?; if num_read == 0 { - #[cfg(feature = "tracing")] trace!("found unexpected EOF on busy connection: {:?}", self.state); self.state.close_read(); Poll::Ready(Err(crate::Error::new_incomplete())) @@ -454,7 +438,6 @@ where let result = ready!(self.io.poll_read_from_io(cx)); Poll::Ready(result.map_err(|e| { - #[cfg(feature = "tracing")] trace!("force_io_read; io error = {:?}", e); self.state.close(); e @@ -484,7 +467,6 @@ where match self.io.poll_read_from_io(cx) { Poll::Ready(Ok(n)) => { if n == 0 { - #[cfg(feature = "tracing")] trace!("maybe_notify; read eof"); if self.state.is_idle() { self.state.close(); @@ -495,12 +477,10 @@ where } } Poll::Pending => { - #[cfg(feature = "tracing")] trace!("maybe_notify; read_from_io blocked"); return; } Poll::Ready(Err(e)) => { - #[cfg(feature = "tracing")] trace!("maybe_notify; read_from_io error: {}", e); self.state.close(); self.state.error = Some(crate::Error::new_io(e)); @@ -739,7 +719,6 @@ where pub(crate) fn poll_flush(&mut self, cx: &mut task::Context<'_>) -> Poll> { ready!(Pin::new(&mut self.io).poll_flush(cx))?; self.try_keep_alive(cx); - #[cfg(feature = "tracing")] trace!("flushed({}): {:?}", T::LOG, self.state); Poll::Ready(Ok(())) } @@ -747,12 +726,10 @@ where pub(crate) fn poll_shutdown(&mut self, cx: &mut task::Context<'_>) -> Poll> { match ready!(Pin::new(self.io.io_mut()).poll_shutdown(cx)) { Ok(()) => { - #[cfg(feature = "tracing")] trace!("shut down IO complete"); Poll::Ready(Ok(())) } Err(e) => { - #[cfg(feature = "tracing")] debug!("error shutting down IO: {}", e); Poll::Ready(Err(e)) } @@ -772,7 +749,6 @@ where // If still in Reading::Body, just give up match self.state.reading { Reading::Init | Reading::KeepAlive => { - #[cfg(feature = "tracing")] trace!("body drained") } _ => self.close_read(), @@ -790,11 +766,9 @@ where #[cfg(feature = "server")] pub(crate) fn disable_keep_alive(&mut self) { if self.state.is_idle() { - #[cfg(feature = "tracing")] trace!("disable_keep_alive; closing idle connection"); self.state.close(); } else { - #[cfg(feature = "tracing")] trace!("disable_keep_alive; in-progress connection"); self.state.disable_keep_alive(); } @@ -809,7 +783,6 @@ where } pub(super) fn on_upgrade(&mut self) -> crate::upgrade::OnUpgrade { - #[cfg(feature = "tracing")] trace!("{}: prepare possible HTTP upgrade", T::LOG); self.state.prepare_upgrade() } @@ -926,7 +899,6 @@ impl fmt::Debug for Writing { impl std::ops::BitAndAssign for KA { fn bitand_assign(&mut self, enabled: bool) { if !enabled { - #[cfg(feature = "tracing")] trace!("remote disabling keep-alive"); *self = KA::Disabled; } @@ -966,7 +938,6 @@ impl KA { impl State { fn close(&mut self) { - #[cfg(feature = "tracing")] trace!("State::close()"); self.reading = Reading::Closed; self.writing = Writing::Closed; @@ -974,14 +945,12 @@ impl State { } fn close_read(&mut self) { - #[cfg(feature = "tracing")] trace!("State::close_read()"); self.reading = Reading::Closed; self.keep_alive.disable(); } fn close_write(&mut self) { - #[cfg(feature = "tracing")] trace!("State::close_write()"); self.writing = Writing::Closed; self.keep_alive.disable(); @@ -1001,7 +970,6 @@ impl State { if let KA::Busy = self.keep_alive.status() { self.idle::(); } else { - #[cfg(feature = "tracing")] trace!( "try_keep_alive({}): could keep-alive, but status = {:?}", T::LOG, diff --git a/src/proto/h1/decode.rs b/src/proto/h1/decode.rs index 2290eec394..81ac3a95c3 100644 --- a/src/proto/h1/decode.rs +++ b/src/proto/h1/decode.rs @@ -4,8 +4,6 @@ use std::io; use std::usize; use bytes::Bytes; -#[cfg(feature = "tracing")] -use tracing::{debug, trace}; use crate::common::{task, Poll}; @@ -107,7 +105,6 @@ impl Decoder { cx: &mut task::Context<'_>, body: &mut R, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("decode; state={:?}", self.kind); match self.kind { Length(ref mut remaining) => { @@ -136,7 +133,6 @@ impl Decoder { // advances the chunked state *state = ready!(state.step(cx, body, size, &mut buf))?; if *state == ChunkedState::End { - #[cfg(feature = "tracing")] trace!("end of chunked"); return Poll::Ready(Ok(Bytes::new())); } @@ -214,7 +210,6 @@ impl ChunkedState { rdr: &mut R, size: &mut u64, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("Read chunk hex size"); macro_rules! or_overflow { @@ -259,7 +254,6 @@ impl ChunkedState { cx: &mut task::Context<'_>, rdr: &mut R, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("read_size_lws"); match byte!(rdr, cx) { // LWS can follow the chunk size, but no more digits can come @@ -276,7 +270,6 @@ impl ChunkedState { cx: &mut task::Context<'_>, rdr: &mut R, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("read_extension"); // We don't care about extensions really at all. Just ignore them. // They "end" at the next CRLF. @@ -298,14 +291,12 @@ impl ChunkedState { rdr: &mut R, size: u64, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("Chunk size is {:?}", size); match byte!(rdr, cx) { b'\n' => { if size == 0 { Poll::Ready(Ok(ChunkedState::EndCr)) } else { - #[cfg(feature = "tracing")] debug!("incoming chunked header: {0:#X} ({0} bytes)", size); Poll::Ready(Ok(ChunkedState::Body)) } @@ -323,7 +314,6 @@ impl ChunkedState { rem: &mut u64, buf: &mut Option, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("Chunked read, remaining={:?}", rem); // cap remaining bytes at the max capacity of usize @@ -381,7 +371,6 @@ impl ChunkedState { cx: &mut task::Context<'_>, rdr: &mut R, ) -> Poll> { - #[cfg(feature = "tracing")] trace!("read_trailer"); match byte!(rdr, cx) { b'\r' => Poll::Ready(Ok(ChunkedState::TrailerLf)), diff --git a/src/proto/h1/dispatch.rs b/src/proto/h1/dispatch.rs index 1baaa0eb00..c1d068a487 100644 --- a/src/proto/h1/dispatch.rs +++ b/src/proto/h1/dispatch.rs @@ -3,8 +3,6 @@ use std::error::Error as StdError; use crate::rt::{Read, Write}; use bytes::{Buf, Bytes}; use http::Request; -#[cfg(feature = "tracing")] -use tracing::{debug, trace}; use super::{Http1Transaction, Wants}; use crate::body::{Body, DecodedLength, Incoming as IncomingBody}; @@ -183,7 +181,6 @@ where } } - #[cfg(feature = "tracing")] trace!("poll_loop yielding (self = {:p})", self); task::yield_now(cx).map(|never| match never {}) @@ -206,7 +203,6 @@ where Poll::Ready(Err(_canceled)) => { // user doesn't care about the body // so we should stop reading - #[cfg(feature = "tracing")] trace!("body receiver dropped before eof, draining or closing"); self.conn.poll_drain_or_close_read(cx); continue; @@ -219,7 +215,6 @@ where } Err(_canceled) => { if self.conn.can_read_body() { - #[cfg(feature = "tracing")] trace!("body receiver dropped before eof, closing"); self.conn.close_read(); } @@ -250,7 +245,6 @@ where match ready!(self.dispatch.poll_ready(cx)) { Ok(()) => (), Err(()) => { - #[cfg(feature = "tracing")] trace!("dispatch no longer receiving messages"); self.close(); return Poll::Ready(Ok(())); @@ -282,7 +276,6 @@ where Poll::Ready(Ok(())) } Some(Err(err)) => { - #[cfg(feature = "tracing")] debug!("read_head error: {}", err); self.dispatch.recv_msg(Err(err))?; // if here, the dispatcher gave the user the error @@ -341,7 +334,6 @@ where { debug_assert!(!*clear_body, "opt guard defaults to keeping body"); if !self.conn.can_write_body() { - #[cfg(feature = "tracing")] trace!( "no more write body allowed, user body is_end_stream = {}", body.is_end_stream(), @@ -359,7 +351,6 @@ where let chunk = if let Ok(data) = frame.into_data() { data } else { - #[cfg(feature = "tracing")] trace!("discarding non-data frame"); continue; }; @@ -367,7 +358,6 @@ where if eos { *clear_body = true; if chunk.remaining() == 0 { - #[cfg(feature = "tracing")] trace!("discarding empty chunk"); self.conn.end_body()?; } else { @@ -375,7 +365,6 @@ where } } else { if chunk.remaining() == 0 { - #[cfg(feature = "tracing")] trace!("discarding empty chunk"); continue; } @@ -399,7 +388,6 @@ where fn poll_flush(&mut self, cx: &mut task::Context<'_>) -> Poll> { self.conn.poll_flush(cx).map_err(|err| { - #[cfg(feature = "tracing")] debug!("error writing: {}", err); crate::Error::new_body_write(err) }) @@ -591,7 +579,6 @@ cfg_client! { // check that future hasn't been canceled already match cb.poll_canceled(cx) { Poll::Ready(()) => { - #[cfg(feature = "tracing")] trace!("request canceled"); Poll::Ready(None) } @@ -610,7 +597,6 @@ cfg_client! { } Poll::Ready(None) => { // user has dropped sender handle - #[cfg(feature = "tracing")] trace!("client tx closed"); this.rx_closed = true; Poll::Ready(None) @@ -640,7 +626,6 @@ cfg_client! { } else if !self.rx_closed { self.rx.close(); if let Some((req, cb)) = self.rx.try_recv() { - #[cfg(feature = "tracing")] trace!("canceling queued request with connection error: {}", err); // in this case, the message was never even started, so it's safe to tell // the user that the request was completely canceled @@ -660,7 +645,6 @@ cfg_client! { match self.callback { Some(ref mut cb) => match cb.poll_canceled(cx) { Poll::Ready(()) => { - #[cfg(feature = "tracing")] trace!("callback receiver has dropped"); Poll::Ready(Err(())) } diff --git a/src/proto/h1/encode.rs b/src/proto/h1/encode.rs index d65dc59fd5..c98c55d664 100644 --- a/src/proto/h1/encode.rs +++ b/src/proto/h1/encode.rs @@ -3,8 +3,6 @@ use std::io::IoSlice; use bytes::buf::{Chain, Take}; use bytes::Buf; -#[cfg(feature = "tracing")] -use tracing::trace; use super::io::WriteBuf; @@ -112,7 +110,6 @@ impl Encoder { let kind = match self.kind { Kind::Chunked => { - #[cfg(feature = "tracing")] trace!("encoding chunked {}B", len); let buf = ChunkSize::new(len) .chain(msg) @@ -120,7 +117,6 @@ impl Encoder { BufKind::Chunked(buf) } Kind::Length(ref mut remaining) => { - #[cfg(feature = "tracing")] trace!("sized write, len = {}", len); if len as u64 > *remaining { let limit = *remaining as usize; @@ -133,7 +129,6 @@ impl Encoder { } #[cfg(feature = "server")] Kind::CloseDelimited => { - #[cfg(feature = "tracing")] trace!("close delimited write {}B", len); BufKind::Exact(msg) } @@ -150,7 +145,6 @@ impl Encoder { match self.kind { Kind::Chunked => { - #[cfg(feature = "tracing")] trace!("encoding chunked {}B", len); let buf = ChunkSize::new(len) .chain(msg) @@ -161,7 +155,6 @@ impl Encoder { Kind::Length(remaining) => { use std::cmp::Ordering; - #[cfg(feature = "tracing")] trace!("sized write, len = {}", len); match (len as u64).cmp(&remaining) { Ordering::Equal => { @@ -180,7 +173,6 @@ impl Encoder { } #[cfg(feature = "server")] Kind::CloseDelimited => { - #[cfg(feature = "tracing")] trace!("close delimited write {}B", len); dst.buffer(msg); false diff --git a/src/proto/h1/io.rs b/src/proto/h1/io.rs index 8c16f267e0..785f6c0221 100644 --- a/src/proto/h1/io.rs +++ b/src/proto/h1/io.rs @@ -8,8 +8,6 @@ use std::mem::MaybeUninit; use crate::rt::{Read, ReadBuf, Write}; use bytes::{Buf, BufMut, Bytes, BytesMut}; -#[cfg(feature = "tracing")] -use tracing::{debug, trace}; use super::{Http1Transaction, ParseContext, ParsedMessage}; use crate::common::buf::BufList; @@ -201,7 +199,6 @@ where }, )? { Some(msg) => { - #[cfg(feature = "tracing")] debug!("parsed {} headers", msg.head.headers.len()); #[cfg(feature = "server")] @@ -214,7 +211,6 @@ where None => { let max = self.read_buf_strategy.max(); if self.read_buf.len() >= max { - #[cfg(feature = "tracing")] debug!("max_buf_size ({}) reached, closing", max); return Poll::Ready(Err(crate::Error::new_too_large())); } @@ -227,8 +223,7 @@ where if Pin::new(h1_header_read_timeout_fut).poll(cx).is_ready() { *parse_ctx.h1_header_read_timeout_running = false; - #[cfg(feature = "tracing")] - tracing::warn!("read header from client timeout"); + warn!("read header from client timeout"); return Poll::Ready(Err(crate::Error::new_header_timeout())); } } @@ -236,7 +231,6 @@ where } } if ready!(self.poll_read_from_io(cx)).map_err(crate::Error::new_io)? == 0 { - #[cfg(feature = "tracing")] trace!("parse eof"); return Poll::Ready(Err(crate::Error::new_incomplete())); } @@ -259,7 +253,6 @@ where match Pin::new(&mut self.io).poll_read(cx, buf.unfilled()) { Poll::Ready(Ok(_)) => { let n = buf.filled().len(); - #[cfg(feature = "tracing")] trace!("received {} bytes", n); unsafe { // Safety: we just read that many bytes into the @@ -311,12 +304,10 @@ where // `poll_write_buf` doesn't exist in Tokio 0.3 yet...when // `poll_write_buf` comes back, the manual advance will need to leave! self.write_buf.advance(n); - #[cfg(feature = "tracing")] debug!("flushed {} bytes", n); if self.write_buf.remaining() == 0 { break; } else if n == 0 { - #[cfg(feature = "tracing")] trace!( "write returned zero, but {} bytes remaining", self.write_buf.remaining() @@ -335,14 +326,12 @@ where fn poll_flush_flattened(&mut self, cx: &mut task::Context<'_>) -> Poll> { loop { let n = ready!(Pin::new(&mut self.io).poll_write(cx, self.write_buf.headers.chunk()))?; - #[cfg(feature = "tracing")] debug!("flushed {} bytes", n); self.write_buf.headers.advance(n); if self.write_buf.headers.remaining() == 0 { self.write_buf.headers.reset(); break; } else if n == 0 { - #[cfg(feature = "tracing")] trace!( "write returned zero, but {} bytes remaining", self.write_buf.remaining() @@ -572,7 +561,6 @@ where let head = self.headers_mut(); head.maybe_unshift(buf.remaining()); - #[cfg(feature = "tracing")] trace!( self.len = head.remaining(), buf.len = buf.remaining(), @@ -593,7 +581,6 @@ where } } WriteStrategy::Queue => { - #[cfg(feature = "tracing")] trace!( self.len = self.remaining(), buf.len = buf.remaining(), diff --git a/src/proto/h1/role.rs b/src/proto/h1/role.rs index 264b6f2ffa..bfd81f5b7a 100644 --- a/src/proto/h1/role.rs +++ b/src/proto/h1/role.rs @@ -9,8 +9,6 @@ use bytes::BytesMut; use http::header::ValueIter; use http::header::{self, Entry, HeaderName, HeaderValue}; use http::{HeaderMap, Method, StatusCode, Version}; -#[cfg(feature = "tracing")] -use tracing::{debug, error, trace, trace_span, warn}; use crate::body::DecodedLength; #[cfg(feature = "server")] @@ -55,7 +53,6 @@ macro_rules! maybe_panic { if cfg!(debug_assertions) { panic!("{:?}", _err); } else { - #[cfg(feature = "tracing")] error!("Internal Hyper error, please report {:?}", _err); return Err(Parse::Internal) } @@ -73,12 +70,8 @@ where if bytes.is_empty() { return Ok(None); } - - #[cfg(feature = "tracing")] - { - let span = trace_span!("parse_headers"); - let _s = span.enter(); - } + + trace_span!("parse_headers"); #[cfg(feature = "server")] if !*ctx.h1_header_read_timeout_running { @@ -87,12 +80,10 @@ where *ctx.h1_header_read_timeout_running = true; match ctx.h1_header_read_timeout_fut { Some(h1_header_read_timeout_fut) => { - #[cfg(feature = "tracing")] debug!("resetting h1 header read timeout timer"); ctx.timer.reset(h1_header_read_timeout_fut, deadline); } None => { - #[cfg(feature = "tracing")] debug!("setting h1 header read timeout timer"); *ctx.h1_header_read_timeout_fut = Some(ctx.timer.sleep_until(deadline)); } @@ -110,11 +101,7 @@ pub(super) fn encode_headers( where T: Http1Transaction, { - #[cfg(feature = "tracing")] - { - let span = trace_span!("encode_headers"); - let _s = span.enter(); - } + trace_span!("encode_headers"); T::encode(enc, dst) } @@ -154,13 +141,11 @@ impl Http1Transaction for Server { /* SAFETY: it is safe to go from MaybeUninit array to array of MaybeUninit */ let mut headers: [MaybeUninit>; MAX_HEADERS] = unsafe { MaybeUninit::uninit().assume_init() }; - #[cfg(feature = "tracing")] trace!(bytes = buf.len(), "Request.parse"); let mut req = httparse::Request::new(&mut []); let bytes = buf.as_ref(); match req.parse_with_uninit_headers(bytes, &mut headers) { Ok(httparse::Status::Complete(parsed_len)) => { - #[cfg(feature = "tracing")] trace!("Request.parse Complete({})", parsed_len); len = parsed_len; let uri = req.path.unwrap(); @@ -250,7 +235,6 @@ impl Http1Transaction for Server { // not the final encoding, and this is a Request, then it is // malformed. A server should respond with 400 Bad Request. if !is_http_11 { - #[cfg(feature = "tracing")] debug!("HTTP/1.0 cannot have Transfer-Encoding header"); return Err(Parse::transfer_encoding_unexpected()); } @@ -270,7 +254,6 @@ impl Http1Transaction for Server { .ok_or_else(Parse::content_length_invalid)?; if let Some(prev) = con_len { if prev != len { - #[cfg(feature = "tracing")] debug!( "multiple Content-Length headers with different values: [{}, {}]", prev, len, @@ -320,7 +303,6 @@ impl Http1Transaction for Server { } if is_te && !is_te_chunked { - #[cfg(feature = "tracing")] debug!("request with transfer-encoding header, but not chunked, bad request"); return Err(Parse::transfer_encoding_invalid()); } @@ -353,7 +335,6 @@ impl Http1Transaction for Server { } fn encode(mut msg: Encode<'_, Self::Outgoing>, dst: &mut Vec) -> crate::Result { - #[cfg(feature = "tracing")] trace!( "Server::encode status={:?}, body={:?}, req_method={:?}", msg.head.subject, @@ -375,7 +356,6 @@ impl Http1Transaction for Server { wrote_len = true; (Ok(()), true) } else if msg.head.subject.is_informational() { - #[cfg(feature = "tracing")] warn!("response with 1xx status code not supported"); *msg.head = MessageHead::default(); msg.head.subject = StatusCode::INTERNAL_SERVER_ERROR; @@ -405,7 +385,6 @@ impl Http1Transaction for Server { Version::HTTP_10 => extend(dst, b"HTTP/1.0 "), Version::HTTP_11 => extend(dst, b"HTTP/1.1 "), Version::HTTP_2 => { - #[cfg(feature = "tracing")] debug!("response with HTTP2 version coerced to HTTP/1.1"); extend(dst, b"HTTP/1.1 "); } @@ -469,7 +448,6 @@ impl Http1Transaction for Server { _ => return None, }; - #[cfg(feature = "tracing")] debug!("sending automatic response ({}) for parse error", status); let mut msg = MessageHead::default(); msg.subject = status; @@ -685,7 +663,6 @@ impl Server { match *name { header::CONTENT_LENGTH => { if wrote_len && !is_name_written { - #[cfg(feature = "tracing")] warn!("unexpected content-length found, canceling"); rewind(dst); return Err(crate::Error::new_user_header()); @@ -733,7 +710,6 @@ impl Server { if let Some(len) = headers::content_length_parse(&value) { if let Some(prev) = prev_con_len { if prev != len { - #[cfg(feature = "tracing")] warn!( "multiple Content-Length values found: [{}, {}]", prev, len @@ -758,7 +734,6 @@ impl Server { continue 'headers; } } else { - #[cfg(feature = "tracing")] warn!("illegal Content-Length value: {:?}", value); rewind(dst); return Err(crate::Error::new_user_header()); @@ -775,7 +750,6 @@ impl Server { debug_assert_eq!(encoder, Encoder::length(0)); } else { if value.as_bytes() != b"0" { - #[cfg(feature = "tracing")] warn!( "content-length value found, but empty body provided: {:?}", value @@ -789,7 +763,6 @@ impl Server { } header::TRANSFER_ENCODING => { if wrote_len && !is_name_written { - #[cfg(feature = "tracing")] warn!("unexpected transfer-encoding found, canceling"); rewind(dst); return Err(crate::Error::new_user_header()); @@ -907,7 +880,6 @@ impl Server { } if !Server::can_have_body(msg.req_method, msg.head.subject) { - #[cfg(feature = "tracing")] trace!( "server body forced to 0; method={:?}, status={:?}", msg.req_method, @@ -967,7 +939,6 @@ impl Http1Transaction for Client { // SAFETY: We can go safely from MaybeUninit array to array of MaybeUninit let mut headers: [MaybeUninit>; MAX_HEADERS] = unsafe { MaybeUninit::uninit().assume_init() }; - #[cfg(feature = "tracing")] trace!(bytes = buf.len(), "Response.parse"); let mut res = httparse::Response::new(&mut []); let bytes = buf.as_ref(); @@ -977,7 +948,6 @@ impl Http1Transaction for Client { &mut headers, ) { Ok(httparse::Status::Complete(len)) => { - #[cfg(feature = "tracing")] trace!("Response.parse Complete({})", len); let status = StatusCode::from_u16(res.code.unwrap())?; @@ -1002,7 +972,6 @@ impl Http1Transaction for Client { } Ok(httparse::Status::Partial) => return Ok(None), Err(httparse::Error::Version) if ctx.h09_responses => { - #[cfg(feature = "tracing")] trace!("Response.parse accepted HTTP/0.9 response"); (0, StatusCode::OK, None, Version::HTTP_09, 0) @@ -1125,7 +1094,6 @@ impl Http1Transaction for Client { } fn encode(msg: Encode<'_, Self::Outgoing>, dst: &mut Vec) -> crate::Result { - #[cfg(feature = "tracing")] trace!( "Client::encode method={:?}, body={:?}", msg.head.subject.0, @@ -1148,7 +1116,6 @@ impl Http1Transaction for Client { Version::HTTP_10 => extend(dst, b"HTTP/1.0"), Version::HTTP_11 => extend(dst, b"HTTP/1.1"), Version::HTTP_2 => { - #[cfg(feature = "tracing")] debug!("request with HTTP2 version coerced to HTTP/1.1"); extend(dst, b"HTTP/1.1"); } @@ -1208,7 +1175,6 @@ impl Client { return Ok(Some((DecodedLength::ZERO, true))); } 100 | 102..=199 => { - #[cfg(feature = "tracing")] trace!("ignoring informational response: {}", inc.subject.as_u16()); return Ok(None); } @@ -1226,7 +1192,6 @@ impl Client { } Some(_) => {} None => { - #[cfg(feature = "tracing")] trace!("Client::decoder is missing the Method"); } } @@ -1237,24 +1202,20 @@ impl Client { // not the final encoding, and this is a Request, then it is // malformed. A server should respond with 400 Bad Request. if inc.version == Version::HTTP_10 { - #[cfg(feature = "tracing")] debug!("HTTP/1.0 cannot have Transfer-Encoding header"); Err(Parse::transfer_encoding_unexpected()) } else if headers::transfer_encoding_is_chunked(&inc.headers) { Ok(Some((DecodedLength::CHUNKED, false))) } else { - #[cfg(feature = "tracing")] trace!("not chunked, read till eof"); Ok(Some((DecodedLength::CLOSE_DELIMITED, false))) } } else if let Some(len) = headers::content_length_parse_all(&inc.headers) { Ok(Some((DecodedLength::checked_new(len)?, false))) } else if inc.headers.contains_key(header::CONTENT_LENGTH) { - #[cfg(feature = "tracing")] debug!("illegal Content-Length header"); Err(Parse::content_length_invalid()) } else { - #[cfg(feature = "tracing")] trace!("neither Transfer-Encoding nor Content-Length"); Ok(Some((DecodedLength::CLOSE_DELIMITED, false))) } @@ -1284,7 +1245,6 @@ impl Client { if !can_chunked { // Chunked isn't legal, so if it is set, we need to remove it. if headers.remove(header::TRANSFER_ENCODING).is_some() { - #[cfg(feature = "tracing")] trace!("removing illegal transfer-encoding header"); } @@ -1307,7 +1267,6 @@ impl Client { if headers::is_chunked(te.iter()) { Some(Encoder::chunked()) } else { - #[cfg(feature = "tracing")] warn!("user provided transfer-encoding does not end in 'chunked'"); // There's a Transfer-Encoding, but it doesn't end in 'chunked'! @@ -1450,7 +1409,6 @@ fn set_content_length(headers: &mut HeaderMap, len: u64) -> Encoder { // Uh oh, the user set `Content-Length` headers, but set bad ones. // This would be an illegal message anyways, so let's try to repair // with our known good length. - #[cfg(feature = "tracing")] error!("user provided content-length header was invalid"); cl.insert(HeaderValue::from(len)); @@ -1482,7 +1440,6 @@ fn record_header_indices( for (header, indices) in headers.iter().zip(indices.iter_mut()) { if header.name.len() >= (1 << 16) { - #[cfg(feature = "tracing")] debug!("header name larger than 64kb: {:?}", header.name); return Err(crate::error::Parse::TooLarge); } diff --git a/src/proto/h2/client.rs b/src/proto/h2/client.rs index 96cae99fb2..16994f5149 100644 --- a/src/proto/h2/client.rs +++ b/src/proto/h2/client.rs @@ -12,8 +12,6 @@ use h2::client::{Builder, Connection, SendRequest}; use h2::SendStream; use http::{Method, StatusCode}; use pin_project_lite::pin_project; -#[cfg(feature = "tracing")] -use tracing::{debug, trace, warn}; use super::ping::{Ponger, Recorder}; use super::{ping, H2Upgraded, PipeToSendStream, SendBuf}; @@ -202,7 +200,6 @@ where this.conn.set_initial_window_size(wnd)?; } Poll::Ready(ping::Ponged::KeepAliveTimedOut) => { - #[cfg(feature = "tracing")] debug!("connection keep-alive timed out"); return Poll::Ready(Ok(())); } @@ -245,8 +242,7 @@ where if polled.is_ready() { *this.is_terminated = true; } - polled.map_err(|e| { - #[cfg(feature = "tracing")] + polled.map_err(|e| { debug!("connection error: {}", e) }) } @@ -319,7 +315,6 @@ where // mpsc has been dropped, hopefully polling // the connection some more should start shutdown // and then close. - #[cfg(feature = "tracing")] trace!("send_request dropped, starting conn shutdown"); drop(this.cancel_tx.take().expect("ConnTask Future polled twice")); } @@ -448,7 +443,6 @@ where match this.pipe.poll_unpin(cx) { Poll::Ready(result) => { if let Err(e) = result { - #[cfg(feature = "tracing")] debug!("client request body error: {}", e); } drop(this.conn_drop_ref.take().expect("Future polled twice")); @@ -554,7 +548,6 @@ where let content_length = headers::content_length_parse_all(res.headers()); if let (Some(mut send_stream), StatusCode::OK) = (send_stream, res.status()) { if content_length.map_or(false, |len| len != 0) { - #[cfg(feature = "tracing")] warn!("h2 connect response with non-zero body not supported"); send_stream.send_reset(h2::Reason::INTERNAL_ERROR); @@ -590,7 +583,6 @@ where Err(err) => { ping.ensure_not_timed_out().map_err(|e| (e, None))?; - #[cfg(feature = "tracing")] debug!("client response error: {}", err); Poll::Ready(Err((crate::Error::new_h2(err), None::>))) } @@ -615,7 +607,6 @@ where Err(err) => { self.ping.ensure_not_timed_out()?; return if err.reason() == Some(::h2::Reason::NO_ERROR) { - #[cfg(feature = "tracing")] trace!("connection gracefully shutdown"); Poll::Ready(Ok(Dispatched::Shutdown)) } else { @@ -638,7 +629,6 @@ where Poll::Ready(Some((req, cb))) => { // check that future hasn't been canceled already if cb.is_canceled() { - #[cfg(feature = "tracing")] trace!("request callback is canceled"); continue; } @@ -658,7 +648,6 @@ where if headers::content_length_parse_all(req.headers()) .map_or(false, |len| len != 0) { - #[cfg(feature = "tracing")] warn!("h2 connect request with non-zero body not supported"); cb.send(Err(( crate::Error::new_h2(h2::Reason::INTERNAL_ERROR.into()), @@ -675,7 +664,6 @@ where let (fut, body_tx) = match self.h2_tx.send_request(req, !is_connect && eos) { Ok(ok) => ok, Err(err) => { - #[cfg(feature = "tracing")] debug!("client send request error: {}", err); cb.send(Err((crate::Error::new_h2(err), None))); continue; @@ -711,7 +699,6 @@ where } Poll::Ready(None) => { - #[cfg(feature = "tracing")] trace!("client::dispatch::Sender dropped"); return Poll::Ready(Ok(Dispatched::Shutdown)); } @@ -719,7 +706,6 @@ where Poll::Pending => match ready!(Pin::new(&mut self.conn_eof).poll(cx)) { Ok(never) => match never {}, Err(_conn_is_eof) => { - #[cfg(feature = "tracing")] trace!("connection task is closed, closing dispatch task"); return Poll::Ready(Ok(Dispatched::Shutdown)); } diff --git a/src/proto/h2/mod.rs b/src/proto/h2/mod.rs index 191030ffd6..defc2512d6 100644 --- a/src/proto/h2/mod.rs +++ b/src/proto/h2/mod.rs @@ -8,8 +8,6 @@ use std::error::Error as StdError; use std::io::{Cursor, IoSlice}; use std::mem; use std::task::Context; -#[cfg(feature = "tracing")] -use tracing::{debug, trace, warn}; use crate::body::Body; use crate::common::{task, Future, Pin, Poll}; @@ -46,7 +44,6 @@ const CONNECTION_HEADERS: [HeaderName; 5] = [ fn strip_connection_headers(headers: &mut HeaderMap, is_request: bool) { for header in &CONNECTION_HEADERS { if headers.remove(header).is_some() { - #[cfg(feature = "tracing")] warn!("Connection header illegal in HTTP/2: {}", header.as_str()); } } @@ -57,17 +54,14 @@ fn strip_connection_headers(headers: &mut HeaderMap, is_request: bool) { .map(|te_header| te_header != "trailers") .unwrap_or(false) { - #[cfg(feature = "tracing")] warn!("TE headers not set to \"trailers\" are illegal in HTTP/2 requests"); headers.remove(TE); } } else if headers.remove(TE).is_some() { - #[cfg(feature = "tracing")] warn!("TE headers illegal in HTTP/2 responses"); } if let Some(header) = headers.remove(CONNECTION) { - #[cfg(feature = "tracing")] warn!( "Connection header illegal in HTTP/2: {}", CONNECTION.as_str() @@ -150,7 +144,6 @@ where .poll_reset(cx) .map_err(crate::Error::new_body_write)? { - #[cfg(feature = "tracing")] debug!("stream received RST_STREAM: {:?}", reason); return Poll::Ready(Err(crate::Error::new_body_write(::h2::Error::from(reason)))); } @@ -160,7 +153,6 @@ where if frame.is_data() { let chunk = frame.into_data().unwrap_or_else(|_| unreachable!()); let is_eos = me.stream.is_end_stream(); - #[cfg(feature = "tracing")] trace!( "send body chunk: {} bytes, eos={}", chunk.remaining(), @@ -183,7 +175,6 @@ where .map_err(crate::Error::new_body_write)?; return Poll::Ready(Ok(())); } else { - #[cfg(feature = "tracing")] trace!("discarding unknown frame"); // loop again } @@ -213,14 +204,12 @@ impl SendStreamExt for SendStream> { E: Into>, { let err = crate::Error::new_user_body(err); - #[cfg(feature = "tracing")] debug!("send body user stream error: {}", err); self.send_reset(err.h2_reason()); err } fn send_eos_frame(&mut self) -> crate::Result<()> { - #[cfg(feature = "tracing")] trace!("send body eos"); self.send_data(SendBuf::None, true) .map_err(crate::Error::new_body_write) diff --git a/src/proto/h2/ping.rs b/src/proto/h2/ping.rs index 21201189ea..f43a37915b 100644 --- a/src/proto/h2/ping.rs +++ b/src/proto/h2/ping.rs @@ -26,8 +26,6 @@ use std::task::{self, Poll}; use std::time::{Duration, Instant}; use h2::{Ping, PingPong}; -#[cfg(feature = "tracing")] -use tracing::{debug, trace}; use crate::common::time::Time; use crate::rt::Sleep; @@ -281,7 +279,6 @@ impl Ponger { .expect("pong received implies ping_sent_at"); locked.ping_sent_at = None; let rtt = now - start; - #[cfg(feature = "tracing")] trace!("recv pong"); if let Some(ref mut ka) = self.keep_alive { @@ -293,7 +290,6 @@ impl Ponger { if let Some(ref mut bdp) = self.bdp { let bytes = locked.bytes.expect("bdp enabled implies bytes"); locked.bytes = Some(0); // reset - #[cfg(feature = "tracing")] trace!("received BDP ack; bytes = {}, rtt = {:?}", bytes, rtt); let update = bdp.calculate(bytes, rtt); @@ -304,7 +300,6 @@ impl Ponger { } } Poll::Ready(Err(e)) => { - #[cfg(feature = "tracing")] debug!("pong error: {}", e); } Poll::Pending => { @@ -334,11 +329,9 @@ impl Shared { match self.ping_pong.send_ping(Ping::opaque()) { Ok(()) => { self.ping_sent_at = Some(Instant::now()); - #[cfg(feature = "tracing")] trace!("sent ping"); } Err(err) => { - #[cfg(feature = "tracing")] debug!("error sending ping: {}", err); } } @@ -384,7 +377,6 @@ impl Bdp { // calculate the current bandwidth let bw = (bytes as f64) / (self.rtt * 1.5); - #[cfg(feature = "tracing")] trace!("current bandwidth = {:.1}B/s", bw); if bw < self.max_bandwidth { @@ -399,7 +391,6 @@ impl Bdp { // bdp, increase to double the current sample. if bytes >= self.bdp as usize * 2 / 3 { self.bdp = (bytes * 2).min(BDP_LIMIT) as WindowSize; - #[cfg(feature = "tracing")] trace!("BDP increased to {}", self.bdp); self.stable_count = 0; @@ -469,7 +460,6 @@ impl KeepAlive { cx.waker().wake_by_ref(); // schedule us again return; } - #[cfg(feature = "tracing")] trace!("keep-alive interval ({:?}) reached", self.interval); shared.send_ping(); self.state = KeepAliveState::PingSent; @@ -486,7 +476,6 @@ impl KeepAlive { if Pin::new(&mut self.sleep).poll(cx).is_pending() { return Ok(()); } - #[cfg(feature = "tracing")] trace!("keep-alive timeout ({:?}) reached", self.timeout); Err(KeepAliveTimedOut) } diff --git a/src/proto/h2/server.rs b/src/proto/h2/server.rs index f03169148c..e9979e9447 100644 --- a/src/proto/h2/server.rs +++ b/src/proto/h2/server.rs @@ -9,8 +9,6 @@ use h2::server::{Connection, Handshake, SendResponse}; use h2::{Reason, RecvStream}; use http::{Method, Request}; use pin_project_lite::pin_project; -#[cfg(feature = "tracing")] -use tracing::{debug, trace, warn}; use super::{ping, PipeToSendStream, SendBuf}; use crate::body::{Body, Incoming as IncomingBody}; @@ -162,7 +160,6 @@ where } pub(crate) fn graceful_shutdown(&mut self) { - #[cfg(feature = "tracing")] trace!("graceful_shutdown"); match self.state { State::Handshaking { .. } => { @@ -250,7 +247,6 @@ where match ready!(self.conn.poll_accept(cx)) { Some(Ok((req, mut respond))) => { - #[cfg(feature = "tracing")] trace!("incoming request"); let content_length = headers::content_length_parse_all(req.headers()); let ping = self @@ -274,7 +270,6 @@ where ) } else { if content_length.map_or(false, |len| len != 0) { - #[cfg(feature = "tracing")] warn!("h2 connect request with non-zero body not supported"); respond.send_reset(h2::Reason::INTERNAL_ERROR); return Poll::Ready(Ok(())); @@ -308,7 +303,6 @@ where ping.ensure_not_timed_out()?; } - #[cfg(feature = "tracing")] trace!("incoming connection complete"); return Poll::Ready(Ok(())); } @@ -334,7 +328,6 @@ where let _ = self.conn.set_initial_window_size(wnd); } Poll::Ready(ping::Ponged::KeepAliveTimedOut) => { - #[cfg(feature = "tracing")] debug!("keep-alive timed out, closing connection"); self.conn.abrupt_shutdown(h2::Reason::NO_ERROR); } @@ -401,7 +394,6 @@ macro_rules! reply { match $me.reply.send_response($res, $eos) { Ok(tx) => tx, Err(e) => { - #[cfg(feature = "tracing")] debug!("send response error: {}", e); $me.reply.send_reset(Reason::INTERNAL_ERROR); return Poll::Ready(Err(crate::Error::new_h2(e))); @@ -434,7 +426,6 @@ where if let Poll::Ready(reason) = me.reply.poll_reset(cx).map_err(crate::Error::new_h2)? { - #[cfg(feature = "tracing")] debug!("stream received RST_STREAM: {:?}", reason); return Poll::Ready(Err(crate::Error::new_h2(reason.into()))); } @@ -442,7 +433,6 @@ where } Poll::Ready(Err(e)) => { let err = crate::Error::new_user_service(e); - #[cfg(feature = "tracing")] warn!("http2 service errored: {}", err); me.reply.send_reset(err.h2_reason()); return Poll::Ready(Err(err)); @@ -463,7 +453,6 @@ where if headers::content_length_parse_all(res.headers()) .map_or(false, |len| len != 0) { - #[cfg(feature = "tracing")] warn!("h2 successful response to CONNECT request with body not supported"); me.reply.send_reset(h2::Reason::INTERNAL_ERROR); return Poll::Ready(Err(crate::Error::new_user_header())); @@ -519,7 +508,6 @@ where fn poll(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll { self.poll2(cx).map(|res| { if let Err(e) = res { - #[cfg(feature = "tracing")] debug!("stream error: {}", e); } }) diff --git a/src/upgrade.rs b/src/upgrade.rs index 56f7ccabcf..5b28d48cf6 100644 --- a/src/upgrade.rs +++ b/src/upgrade.rs @@ -48,8 +48,6 @@ use std::marker::Unpin; use crate::rt::{Read, ReadBufCursor, Write}; use bytes::Bytes; use tokio::sync::oneshot; -#[cfg(all(any(feature = "http1", feature = "http2"), feature = "tracing"))] -use tracing::trace; use crate::common::io::Rewind; use crate::common::{task, Future, Pin, Poll}; @@ -233,7 +231,7 @@ impl fmt::Debug for OnUpgrade { #[cfg(any(feature = "http1", feature = "http2"))] impl Pending { pub(super) fn fulfill(self, upgraded: Upgraded) { - #[cfg(feature = "tracing")] + #[cfg(any(feature = "http1", feature = "http2"))] trace!("pending upgrade fulfill"); let _ = self.tx.send(Ok(upgraded)); } @@ -242,7 +240,7 @@ impl Pending { /// Don't fulfill the pending Upgrade, but instead signal that /// upgrades are handled manually. pub(super) fn manual(self) { - #[cfg(feature = "tracing")] + #[cfg(any(feature = "http1", feature = "http2"))] trace!("pending upgrade handled manually"); let _ = self.tx.send(Err(crate::Error::new_user_manual_upgrade())); } From ff69931bc355263d7cf32aa43a74c12070b97e75 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Thu, 28 Sep 2023 12:38:10 +0100 Subject: [PATCH 04/13] style(proto): address unused variable warning caused by conditional compilation. Usage of variables passed into the `trace` module is dependent on whether the `tracing` feature is enabled, thus producing a compiler warning when `tracing` is disabled. Prefix potentially unused variables with an underscore to indicate that this is intentional. --- src/proto/h1/role.rs | 2 +- src/proto/h2/client.rs | 8 ++++---- src/proto/h2/ping.rs | 8 ++++---- src/proto/h2/server.rs | 4 ++-- 4 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/proto/h1/role.rs b/src/proto/h1/role.rs index bfd81f5b7a..98c100b066 100644 --- a/src/proto/h1/role.rs +++ b/src/proto/h1/role.rs @@ -70,7 +70,7 @@ where if bytes.is_empty() { return Ok(None); } - + trace_span!("parse_headers"); #[cfg(feature = "server")] diff --git a/src/proto/h2/client.rs b/src/proto/h2/client.rs index 16994f5149..2c527b2fb6 100644 --- a/src/proto/h2/client.rs +++ b/src/proto/h2/client.rs @@ -242,8 +242,8 @@ where if polled.is_ready() { *this.is_terminated = true; } - polled.map_err(|e| { - debug!("connection error: {}", e) + polled.map_err(|_e| { + debug!("connection error: {}", _e) }) } } @@ -442,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")); diff --git a/src/proto/h2/ping.rs b/src/proto/h2/ping.rs index f43a37915b..61d24112f6 100644 --- a/src/proto/h2/ping.rs +++ b/src/proto/h2/ping.rs @@ -299,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 { @@ -331,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); } } } diff --git a/src/proto/h2/server.rs b/src/proto/h2/server.rs index e9979e9447..0d830ad017 100644 --- a/src/proto/h2/server.rs +++ b/src/proto/h2/server.rs @@ -507,8 +507,8 @@ where fn poll(self: Pin<&mut Self>, cx: &mut task::Context<'_>) -> Poll { self.poll2(cx).map(|res| { - if let Err(e) = res { - debug!("stream error: {}", e); + if let Err(_e) = res { + debug!("stream error: {}", _e); } }) } From ae429f1b03bd8e38cea6b38b96207e435b2134eb Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Thu, 28 Sep 2023 12:42:30 +0100 Subject: [PATCH 05/13] feat(trace): introduce a cfg flag for the unstable tracing feature 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 #3326 and #2874. --- src/trace.rs | 78 +++++++++++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 77 insertions(+), 1 deletion(-) diff --git a/src/trace.rs b/src/trace.rs index c001e4092f..40ff8d0cc1 100644 --- a/src/trace.rs +++ b/src/trace.rs @@ -4,7 +4,13 @@ macro_rules! debug { ($($arg:tt)+) => { #[cfg(feature = "tracing")] { - println!($($arg)+); + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); tracing::debug!($($arg)+); } } @@ -14,6 +20,13 @@ macro_rules! debug_span { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); let span = tracing::debug_span!($($arg)+); let _ = span.enter(); } @@ -24,6 +37,13 @@ macro_rules! error { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); tracing::error!($($arg)+); } } @@ -33,6 +53,13 @@ macro_rules! error_span { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); let span = tracing::error_span!($($arg)+); let _ = span.enter(); } @@ -43,6 +70,13 @@ macro_rules! info { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); tracing::info!($($arg)+); } } @@ -52,6 +86,13 @@ macro_rules! info_span { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); let span = tracing::info_span!($($arg)+); let _ = span.enter(); } @@ -62,6 +103,13 @@ macro_rules! trace { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); tracing::trace!($($arg)+); } } @@ -71,6 +119,13 @@ macro_rules! trace_span { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); let span = tracing::trace_span!($($arg)+); let _ = span.enter(); } @@ -81,6 +136,13 @@ macro_rules! span { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); let span = tracing::span!($($arg)+); let _ = span.enter(); } @@ -91,6 +153,13 @@ macro_rules! warn { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); tracing::warn!($($arg)+); } } @@ -100,6 +169,13 @@ macro_rules! warn_span { ($($arg:tt)*) => { #[cfg(feature = "tracing")] { + #[cfg(not(hyper_unstable_tracing))] + compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); let span = tracing::warn_span!($($arg)+); let _ = span.enter(); } From bab6597f6755fb0f5b77c86967a14758be72e1a2 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Thu, 28 Sep 2023 15:17:48 +0100 Subject: [PATCH 06/13] fix(proto): fix a forgotten change during refactor of tracing macro usage Add curly braces around a call to the `trace::debug` macro within a `map_err` anonymous function. The change is necessary to convert the function from an expression to a block to allow for conditional compilation. --- src/proto/h2/client.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/proto/h2/client.rs b/src/proto/h2/client.rs index 2c527b2fb6..9ad884d151 100644 --- a/src/proto/h2/client.rs +++ b/src/proto/h2/client.rs @@ -243,7 +243,7 @@ where *this.is_terminated = true; } polled.map_err(|_e| { - debug!("connection error: {}", _e) + debug!("connection error: {}", _e); }) } } From ebeb031f4569d087a7e83065f0d9085d84f0d9ff Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Thu, 28 Sep 2023 15:38:34 +0100 Subject: [PATCH 07/13] docs(trace): add documentation to trace module and new features to feature list Document `trace` and add new features to the documentation feature list. 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`. --- Cargo.toml | 4 ++-- src/lib.rs | 3 +++ src/trace.rs | 29 +++++++++++++++++++++++++++++ 3 files changed, 34 insertions(+), 2 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index cac55da78c..73ed313319 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -91,8 +91,8 @@ tracing = ["dep:tracing"] 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"] diff --git a/src/lib.rs b/src/lib.rs index 319ddc9c07..b0ded0ff30 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -67,8 +67,11 @@ pub use crate::error::{Error, Result}; #[macro_use] mod cfg; + #[macro_use] +#[cfg_attr(docsrs, doc(all(feature = "tracing"), hyper_unstable_tracing))] mod trace; + #[macro_use] mod common; pub mod body; diff --git a/src/trace.rs b/src/trace.rs index 40ff8d0cc1..7921e39654 100644 --- a/src/trace.rs +++ b/src/trace.rs @@ -1,5 +1,34 @@ +// For completeness, wrappers around all of tracing's public macros are provided, even if they are +// not used at the present time. #![allow(unused_macros)] +//! Internal Tracing macro module +//! +//! The [`trace`][crate::trace] module is an internal module that contains wrapper macros encapsulating +//! [`tracing`][tracing]'s macros. These macros allow for conditional expansion of +//! [`tracing`][tracing] macros during compilation when the `tracing` feature is enabled, or trimming +//! them when the feature is disabled, all in a concise manner. +//! +//! The macros from the [`trace`][crate::trace] module are declared by default and can be used throughout the +//! crate. However, as the contents of these macros are conditionally compiled, they are effectively trimmed +//! during inline expansion when the `tracing` feature is disabled. +//! +//! # Unstable +//! +//! The [`tracing`][tracing] module is currenty **unstable**, hence the existence of this module. As a +//! result, hyper's [`tracing`][tracing] logs are only accessibe if `--cfg hyper_unstable_tracing` is +//! passed to `rustc` when compiling. The easiest way to do that is through setting the `RUSTFLAGS` +//! enviornment variable. +//! +//! # Building +//! +//! Enabling [`trace`][crate::trace] logs, can be done 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 +//! ``` + macro_rules! debug { ($($arg:tt)+) => { #[cfg(feature = "tracing")] From 8ebbd49f17709183bc54e1a7a97570a16ece0a93 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Sat, 30 Sep 2023 16:21:31 +0100 Subject: [PATCH 08/13] fix(trace): change span macros to ensure that `Span` is not dropped early Span macros in the `trace` module drop the `Span` early, making them useless. The fix changes their implementation such that they return the RAII guard, so the span is consumed and the guard is not dropped. --- src/lib.rs | 1 - src/proto/h1/role.rs | 4 +- src/trace.rs | 157 +++++++++++++------------------------------ 3 files changed, 47 insertions(+), 115 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index b0ded0ff30..230208fb5b 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -69,7 +69,6 @@ pub use crate::error::{Error, Result}; mod cfg; #[macro_use] -#[cfg_attr(docsrs, doc(all(feature = "tracing"), hyper_unstable_tracing))] mod trace; #[macro_use] diff --git a/src/proto/h1/role.rs b/src/proto/h1/role.rs index 98c100b066..f964d2138f 100644 --- a/src/proto/h1/role.rs +++ b/src/proto/h1/role.rs @@ -71,7 +71,7 @@ where return Ok(None); } - trace_span!("parse_headers"); + let _entered = trace_span!("parse_headers"); #[cfg(feature = "server")] if !*ctx.h1_header_read_timeout_running { @@ -101,7 +101,7 @@ pub(super) fn encode_headers( where T: Http1Transaction, { - trace_span!("encode_headers"); + let _entered = trace_span!("encode_headers"); T::encode(enc, dst) } diff --git a/src/trace.rs b/src/trace.rs index 7921e39654..73222205a3 100644 --- a/src/trace.rs +++ b/src/trace.rs @@ -1,5 +1,5 @@ -// For completeness, wrappers around all of tracing's public macros are provided, even if they are -// not used at the present time. +// For completeness, wrappers around all of tracing's public logging and span macros are provided, +// even if they are not used at the present time. #![allow(unused_macros)] //! Internal Tracing macro module @@ -29,35 +29,29 @@ //! RUSTFLAGS="--cfg hyper_unstable_tracing" cargo rustc --features client,http1,http2,tracing --crate-type cdylib //! ``` +#[cfg(not(hyper_unstable_tracing))] +compile_error!( + "\ + The `tracing` feature is unstable, and requires the \ + `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ + " + ); + macro_rules! debug { ($($arg:tt)+) => { #[cfg(feature = "tracing")] - { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - tracing::debug!($($arg)+); - } + tracing::debug!($($arg)+); } } macro_rules! debug_span { ($($arg:tt)*) => { - #[cfg(feature = "tracing")] { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - let span = tracing::debug_span!($($arg)+); - let _ = span.enter(); + #[cfg(feature = "tracing")] + { + let _span = tracing::debug_span!($($arg)+); + _span.entered(); + } } } } @@ -65,32 +59,18 @@ macro_rules! debug_span { macro_rules! error { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - tracing::error!($($arg)+); - } + tracing::error!($($arg)+); } } macro_rules! error_span { ($($arg:tt)*) => { - #[cfg(feature = "tracing")] { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - let span = tracing::error_span!($($arg)+); - let _ = span.enter(); + #[cfg(feature = "tracing")] + { + let _span = tracing::error_span!($($arg)+); + _span.entered(); + } } } } @@ -98,32 +78,18 @@ macro_rules! error_span { macro_rules! info { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - tracing::info!($($arg)+); - } + tracing::info!($($arg)+); } } macro_rules! info_span { ($($arg:tt)*) => { - #[cfg(feature = "tracing")] { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - let span = tracing::info_span!($($arg)+); - let _ = span.enter(); + #[cfg(feature = "tracing")] + { + let _span = tracing::info_span!($($arg)+); + _span.entered(); + } } } } @@ -131,49 +97,30 @@ macro_rules! info_span { macro_rules! trace { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - tracing::trace!($($arg)+); - } + tracing::trace!($($arg)+); } } macro_rules! trace_span { ($($arg:tt)*) => { - #[cfg(feature = "tracing")] { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - let span = tracing::trace_span!($($arg)+); - let _ = span.enter(); + #[cfg(feature = "tracing")] + { + let _span = tracing::trace_span!($($arg)+); + _span.entered(); + } } } } macro_rules! span { ($($arg:tt)*) => { - #[cfg(feature = "tracing")] { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - let span = tracing::span!($($arg)+); - let _ = span.enter(); + #[cfg(feature = "tracing")] + { + let _span = tracing::span!($($arg)+); + _span.entered(); + } } } } @@ -181,32 +128,18 @@ macro_rules! span { macro_rules! warn { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - tracing::warn!($($arg)+); - } + tracing::warn!($($arg)+); } } macro_rules! warn_span { ($($arg:tt)*) => { - #[cfg(feature = "tracing")] { - #[cfg(not(hyper_unstable_tracing))] - compile_error!( - "\ - The `tracing` feature is unstable, and requires the \ - `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); - let span = tracing::warn_span!($($arg)+); - let _ = span.enter(); + #[cfg(feature = "tracing")] + { + let _span = tracing::warn_span!($($arg)+); + _span.entered(); + } } } } From 32c1df7d767f1bf253484b3fa5fad367eadd714a Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Sat, 30 Sep 2023 16:28:46 +0100 Subject: [PATCH 09/13] style(upgrade): remove unncessary cfg attribute Remove an extraneous cfg attribute that was added erroneously in a previous commit. --- src/upgrade.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/upgrade.rs b/src/upgrade.rs index 5b28d48cf6..03a56af6c5 100644 --- a/src/upgrade.rs +++ b/src/upgrade.rs @@ -231,7 +231,6 @@ impl fmt::Debug for OnUpgrade { #[cfg(any(feature = "http1", feature = "http2"))] impl Pending { pub(super) fn fulfill(self, upgraded: Upgraded) { - #[cfg(any(feature = "http1", feature = "http2"))] trace!("pending upgrade fulfill"); let _ = self.tx.send(Ok(upgraded)); } From 282643eae3498bf789ee101828eb1b4392c4cdd4 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Sat, 30 Sep 2023 19:08:17 +0100 Subject: [PATCH 10/13] docs(trace): move `trace` documentation to lib and reduce information Remove `trace` documetationfrom `trace.rs`. Add unstable section to `lib.rs` detailing unstable features. Add information about `tracing` and `ffi` to unstable features section. --- src/lib.rs | 15 ++++++++++++++- src/trace.rs | 27 --------------------------- 2 files changed, 14 insertions(+), 28 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index 230208fb5b..0d1db8320a 100644 --- a/src/lib.rs +++ b/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; diff --git a/src/trace.rs b/src/trace.rs index 73222205a3..ca6e419e3d 100644 --- a/src/trace.rs +++ b/src/trace.rs @@ -2,33 +2,6 @@ // even if they are not used at the present time. #![allow(unused_macros)] -//! Internal Tracing macro module -//! -//! The [`trace`][crate::trace] module is an internal module that contains wrapper macros encapsulating -//! [`tracing`][tracing]'s macros. These macros allow for conditional expansion of -//! [`tracing`][tracing] macros during compilation when the `tracing` feature is enabled, or trimming -//! them when the feature is disabled, all in a concise manner. -//! -//! The macros from the [`trace`][crate::trace] module are declared by default and can be used throughout the -//! crate. However, as the contents of these macros are conditionally compiled, they are effectively trimmed -//! during inline expansion when the `tracing` feature is disabled. -//! -//! # Unstable -//! -//! The [`tracing`][tracing] module is currenty **unstable**, hence the existence of this module. As a -//! result, hyper's [`tracing`][tracing] logs are only accessibe if `--cfg hyper_unstable_tracing` is -//! passed to `rustc` when compiling. The easiest way to do that is through setting the `RUSTFLAGS` -//! enviornment variable. -//! -//! # Building -//! -//! Enabling [`trace`][crate::trace] logs, can be done 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 -//! ``` - #[cfg(not(hyper_unstable_tracing))] compile_error!( "\ From 1fc8310cbf2293ce28ac6c417cfee140ef8c1a61 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Sat, 30 Sep 2023 20:04:35 +0100 Subject: [PATCH 11/13] fix(trace): fix when compile error is thrown and return `Entered` Change condition for when compile error is thrown in the `trace` module, as the module is compiled even when tracing is disabled. Throw when `unstable_hyper_tracing` is not specified while tracing flag is enabled. Removed semi-colons after `Span.entered()` to ensure RAII guard is returned. --- src/trace.rs | 40 +++++++++++++++++++++++++--------------- 1 file changed, 25 insertions(+), 15 deletions(-) diff --git a/src/trace.rs b/src/trace.rs index ca6e419e3d..88f9a243a0 100644 --- a/src/trace.rs +++ b/src/trace.rs @@ -1,19 +1,21 @@ -// For completeness, wrappers around all of tracing's public logging and span macros are provided, +// For completeness, wrappers around all of tracing's public logging and span macros are provided, // even if they are not used at the present time. #![allow(unused_macros)] -#[cfg(not(hyper_unstable_tracing))] +#[cfg(all(not(hyper_unstable_tracing), feature = "tracing"))] compile_error!( "\ The `tracing` feature is unstable, and requires the \ `RUSTFLAGS='--cfg hyper_unstable_tracing'` environment variable to be set.\ - " - ); +" +); macro_rules! debug { ($($arg:tt)+) => { #[cfg(feature = "tracing")] - tracing::debug!($($arg)+); + { + tracing::debug!($($arg)+); + } } } @@ -23,7 +25,7 @@ macro_rules! debug_span { #[cfg(feature = "tracing")] { let _span = tracing::debug_span!($($arg)+); - _span.entered(); + _span.entered() } } } @@ -32,7 +34,9 @@ macro_rules! debug_span { macro_rules! error { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - tracing::error!($($arg)+); + { + tracing::error!($($arg)+); + } } } @@ -42,7 +46,7 @@ macro_rules! error_span { #[cfg(feature = "tracing")] { let _span = tracing::error_span!($($arg)+); - _span.entered(); + _span.entered() } } } @@ -51,7 +55,9 @@ macro_rules! error_span { macro_rules! info { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - tracing::info!($($arg)+); + { + tracing::info!($($arg)+); + } } } @@ -61,7 +67,7 @@ macro_rules! info_span { #[cfg(feature = "tracing")] { let _span = tracing::info_span!($($arg)+); - _span.entered(); + _span.entered() } } } @@ -70,7 +76,9 @@ macro_rules! info_span { macro_rules! trace { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - tracing::trace!($($arg)+); + { + tracing::trace!($($arg)+); + } } } @@ -80,7 +88,7 @@ macro_rules! trace_span { #[cfg(feature = "tracing")] { let _span = tracing::trace_span!($($arg)+); - _span.entered(); + _span.entered() } } } @@ -92,7 +100,7 @@ macro_rules! span { #[cfg(feature = "tracing")] { let _span = tracing::span!($($arg)+); - _span.entered(); + _span.entered() } } } @@ -101,7 +109,9 @@ macro_rules! span { macro_rules! warn { ($($arg:tt)*) => { #[cfg(feature = "tracing")] - tracing::warn!($($arg)+); + { + tracing::warn!($($arg)+); + } } } @@ -111,7 +121,7 @@ macro_rules! warn_span { #[cfg(feature = "tracing")] { let _span = tracing::warn_span!($($arg)+); - _span.entered(); + _span.entered() } } } From 48e09e0de5ce13c21fab31affa5d92bd252aa0c6 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Sat, 30 Sep 2023 20:12:55 +0100 Subject: [PATCH 12/13] refactor(proto): record error as structured field. Log errors as a field rather than part of a formatted string. --- src/proto/h1/conn.rs | 2 +- src/proto/h2/client.rs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/proto/h1/conn.rs b/src/proto/h1/conn.rs index 45fcf69915..ce7c41a366 100644 --- a/src/proto/h1/conn.rs +++ b/src/proto/h1/conn.rs @@ -438,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 })) diff --git a/src/proto/h2/client.rs b/src/proto/h2/client.rs index 9ad884d151..ebd8822a5d 100644 --- a/src/proto/h2/client.rs +++ b/src/proto/h2/client.rs @@ -243,7 +243,7 @@ where *this.is_terminated = true; } polled.map_err(|_e| { - debug!("connection error: {}", _e); + debug!(error = %_e, "connection error"); }) } } From 5565f0ab33c20d6854175cb8b0b33c2248750073 Mon Sep 17 00:00:00 2001 From: RamziA961 <60425857+RamziA961@users.noreply.github.com> Date: Mon, 2 Oct 2023 20:52:56 +0100 Subject: [PATCH 13/13] chore(ci): update features job to skip `tracing` feature Similar to ffi, the feature job will skip tracing as it is unstable and requires a cfg flag to compile without an error. Once #3326 is merged, subsequent PRs will fail the feature CI job without this change. --- .github/workflows/CI.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index 295e3c8773..36d1c885db 100644 --- a/.github/workflows/CI.yml +++ b/.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)