Skip to content

tracing: Instrument std::future::Future in tracing #808

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 16 commits into from
Sep 25, 2020
Merged
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 5 additions & 5 deletions README.md
Original file line number Diff line number Diff line change
@@ -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

6 changes: 3 additions & 3 deletions examples/examples/echo.rs
Original file line number Diff line number Diff line change
@@ -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<dyn Error + Send + Sync + 'static>> {
@@ -117,6 +116,7 @@ async fn main() -> Result<(), Box<dyn Error + Send + Sync + 'static>> {
info!(message = "echo'd data", %peer_addr, size = n);
}
})
.instrument(info_span!("echo", %peer_addr));
.instrument(info_span!("echo", %peer_addr))
.await?;
Comment on lines +119 to +120
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

whoopsy

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yup 😬

}
}
4 changes: 1 addition & 3 deletions examples/examples/futures-proxy-server.rs
Original file line number Diff line number Diff line change
@@ -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<dyn std::error::Error + Send + Sync + 'static>;

3 changes: 1 addition & 2 deletions examples/examples/hyper-echo.rs
Original file line number Diff line number Diff line change
@@ -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<Body>) -> Result<Response<Body>, hyper::Error> {
let span = span!(
3 changes: 1 addition & 2 deletions examples/examples/tokio-spawny-thing.rs
Original file line number Diff line number Diff line change
@@ -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<dyn std::error::Error + Send + Sync + 'static>;

3 changes: 1 addition & 2 deletions examples/examples/tower-load.rs
Original file line number Diff line number Diff line change
@@ -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};

1 change: 0 additions & 1 deletion tracing-attributes/Cargo.toml
Original file line number Diff line number Diff line change
@@ -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"
5 changes: 2 additions & 3 deletions tracing-attributes/src/lib.rs
Original file line number Diff line number Diff line change
@@ -189,7 +189,6 @@ use syn::{
/// }
/// ```
///
/// If `tracing_futures` is specified as a dependency in `Cargo.toml`,
/// `async fn`s may also be instrumented:
///
/// ```
@@ -443,7 +442,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) => {
@@ -456,7 +455,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
)
12 changes: 6 additions & 6 deletions tracing-futures/src/lib.rs
Original file line number Diff line number Diff line change
@@ -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()
2 changes: 1 addition & 1 deletion tracing-futures/tests/std_future.rs
Original file line number Diff line number Diff line change
@@ -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() {
4 changes: 2 additions & 2 deletions tracing-tower/src/request_span.rs
Original file line number Diff line number Diff line change
@@ -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<S, R, G = fn(&R) -> tracing::Span>
@@ -236,7 +236,7 @@ where
{
type Response = S::Response;
type Error = S::Error;
type Future = tracing_futures::Instrumented<S::Future>;
type Future = tracing::instrument::Instrumented<S::Future>;

fn poll_ready(&mut self, cx: &mut Context<'_>) -> Poll<Result<(), Self::Error>> {
self.inner.poll_ready(cx)
2 changes: 2 additions & 0 deletions tracing/Cargo.toml
Original file line number Diff line number Diff line change
@@ -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"
4 changes: 2 additions & 2 deletions tracing/README.md
Original file line number Diff line number Diff line change
@@ -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 {
// ...
194 changes: 194 additions & 0 deletions tracing/src/instrument.rs
Original file line number Diff line number Diff line change
@@ -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<Self> {
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> {
self.instrument(Span::current())
}
}

/// Extension trait allowing futures to be instrumented with
/// a `tracing` [`Subscriber`].
///
/// [`Subscriber`]: ../trait.Subscriber.html
pub trait WithSubscriber: Sized {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i'm on the fence about whether or not this needs to be in tracing proper. it isn't a whole lot of code, but I also think it's probably fine for it to stay in tracing-futures...

/// 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<S>(self, subscriber: S) -> WithDispatch<Self>
where
S: Into<Dispatch>,
{
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<Self> {
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<T> {
#[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<T> {
#[pin]
inner: T,
span: Span,
}
}

impl<T: Future> Future for Instrumented<T> {
type Output = T::Output;

fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
let this = self.project();
let _enter = this.span.enter();
this.inner.poll(cx)
}
}

impl<T: Sized> Instrument for T {}

impl<T> Instrumented<T> {
/// 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
}
}
13 changes: 4 additions & 9 deletions tracing/src/lib.rs
Original file line number Diff line number Diff line change
@@ -173,15 +173,6 @@
//! # fn main() {}
//! ```
//!
//! <div class="information">
//! <div class="tooltip ignore" style="">ⓘ<span class="tooltiptext">Note</span></div>
//! </div>
//! <div class="example-wrap" style="display:inline-block">
//! <pre class="ignore" style="white-space:normal;font:inherit;">
//! <strong>Note</strong>: Using <code>#[instrument]</code> on
//! <code>async fn</code>s requires the <a href="https://crates.io/crates/tracing-futures">
//! <code>tracing-futures</code> crate</a> as a dependency as well.
//! </pre></div>
//!
//! You can find more examples showing how to use this crate [here][examples].
//!
@@ -889,6 +880,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)]
@@ -913,6 +906,8 @@ mod macros;

pub mod dispatcher;
pub mod field;
/// Attach a span to a `std::future::Future`.
pub mod instrument;
Comment on lines +909 to +910
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

IDK if I really think this needs its own module, I might either reexport it from the root and make the instrument module hidden, or put it in the span module. but, i don't really care.

pub mod level_filters;
pub mod span;
pub(crate) mod stdlib;
14 changes: 6 additions & 8 deletions tracing/src/span.rs
Original file line number Diff line number Diff line change
@@ -619,16 +619,16 @@ 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.
///
/// `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