diff --git a/Cargo.toml b/Cargo.toml index 13683036..150b5c3a 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -32,6 +32,7 @@ spnego = ["curl-sys/spnego"] static-curl = ["curl/static-curl"] static-ssl = ["curl/static-ssl"] text-decoding = ["encoding_rs", "mime"] +tracing-01 = ["tracing", "tracing-futures"] unstable-interceptors = [] [dependencies] @@ -103,13 +104,15 @@ optional = true # tracing ecosystem compatibility [dependencies.tracing] version = "0.1.17" -features = ["log"] +default-features = false +optional = true # tracing ecosystem compatibility [dependencies.tracing-futures] version = "0.2" default-features = false features = ["std", "std-future"] +optional = true [dev-dependencies] env_logger = "0.9" diff --git a/src/agent/mod.rs b/src/agent/mod.rs index d3ceee98..29b00842 100644 --- a/src/agent/mod.rs +++ b/src/agent/mod.rs @@ -90,14 +90,15 @@ impl AgentBuilder { // Create a span for the agent thread that outlives this method call, // but rather was caused by it. - let agent_span = tracing::debug_span!("agent_thread", id); - agent_span.follows_from(tracing::Span::current()); + let agent_span = span!(DEBUG, "agent_thread", id); + span_follows_from_current!(agent_span); let waker = selector.waker(); let message_tx_clone = message_tx.clone(); let thread_main = move || { - let _enter = agent_span.enter(); + enter_span!(agent_span); + let mut multi = Multi::new(); if max_connections > 0 { @@ -123,12 +124,12 @@ impl AgentBuilder { drop(wait_group_thread); - tracing::debug!("agent took {:?} to start up", create_start.elapsed()); + debug!("agent took {:?} to start up", create_start.elapsed()); let result = agent.run(); if let Err(e) = &result { - tracing::error!("agent shut down with error: {:?}", e); + error!("agent shut down with error: {:?}", e); } result @@ -270,14 +271,14 @@ impl Drop for Handle { fn drop(&mut self) { // Request the agent thread to shut down. if self.send_message(Message::Close).is_err() { - tracing::error!("agent thread terminated prematurely"); + error!("agent thread terminated prematurely"); } // Wait for the agent thread to shut down before continuing. match self.try_join() { - JoinResult::Ok => tracing::trace!("agent thread joined cleanly"), - JoinResult::Err(e) => tracing::error!("agent thread terminated with error: {}", e), - JoinResult::Panic => tracing::error!("agent thread panicked"), + JoinResult::Ok => trace!("agent thread joined cleanly"), + JoinResult::Err(e) => error!("agent thread terminated with error: {}", e), + JoinResult::Panic => error!("agent thread panicked"), _ => {} } } @@ -329,10 +330,15 @@ impl AgentContext { }) } - #[tracing::instrument(level = "trace", skip(self))] fn begin_request(&mut self, mut request: EasyHandle) -> Result<(), Error> { + let span = span!(TRACE, "begin_request", ?request); + enter_span!(span); + let id = request.get_ref().id(); + let request_span = request.get_ref().span().clone(); + let response_span = request.get_ref().span().clone(); + // Initialize the handler. request.get_mut().init( { @@ -342,7 +348,8 @@ impl AgentContext { .chain(move |inner| match tx.try_send(Message::UnpauseRead(id)) { Ok(()) => inner.wake_by_ref(), Err(_) => { - tracing::warn!(id, "agent went away while resuming read for request") + enter_span!(request_span); + warn!("agent went away while resuming read for request") } }) }, @@ -353,7 +360,8 @@ impl AgentContext { .chain(move |inner| match tx.try_send(Message::UnpauseWrite(id)) { Ok(()) => inner.wake_by_ref(), Err(_) => { - tracing::warn!(id, "agent went away while resuming write for request") + enter_span!(response_span); + warn!("agent went away while resuming write for request") } }) }, @@ -370,12 +378,14 @@ impl AgentContext { Ok(()) } - #[tracing::instrument(level = "trace", skip(self))] fn complete_request( &mut self, token: usize, result: Result<(), curl::Error>, ) -> Result<(), Error> { + let span = span!(TRACE, "complete_request", token, ?result); + enter_span!(span); + let handle = self.requests.remove(&token).unwrap(); let mut handle = self.multi.remove2(handle).map_err(Error::from_any)?; @@ -388,14 +398,16 @@ impl AgentContext { /// /// If there are no active requests right now, this function will block /// until a message is received. - #[tracing::instrument(level = "trace", skip(self))] fn poll_messages(&mut self) -> Result<(), Error> { + let span = span!(TRACE, "poll_messages"); + enter_span!(span); + while !self.close_requested { if self.requests.is_empty() { match block_on(self.message_rx.recv()) { Ok(message) => self.handle_message(message)?, _ => { - tracing::warn!("agent handle disconnected without close message"); + warn!("agent handle disconnected without close message"); self.close_requested = true; break; } @@ -405,7 +417,7 @@ impl AgentContext { Ok(message) => self.handle_message(message)?, Err(async_channel::TryRecvError::Empty) => break, Err(async_channel::TryRecvError::Closed) => { - tracing::warn!("agent handle disconnected without close message"); + warn!("agent handle disconnected without close message"); self.close_requested = true; break; } @@ -416,15 +428,18 @@ impl AgentContext { Ok(()) } - #[tracing::instrument(level = "trace", skip(self))] fn handle_message(&mut self, message: Message) -> Result<(), Error> { - tracing::trace!("received message from agent handle"); + let span = span!(TRACE, "handle_message", ?message); + enter_span!(span); + trace!("received message from agent handle"); match message { Message::Close => self.close_requested = true, Message::Execute(request) => self.begin_request(request)?, Message::UnpauseRead(token) => { if let Some(request) = self.requests.get(&token) { + enter_span!(request.get_ref().span()); + if let Err(e) = request.unpause_read() { // If unpausing returned an error, it is likely because // curl called our callback inline and the callback @@ -433,10 +448,10 @@ impl AgentContext { // the transfer alive until it errors through the normal // means, which is likely to happen this turn of the // event loop anyway. - tracing::debug!(id = token, "error unpausing read for request: {:?}", e); + debug!("error unpausing read for request: {:?}", e); } } else { - tracing::warn!( + warn!( "received unpause request for unknown request token: {}", token ); @@ -444,6 +459,8 @@ impl AgentContext { } Message::UnpauseWrite(token) => { if let Some(request) = self.requests.get(&token) { + enter_span!(request.get_ref().span()); + if let Err(e) = request.unpause_write() { // If unpausing returned an error, it is likely because // curl called our callback inline and the callback @@ -452,10 +469,10 @@ impl AgentContext { // the transfer alive until it errors through the normal // means, which is likely to happen this turn of the // event loop anyway. - tracing::debug!(id = token, "error unpausing write for request: {:?}", e); + debug!("error unpausing write for request: {:?}", e); } } else { - tracing::warn!( + warn!( "received unpause request for unknown request token: {}", token ); @@ -496,7 +513,7 @@ impl AgentContext { } } - tracing::debug!("agent shutting down"); + debug!("agent shutting down"); self.requests.clear(); @@ -517,7 +534,8 @@ impl AgentContext { if self.selector.poll(poll_timeout)? { // At least one I/O event occurred, handle them. for (socket, readable, writable) in self.selector.events() { - tracing::trace!(socket, readable, writable, "socket event"); + #[cfg(feature = "tracing")] + trace!(socket, readable, writable, "socket event"); let mut events = Events::new(); events.input(readable); events.output(writable); diff --git a/src/agent/selector.rs b/src/agent/selector.rs index 813e708f..be73a5e4 100644 --- a/src/agent/selector.rs +++ b/src/agent/selector.rs @@ -104,7 +104,11 @@ impl Selector { // hold onto this currently invalid socket for later. Whenever // `poll` is called, we retry registering these sockets in the // hope that they will eventually become valid. - tracing::debug!(socket, error = ?e, "bad socket registered, will try again later"); + #[cfg(feature = "tracing")] + debug!(socket, error = ?e, "bad socket registered, will try again later"); + #[cfg(not(feature = "tracing"))] + debug!("bad socket registered, will try again later: {:?}", e); + self.bad_sockets.insert(socket); Ok(()) } @@ -216,7 +220,7 @@ fn poller_add(poller: &Poller, socket: Socket, readable: bool, writable: bool) - readable, writable, }) { - tracing::debug!( + debug!( "failed to add interest for socket {}, retrying as a modify: {}", socket, e @@ -244,7 +248,7 @@ fn poller_modify( readable, writable, }) { - tracing::debug!( + debug!( "failed to modify interest for socket {}, retrying as an add: {}", socket, e diff --git a/src/client.rs b/src/client.rs index e7894b3c..d337a334 100644 --- a/src/client.rs +++ b/src/client.rs @@ -35,7 +35,6 @@ use std::{ task::{Context, Poll}, time::Duration, }; -use tracing_futures::Instrument; static USER_AGENT: Lazy = Lazy::new(|| { format!( @@ -910,7 +909,8 @@ impl HttpClient { where B: Into, { - let span = tracing::debug_span!( + let span = span!( + DEBUG, "send", method = ?request.method(), uri = ?request.uri(), @@ -925,7 +925,7 @@ impl HttpClient { }); let response = block_on( - async move { + instrument_span!(span, async move { // Instead of simply blocking the current thread until the response // is received, we can use the current thread to read from the // request body synchronously while concurrently waiting for the @@ -943,8 +943,7 @@ impl HttpClient { } else { self.send_async_inner(request).await } - } - .instrument(span), + }), )?; Ok(response.map(|body| body.into_sync())) @@ -1001,15 +1000,15 @@ impl HttpClient { where B: Into, { - let span = tracing::debug_span!( + let span = span!( + DEBUG, "send_async", method = ?request.method(), uri = ?request.uri(), ); ResponseFuture::new( - self.send_async_inner(request.map(Into::into)) - .instrument(span), + instrument_span!(span, self.send_async_inner(request.map(Into::into))) ) } diff --git a/src/cookies/interceptor.rs b/src/cookies/interceptor.rs index 408c066e..08bc483e 100644 --- a/src/cookies/interceptor.rs +++ b/src/cookies/interceptor.rs @@ -85,13 +85,13 @@ impl Interceptor for CookieInterceptor { .into_iter() .filter_map(|header| { header.to_str().ok().or_else(|| { - tracing::warn!("invalid encoding in Set-Cookie header"); + warn!("invalid encoding in Set-Cookie header"); None }) }) .filter_map(|header| { Cookie::parse(header).ok().or_else(|| { - tracing::warn!("could not parse Set-Cookie header"); + warn!("could not parse Set-Cookie header"); None }) }); diff --git a/src/cookies/jar.rs b/src/cookies/jar.rs index 46b92d64..9a3c9d72 100644 --- a/src/cookies/jar.rs +++ b/src/cookies/jar.rs @@ -134,7 +134,7 @@ impl CookieJar { let request_host = if let Some(host) = request_uri.host() { host } else { - tracing::warn!( + warn!( "cookie '{}' dropped, no domain specified in request URI", cookie.name() ); @@ -149,7 +149,7 @@ impl CookieJar { // The given domain must domain-match the origin. // https://tools.ietf.org/html/rfc6265#section-5.3.6 if !domain_matches(request_host, domain) { - tracing::warn!( + warn!( "cookie '{}' dropped, domain '{}' not allowed to set cookies for '{}'", cookie.name(), request_host, @@ -163,7 +163,7 @@ impl CookieJar { // Drop cookies for top-level domains. if !domain.contains('.') { - tracing::warn!( + warn!( "cookie '{}' dropped, setting cookies for domain '{}' is not allowed", cookie.name(), domain @@ -179,7 +179,7 @@ impl CookieJar { #[cfg(feature = "psl")] { if super::psl::is_public_suffix(domain) { - tracing::warn!( + warn!( "cookie '{}' dropped, setting cookies for domain '{}' is not allowed", cookie.name(), domain diff --git a/src/cookies/psl/mod.rs b/src/cookies/psl/mod.rs index e9c558f7..02d66e69 100644 --- a/src/cookies/psl/mod.rs +++ b/src/cookies/psl/mod.rs @@ -111,7 +111,7 @@ impl ListCache { // Parse the suffix list. self.list = response.text()?.parse()?; self.last_updated = Some(SystemTime::now()); - tracing::debug!("public suffix list updated"); + debug!("public suffix list updated"); } http::StatusCode::NOT_MODIFIED => { @@ -119,7 +119,7 @@ impl ListCache { self.last_updated = Some(SystemTime::now()); } - status => tracing::warn!( + status => warn!( "could not update public suffix list, got status code {}", status, ), @@ -157,7 +157,7 @@ fn refresh_in_background() { let mut cache = CACHE.write().unwrap(); if let Err(e) = cache.refresh() { - tracing::warn!("could not refresh public suffix list: {}", e); + warn!("could not refresh public suffix list: {}", e); } IS_REFRESHING.store(false, Ordering::SeqCst); diff --git a/src/handler.rs b/src/handler.rs index 9a21df83..9aba7a9f 100644 --- a/src/handler.rs +++ b/src/handler.rs @@ -54,7 +54,7 @@ pub(crate) struct RequestHandler { /// /// We enter and exit this span whenever curl invokes one of our callbacks /// to make progress on this request. - span: tracing::Span, + span: crate::log::Span, /// State shared by the handler and its future. shared: Arc, @@ -129,7 +129,7 @@ impl RequestHandler { let (response_body_reader, response_body_writer) = pipe::pipe(); let handler = Self { - span: tracing::debug_span!("handler", id = tracing::field::Empty), + span: span!(DEBUG, "handler", id = tracing::field::Empty), sender: Some(sender), shared: shared.clone(), request_body, @@ -166,8 +166,12 @@ impl RequestHandler { // Create a curl handle and populate remaining handler fields from it. let mut easy = Easy2::new(handler); easy.get_mut().handle = easy.raw(); - let id = easy.get_ref().id(); - easy.get_mut().span.record("id", &id); + + #[cfg(feature = "tracing")] + { + let id = easy.get_ref().id(); + easy.get_mut().span.record("id", &id); + } (easy, future) } @@ -191,11 +195,17 @@ impl RequestHandler { // // This logic seems a little screwy when comparing to what the docs say, // but it works. + #[cfg(feature = "tracing")] if self.span.is_none() { - false - } else { - log::log_enabled!(log::Level::Debug) + return false; } + + log::log_enabled!(log::Level::Debug) + } + + /// Get the tracing span that represents the lifetime of this request. + pub(crate) fn span(&self) -> &crate::log::Span { + &self.span } fn is_future_canceled(&self) -> bool { @@ -212,7 +222,7 @@ impl RequestHandler { request_waker: Waker, response_waker: Waker, ) { - let _enter = self.span.enter(); + enter_span!(self.span); // Init should not be called more than once. debug_assert!(self.request_body_waker.is_none()); @@ -237,7 +247,7 @@ impl RequestHandler { }); if self.shared.result.set(result).is_err() { - tracing::debug!("attempted to set error multiple times"); + debug!("attempted to set error multiple times"); } // Flush the trailer, if we haven't already. @@ -255,14 +265,14 @@ impl RequestHandler { if let Some(sender) = self.sender.take() { // If our request has already failed early with an error, return that instead. let result = if let Some(Err(e)) = self.shared.result.get() { - tracing::warn!("request completed with error: {}", e); + warn!("request completed with error: {}", e); Err(e.clone()) } else { Ok(self.build_response()) }; if sender.try_send(result).is_err() { - tracing::debug!("request canceled by user"); + debug!("request canceled by user"); } } } @@ -410,8 +420,7 @@ impl curl::easy::Handler for RequestHandler { return false; } - let span = tracing::trace_span!(parent: &self.span, "header"); - let _enter = span.enter(); + enter_span!(self.span); // If we already returned the response headers, then this header is from // the trailer. @@ -471,8 +480,7 @@ impl curl::easy::Handler for RequestHandler { return Err(ReadError::Abort); } - let span = tracing::trace_span!(parent: &self.span, "read"); - let _enter = span.enter(); + enter_span!(self.span); // Create a task context using a waker provided by the agent so we can // do an asynchronous read. @@ -483,7 +491,7 @@ impl curl::easy::Handler for RequestHandler { Poll::Pending => Err(ReadError::Pause), Poll::Ready(Ok(len)) => Ok(len), Poll::Ready(Err(e)) => { - tracing::error!("error reading request body: {}", e); + error!("error reading request body: {}", e); // While we could just return an error here to curl and let // the error bubble up through naturally, right now we have @@ -498,7 +506,7 @@ impl curl::easy::Handler for RequestHandler { } } else { // The request should never be started without calling init first. - tracing::error!("request has not been initialized!"); + error!("request has not been initialized!"); Err(ReadError::Abort) } } @@ -510,15 +518,14 @@ impl curl::easy::Handler for RequestHandler { /// seek, we can't do any async operations in this callback. That's why we /// only support trivial types of seeking. fn seek(&mut self, whence: io::SeekFrom) -> SeekResult { - let span = tracing::trace_span!(parent: &self.span, "seek", whence = ?whence); - let _enter = span.enter(); + enter_span!(self.span); // If curl wants to seek to the beginning, there's a chance that we // can do that. if whence == io::SeekFrom::Start(0) && self.request_body.reset() { SeekResult::Ok } else { - tracing::warn!("seek requested for request body, but it is not supported"); + warn!("seek requested for request body, but it is not supported"); // We can't do any other type of seek, sorry :( SeekResult::CantSeek } @@ -526,9 +533,8 @@ impl curl::easy::Handler for RequestHandler { /// Gets called by curl when bytes from the response body are received. fn write(&mut self, data: &[u8]) -> Result { - let span = tracing::trace_span!(parent: &self.span, "write"); - let _enter = span.enter(); - tracing::trace!("received {} bytes of data", data.len()); + enter_span!(self.span); + trace!("received {} bytes of data", data.len()); // Now that we've started receiving the response body, we know no more // redirects can happen and we can complete the future safely. @@ -548,22 +554,21 @@ impl curl::easy::Handler for RequestHandler { if !self.disable_connection_reuse_log && self.response_version < Some(http::Version::HTTP_2) { - tracing::info!( - "\ + info!("\ response dropped without fully consuming the response body, connection won't be reused\n\ Aborting a response without fully consuming the response body can result in sub-optimal \ performance. See https://github.com/sagebind/isahc/wiki/Connection-Reuse#closing-connections-early." ); } } else { - tracing::error!("error writing response body to buffer: {}", e); + error!("error writing response body to buffer: {}", e); } Ok(0) } } } else { // The request should never be started without calling init first. - tracing::error!("request has not been initialized!"); + error!("request has not been initialized!"); Ok(0) } } @@ -646,7 +651,7 @@ impl curl::easy::Handler for RequestHandler { /// Since we're using the log crate, this callback normalizes the debug info /// and writes it to our log. fn debug(&mut self, kind: InfoType, data: &[u8]) { - let _enter = self.span.enter(); + enter_span!(self.span); struct FormatAscii(T); @@ -661,13 +666,13 @@ impl curl::easy::Handler for RequestHandler { match kind { InfoType::Text => { - tracing::debug!("{}", String::from_utf8_lossy(data).trim_end()) + debug!("{}", String::from_utf8_lossy(data).trim_end()) } InfoType::HeaderIn | InfoType::DataIn => { - tracing::trace!(target: "isahc::wire", "<< {}", FormatAscii(data)) + trace!(target: "isahc::wire", "<< {}", FormatAscii(data)) } InfoType::HeaderOut | InfoType::DataOut => { - tracing::trace!(target: "isahc::wire", ">> {}", FormatAscii(data)) + trace!(target: "isahc::wire", ">> {}", FormatAscii(data)) } _ => (), } diff --git a/src/lib.rs b/src/lib.rs index e9813c90..7b1ceaa6 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -243,6 +243,9 @@ use std::convert::TryFrom; +#[macro_use] +mod log; + #[macro_use] mod macros; diff --git a/src/log.rs b/src/log.rs new file mode 100644 index 00000000..9d741125 --- /dev/null +++ b/src/log.rs @@ -0,0 +1,105 @@ +//! Logging facade that delegates to either the `log` crate or the `tracing` +//! crate depending on compile-time features. + +#[cfg(feature = "tracing")] +pub(crate) type Span = tracing::Span; + +#[cfg(not(feature = "tracing"))] +#[derive(Clone)] +pub(crate) struct Span; + +macro_rules! span { + ($level:ident, $($t:tt)+) => {{ + #[cfg(feature = "tracing")] + { + ::tracing::span!(::tracing::Level::$level, $($t)*) + } + + #[cfg(not(feature = "tracing"))] + { + $crate::log::Span + } + }}; +} + +macro_rules! span_follows_from_current { + ($span:expr) => {{ + #[cfg(feature = "tracing")] + $span.follows_from(::tracing::Span::current()); + }}; +} + +macro_rules! enter_span { + ($span:expr) => {{ + #[cfg(feature = "tracing")] + let _enter = $span.enter(); + + #[cfg(not(feature = "tracing"))] + let _enter = &$span; + }}; +} + +macro_rules! instrument_span { + ($span:expr, $future:expr) => {{ + #[cfg(feature = "tracing-futures")] + { + ::tracing_futures::Instrument::instrument($future, $span) + } + + #[cfg(not(feature = "tracing-futures"))] + { + let _span = $span; + $future + } + }}; +} + +macro_rules! error { + ($($t:tt)+) => {{ + #[cfg(feature = "tracing")] + ::tracing::error!($($t)*); + + #[cfg(not(feature = "tracing"))] + ::log::error!($($t)*); + }}; +} + +macro_rules! warn { + ($($t:tt)+) => {{ + #[cfg(feature = "tracing")] + ::tracing::warn!($($t)*); + + #[cfg(not(feature = "tracing"))] + ::log::warn!($($t)*); + }}; +} + +macro_rules! info { + ($($t:tt)+) => {{ + #[cfg(feature = "tracing")] + ::tracing::info!($($t)*); + + #[cfg(not(feature = "tracing"))] + ::log::info!($($t)*); + }}; +} + +macro_rules! debug { + ($($t:tt)+) => {{ + #[cfg(feature = "tracing")] + ::tracing::debug!($($t)*); + + #[cfg(not(feature = "tracing"))] + ::log::debug!($($t)*); + }}; +} + +macro_rules! trace { + ($($t:tt)+) => {{ + #[cfg(feature = "tracing")] + ::tracing::trace!($($t)*); + + #[cfg(not(feature = "tracing"))] + ::log::trace!($($t)*); + }}; +} diff --git a/src/redirect.rs b/src/redirect.rs index 21489e56..cbc7bb21 100644 --- a/src/redirect.rs +++ b/src/redirect.rs @@ -165,11 +165,11 @@ fn get_redirect_location(request_uri: &Uri, response: &Response) -> Option Ok(location) => match resolve(request_uri, location.as_ref()) { Ok(uri) => return Some(uri), Err(e) => { - tracing::debug!("invalid redirect location: {}", e); + debug!("invalid redirect location: {}", e); } }, Err(e) => { - tracing::debug!("invalid redirect location: {}", e); + debug!("invalid redirect location: {}", e); } } } diff --git a/src/text.rs b/src/text.rs index 946b463d..acb68e1d 100644 --- a/src/text.rs +++ b/src/text.rs @@ -67,7 +67,7 @@ impl Decoder { { return Self::new(encoding); } else { - tracing::warn!("unknown encoding '{}', falling back to UTF-8", charset); + warn!("unknown encoding '{}', falling back to UTF-8", charset); } } } diff --git a/src/trailer.rs b/src/trailer.rs index 70cad5f0..662a6baa 100644 --- a/src/trailer.rs +++ b/src/trailer.rs @@ -184,7 +184,7 @@ impl TrailerWriter { #[inline] pub(crate) fn flush(&mut self) { if !self.flush_impl() { - tracing::warn!("tried to flush trailer multiple times"); + warn!("tried to flush trailer multiple times"); } }