From a8cc977e01ec4e1dce4137e37cfc1bfba7ebbed8 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Fri, 25 Sep 2020 16:15:06 -0400 Subject: [PATCH] tracing: Instrument std::future::Future (#808) Authored-by: David Barsky Co-authored-by: Eliza Weisman --- README.md | 10 +- examples/examples/echo.rs | 6 +- examples/examples/futures-proxy-server.rs | 4 +- examples/examples/hyper-echo.rs | 3 +- examples/examples/tokio-spawny-thing.rs | 3 +- examples/examples/tower-load.rs | 3 +- tracing-attributes/Cargo.toml | 1 - tracing-attributes/src/lib.rs | 5 +- tracing-futures/src/lib.rs | 12 +- tracing-futures/tests/std_future.rs | 2 +- tracing-tower/src/request_span.rs | 4 +- tracing/Cargo.toml | 2 + tracing/README.md | 4 +- tracing/src/instrument.rs | 194 ++++++++++++++++++++++ tracing/src/lib.rs | 13 +- tracing/src/span.rs | 14 +- 16 files changed, 231 insertions(+), 49 deletions(-) create mode 100644 tracing/src/instrument.rs diff --git a/README.md b/README.md index a7837c589a..1c3057aeee 100644 --- a/README.md +++ b/README.md @@ -230,7 +230,7 @@ For more details, see [the documentation on closing spans][closing]. This problem can be solved using the [`Future::instrument`] combinator: ```rust -use tracing_futures::Instrument; +use tracing::Instrument; let my_future = async { // ... @@ -248,10 +248,10 @@ Under the hood, the `#[instrument]` macro performs same the explicit span attachment that `Future::instrument` does. [std-future]: https://doc.rust-lang.org/stable/std/future/trait.Future.html -[tracing-futures-docs]: https://docs.rs/tracing-futures -[closing]: https://docs.rs/tracing/latest/tracing/span/index.html#closing-spans -[`Future::instrument`]: https://docs.rs/tracing-futures/latest/tracing_futures/trait.Instrument.html#method.instrument -[instrument]: https://docs.rs/tracing/0.1.14/tracing/attr.instrument.html +[`tracing-futures`]: https://docs.rs/tracing-futures +[closing]: https://docs.rs/tracing/latest/span/index.html#closing-spans +[`Future::instrument`]: https://docs.rs/tracing/latest/tracing/trait.Instrument.html#method.instrument +[`#[instrument]`]: https://docs.rs/tracing/0.1.11/tracing/attr.instrument.html ## Supported Rust Versions diff --git a/examples/examples/echo.rs b/examples/examples/echo.rs index 380a224329..3edd63cef4 100644 --- a/examples/examples/echo.rs +++ b/examples/examples/echo.rs @@ -31,8 +31,7 @@ use std::env; use std::error::Error; use std::net::SocketAddr; -use tracing::{debug, info, info_span, trace_span, warn}; -use tracing_futures::Instrument; +use tracing::{debug, info, info_span, trace_span, warn, Instrument as _}; #[tokio::main] async fn main() -> Result<(), Box> { @@ -117,6 +116,7 @@ async fn main() -> Result<(), Box> { info!(message = "echo'd data", %peer_addr, size = n); } }) - .instrument(info_span!("echo", %peer_addr)); + .instrument(info_span!("echo", %peer_addr)) + .await?; } } diff --git a/examples/examples/futures-proxy-server.rs b/examples/examples/futures-proxy-server.rs index db289f3baf..1010a87441 100644 --- a/examples/examples/futures-proxy-server.rs +++ b/examples/examples/futures-proxy-server.rs @@ -32,9 +32,7 @@ use tokio::{ self, io, net::{TcpListener, TcpStream}, }; -use tracing::{debug, debug_span, info, warn}; -use tracing_attributes::instrument; -use tracing_futures::Instrument; +use tracing::{debug, debug_span, info, instrument, warn, Instrument as _}; type Error = Box; diff --git a/examples/examples/hyper-echo.rs b/examples/examples/hyper-echo.rs index dc318eabdc..3404a8d5e9 100644 --- a/examples/examples/hyper-echo.rs +++ b/examples/examples/hyper-echo.rs @@ -6,8 +6,7 @@ use hyper::{ Body, Server, }; use std::str; -use tracing::{debug, info, span, Level}; -use tracing_futures::Instrument; +use tracing::{debug, info, span, Instrument as _, Level}; async fn echo(req: Request) -> Result, hyper::Error> { let span = span!( diff --git a/examples/examples/tokio-spawny-thing.rs b/examples/examples/tokio-spawny-thing.rs index 845b82d3b1..b97318a79a 100644 --- a/examples/examples/tokio-spawny-thing.rs +++ b/examples/examples/tokio-spawny-thing.rs @@ -8,8 +8,7 @@ /// cargo run --example tokio-spawny-thing /// ``` use futures::future::try_join_all; -use tracing::{debug, info, instrument, span, Level}; -use tracing_futures::Instrument; +use tracing::{debug, info, instrument, span, Instrument as _, Level}; type Error = Box; diff --git a/examples/examples/tower-load.rs b/examples/examples/tower-load.rs index 71417de9bd..443f74ddf2 100644 --- a/examples/examples/tower-load.rs +++ b/examples/examples/tower-load.rs @@ -42,8 +42,7 @@ use std::{ }; use tokio::{time, try_join}; use tower::{Service, ServiceBuilder, ServiceExt}; -use tracing::{self, debug, error, info, span, trace, warn, Level, Span}; -use tracing_futures::Instrument; +use tracing::{self, debug, error, info, span, trace, warn, Instrument as _, Level, Span}; use tracing_subscriber::{filter::EnvFilter, reload::Handle}; use tracing_tower::{request_span, request_span::make}; diff --git a/tracing-attributes/Cargo.toml b/tracing-attributes/Cargo.toml index b8c525a0b7..2dae754a43 100644 --- a/tracing-attributes/Cargo.toml +++ b/tracing-attributes/Cargo.toml @@ -45,7 +45,6 @@ quote = "1" [dev-dependencies] tracing = { path = "../tracing", version = "0.1" } -tracing-futures = { path = "../tracing-futures", version = "0.2" } tokio-test = { version = "0.2.0" } tracing-core = { path = "../tracing-core", version = "0.1"} async-trait = "0.1" diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index c674095d3b..fd5f854a64 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -190,7 +190,6 @@ use syn::{ /// } /// ``` /// -/// If `tracing_futures` is specified as a dependency in `Cargo.toml`, /// `async fn`s may also be instrumented: /// /// ``` @@ -445,7 +444,7 @@ fn gen_body( if err { quote_spanned! {block.span()=> let __tracing_attr_span = #span; - tracing_futures::Instrument::instrument(async move { + tracing::Instrument::instrument(async move { match async move { #block }.await { Ok(x) => Ok(x), Err(e) => { @@ -458,7 +457,7 @@ fn gen_body( } else { quote_spanned!(block.span()=> let __tracing_attr_span = #span; - tracing_futures::Instrument::instrument( + tracing::Instrument::instrument( async move { #block }, __tracing_attr_span ) diff --git a/tracing-futures/src/lib.rs b/tracing-futures/src/lib.rs index 9dc1afb4b1..71bda8ed2d 100644 --- a/tracing-futures/src/lib.rs +++ b/tracing-futures/src/lib.rs @@ -110,8 +110,10 @@ pub(crate) mod stdlib; #[cfg(feature = "std-future")] use crate::stdlib::{pin::Pin, task::Context}; -use tracing::dispatcher; -use tracing::{Dispatch, Span}; +#[cfg(feature = "std")] +use tracing::{dispatcher, Dispatch}; + +use tracing::Span; /// Implementations for `Instrument`ed future executors. pub mod executor; @@ -673,8 +675,7 @@ mod tests { .drop_span(span::mock().named("foo")) .run_with_handle(); with_default(subscriber, || { - stream::iter(&[1, 2, 3]) - .instrument(tracing::trace_span!("foo")) + Instrument::instrument(stream::iter(&[1, 2, 3]), tracing::trace_span!("foo")) .for_each(|_| future::ready(())) .now_or_never() .unwrap(); @@ -694,8 +695,7 @@ mod tests { .drop_span(span::mock().named("foo")) .run_with_handle(); with_default(subscriber, || { - sink::drain() - .instrument(tracing::trace_span!("foo")) + Instrument::instrument(sink::drain(), tracing::trace_span!("foo")) .send(1u8) .now_or_never() .unwrap() diff --git a/tracing-futures/tests/std_future.rs b/tracing-futures/tests/std_future.rs index 5bc402cccb..a5431d37da 100644 --- a/tracing-futures/tests/std_future.rs +++ b/tracing-futures/tests/std_future.rs @@ -1,8 +1,8 @@ mod support; use support::*; +use tracing::Instrument; use tracing::{subscriber::with_default, Level}; -use tracing_futures::Instrument; #[test] fn enter_exit_is_reasonable() { diff --git a/tracing-tower/src/request_span.rs b/tracing-tower/src/request_span.rs index 9a04537c60..3c9ed61215 100644 --- a/tracing-tower/src/request_span.rs +++ b/tracing-tower/src/request_span.rs @@ -4,7 +4,7 @@ use futures::future::Future; use std::marker::PhantomData; use std::pin::Pin; use std::task::{Context, Poll}; -use tracing_futures::Instrument; +use tracing::Instrument; #[derive(Debug)] pub struct Service tracing::Span> @@ -236,7 +236,7 @@ where { type Response = S::Response; type Error = S::Error; - type Future = tracing_futures::Instrumented; + type Future = tracing::instrument::Instrumented; fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll> { self.inner.poll_ready(cx) diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml index 0454b8a41a..d326602497 100644 --- a/tracing/Cargo.toml +++ b/tracing/Cargo.toml @@ -31,11 +31,13 @@ tracing-core = { path = "../tracing-core", version = "0.1.15", default-features log = { version = "0.4", optional = true } tracing-attributes = { path = "../tracing-attributes", version = "0.1.10", optional = true } cfg-if = "0.1.10" +pin-project-lite = "0.1" [dev-dependencies] futures = "0.1" criterion = { version = "0.3", default_features = false } log = "0.4" +tokio = { version = "0.2.21", features = ["rt-core"] } [target.'cfg(target_arch = "wasm32")'.dev-dependencies] wasm-bindgen-test = "^0.3" diff --git a/tracing/README.md b/tracing/README.md index 9114168fe6..1492d31947 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -228,10 +228,10 @@ it is polled, leading to very confusing and incorrect output. For more details, see [the documentation on closing spans](https://tracing.rs/tracing/span/index.html#closing-spans). There are two ways to instrument asynchronous code. The first is through the -[`Future::instrument`](https://docs.rs/tracing-futures/0.2.0/tracing_futures/trait.Instrument.html#method.instrument) combinator: +[`Future::instrument`](https://docs.rs/tracing/latest/tracing/trait.Instrument.html#method.instrument) combinator: ```rust -use tracing_futures::Instrument; +use tracing::Instrument; let my_future = async { // ... diff --git a/tracing/src/instrument.rs b/tracing/src/instrument.rs new file mode 100644 index 0000000000..d1070ba8e2 --- /dev/null +++ b/tracing/src/instrument.rs @@ -0,0 +1,194 @@ +use crate::stdlib::pin::Pin; +use crate::stdlib::task::{Context, Poll}; +use crate::stdlib::{future::Future, marker::Sized}; +use crate::{dispatcher, span::Span, Dispatch}; +use pin_project_lite::pin_project; + +/// Attaches spans to a `std::future::Future`. +/// +/// Extension trait allowing futures to be +/// instrumented with a `tracing` [span]. +/// +/// [span]: ../struct.Span.html +pub trait Instrument: Sized { + /// Instruments this type with the provided `Span`, returning an + /// `Instrumented` wrapper. + /// + /// The attached `Span` will be [entered] every time the instrumented `Future` is polled. + /// + /// # Examples + /// + /// Instrumenting a future: + /// + /// ```rust + /// use tracing::Instrument; + /// + /// # async fn doc() { + /// let my_future = async { + /// // ... + /// }; + /// + /// my_future + /// .instrument(tracing::info_span!("my_future")) + /// .await + /// # } + /// ``` + /// + /// [entered]: ../struct.Span.html#method.enter + fn instrument(self, span: Span) -> Instrumented { + Instrumented { inner: self, span } + } + + /// Instruments this type with the [current] `Span`, returning an + /// `Instrumented` wrapper. + /// + /// If the instrumented type is a future, stream, or sink, the attached `Span` + /// will be [entered] every time it is polled. If the instrumented type + /// is a future executor, every future spawned on that executor will be + /// instrumented by the attached `Span`. + /// + /// This can be used to propagate the current span when spawning a new future. + /// + /// # Examples + /// + /// ```rust + /// use tracing::Instrument; + /// + /// # async fn doc() { + /// let span = tracing::info_span!("my_span"); + /// let _enter = span.enter(); + /// + /// // ... + /// + /// let future = async { + /// tracing::debug!("this event will occur inside `my_span`"); + /// // ... + /// }; + /// tokio::spawn(future.in_current_span()); + /// # } + /// ``` + /// + /// [current]: ../struct.Span.html#method.current + /// [entered]: ../struct.Span.html#method.enter + #[inline] + fn in_current_span(self) -> Instrumented { + self.instrument(Span::current()) + } +} + +/// Extension trait allowing futures to be instrumented with +/// a `tracing` [`Subscriber`]. +/// +/// [`Subscriber`]: ../trait.Subscriber.html +pub trait WithSubscriber: Sized { + /// Attaches the provided [`Subscriber`] to this type, returning a + /// `WithDispatch` wrapper. + /// + /// The attached subscriber will be set as the [default] when the returned `Future` is polled. + /// + /// [`Subscriber`]: ../trait.Subscriber.html + /// [default]: https://docs.rs/tracing/latest/tracing/dispatcher/index.html#setting-the-default-subscriber + fn with_subscriber(self, subscriber: S) -> WithDispatch + where + S: Into, + { + WithDispatch { + inner: self, + dispatch: subscriber.into(), + } + } + + /// Attaches the current [default] [`Subscriber`] to this type, returning a + /// `WithDispatch` wrapper. + /// + /// When the wrapped type is a future, stream, or sink, the attached + /// subscriber will be set as the [default] while it is being polled. + /// When the wrapped type is an executor, the subscriber will be set as the + /// default for any futures spawned on that executor. + /// + /// This can be used to propagate the current dispatcher context when + /// spawning a new future. + /// + /// [`Subscriber`]: ../trait.Subscriber.html + /// [default]: https://docs.rs/tracing/latest/tracing/dispatcher/index.html#setting-the-default-subscriber + #[inline] + fn with_current_subscriber(self) -> WithDispatch { + WithDispatch { + inner: self, + dispatch: dispatcher::get_default(|default| default.clone()), + } + } +} + +pin_project! { + /// A future that has been instrumented with a `tracing` subscriber. + #[derive(Clone, Debug)] + #[must_use = "futures do nothing unless you `.await` or poll them"] + pub struct WithDispatch { + #[pin] + inner: T, + dispatch: Dispatch, + } +} + +pin_project! { + /// A future that has been instrumented with a `tracing` span. + #[derive(Debug, Clone)] + #[must_use = "futures do nothing unless you `.await` or poll them"] + pub struct Instrumented { + #[pin] + inner: T, + span: Span, + } +} + +impl Future for Instrumented { + type Output = T::Output; + + fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll { + let this = self.project(); + let _enter = this.span.enter(); + this.inner.poll(cx) + } +} + +impl Instrument for T {} + +impl Instrumented { + /// Borrows the `Span` that this type is instrumented by. + pub fn span(&self) -> &Span { + &self.span + } + + /// Mutably borrows the `Span` that this type is instrumented by. + pub fn span_mut(&mut self) -> &mut Span { + &mut self.span + } + + /// Borrows the wrapped type. + pub fn inner(&self) -> &T { + &self.inner + } + + /// Mutably borrows the wrapped type. + pub fn inner_mut(&mut self) -> &mut T { + &mut self.inner + } + + /// Get a pinned reference to the wrapped type. + pub fn inner_pin_ref(self: Pin<&Self>) -> Pin<&T> { + self.project_ref().inner + } + + /// Get a pinned mutable reference to the wrapped type. + pub fn inner_pin_mut(self: Pin<&mut Self>) -> Pin<&mut T> { + self.project().inner + } + + /// Consumes the `Instrumented`, returning the wrapped type. + /// + /// Note that this drops the span. + pub fn into_inner(self) -> T { + self.inner + } +} diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index ea6e1fb5a8..86123324b1 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -173,15 +173,6 @@ //! # fn main() {} //! ``` //! -//!
-//!
ⓘNote
-//!
-//!
-//! 
-//!     Note: Using #[instrument] on
-//!     async fns requires the 
-//!     tracing-futures crate as a dependency as well.
-//!
//! //! You can find more examples showing how to use this crate [here][examples]. //! @@ -890,6 +881,8 @@ pub use log; #[doc(hidden)] use tracing_core::*; +#[doc(inline)] +pub use self::instrument::Instrument; pub use self::{dispatcher::Dispatch, event::Event, field::Value, subscriber::Subscriber}; #[doc(hidden)] @@ -914,6 +907,8 @@ mod macros; pub mod dispatcher; pub mod field; +/// Attach a span to a `std::future::Future`. +pub mod instrument; pub mod level_filters; pub mod span; pub(crate) mod stdlib; diff --git a/tracing/src/span.rs b/tracing/src/span.rs index 574dd7e3a3..03768fd626 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -619,8 +619,8 @@ impl Span { /// // ... /// } /// ``` - /// * For instrumenting asynchronous code, the [`tracing-futures` crate] - /// provides the [`Future::instrument` combinator][instrument] for + /// * For instrumenting asynchronous code, `tracing` provides the + /// [`Future::instrument` combinator][instrument] for /// attaching a span to a future (async function or block). This will /// enter the span _every_ time the future is polled, and exit it whenever /// the future yields. @@ -628,7 +628,7 @@ impl Span { /// `Instrument` can be used with an async block inside an async function: /// ```ignore /// # use tracing::info_span; - /// use tracing_futures::Instrument; + /// use tracing::Instrument; /// /// # async fn some_other_async_function() {} /// async fn my_async_function() { @@ -652,7 +652,7 @@ impl Span { /// callsite: /// ```ignore /// # use tracing::debug_span; - /// use tracing_futures::Instrument; + /// use tracing::Instrument; /// /// # async fn some_other_async_function() {} /// async fn my_async_function() { @@ -664,8 +664,7 @@ impl Span { /// } /// ``` /// - /// * Finally, if your crate depends on the `tracing-futures` crate, the - /// [`#[instrument]` attribute macro][attr] will automatically generate + /// * The [`#[instrument]` attribute macro][attr] can automatically generate /// correct code when used on an async function: /// /// ```ignore @@ -684,8 +683,7 @@ impl Span { /// /// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html /// [`Span::in_scope`]: #method.in_scope - /// [`tracing-futures` crate]: https://docs.rs/tracing-futures/ - /// [instrument]: https://docs.rs/tracing-futures/latest/tracing_futures/trait.Instrument.html + /// [instrument]: https://docs.rs/tracing/latest/tracing/trait.Instrument.html /// [attr]: ../../attr.instrument.html /// /// # Examples