From d76ae1829d7c14655d91ff12f7d98952d37d674c Mon Sep 17 00:00:00 2001 From: tottoto Date: Wed, 8 May 2024 20:42:28 +0900 Subject: [PATCH] chore: make tracing optional --- .github/workflows/CI.yml | 3 ++ Cargo.toml | 7 ++- src/client.rs | 17 +++++-- src/codec/framed_read.rs | 47 +++++++++---------- src/codec/framed_write.rs | 8 ++-- src/frame/go_away.rs | 1 + src/frame/headers.rs | 1 + src/frame/ping.rs | 1 + src/frame/reset.rs | 1 + src/frame/settings.rs | 1 + src/frame/window_update.rs | 1 + src/hpack/decoder.rs | 6 +-- src/hpack/encoder.rs | 4 +- src/lib.rs | 6 ++- src/proto/connection.rs | 23 ++++----- src/proto/peer.rs | 1 + src/proto/ping_pong.rs | 1 + src/proto/settings.rs | 1 + src/proto/streams/counts.rs | 3 ++ src/proto/streams/flow_control.rs | 1 + src/proto/streams/prioritize.rs | 78 ++++++++++++++----------------- src/proto/streams/recv.rs | 9 ++-- src/proto/streams/send.rs | 6 ++- src/proto/streams/state.rs | 21 +++++---- src/proto/streams/store.rs | 2 + src/proto/streams/stream.rs | 2 +- src/proto/streams/streams.rs | 4 +- src/server.rs | 57 +++++++++++++++------- src/tracing.rs | 52 +++++++++++++++++++++ 29 files changed, 233 insertions(+), 132 deletions(-) create mode 100644 src/tracing.rs diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index 0952337e4..c47ba5c82 100644 --- a/.github/workflows/CI.yml +++ b/.github/workflows/CI.yml @@ -51,6 +51,9 @@ jobs: - name: Check with unstable flag run: cargo check --features unstable + - name: Check with tracing feature + run: cargo check --features tracing + - name: Run lib tests and doc tests run: cargo test diff --git a/Cargo.toml b/Cargo.toml index b7eb80511..0d4d6b7ad 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -23,6 +23,9 @@ rust-version = "1.63" # Enables `futures::Stream` implementations for various types. stream = [] +# Enables tracing. +tracing = ["dep:tracing"] + # Enables **unstable** APIs. Any API exposed by this feature has no backwards # compatibility guarantees. In other words, you should not use this feature for # anything besides experimentation. Definitely **do not** publish a crate that @@ -46,12 +49,14 @@ tokio-util = { version = "0.7.1", features = ["codec", "io"] } tokio = { version = "1", features = ["io-util"] } bytes = "1" http = "1" -tracing = { version = "0.1.35", default-features = false, features = ["std"] } +tracing = { version = "0.1.35", default-features = false, features = ["std"], optional = true } fnv = "1.0.5" slab = "0.4.2" indexmap = { version = "2", features = ["std"] } [dev-dependencies] +# Test +tracing = { version = "0.1.35", default-features = false, features = ["std"] } # Fuzzing quickcheck = { version = "1.0.3", default-features = false } diff --git a/src/client.rs b/src/client.rs index ffeda6077..003ce0232 100644 --- a/src/client.rs +++ b/src/client.rs @@ -139,8 +139,10 @@ use crate::codec::{Codec, SendError, UserError}; use crate::ext::Protocol; use crate::frame::{Headers, Pseudo, Reason, Settings, StreamId}; use crate::proto::{self, Error}; -use crate::{FlowControl, PingPong, RecvStream, SendStream}; +use crate::{tracing, FlowControl, PingPong, RecvStream, SendStream}; +#[cfg(feature = "tracing")] +use ::tracing::Instrument; use bytes::{Buf, Bytes}; use http::{uri, HeaderMap, Method, Request, Response, Version}; use std::fmt; @@ -149,7 +151,6 @@ use std::pin::Pin; use std::task::{Context, Poll}; use std::time::Duration; use tokio::io::{AsyncRead, AsyncWrite, AsyncWriteExt}; -use tracing::Instrument; /// Initializes new HTTP/2 streams on a connection by sending a request. /// @@ -1275,10 +1276,15 @@ where T: AsyncRead + AsyncWrite + Unpin, { let builder = Builder::new(); - builder + + #[cfg(feature = "tracing")] + return builder .handshake(io) - .instrument(tracing::trace_span!("client_handshake")) - .await + .instrument(::tracing::trace_span!("client_handshake")) + .await; + + #[cfg(not(feature = "tracing"))] + return builder.handshake(io).await; } // ===== impl Connection ===== @@ -1646,6 +1652,7 @@ impl Peer { impl proto::Peer for Peer { type Poll = Response<()>; + #[cfg(feature = "tracing")] const NAME: &'static str = "Client"; fn r#dyn() -> proto::DynPeer { diff --git a/src/codec/framed_read.rs b/src/codec/framed_read.rs index 9270a8635..fbc4299a6 100644 --- a/src/codec/framed_read.rs +++ b/src/codec/framed_read.rs @@ -5,6 +5,7 @@ use crate::frame::{ use crate::proto::Error; use crate::hpack; +use crate::tracing; use futures_core::Stream; @@ -126,8 +127,7 @@ fn decode_frame( partial_inout: &mut Option, mut bytes: BytesMut, ) -> Result, Error> { - let span = tracing::trace_span!("FramedRead::decode_frame", offset = bytes.len()); - let _e = span.enter(); + let _span = tracing::trace_span!("FramedRead::decode_frame", offset = bytes.len()); tracing::trace!("decoding frame from {}B", bytes.len()); @@ -159,8 +159,8 @@ fn decode_frame( // `PROTOCOL_ERROR`. return Err(Error::library_reset($head.stream_id(), Reason::PROTOCOL_ERROR)); }, - Err(e) => { - proto_err!(conn: "failed to load frame; err={:?}", e); + Err(_e) => { + proto_err!(conn: "failed to load frame; err={:?}", _e); return Err(Error::library_go_away(Reason::PROTOCOL_ERROR)); } }; @@ -176,8 +176,8 @@ fn decode_frame( proto_err!(stream: "malformed header block; stream={:?}", id); return Err(Error::library_reset(id, Reason::PROTOCOL_ERROR)); }, - Err(e) => { - proto_err!(conn: "failed HPACK decoding; err={:?}", e); + Err(_e) => { + proto_err!(conn: "failed HPACK decoding; err={:?}", _e); return Err(Error::library_go_away(Reason::PROTOCOL_ERROR)); } } @@ -202,8 +202,8 @@ fn decode_frame( Kind::Settings => { let res = frame::Settings::load(head, &bytes[frame::HEADER_LEN..]); - res.map_err(|e| { - proto_err!(conn: "failed to load SETTINGS frame; err={:?}", e); + res.map_err(|_e| { + proto_err!(conn: "failed to load SETTINGS frame; err={:?}", _e); Error::library_go_away(Reason::PROTOCOL_ERROR) })? .into() @@ -211,8 +211,8 @@ fn decode_frame( Kind::Ping => { let res = frame::Ping::load(head, &bytes[frame::HEADER_LEN..]); - res.map_err(|e| { - proto_err!(conn: "failed to load PING frame; err={:?}", e); + res.map_err(|_e| { + proto_err!(conn: "failed to load PING frame; err={:?}", _e); Error::library_go_away(Reason::PROTOCOL_ERROR) })? .into() @@ -220,8 +220,8 @@ fn decode_frame( Kind::WindowUpdate => { let res = frame::WindowUpdate::load(head, &bytes[frame::HEADER_LEN..]); - res.map_err(|e| { - proto_err!(conn: "failed to load WINDOW_UPDATE frame; err={:?}", e); + res.map_err(|_e| { + proto_err!(conn: "failed to load WINDOW_UPDATE frame; err={:?}", _e); Error::library_go_away(Reason::PROTOCOL_ERROR) })? .into() @@ -231,8 +231,8 @@ fn decode_frame( let res = frame::Data::load(head, bytes.freeze()); // TODO: Should this always be connection level? Probably not... - res.map_err(|e| { - proto_err!(conn: "failed to load DATA frame; err={:?}", e); + res.map_err(|_e| { + proto_err!(conn: "failed to load DATA frame; err={:?}", _e); Error::library_go_away(Reason::PROTOCOL_ERROR) })? .into() @@ -240,16 +240,16 @@ fn decode_frame( Kind::Headers => header_block!(Headers, head, bytes), Kind::Reset => { let res = frame::Reset::load(head, &bytes[frame::HEADER_LEN..]); - res.map_err(|e| { - proto_err!(conn: "failed to load RESET frame; err={:?}", e); + res.map_err(|_e| { + proto_err!(conn: "failed to load RESET frame; err={:?}", _e); Error::library_go_away(Reason::PROTOCOL_ERROR) })? .into() } Kind::GoAway => { let res = frame::GoAway::load(&bytes[frame::HEADER_LEN..]); - res.map_err(|e| { - proto_err!(conn: "failed to load GO_AWAY frame; err={:?}", e); + res.map_err(|_e| { + proto_err!(conn: "failed to load GO_AWAY frame; err={:?}", _e); Error::library_go_away(Reason::PROTOCOL_ERROR) })? .into() @@ -272,8 +272,8 @@ fn decode_frame( proto_err!(stream: "PRIORITY invalid dependency ID; stream={:?}", id); return Err(Error::library_reset(id, Reason::PROTOCOL_ERROR)); } - Err(e) => { - proto_err!(conn: "failed to load PRIORITY frame; err={:?};", e); + Err(_e) => { + proto_err!(conn: "failed to load PRIORITY frame; err={:?};", _e); return Err(Error::library_go_away(Reason::PROTOCOL_ERROR)); } } @@ -348,8 +348,8 @@ fn decode_frame( proto_err!(stream: "malformed CONTINUATION frame; stream={:?}", id); return Err(Error::library_reset(id, Reason::PROTOCOL_ERROR)); } - Err(e) => { - proto_err!(conn: "failed HPACK decoding; err={:?}", e); + Err(_e) => { + proto_err!(conn: "failed HPACK decoding; err={:?}", _e); return Err(Error::library_go_away(Reason::PROTOCOL_ERROR)); } } @@ -377,8 +377,7 @@ where type Item = Result; fn poll_next(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll> { - let span = tracing::trace_span!("FramedRead::poll_next"); - let _e = span.enter(); + let _span = tracing::trace_span!("FramedRead::poll_next"); loop { tracing::trace!("poll"); let bytes = match ready!(Pin::new(&mut self.inner).poll_next(cx)) { diff --git a/src/codec/framed_write.rs b/src/codec/framed_write.rs index c88af02da..54d64a44b 100644 --- a/src/codec/framed_write.rs +++ b/src/codec/framed_write.rs @@ -1,7 +1,7 @@ use crate::codec::UserError; use crate::codec::UserError::*; use crate::frame::{self, Frame, FrameSize}; -use crate::hpack; +use crate::{hpack, tracing}; use bytes::{Buf, BufMut, BytesMut}; use std::pin::Pin; @@ -128,8 +128,7 @@ where /// Flush buffered data to the wire pub fn flush(&mut self, cx: &mut Context) -> Poll> { - let span = tracing::trace_span!("FramedWrite::flush"); - let _e = span.enter(); + let _span = tracing::trace_span!("FramedWrite::flush"); loop { while !self.encoder.is_empty() { @@ -207,8 +206,7 @@ where fn buffer(&mut self, item: Frame) -> Result<(), UserError> { // Ensure that we have enough capacity to accept the write. assert!(self.has_capacity()); - let span = tracing::trace_span!("FramedWrite::buffer", frame = ?item); - let _e = span.enter(); + let _span = tracing::trace_span!("FramedWrite::buffer", frame = ?item); tracing::debug!(frame = ?item, "send"); diff --git a/src/frame/go_away.rs b/src/frame/go_away.rs index 99330e981..26fcac768 100644 --- a/src/frame/go_away.rs +++ b/src/frame/go_away.rs @@ -3,6 +3,7 @@ use std::fmt; use bytes::{BufMut, Bytes}; use crate::frame::{self, Error, Head, Kind, Reason, StreamId}; +use crate::tracing; #[derive(Clone, Eq, PartialEq)] pub struct GoAway { diff --git a/src/frame/headers.rs b/src/frame/headers.rs index 0c756325f..2b4a54d83 100644 --- a/src/frame/headers.rs +++ b/src/frame/headers.rs @@ -2,6 +2,7 @@ use super::{util, StreamDependency, StreamId}; use crate::ext::Protocol; use crate::frame::{Error, Frame, Head, Kind}; use crate::hpack::{self, BytesStr}; +use crate::tracing; use http::header::{self, HeaderName, HeaderValue}; use http::{uri, HeaderMap, Method, Request, StatusCode, Uri}; diff --git a/src/frame/ping.rs b/src/frame/ping.rs index 241d06ea1..9a7c5d10e 100644 --- a/src/frame/ping.rs +++ b/src/frame/ping.rs @@ -1,4 +1,5 @@ use crate::frame::{Error, Frame, Head, Kind, StreamId}; +use crate::tracing; use bytes::BufMut; const ACK_FLAG: u8 = 0x1; diff --git a/src/frame/reset.rs b/src/frame/reset.rs index 39f6ac202..0f8266231 100644 --- a/src/frame/reset.rs +++ b/src/frame/reset.rs @@ -1,4 +1,5 @@ use crate::frame::{self, Error, Head, Kind, Reason, StreamId}; +use crate::tracing; use bytes::BufMut; diff --git a/src/frame/settings.rs b/src/frame/settings.rs index 484498a9d..c588dc5e1 100644 --- a/src/frame/settings.rs +++ b/src/frame/settings.rs @@ -1,6 +1,7 @@ use std::fmt; use crate::frame::{util, Error, Frame, FrameSize, Head, Kind, StreamId}; +use crate::tracing; use bytes::{BufMut, BytesMut}; #[derive(Clone, Default, Eq, PartialEq)] diff --git a/src/frame/window_update.rs b/src/frame/window_update.rs index eed2ce17e..eaa3f9e14 100644 --- a/src/frame/window_update.rs +++ b/src/frame/window_update.rs @@ -1,4 +1,5 @@ use crate::frame::{self, Error, Head, Kind, StreamId}; +use crate::tracing; use bytes::BufMut; diff --git a/src/hpack/decoder.rs b/src/hpack/decoder.rs index e48976c36..b6b381be0 100644 --- a/src/hpack/decoder.rs +++ b/src/hpack/decoder.rs @@ -1,5 +1,5 @@ use super::{header::BytesStr, huffman, Header}; -use crate::frame; +use crate::{frame, tracing}; use bytes::{Buf, Bytes, BytesMut}; use http::header; @@ -189,8 +189,7 @@ impl Decoder { self.last_max_update = size; } - let span = tracing::trace_span!("hpack::decode"); - let _e = span.enter(); + let _span = tracing::trace_span!("hpack::decode"); tracing::trace!("decode"); @@ -494,6 +493,7 @@ impl Table { } } + #[cfg(any(feature = "tracing", test))] fn size(&self) -> usize { self.size } diff --git a/src/hpack/encoder.rs b/src/hpack/encoder.rs index 06ccda400..c46819cbd 100644 --- a/src/hpack/encoder.rs +++ b/src/hpack/encoder.rs @@ -1,5 +1,6 @@ use super::table::{Index, Table}; use super::{huffman, Header}; +use crate::tracing; use bytes::{BufMut, BytesMut}; use http::header::{HeaderName, HeaderValue}; @@ -62,8 +63,7 @@ impl Encoder { where I: IntoIterator>>, { - let span = tracing::trace_span!("hpack::encode"); - let _e = span.enter(); + let _span = tracing::trace_span!("hpack::encode"); self.encode_size_updates(dst); diff --git a/src/lib.rs b/src/lib.rs index 3d59ef21e..36658fd8f 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -87,12 +87,14 @@ #![allow(clippy::type_complexity, clippy::manual_range_contains)] #![cfg_attr(test, deny(warnings))] +mod tracing; + macro_rules! proto_err { (conn: $($msg:tt)+) => { - tracing::debug!("connection error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) + crate::tracing::debug!("connection error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) }; (stream: $($msg:tt)+) => { - tracing::debug!("stream error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) + crate::tracing::debug!("stream error PROTOCOL_ERROR -- {};", format_args!($($msg)+)) }; } diff --git a/src/proto/connection.rs b/src/proto/connection.rs index 5589fabcb..10a579504 100644 --- a/src/proto/connection.rs +++ b/src/proto/connection.rs @@ -1,6 +1,6 @@ use crate::codec::UserError; use crate::frame::{Reason, StreamId}; -use crate::{client, server}; +use crate::{client, server, tracing}; use crate::frame::DEFAULT_INITIAL_WINDOW_SIZE; use crate::proto::*; @@ -55,7 +55,8 @@ where streams: Streams, /// A `tracing` span tracking the lifetime of the connection. - span: tracing::Span, + #[cfg(feature = "tracing")] + span: ::tracing::Span, /// Client or server _phantom: PhantomData

