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())); }