itsscb/tracing
1
0
Fork 0
mirror of https://github.com/tokio-rs/tracing.git synced 2025-10-02 15:24:47 +00:00
Code Issues Packages Projects Releases Wiki Activity

tracing: Instrument std::future::Future (#808)

Browse Source 
Authored-by: David Barsky <dbarsky@amazon.com>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
This commit is contained in:
David Barsky 2020-09-25 16:15:06 -04:00 committed by GitHub
parent 216b98edc7
commit a8cc977e01
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
16 changed files with 231 additions and 49 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

10
README.md
View File

@ -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
examples/examples/echo.rs
View File

@ -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?;
}
}

4
examples/examples/futures-proxy-server.rs
View File

@ -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
examples/examples/hyper-echo.rs
View File

@ -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
examples/examples/tokio-spawny-thing.rs
View File

@ -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
examples/examples/tower-load.rs
View File

@ -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
tracing-attributes/Cargo.toml
View File

@ -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
tracing-attributes/src/lib.rs
View File

@ -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
)

12
tracing-futures/src/lib.rs
View File

@ -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
tracing-futures/tests/std_future.rs
View File

@ -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
tracing-tower/src/request_span.rs
View File

@ -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
tracing/Cargo.toml
View File

@ -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
tracing/README.md
View File

@ -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
tracing/src/instrument.rs Normal file
View File

@ -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 {
/// 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
tracing/src/lib.rs
View File

@ -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].
//!
@ -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;

14
tracing/src/span.rs
View File

@ -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