, @@ -135,7 +136,8 @@ where ping_pong: PingPong::new(), settings: Settings::new(config.settings), streams, - span: tracing::debug_span!("Connection", peer = %P::NAME), + #[cfg(feature = "tracing")] + span: ::tracing::debug_span!("Connection", peer = %P::NAME), _phantom: PhantomData, }, } @@ -184,9 +186,9 @@ where /// Returns `Error` as this may raise errors that are caused by delayed /// processing of received frames. fn poll_ready(&mut self, cx: &mut Context) -> Poll> { + #[cfg(feature = "tracing")] let _e = self.inner.span.enter(); - let span = tracing::trace_span!("poll_ready"); - let _e = span.enter(); + let _span = tracing::trace_span!("poll_ready"); // The order of these calls don't really matter too much ready!(self.inner.ping_pong.send_pending_pong(cx, &mut self.codec))?; ready!(self.inner.ping_pong.send_pending_ping(cx, &mut self.codec))?; @@ -259,10 +261,9 @@ where // order to placate the borrow checker — `self` is mutably borrowed by // `poll2`, which means that we can't borrow `self.span` to enter it. // The clone is just an atomic ref bump. - let span = self.inner.span.clone(); - let _e = span.enter(); - let span = tracing::trace_span!("poll"); - let _e = span.enter(); + #[cfg(feature = "tracing")] + let _span1 = self.inner.span.clone().entered(); + let _span2 = tracing::trace_span!("poll"); loop { tracing::trace!(connection.state = ?self.inner.state); @@ -540,8 +541,8 @@ where tracing::trace!(?frame, "recv WINDOW_UPDATE"); self.streams.recv_window_update(frame)?; } - Some(Priority(frame)) => { - tracing::trace!(?frame, "recv PRIORITY"); + Some(Priority(_frame)) => { + tracing::trace!(?_frame, "recv PRIORITY"); // TODO: handle } None => { diff --git a/src/proto/peer.rs b/src/proto/peer.rs index cbe7fb289..fe6d4f7b1 100644 --- a/src/proto/peer.rs +++ b/src/proto/peer.rs @@ -10,6 +10,7 @@ use std::fmt; pub(crate) trait Peer { /// Message type polled from the transport type Poll: fmt::Debug; + #[cfg(feature = "tracing")] const NAME: &'static str; fn r#dyn() -> Dyn; diff --git a/src/proto/ping_pong.rs b/src/proto/ping_pong.rs index 692c0bae9..28ba47f69 100644 --- a/src/proto/ping_pong.rs +++ b/src/proto/ping_pong.rs @@ -1,6 +1,7 @@ use crate::codec::Codec; use crate::frame::Ping; use crate::proto::{self, PingPayload}; +use crate::tracing; use atomic_waker::AtomicWaker; use bytes::Buf; diff --git a/src/proto/settings.rs b/src/proto/settings.rs index d6155fc3d..3ed4574d6 100644 --- a/src/proto/settings.rs +++ b/src/proto/settings.rs @@ -1,6 +1,7 @@ use crate::codec::UserError; use crate::error::Reason; use crate::proto::*; +use crate::tracing; use std::task::{Context, Poll}; #[derive(Debug)] diff --git a/src/proto/streams/counts.rs b/src/proto/streams/counts.rs index a214892b6..33e7c8454 100644 --- a/src/proto/streams/counts.rs +++ b/src/proto/streams/counts.rs @@ -1,4 +1,5 @@ use super::*; +use crate::tracing; #[derive(Debug)] pub(super) struct Counts { @@ -92,6 +93,7 @@ impl Counts { self.num_local_error_reset_streams += 1; } + #[cfg(feature = "tracing")] pub(crate) fn max_local_error_resets(&self) -> Option { self.max_local_error_reset_streams } @@ -150,6 +152,7 @@ impl Counts { self.num_local_reset_streams += 1; } + #[cfg(feature = "tracing")] pub(crate) fn max_remote_reset_streams(&self) -> usize { self.max_remote_reset_streams } diff --git a/src/proto/streams/flow_control.rs b/src/proto/streams/flow_control.rs index 57a935825..6bfe9d076 100644 --- a/src/proto/streams/flow_control.rs +++ b/src/proto/streams/flow_control.rs @@ -1,5 +1,6 @@ use crate::frame::Reason; use crate::proto::{WindowSize, MAX_WINDOW_SIZE}; +use crate::tracing; use std::fmt; diff --git a/src/proto/streams/prioritize.rs b/src/proto/streams/prioritize.rs index 81825f404..870e3a4e0 100644 --- a/src/proto/streams/prioritize.rs +++ b/src/proto/streams/prioritize.rs @@ -6,6 +6,8 @@ use crate::frame::Reason; use crate::codec::UserError; use crate::codec::UserError::*; +use crate::tracing; + use bytes::buf::Take; use std::{ cmp::{self, Ordering}, @@ -116,8 +118,7 @@ impl Prioritize { stream: &mut store::Ptr, task: &mut Option, ) { - let span = tracing::trace_span!("Prioritize::queue_frame", ?stream.id); - let _e = span.enter(); + let _span = tracing::trace_span!("Prioritize::queue_frame", ?stream.id); // Queue the frame in the buffer stream.pending_send.push_back(buffer, frame); self.schedule_send(stream, task); @@ -172,9 +173,8 @@ impl Prioritize { // Update the buffered data counter stream.buffered_send_data += sz as usize; - let span = + let _span = tracing::trace_span!("send_data", sz, requested = stream.requested_send_capacity); - let _e = span.enter(); tracing::trace!(buffered = stream.buffered_send_data); // Implicitly request more send capacity if not enough has been @@ -234,14 +234,13 @@ impl Prioritize { stream: &mut store::Ptr, counts: &mut Counts, ) { - let span = tracing::trace_span!( + let _span = tracing::trace_span!( "reserve_capacity", ?stream.id, requested = capacity, effective = (capacity as usize) + stream.buffered_send_data, curr = stream.requested_send_capacity ); - let _e = span.enter(); // Actual capacity is `capacity` + the current amount of buffered data. // If it were less, then we could never send out the buffered data. @@ -294,14 +293,13 @@ impl Prioritize { inc: WindowSize, stream: &mut store::Ptr, ) -> Result<(), Reason> { - let span = tracing::trace_span!( + let _span = tracing::trace_span!( "recv_stream_window_update", ?stream.id, ?stream.state, inc, flow = ?stream.send_flow ); - let _e = span.enter(); if stream.state.is_send_closed() && stream.buffered_send_data == 0 { // We can't send any data, so don't bother doing anything else. @@ -359,11 +357,10 @@ impl Prioritize { } pub fn clear_pending_capacity(&mut self, store: &mut Store, counts: &mut Counts) { - let span = tracing::trace_span!("clear_pending_capacity"); - let _e = span.enter(); + let _span = tracing::trace_span!("clear_pending_capacity"); while let Some(stream) = self.pending_capacity.pop(store) { - counts.transition(stream, |_, stream| { - tracing::trace!(?stream.id, "clear_pending_capacity"); + counts.transition(stream, |_, _stream| { + tracing::trace!(?_stream.id, "clear_pending_capacity"); }) } } @@ -376,8 +373,7 @@ impl Prioritize { ) where R: Resolve, { - let span = tracing::trace_span!("assign_connection_capacity", inc); - let _e = span.enter(); + let _span = tracing::trace_span!("assign_connection_capacity", inc); // TODO: proper error handling let _res = self.flow.assign_capacity(inc); @@ -422,8 +418,7 @@ impl Prioritize { // Can't assign more than what is available stream.send_flow.window_size() - stream.send_flow.available().as_size(), ); - let span = tracing::trace_span!("try_assign_capacity", ?stream.id); - let _e = span.enter(); + let _span = tracing::trace_span!("try_assign_capacity", ?stream.id); tracing::trace!( requested = total_requested, additional, @@ -581,8 +576,7 @@ impl Prioritize { where B: Buf, { - let span = tracing::trace_span!("try_reclaim_frame"); - let _e = span.enter(); + let _span = tracing::trace_span!("try_reclaim_frame"); // First check if there are any data chunks to take back if let Some(frame) = dst.take_last_data_frame() { @@ -661,12 +655,11 @@ impl Prioritize { } pub fn clear_queue(&mut self, buffer: &mut Buffer>, stream: &mut store::Ptr) { - let span = tracing::trace_span!("clear_queue", ?stream.id); - let _e = span.enter(); + let _span = tracing::trace_span!("clear_queue", ?stream.id); // TODO: make this more efficient? - while let Some(frame) = stream.pending_send.pop_front(buffer) { - tracing::trace!(?frame, "dropping"); + while let Some(_frame) = stream.pending_send.pop_front(buffer) { + tracing::trace!(?_frame, "dropping"); } stream.buffered_send_data = 0; @@ -703,14 +696,12 @@ impl Prioritize { where B: Buf, { - let span = tracing::trace_span!("pop_frame"); - let _e = span.enter(); + let _span = tracing::trace_span!("pop_frame"); loop { match self.pending_send.pop(store) { Some(mut stream) => { - let span = tracing::trace_span!("popped", ?stream.id, ?stream.state); - let _e = span.enter(); + let _span = tracing::trace_span!("popped", ?stream.id, ?stream.state); // It's possible that this stream, besides having data to send, // is also queued to send a reset, and thus is already in the queue @@ -780,7 +771,9 @@ impl Prioritize { tracing::trace!(len, "sending data frame"); // Update the flow control - tracing::trace_span!("updating stream flow").in_scope(|| { + { + let _span = tracing::trace_span!("updating stream flow"); + stream.send_data(len, self.max_buffer_size); // Assign the capacity back to the connection that @@ -789,25 +782,26 @@ impl Prioritize { // TODO: proper error handling let _res = self.flow.assign_capacity(len); debug_assert!(_res.is_ok()); - }); + } - let (eos, len) = tracing::trace_span!("updating connection flow") - .in_scope(|| { - // TODO: proper error handling - let _res = self.flow.send_data(len); - debug_assert!(_res.is_ok()); + let (eos, len) = { + let _span = tracing::trace_span!("updating connection flow"); - // Wrap the frame's data payload to ensure that the - // correct amount of data gets written. + // TODO: proper error handling + let _res = self.flow.send_data(len); + debug_assert!(_res.is_ok()); - let eos = frame.is_end_stream(); - let len = len as usize; + // Wrap the frame's data payload to ensure that the + // correct amount of data gets written. - if frame.payload().remaining() > len { - frame.set_end_stream(false); - } - (eos, len) - }); + let eos = frame.is_end_stream(); + let len = len as usize; + + if frame.payload().remaining() > len { + frame.set_end_stream(false); + } + (eos, len) + }; Frame::Data(frame.map(|buf| Prioritized { inner: buf.take(len), diff --git a/src/proto/streams/recv.rs b/src/proto/streams/recv.rs index a70527e2a..7514f820d 100644 --- a/src/proto/streams/recv.rs +++ b/src/proto/streams/recv.rs @@ -2,6 +2,7 @@ use super::*; use crate::codec::UserError; use crate::frame::{PushPromiseHeaderError, Reason, DEFAULT_INITIAL_WINDOW_SIZE}; use crate::proto; +use crate::tracing; use http::{HeaderMap, Request, Response}; @@ -745,10 +746,10 @@ impl Recv { req.method(), promised_id, ), - InvalidContentLength(e) => proto_err!( + InvalidContentLength(_e) => proto_err!( stream: "recv_push_promise; promised request has invalid content-length {:?}; promised_id={:?}", - e, + _e, promised_id, ), } @@ -965,8 +966,8 @@ impl Recv { fn clear_stream_window_update_queue(&mut self, store: &mut Store, counts: &mut Counts) { while let Some(stream) = self.pending_window_updates.pop(store) { - counts.transition(stream, |_, stream| { - tracing::trace!("clear_stream_window_update_queue; stream={:?}", stream.id); + counts.transition(stream, |_, _stream| { + tracing::trace!("clear_stream_window_update_queue; stream={:?}", _stream.id); }) } } diff --git a/src/proto/streams/send.rs b/src/proto/streams/send.rs index 2a7abba06..f19f4b24d 100644 --- a/src/proto/streams/send.rs +++ b/src/proto/streams/send.rs @@ -5,6 +5,7 @@ use super::{ use crate::codec::UserError; use crate::frame::{self, Reason}; use crate::proto::{self, Error, Initiator}; +use crate::tracing; use bytes::Buf; use tokio::io::AsyncWrite; @@ -180,6 +181,7 @@ impl Send { let is_reset = stream.state.is_reset(); let is_closed = stream.state.is_closed(); let is_empty = stream.pending_send.is_empty(); + #[cfg(feature = "tracing")] let stream_id = stream.id; tracing::trace!( @@ -487,7 +489,7 @@ impl Send { // and reassign it to other streams. let window_size = stream.send_flow.window_size(); let available = stream.send_flow.available().as_size(); - let reclaimed = if available > window_size { + let _reclaimed = if available > window_size { // Drop down to `window_size`. let reclaim = available - window_size; stream @@ -504,7 +506,7 @@ impl Send { "decremented stream window; id={:?}; decr={}; reclaimed={}; flow={:?}", stream.id, dec, - reclaimed, + _reclaimed, stream.send_flow ); diff --git a/src/proto/streams/state.rs b/src/proto/streams/state.rs index 5256f09cf..2fc44ff74 100644 --- a/src/proto/streams/state.rs +++ b/src/proto/streams/state.rs @@ -3,6 +3,7 @@ use std::io; use crate::codec::UserError; use crate::frame::{self, Reason, StreamId}; use crate::proto::{self, Error, Initiator, PollReset}; +use crate::tracing; use self::Inner::*; use self::Peer::*; @@ -193,9 +194,9 @@ impl State { HalfClosedLocal(Streaming) } } - ref state => { + ref _state => { // All other transitions result in a protocol error - proto_err!(conn: "recv_open: in unexpected state {:?}", state); + proto_err!(conn: "recv_open: in unexpected state {:?}", _state); return Err(Error::library_go_away(Reason::PROTOCOL_ERROR)); } }; @@ -210,8 +211,8 @@ impl State { self.inner = ReservedRemote; Ok(()) } - ref state => { - proto_err!(conn: "reserve_remote: in unexpected state {:?}", state); + ref _state => { + proto_err!(conn: "reserve_remote: in unexpected state {:?}", _state); Err(Error::library_go_away(Reason::PROTOCOL_ERROR)) } } @@ -242,8 +243,8 @@ impl State { self.inner = Closed(Cause::EndStream); Ok(()) } - ref state => { - proto_err!(conn: "recv_close: in unexpected state {:?}", state); + ref _state => { + proto_err!(conn: "recv_close: in unexpected state {:?}", _state); Err(Error::library_go_away(Reason::PROTOCOL_ERROR)) } } @@ -273,11 +274,11 @@ impl State { // In either of these cases, we want to overwrite the stream's // previous state with the received RST_STREAM, so that the queue // will be cleared by `Prioritize::pop_frame`. - ref state => { + ref _state => { tracing::trace!( "recv_reset; frame={:?}; state={:?}; queued={:?}", frame, - state, + _state, queued ); self.inner = Closed(Cause::Error(Error::remote_reset( @@ -302,8 +303,8 @@ impl State { pub fn recv_eof(&mut self) { match self.inner { Closed(..) => {} - ref state => { - tracing::trace!("recv_eof; state={:?}", state); + ref _state => { + tracing::trace!("recv_eof; state={:?}", _state); self.inner = Closed(Cause::Error( io::Error::new( io::ErrorKind::BrokenPipe, diff --git a/src/proto/streams/store.rs b/src/proto/streams/store.rs index 79c1f93ba..1c2d97bc5 100644 --- a/src/proto/streams/store.rs +++ b/src/proto/streams/store.rs @@ -7,6 +7,8 @@ use std::fmt; use std::marker::PhantomData; use std::ops; +use crate::tracing; + /// Storage for streams #[derive(Debug)] pub(super) struct Store { diff --git a/src/proto/streams/stream.rs b/src/proto/streams/stream.rs index c93c89d2f..66a0c342c 100644 --- a/src/proto/streams/stream.rs +++ b/src/proto/streams/stream.rs @@ -1,4 +1,4 @@ -use crate::Reason; +use crate::{tracing, Reason}; use super::*; diff --git a/src/proto/streams/streams.rs b/src/proto/streams/streams.rs index 132d91bda..c36d99a1f 100644 --- a/src/proto/streams/streams.rs +++ b/src/proto/streams/streams.rs @@ -5,7 +5,7 @@ use crate::codec::{Codec, SendError, UserError}; use crate::ext::Protocol; use crate::frame::{self, Frame, Reason}; use crate::proto::{peer, Error, Initiator, Open, Peer, WindowSize}; -use crate::{client, proto, server}; +use crate::{client, proto, server, tracing}; use bytes::{Buf, Bytes}; use http::{HeaderMap, Request, Response}; @@ -487,7 +487,7 @@ impl Inner { let send_buffer = &mut *send_buffer; self.counts.transition(stream, |counts, stream| { - tracing::trace!( + tracing::trace!( "recv_headers; stream={:?}; state={:?}", stream.id, stream.state diff --git a/src/server.rs b/src/server.rs index b00bc0866..c504ec8ae 100644 --- a/src/server.rs +++ b/src/server.rs @@ -118,8 +118,10 @@ use crate::codec::{Codec, UserError}; use crate::frame::{self, Pseudo, PushPromiseHeaderError, Reason, Settings, StreamId}; use crate::proto::{self, Config, Error, Prioritized}; -use crate::{FlowControl, PingPong, RecvStream, SendStream}; +use crate::{tracing, FlowControl, PingPong, RecvStream, SendStream}; +#[cfg(feature = "tracing")] +use ::tracing::instrument::{Instrument, Instrumented}; use bytes::{Buf, Bytes}; use http::{HeaderMap, Method, Request, Response}; use std::future::Future; @@ -128,7 +130,6 @@ use std::task::{Context, Poll}; use std::time::Duration; use std::{fmt, io}; use tokio::io::{AsyncRead, AsyncWrite, ReadBuf}; -use tracing::instrument::{Instrument, Instrumented}; /// In progress HTTP/2 connection handshake future. /// @@ -151,7 +152,8 @@ pub struct Handshake { /// The current state of the handshake. state: Handshaking, /// Span tracking the handshake - span: tracing::Span, + #[cfg(feature = "tracing")] + span: ::tracing::Span, } /// Accepts inbound HTTP/2 streams on a connection. @@ -308,9 +310,17 @@ impl fmt::Debug for SendPushedResponse { /// Stages of an in-progress handshake. enum Handshaking { /// State 1. Connection is flushing pending SETTINGS frame. + #[cfg(feature = "tracing")] Flushing(Instrumented>>), + #[cfg(not(feature = "tracing"))] + Flushing(Flush>), + /// State 2. Connection is waiting for the client preface. + #[cfg(feature = "tracing")] ReadingPreface(Instrumented>>), + #[cfg(not(feature = "tracing"))] + ReadingPreface(ReadPreface>), + /// State 3. Handshake is done, polling again would panic. Done, } @@ -377,7 +387,9 @@ where B: Buf, { fn handshake2(io: T, builder: Builder) -> Handshake { - let span = tracing::trace_span!("server_handshake"); + #[cfg(feature = "tracing")] + let span = ::tracing::trace_span!("server_handshake"); + #[cfg(feature = "tracing")] let entered = span.enter(); // Create the codec. @@ -397,14 +409,19 @@ where .expect("invalid SETTINGS frame"); // Create the handshake future. + #[cfg(feature = "tracing")] let state = - Handshaking::Flushing(Flush::new(codec).instrument(tracing::trace_span!("flush"))); + Handshaking::Flushing(Flush::new(codec).instrument(::tracing::trace_span!("flush"))); + #[cfg(not(feature = "tracing"))] + let state = Handshaking::Flushing(Flush::new(codec)); + #[cfg(feature = "tracing")] drop(entered); Handshake { builder, state, + #[cfg(feature = "tracing")] span, } } @@ -1342,8 +1359,8 @@ where type Output = Result, crate::Error>; fn poll(mut self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { - let span = self.span.clone(); // XXX(eliza): T_T - let _e = span.enter(); + #[cfg(feature = "tracing")] + let _span = self.span.clone().entered(); // XXX(eliza): T_T tracing::trace!(state = ?self.state); loop { @@ -1363,7 +1380,10 @@ where } }; self.state = Handshaking::ReadingPreface( - ReadPreface::new(codec).instrument(tracing::trace_span!("read_preface")), + #[cfg(feature = "tracing")] + ReadPreface::new(codec).instrument(::tracing::trace_span!("read_preface")), + #[cfg(not(feature = "tracing"))] + ReadPreface::new(codec), ); } Handshaking::ReadingPreface(read) => { @@ -1459,10 +1479,10 @@ impl Peer { "convert_push_message: method {} is not safe and cacheable", request.method(), ), - InvalidContentLength(e) => tracing::debug!( + InvalidContentLength(_e) => tracing::debug!( ?promised_id, "convert_push_message; promised request has invalid content-length {:?}", - e, + _e, ), } return Err(UserError::MalformedHeaders); @@ -1493,6 +1513,7 @@ impl Peer { impl proto::Peer for Peer { type Poll = Request<()>; + #[cfg(feature = "tracing")] const NAME: &'static str = "Server"; /* @@ -1552,11 +1573,11 @@ impl proto::Peer for Peer { // header if let Some(authority) = pseudo.authority { let maybe_authority = uri::Authority::from_maybe_shared(authority.clone().into_inner()); - parts.authority = Some(maybe_authority.or_else(|why| { + parts.authority = Some(maybe_authority.or_else(|_why| { malformed!( "malformed headers: malformed authority ({:?}): {}", authority, - why, + _why, ) })?); } @@ -1567,11 +1588,11 @@ impl proto::Peer for Peer { malformed!("malformed headers: :scheme in CONNECT"); } let maybe_scheme = scheme.parse(); - let scheme = maybe_scheme.or_else(|why| { + let scheme = maybe_scheme.or_else(|_why| { malformed!( "malformed headers: malformed scheme ({:?}): {}", scheme, - why, + _why, ) })?; @@ -1596,8 +1617,8 @@ impl proto::Peer for Peer { } let maybe_path = uri::PathAndQuery::from_maybe_shared(path.clone().into_inner()); - parts.path_and_query = Some(maybe_path.or_else(|why| { - malformed!("malformed headers: malformed path ({:?}): {}", path, why,) + parts.path_and_query = Some(maybe_path.or_else(|_why| { + malformed!("malformed headers: malformed path ({:?}): {}", path, _why,) })?); } else if is_connect && has_protocol { malformed!("malformed headers: missing path in extended CONNECT"); @@ -1607,10 +1628,10 @@ impl proto::Peer for Peer { let mut request = match b.body(()) { Ok(request) => request, - Err(e) => { + Err(_e) => { // TODO: Should there be more specialized handling for different // kinds of errors - proto_err!(stream: "error building request: {}; stream={:?}", e, stream_id); + proto_err!(stream: "error building request: {}; stream={:?}", _e, stream_id); return Err(Error::library_reset(stream_id, Reason::PROTOCOL_ERROR)); } }; diff --git a/src/tracing.rs b/src/tracing.rs new file mode 100644 index 000000000..2fdc45dc7 --- /dev/null +++ b/src/tracing.rs @@ -0,0 +1,52 @@ +macro_rules! debug { + ($($arg:tt)+) => { + { + #[cfg(feature = "tracing")] + { + ::tracing::debug!($($arg)+); + } + } + } +} + +pub(crate) use debug; + +macro_rules! trace { + ($($arg:tt)*) => { + { + #[cfg(feature = "tracing")] + { + ::tracing::trace!($($arg)+); + } + } + } +} + +pub(crate) use trace; + +macro_rules! trace_span { + ($($arg:tt)*) => { + { + #[cfg(feature = "tracing")] + { + let _span = ::tracing::trace_span!($($arg)+); + _span.entered() + } + } + } +} + +pub(crate) use trace_span; + +macro_rules! _warn { + ($($arg:tt)*) => { + { + #[cfg(feature = "tracing")] + { + ::tracing::warn!($($arg)+); + } + } + } +} + +pub(crate) use _warn as warn;