tokio-rs/tokio
1
0
Fork 0
mirror of https://github.com/tokio-rs/tokio.git synced 2026-09-07 00:00:08 +02:00
Code Issues Packages Projects Releases Wiki Activity

trace: Change Span::enter to return a guard, add Span::in_scope (#1076)

Browse Source 
## Motivation

Currently, the primary way to use a span is to use `.enter` and pass a
closure to be executed under the span. While that is convenient in many
settings, it also comes with two decently inconvenient drawbacks:

 - It breaks control flow statements like `return`, `?`, `break`, and
   `continue`
 - It require re-indenting a potentially large chunk of code if you wish
   it to appear under a span

## Solution

This branch changes the `Span::enter` function to return a scope guard 
that exits the span when dropped, as in:
```rust
let guard = span.enter();

// code here is within the span

drop(guard);

// code here is no longer within the span
```
The method previously called `enter`, which takes a closure and 
executes it in the span's context, is now called `Span::in_scope`, and
was reimplemented on top of the new `enter` method. 

This is a breaking change to `tokio-trace` that will be part of the
upcoming 0.2 release.

Closes #1075 

Signed-off-by: Eliza Weisman <[email protected]>
This commit is contained in:
Eliza Weisman
2019-05-24 15:24:13 -07:00
committed by GitHub
parent 1b498e8aa2
commit 84d5a7f5a0
12 changed files with 284 additions and 131 deletions
Download Patch File Download Diff File Expand all files Collapse all files
tokio-trace/README.md
+2 -2
View File
@@ -56,7 +56,7 @@ to indicate that some code takes place within the context of that `Span`:
```rust ```rust
// Construct a new span named "my span". // Construct a new span named "my span".
let mut span = span!("my span"); let mut span = span!("my span");
span.enter(|| { span.in_scope(|| {
// Any trace events in this closure or code called by it will occur within // Any trace events in this closure or code called by it will occur within
// the span. // the span.
}); });
@@ -88,7 +88,7 @@ use tokio_trace::field;
pub fn shave_the_yak(yak: &mut Yak) { pub fn shave_the_yak(yak: &mut Yak) {
// Create a new span for this invocation of `shave_the_yak`, annotated // Create a new span for this invocation of `shave_the_yak`, annotated
// with the yak being shaved as a *field* on the span. // with the yak being shaved as a *field* on the span.
span!("shave_the_yak", yak = field::debug(&yak)).enter(|| { span!("shave_the_yak", yak = field::debug(&yak)).in_scope(|| {
// Since the span is annotated with the yak, it is part of the context // Since the span is annotated with the yak, it is part of the context
// for everything happening inside the span. Therefore, we don't need // for everything happening inside the span. Therefore, we don't need
// to add it to the message for this event, as the `log` crate does. // to add it to the message for this event, as the `log` crate does.
tokio-trace/benches/subscriber.rs
+1 -1
View File
@@ -107,7 +107,7 @@ fn span_no_fields(b: &mut Bencher) {
fn enter_span(b: &mut Bencher) { fn enter_span(b: &mut Bencher) {
tokio_trace::subscriber::with_default(EnabledSubscriber, || { tokio_trace::subscriber::with_default(EnabledSubscriber, || {
let span = span!(Level::TRACE, "span"); let span = span!(Level::TRACE, "span");
b.iter(|| test::black_box(span.enter(|| {}))) b.iter(|| test::black_box(span.in_scope(|| {})))
}); });
} }
tokio-trace/examples/counters.rs
+2 -2
View File
@@ -125,7 +125,7 @@ fn main() {
tokio_trace::subscriber::with_default(subscriber, || { tokio_trace::subscriber::with_default(subscriber, || {
let mut foo: u64 = 2; let mut foo: u64 = 2;
span!(Level::TRACE, "my_great_span", foo_count = &foo).enter(|| { span!(Level::TRACE, "my_great_span", foo_count = &foo).in_scope(|| {
foo += 1; foo += 1;
info!({ yak_shaved = true, yak_count = 1 }, "hi from inside my span"); info!({ yak_shaved = true, yak_count = 1 }, "hi from inside my span");
span!( span!(
@@ -134,7 +134,7 @@ fn main() {
foo_count = &foo, foo_count = &foo,
baz_count = 5 baz_count = 5
) )
.enter(|| { .in_scope(|| {
warn!({ yak_shaved = false, yak_count = -1 }, "failed to shave yak"); warn!({ yak_shaved = false, yak_count = -1 }, "failed to shave yak");
}); });
}); });
tokio-trace/examples/sloggish/main.rs
+6 -6
View File
@@ -22,25 +22,25 @@ fn main() {
let subscriber = SloggishSubscriber::new(2); let subscriber = SloggishSubscriber::new(2);
tokio_trace::subscriber::with_default(subscriber, || { tokio_trace::subscriber::with_default(subscriber, || {
span!(Level::TRACE, "", version = &field::display(5.0)).enter(|| { span!(Level::TRACE, "", version = &field::display(5.0)).in_scope(|| {
span!(Level::TRACE, "server", host = "localhost", port = 8080).enter(|| { span!(Level::TRACE, "server", host = "localhost", port = 8080).in_scope(|| {
info!("starting"); info!("starting");
info!("listening"); info!("listening");
let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381); let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381);
peer1.enter(|| { peer1.in_scope(|| {
debug!("connected"); debug!("connected");
debug!({ length = 2 }, "message received"); debug!({ length = 2 }, "message received");
}); });
let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230); let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230);
peer2.enter(|| { peer2.in_scope(|| {
debug!("connected"); debug!("connected");
}); });
peer1.enter(|| { peer1.in_scope(|| {
warn!({ algo = "xor" }, "weak encryption requested"); warn!({ algo = "xor" }, "weak encryption requested");
debug!({ length = 8 }, "response sent"); debug!({ length = 8 }, "response sent");
debug!("disconnected"); debug!("disconnected");
}); });
peer2.enter(|| { peer2.in_scope(|| {
debug!({ length = 5 }, "message received"); debug!({ length = 5 }, "message received");
debug!({ length = 8 }, "response sent"); debug!({ length = 8 }, "response sent");
debug!("disconnected"); debug!("disconnected");
tokio-trace/src/lib.rs
+60 -45
View File
@@ -43,8 +43,22 @@
//! use tokio_trace::Level; //! use tokio_trace::Level;
//! //!
//! # fn main() { //! # fn main() {
//! span!(Level::TRACE, "my_span").enter(|| { //! let span = span!(Level::TRACE, "my_span");
//! // perform some work in the context of `my_span`... //! let _enter = span.enter();
//! // perform some work in the context of `my_span`...
//! # }
//!```
//!
//! The [`in_scope`] method may be used to execute a closure inside a
//! span:
//!
//! ```
//! # #[macro_use] extern crate tokio_trace;
//! # use tokio_trace::Level;
//! # fn main() {
//! # let span = span!(Level::TRACE, "my_span");
//! span.in_scope(|| {
//! // perform some more work in the context of `my_span`...
//! }); //! });
//! # } //! # }
//!``` //!```
@@ -61,13 +75,13 @@
//! # use tokio_trace::Level; //! # use tokio_trace::Level;
//! # fn main() { //! # fn main() {
//! // this span is considered the "root" of a new trace tree: //! // this span is considered the "root" of a new trace tree:
//! span!(Level::INFO, "root").enter(|| { //! span!(Level::INFO, "root").in_scope(|| {
//! // since we are now inside "root", this span is considered a child //! // since we are now inside "root", this span is considered a child
//! // of "root": //! // of "root":
//! span!(Level::DEBUG, "outer_child").enter(|| { //! span!(Level::DEBUG, "outer_child").in_scope(|| {
//! // this span is a child of "outer_child", which is in turn a //! // this span is a child of "outer_child", which is in turn a
//! // child of "root": //! // child of "root":
//! span!(Level::TRACE, "inner_child").enter(|| { //! span!(Level::TRACE, "inner_child").in_scope(|| {
//! // and so on... //! // and so on...
//! }); //! });
//! }); //! });
@@ -143,12 +157,12 @@
//! # use tokio_trace::Level; //! # use tokio_trace::Level;
//! # fn main() { //! # fn main() {
//! # let n = 1; //! # let n = 1;
//! span!(Level::TRACE, "my loop").enter(|| { //! let span = span!(Level::TRACE, "my_loop");
//! for i in 0..n { //! let _enter = span.enter();
//! # let _ = i; //! for i in 0..n {
//! // ... //! # let _ = i;
//! } //! // ...
//! }) //! }
//! # } //! # }
//! ``` //! ```
//! Or, should we create a new span for each iteration of the loop, as in: //! Or, should we create a new span for each iteration of the loop, as in:
@@ -158,10 +172,9 @@
//! # fn main() { //! # fn main() {
//! # let n = 1u64; //! # let n = 1u64;
//! for i in 0..n { //! for i in 0..n {
//! # let _ = i; //! let span = span!(Level::TRACE, "my_loop", iteration = i);
//! span!(Level::TRACE, "my loop", iteration = i).enter(|| { //! let _enter = span.enter();
//! // ... //! // ...
//! })
//! } //! }
//! # } //! # }
//! ``` //! ```
@@ -189,7 +202,7 @@
//! // records an event outside of any span context: //! // records an event outside of any span context:
//! event!(Level::INFO, "something happened"); //! event!(Level::INFO, "something happened");
//! //!
//! span!(Level::INFO, "my_span").enter(|| { //! span!(Level::INFO, "my_span").in_scope(|| {
//! // records an event within "my_span". //! // records an event within "my_span".
//! event!(Level::DEBUG, "something happened inside my_span"); //! event!(Level::DEBUG, "something happened inside my_span");
//! }); //! });
@@ -257,11 +270,14 @@
//! # fn main() { //! # fn main() {
//! // Construct a new span named "my span" with trace log level. //! // Construct a new span named "my span" with trace log level.
//! let span = span!(Level::TRACE, "my span"); //! let span = span!(Level::TRACE, "my span");
//! span.enter(|| { //!
//! // Any trace events in this closure or code called by it will occur within //! // Enter the span, returning a guard object.
//! // the span. //! let _enter = span.enter();
//! }); //!
//! // Dropping the span will close it, indicating that it has ended. //! // Any trace events that occur before the guard is dropped will occur
//! // within the span.
//!
//! // Dropping the guard will exit the span.
//! # } //! # }
//! ``` //! ```
//! //!
@@ -295,32 +311,30 @@
//! # fn find_a_razor() -> Result<u32, u32> { Ok(1) } //! # fn find_a_razor() -> Result<u32, u32> { Ok(1) }
//! # fn main() { //! # fn main() {
//! pub fn shave_the_yak(yak: &mut Yak) { //! pub fn shave_the_yak(yak: &mut Yak) {
//! // Create a new span for this invocation of `shave_the_yak`, annotated //! let span = span!(Level::TRACE, "shave_the_yak", yak = ?yak);
//! // with the yak being shaved as a *field* on the span. //! let _enter = span.enter();
//! span!(Level::TRACE, "shave_the_yak", yak = ?yak).enter(|| {
//! // Since the span is annotated with the yak, it is part of the context
//! // for everything happening inside the span. Therefore, we don't need
//! // to add it to the message for this event, as the `log` crate does.
//! info!(target: "yak_events", "Commencing yak shaving");
//! //!
//! loop { //! // Since the span is annotated with the yak, it is part of the context
//! match find_a_razor() { //! // for everything happening inside the span. Therefore, we don't need
//! Ok(razor) => { //! // to add it to the message for this event, as the `log` crate does.
//! // We can add the razor as a field rather than formatting it //! info!(target: "yak_events", "Commencing yak shaving");
//! // as part of the message, allowing subscribers to consume it //! loop {
//! // in a more structured manner: //! match find_a_razor() {
//! info!({ razor = %razor }, "Razor located"); //! Ok(razor) => {
//! yak.shave(razor); //! // We can add the razor as a field rather than formatting it
//! break; //! // as part of the message, allowing subscribers to consume it
//! } //! // in a more structured manner:
//! Err(err) => { //! info!({ razor = %razor }, "Razor located");
//! // However, we can also create events with formatted messages, //! yak.shave(razor);
//! // just as we would for log records. //! break;
//! warn!("Unable to locate a razor: {}, retrying", err); //! }
//! } //! Err(err) => {
//! // However, we can also create events with formatted messages,
//! // just as we would for log records.
//! warn!("Unable to locate a razor: {}, retrying", err);
//! } //! }
//! } //! }
//! }) //! }
//! } //! }
//! # } //! # }
//! ``` //! ```
@@ -414,7 +428,8 @@
//! ``` //! ```
//! //!
//! [`log`]: https://docs.rs/log/0.4.6/log/ //! [`log`]: https://docs.rs/log/0.4.6/log/
//! [`Span`]: span/struct.Span //! [`Span`]: span/struct.Span.html
//! [`in_scope`]: span/struct.Span.html#method.in_scope
//! [`Event`]: struct.Event.html //! [`Event`]: struct.Event.html
//! [`Subscriber`]: subscriber/trait.Subscriber.html //! [`Subscriber`]: subscriber/trait.Subscriber.html
//! [`observe_event`]: subscriber/trait.Subscriber.html#tymethod.observe_event //! [`observe_event`]: subscriber/trait.Subscriber.html#tymethod.observe_event
tokio-trace/src/macros.rs
+7 -7
View File
@@ -9,7 +9,7 @@
/// # use tokio_trace::Level; /// # use tokio_trace::Level;
/// # fn main() { /// # fn main() {
/// let span = span!(Level::TRACE, "my span"); /// let span = span!(Level::TRACE, "my span");
/// span.enter(|| { /// span.in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
@@ -21,7 +21,7 @@
/// # extern crate tokio_trace; /// # extern crate tokio_trace;
/// # use tokio_trace::Level; /// # use tokio_trace::Level;
/// # fn main() { /// # fn main() {
/// span!(Level::TRACE, "my span", foo = 2, bar = "a string").enter(|| { /// span!(Level::TRACE, "my span", foo = 2, bar = "a string").in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
@@ -240,7 +240,7 @@ macro_rules! span {
/// # extern crate tokio_trace; /// # extern crate tokio_trace;
/// # fn main() { /// # fn main() {
/// let span = trace_span!("my span"); /// let span = trace_span!("my span");
/// span.enter(|| { /// span.in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
@@ -301,7 +301,7 @@ macro_rules! trace_span {
/// # extern crate tokio_trace; /// # extern crate tokio_trace;
/// # fn main() { /// # fn main() {
/// let span = debug_span!("my span"); /// let span = debug_span!("my span");
/// span.enter(|| { /// span.in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
@@ -362,7 +362,7 @@ macro_rules! debug_span {
/// # extern crate tokio_trace; /// # extern crate tokio_trace;
/// # fn main() { /// # fn main() {
/// let span = info_span!("my span"); /// let span = info_span!("my span");
/// span.enter(|| { /// span.in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
@@ -423,7 +423,7 @@ macro_rules! info_span {
/// # extern crate tokio_trace; /// # extern crate tokio_trace;
/// # fn main() { /// # fn main() {
/// let span = warn_span!("my span"); /// let span = warn_span!("my span");
/// span.enter(|| { /// span.in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
@@ -483,7 +483,7 @@ macro_rules! warn_span {
/// # extern crate tokio_trace; /// # extern crate tokio_trace;
/// # fn main() { /// # fn main() {
/// let span = error_span!("my span"); /// let span = error_span!("my span");
/// span.enter(|| { /// span.in_scope(|| {
/// // do work inside the span... /// // do work inside the span...
/// }); /// });
/// # } /// # }
tokio-trace/src/span.rs
+155 -35
View File
@@ -4,12 +4,10 @@
//! //!
//! A thread of execution is said to _enter_ a span when it begins executing, //! A thread of execution is said to _enter_ a span when it begins executing,
//! and _exit_ the span when it switches to another context. Spans may be //! and _exit_ the span when it switches to another context. Spans may be
//! entered through the [`enter`] method, which enters the target span, //! entered through the [`enter`] and [`in_scope`] methods.
//! performs a given function (either a closure or a function pointer), exits
//! the span, and then returns the result.
//! //!
//! Calling `enter` on a span handle enters the span that handle corresponds to, //! The `enter` method enters a span, returning a [guard] that exits the span
//! if the span exists: //! when dropped
//! ``` //! ```
//! # #[macro_use] extern crate tokio_trace; //! # #[macro_use] extern crate tokio_trace;
//! # use tokio_trace::Level; //! # use tokio_trace::Level;
@@ -17,18 +15,36 @@
//! let my_var: u64 = 5; //! let my_var: u64 = 5;
//! let my_span = span!(Level::TRACE, "my_span", my_var = &my_var); //! let my_span = span!(Level::TRACE, "my_span", my_var = &my_var);
//! //!
//! my_span.enter(|| { //! // `my_span` exists but has not been entered.
//!
//! let _enter = my_span.enter();
//!
//! // Perform some work inside of the context of `my_span`...
//! # }
//!```
//!
//! `in_scope` takes a closure or function pointer and executes it inside the
//! span.
//! ```
//! # #[macro_use] extern crate tokio_trace;
//! # use tokio_trace::Level;
//! # fn main() {
//! let my_var: u64 = 5;
//! let my_span = span!(Level::TRACE, "my_span", my_var = &my_var);
//!
//! my_span.in_scope(|| {
//! // perform some work in the context of `my_span`... //! // perform some work in the context of `my_span`...
//! }); //! });
//! //!
//! // Perform some work outside of the context of `my_span`... //! // Perform some work outside of the context of `my_span`...
//! //!
//! my_span.enter(|| { //! my_span.in_scope(|| {
//! // Perform some more work in the context of `my_span`. //! // Perform some more work in the context of `my_span`.
//! }); //! });
//! # } //! # }
//! ``` //! ```
//! //!
//!
//! # The Span Lifecycle //! # The Span Lifecycle
//! //!
//! Execution may enter and exit a span multiple times before that //! Execution may enter and exit a span multiple times before that
@@ -48,7 +64,7 @@
//! type Error = (); //! type Error = ();
//! //!
//! fn poll(&mut self) -> Poll<Self::Item, Self::Error> { //! fn poll(&mut self) -> Poll<Self::Item, Self::Error> {
//! self.span.enter(|| { //! self.span.in_scope(|| {
//! // Do actual future work //! // Do actual future work
//! # Ok(Async::Ready(())) //! # Ok(Async::Ready(()))
//! }) //! })
@@ -81,7 +97,7 @@
//! # use tokio_trace::Level; //! # use tokio_trace::Level;
//! # fn main() { //! # fn main() {
//! { //! {
//! span!(Level::TRACE, "my_span").enter(|| { //! span!(Level::TRACE, "my_span").in_scope(|| {
//! // perform some work in the context of `my_span`... //! // perform some work in the context of `my_span`...
//! }); // --> Subscriber::exit(my_span) //! }); // --> Subscriber::exit(my_span)
//! //!
@@ -116,6 +132,8 @@
//! [`Subscriber`]: ../subscriber/trait.Subscriber.html //! [`Subscriber`]: ../subscriber/trait.Subscriber.html
//! [`Attributes`]: struct.Attributes.html //! [`Attributes`]: struct.Attributes.html
//! [`enter`]: struct.Span.html#method.enter //! [`enter`]: struct.Span.html#method.enter
//! [`in_scope`]: struct.Span.html#method.in_scope
//! [`guard`]: struct.Entered.html
pub use tokio_trace_core::span::{Attributes, Id, Record}; pub use tokio_trace_core::span::{Attributes, Id, Record};
use std::{ use std::{
@@ -166,15 +184,15 @@ pub(crate) struct Inner {
/// A guard representing a span which has been entered and is currently /// A guard representing a span which has been entered and is currently
/// executing. /// executing.
/// ///
/// This guard may be used to exit the span, returning an `Enter` to /// When the guard is dropped, the span will be exited.
/// re-enter it.
/// ///
/// This type is primarily used for implementing span handles; users should /// This is returned by the [`Span::enter`] function.
/// typically not need to interact with it directly. ///
/// [`Span::enter`]: ../struct.Span.html#method.enter
#[derive(Debug)] #[derive(Debug)]
#[must_use = "once a span has been entered, it should be exited"] #[must_use = "once a span has been entered, it should be exited"]
struct Entered<'a> { pub struct Entered<'a> {
inner: &'a Inner, span: &'a Span,
} }
// ===== impl Span ===== // ===== impl Span =====
@@ -254,20 +272,131 @@ impl Span {
span span
} }
/// Enters this span, returning a guard that will exit the span when dropped.
///
/// If this span is enabled by the current subscriber, then this function will
/// call [`Subscriber::enter`] with the span's [`Id`], and dropping the guard
/// will call [`Subscriber::exit`]. If the span is disabled, this does nothing.
///
/// # Examples
///
/// ```
/// #[macro_use] extern crate tokio_trace;
/// # use tokio_trace::Level;
/// # fn main() {
/// let span = span!(Level::INFO, "my_span");
/// let guard = span.enter();
///
/// // code here is within the span
///
/// drop(guard);
///
/// // code here is no longer within the span
///
/// # }
/// ```
///
/// Guards need not be explicitly dropped:
///
/// ```
/// #[macro_use] extern crate tokio_trace;
/// # fn main() {
/// fn my_function() -> String {
/// // enter a span for the duration of this function.
/// let span = trace_span!("my_function");
/// let _enter = span.enter();
///
/// // anything happening in functions we call is still inside the span...
/// my_other_function();
///
/// // returning from the function drops the guard, exiting the span.
/// return "Hello world".to_owned();
/// }
///
/// fn my_other_function() {
/// // ...
/// }
/// # }
/// ```
///
/// Sub-scopes may be created to limit the duration for which the span is
/// entered:
///
/// ```
/// #[macro_use] extern crate tokio_trace;
/// # fn main() {
/// let span = info_span!("my_great_span");
///
/// {
/// let _enter = span.enter();
///
/// // this event occurs inside the span.
/// info!("i'm in the span!");
///
/// // exiting the scope drops the guard, exiting the span.
/// }
///
/// // this event is not inside the span.
/// info!("i'm outside the span!")
/// # }
/// ```
///
/// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
/// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
/// [`Id`]: ../struct.Id.html
pub fn enter<'a>(&'a self) -> Entered<'a> {
if let Some(ref inner) = self.inner.as_ref() {
inner.subscriber.enter(&inner.id);
}
self.log(format_args!("-> {}", self.meta.name));
Entered { span: self }
}
/// Executes the given function in the context of this span. /// Executes the given function in the context of this span.
/// ///
/// If this span is enabled, then this function enters the span, invokes /// If this span is enabled, then this function enters the span, invokes `f`
/// and then exits the span. If the span is disabled, `f` will still be /// and then exits the span. If the span is disabled, `f` will still be
/// invoked, but in the context of the currently-executing span (if there is /// invoked, but in the context of the currently-executing span (if there is
/// one). /// one).
/// ///
/// Returns the result of evaluating `f`. /// Returns the result of evaluating `f`.
pub fn enter<F: FnOnce() -> T, T>(&self, f: F) -> T { ///
self.log(format_args!("-> {}", self.meta.name)); /// # Examples
let _enter = self.inner.as_ref().map(Inner::enter); ///
let result = f(); /// ```
self.log(format_args!("<- {}", self.meta.name)); /// # #[macro_use] extern crate tokio_trace;
result /// # use tokio_trace::Level;
/// # fn main() {
/// let my_span = span!(Level::TRACE, "my_span");
///
/// my_span.in_scope(|| {
/// // this event occurs within the span.
/// trace!("i'm in the span!");
/// });
///
/// // this event occurs outside the span.
/// trace!("i'm not in the span!");
/// # }
/// ```
///
/// Calling a function and returning the result:
/// ```
/// # #[macro_use] extern crate tokio_trace;
/// # use tokio_trace::Level;
/// fn hello_world() -> String {
/// "Hello world!".to_owned()
/// }
///
/// # fn main() {
/// let span = info_span!("hello_world");
/// // the span will be entered for the duration of the call to
/// // `hello_world`.
/// let a_string = span.in_scope(hello_world);
/// # }
///
pub fn in_scope<F: FnOnce() -> T, T>(&self, f: F) -> T {
let _enter = self.enter();
f()
} }
/// Returns a [`Field`](../field/struct.Field.html) for the field with the /// Returns a [`Field`](../field/struct.Field.html) for the field with the
@@ -435,18 +564,6 @@ impl fmt::Debug for Span {
// ===== impl Inner ===== // ===== impl Inner =====
impl Inner { impl Inner {
/// Enters the span, returning a guard that may be used to exit the span and
/// re-enter the prior span.
///
/// This is used internally to implement `Span::enter`. It may be used for
/// writing custom span handles, but should generally not be called directly
/// when entering a span.
#[inline]
fn enter(&self) -> Entered {
self.subscriber.enter(&self.id);
Entered { inner: self }
}
/// Indicates that the span with the given ID has an indirect causal /// Indicates that the span with the given ID has an indirect causal
/// relationship with this span. /// relationship with this span.
/// ///
@@ -519,7 +636,10 @@ impl<'a> Drop for Entered<'a> {
// //
// Running this behaviour on drop rather than with an explicit function // Running this behaviour on drop rather than with an explicit function
// call means that spans may still be exited when unwinding. // call means that spans may still be exited when unwinding.
self.inner.subscriber.exit(&self.inner.id); if let Some(inner) = self.span.inner.as_ref() {
inner.subscriber.exit(&inner.id);
}
self.span.log(format_args!("<- {}", self.span.meta.name));
} }
} }
tokio-trace/test-log-support/tests/log_no_trace.rs
+1 -1
View File
@@ -44,7 +44,7 @@ fn test_always_log() {
let mut foo = span!(Level::TRACE, "foo"); let mut foo = span!(Level::TRACE, "foo");
last(&a, "foo;"); last(&a, "foo;");
foo.enter(|| { foo.in_scope(|| {
last(&a, "-> foo"); last(&a, "-> foo");
trace!({foo = 3, bar = 4}, "hello {};", "san francisco"); trace!({foo = 3, bar = 4}, "hello {};", "san francisco");
tokio-trace/tests/filter_caching_is_lexically_scoped.rs
+2 -2
View File
@@ -20,11 +20,11 @@ use std::sync::{
#[test] #[test]
fn filter_caching_is_lexically_scoped() { fn filter_caching_is_lexically_scoped() {
pub fn my_great_function() -> bool { pub fn my_great_function() -> bool {
span!(Level::TRACE, "emily").enter(|| true) span!(Level::TRACE, "emily").in_scope(|| true)
} }
pub fn my_other_function() -> bool { pub fn my_other_function() -> bool {
span!(Level::TRACE, "frank").enter(|| true) span!(Level::TRACE, "frank").in_scope(|| true)
} }
let count = Arc::new(AtomicUsize::new(0)); let count = Arc::new(AtomicUsize::new(0));
tokio-trace/tests/filters_are_not_reevaluated_for_the_same_span.rs
+4 -4
View File
@@ -44,9 +44,9 @@ fn filters_are_not_reevaluated_for_the_same_span() {
// Enter "alice" and then "bob". The dispatcher expects to see "bob" but // Enter "alice" and then "bob". The dispatcher expects to see "bob" but
// not "alice." // not "alice."
let alice = span!(Level::TRACE, "alice"); let alice = span!(Level::TRACE, "alice");
let bob = alice.enter(|| { let bob = alice.in_scope(|| {
let bob = span!(Level::TRACE, "bob"); let bob = span!(Level::TRACE, "bob");
bob.enter(|| ()); bob.in_scope(|| ());
bob bob
}); });
@@ -54,14 +54,14 @@ fn filters_are_not_reevaluated_for_the_same_span() {
assert_eq!(alice_count.load(Ordering::Relaxed), 1); assert_eq!(alice_count.load(Ordering::Relaxed), 1);
assert_eq!(bob_count.load(Ordering::Relaxed), 1); assert_eq!(bob_count.load(Ordering::Relaxed), 1);
alice.enter(|| bob.enter(|| {})); alice.in_scope(|| bob.in_scope(|| {}));
// The subscriber should see "bob" again, but the filter should not have // The subscriber should see "bob" again, but the filter should not have
// been called. // been called.
assert_eq!(alice_count.load(Ordering::Relaxed), 1); assert_eq!(alice_count.load(Ordering::Relaxed), 1);
assert_eq!(bob_count.load(Ordering::Relaxed), 1); assert_eq!(bob_count.load(Ordering::Relaxed), 1);
bob.enter(|| {}); bob.in_scope(|| {});
assert_eq!(alice_count.load(Ordering::Relaxed), 1); assert_eq!(alice_count.load(Ordering::Relaxed), 1);
assert_eq!(bob_count.load(Ordering::Relaxed), 1); assert_eq!(bob_count.load(Ordering::Relaxed), 1);
}); });
tokio-trace/tests/filters_are_reevaluated_for_different_call_sites.rs
+5 -5
View File
@@ -47,9 +47,9 @@ fn filters_are_reevaluated_for_different_call_sites() {
// Enter "charlie" and then "dave". The dispatcher expects to see "dave" but // Enter "charlie" and then "dave". The dispatcher expects to see "dave" but
// not "charlie." // not "charlie."
let charlie = span!(Level::TRACE, "charlie"); let charlie = span!(Level::TRACE, "charlie");
let dave = charlie.enter(|| { let dave = charlie.in_scope(|| {
let dave = span!(Level::TRACE, "dave"); let dave = span!(Level::TRACE, "dave");
dave.enter(|| {}); dave.in_scope(|| {});
dave dave
}); });
@@ -57,7 +57,7 @@ fn filters_are_reevaluated_for_different_call_sites() {
assert_eq!(charlie_count.load(Ordering::Relaxed), 1); assert_eq!(charlie_count.load(Ordering::Relaxed), 1);
assert_eq!(dave_count.load(Ordering::Relaxed), 1); assert_eq!(dave_count.load(Ordering::Relaxed), 1);
charlie.enter(|| dave.enter(|| {})); charlie.in_scope(|| dave.in_scope(|| {}));
// The subscriber should see "dave" again, but the filter should not have // The subscriber should see "dave" again, but the filter should not have
// been called. // been called.
@@ -67,13 +67,13 @@ fn filters_are_reevaluated_for_different_call_sites() {
// A different span with the same name has a different call site, so it // A different span with the same name has a different call site, so it
// should cause the filter to be reapplied. // should cause the filter to be reapplied.
let charlie2 = span!(Level::TRACE, "charlie"); let charlie2 = span!(Level::TRACE, "charlie");
charlie.enter(|| {}); charlie.in_scope(|| {});
assert_eq!(charlie_count.load(Ordering::Relaxed), 2); assert_eq!(charlie_count.load(Ordering::Relaxed), 2);
assert_eq!(dave_count.load(Ordering::Relaxed), 1); assert_eq!(dave_count.load(Ordering::Relaxed), 1);
// But, the filter should not be re-evaluated for the new "charlie" span // But, the filter should not be re-evaluated for the new "charlie" span
// when it is re-entered. // when it is re-entered.
charlie2.enter(|| span!(Level::TRACE, "dave").enter(|| {})); charlie2.in_scope(|| span!(Level::TRACE, "dave").in_scope(|| {}));
assert_eq!(charlie_count.load(Ordering::Relaxed), 2); assert_eq!(charlie_count.load(Ordering::Relaxed), 2);
assert_eq!(dave_count.load(Ordering::Relaxed), 2); assert_eq!(dave_count.load(Ordering::Relaxed), 2);
}); });
tokio-trace/tests/span.rs
+39 -21
View File
@@ -67,12 +67,12 @@ fn spans_always_go_to_the_subscriber_that_tagged_them() {
let foo = with_default(subscriber1, || { let foo = with_default(subscriber1, || {
let foo = span!(Level::TRACE, "foo"); let foo = span!(Level::TRACE, "foo");
foo.enter(|| {}); foo.in_scope(|| {});
foo foo
}); });
// Even though we enter subscriber 2's context, the subscriber that // Even though we enter subscriber 2's context, the subscriber that
// tagged the span should see the enter/exit. // tagged the span should see the enter/exit.
with_default(subscriber2, move || foo.enter(|| {})); with_default(subscriber2, move || foo.in_scope(|| {}));
} }
#[test] #[test]
@@ -87,7 +87,7 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
.run(); .run();
let foo = with_default(subscriber1, || { let foo = with_default(subscriber1, || {
let foo = span!(Level::TRACE, "foo"); let foo = span!(Level::TRACE, "foo");
foo.enter(|| {}); foo.in_scope(|| {});
foo foo
}); });
@@ -95,7 +95,7 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() {
// tagged the span should see the enter/exit. // tagged the span should see the enter/exit.
thread::spawn(move || { thread::spawn(move || {
with_default(subscriber::mock().run(), || { with_default(subscriber::mock().run(), || {
foo.enter(|| {}); foo.in_scope(|| {});
}) })
}) })
.join() .join()
@@ -112,7 +112,7 @@ fn dropping_a_span_calls_drop_span() {
.run_with_handle(); .run_with_handle();
with_default(subscriber, || { with_default(subscriber, || {
let span = span!(Level::TRACE, "foo"); let span = span!(Level::TRACE, "foo");
span.enter(|| {}); span.in_scope(|| {});
drop(span); drop(span);
}); });
@@ -129,7 +129,7 @@ fn span_closes_after_event() {
.done() .done()
.run_with_handle(); .run_with_handle();
with_default(subscriber, || { with_default(subscriber, || {
span!(Level::TRACE, "foo").enter(|| { span!(Level::TRACE, "foo").in_scope(|| {
event!(Level::DEBUG, {}, "my event!"); event!(Level::DEBUG, {}, "my event!");
}); });
}); });
@@ -150,10 +150,10 @@ fn new_span_after_event() {
.done() .done()
.run_with_handle(); .run_with_handle();
with_default(subscriber, || { with_default(subscriber, || {
span!(Level::TRACE, "foo").enter(|| { span!(Level::TRACE, "foo").in_scope(|| {
event!(Level::DEBUG, {}, "my event!"); event!(Level::DEBUG, {}, "my event!");
}); });
span!(Level::TRACE, "bar").enter(|| {}); span!(Level::TRACE, "bar").in_scope(|| {});
}); });
handle.assert_finished(); handle.assert_finished();
@@ -170,7 +170,7 @@ fn event_outside_of_span() {
.run_with_handle(); .run_with_handle();
with_default(subscriber, || { with_default(subscriber, || {
debug!("my event!"); debug!("my event!");
span!(Level::TRACE, "foo").enter(|| {}); span!(Level::TRACE, "foo").in_scope(|| {});
}); });
handle.assert_finished(); handle.assert_finished();
@@ -220,14 +220,14 @@ fn clone_and_drop_span_always_go_to_the_subscriber_that_tagged_the_span() {
let foo = with_default(subscriber1, || { let foo = with_default(subscriber1, || {
let foo = span!(Level::TRACE, "foo"); let foo = span!(Level::TRACE, "foo");
foo.enter(|| {}); foo.in_scope(|| {});
foo foo
}); });
// Even though we enter subscriber 2's context, the subscriber that // Even though we enter subscriber 2's context, the subscriber that
// tagged the span should see the enter/exit. // tagged the span should see the enter/exit.
with_default(subscriber2, move || { with_default(subscriber2, move || {
let foo2 = foo.clone(); let foo2 = foo.clone();
foo.enter(|| {}); foo.in_scope(|| {});
drop(foo); drop(foo);
drop(foo2); drop(foo2);
}); });
@@ -246,7 +246,7 @@ fn span_closes_when_exited() {
with_default(subscriber, || { with_default(subscriber, || {
let foo = span!(Level::TRACE, "foo"); let foo = span!(Level::TRACE, "foo");
foo.enter(|| {}); foo.in_scope(|| {});
drop(foo); drop(foo);
}); });
@@ -254,6 +254,24 @@ fn span_closes_when_exited() {
handle.assert_finished(); handle.assert_finished();
} }
#[test]
fn enter() {
let (subscriber, handle) = subscriber::mock()
.enter(span::mock().named("foo"))
.event(event::mock())
.exit(span::mock().named("foo"))
.drop_span(span::mock().named("foo"))
.done()
.run_with_handle();
with_default(subscriber, || {
let foo = span!(Level::TRACE, "foo");
let _enter = foo.enter();
debug!("dropping guard...");
});
handle.assert_finished();
}
#[test] #[test]
fn moved_field() { fn moved_field() {
let (subscriber, handle) = subscriber::mock() let (subscriber, handle) = subscriber::mock()
@@ -276,7 +294,7 @@ fn moved_field() {
"foo", "foo",
bar = display(format!("hello from {}", from)) bar = display(format!("hello from {}", from))
); );
span.enter(|| {}); span.in_scope(|| {});
}); });
handle.assert_finished(); handle.assert_finished();
@@ -319,7 +337,7 @@ fn borrowed_field() {
let from = "my span"; let from = "my span";
let mut message = format!("hello from {}", from); let mut message = format!("hello from {}", from);
let span = span!(Level::TRACE, "foo", bar = display(&message)); let span = span!(Level::TRACE, "foo", bar = display(&message));
span.enter(|| { span.in_scope(|| {
message.insert_str(10, " inside"); message.insert_str(10, " inside");
}); });
}); });
@@ -366,8 +384,8 @@ fn move_field_out_of_struct() {
}; };
let foo = span!(Level::TRACE, "foo", x = debug(pos.x), y = debug(pos.y)); let foo = span!(Level::TRACE, "foo", x = debug(pos.x), y = debug(pos.y));
let bar = span!(Level::TRACE, "bar", position = debug(pos)); let bar = span!(Level::TRACE, "bar", position = debug(pos));
foo.enter(|| {}); foo.in_scope(|| {});
bar.enter(|| {}); bar.in_scope(|| {});
}); });
handle.assert_finished(); handle.assert_finished();
@@ -394,7 +412,7 @@ fn add_field_after_new_span() {
with_default(subscriber, || { with_default(subscriber, || {
let span = span!(Level::TRACE, "foo", bar = 5, baz); let span = span!(Level::TRACE, "foo", bar = 5, baz);
span.record("baz", &true); span.record("baz", &true);
span.enter(|| {}) span.in_scope(|| {})
}); });
handle.assert_finished(); handle.assert_finished();
@@ -422,7 +440,7 @@ fn add_fields_only_after_new_span() {
let span = span!(Level::TRACE, "foo", bar, baz); let span = span!(Level::TRACE, "foo", bar, baz);
span.record("bar", &5); span.record("bar", &5);
span.record("baz", &true); span.record("baz", &true);
span.enter(|| {}) span.in_scope(|| {})
}); });
handle.assert_finished(); handle.assert_finished();
@@ -472,7 +490,7 @@ fn explicit_root_span_is_root_regardless_of_ctx() {
.run_with_handle(); .run_with_handle();
with_default(subscriber, || { with_default(subscriber, || {
span!(Level::TRACE, "foo").enter(|| { span!(Level::TRACE, "foo").in_scope(|| {
span!(Level::TRACE, parent: None, "bar"); span!(Level::TRACE, parent: None, "bar");
}) })
}); });
@@ -509,7 +527,7 @@ fn explicit_child_regardless_of_ctx() {
with_default(subscriber, || { with_default(subscriber, || {
let foo = span!(Level::TRACE, "foo"); let foo = span!(Level::TRACE, "foo");
span!(Level::TRACE, "bar").enter(|| span!(Level::TRACE, parent: foo.id(), "baz")) span!(Level::TRACE, "bar").in_scope(|| span!(Level::TRACE, parent: foo.id(), "baz"))
}); });
handle.assert_finished(); handle.assert_finished();
@@ -544,7 +562,7 @@ fn contextual_child() {
.run_with_handle(); .run_with_handle();
with_default(subscriber, || { with_default(subscriber, || {
span!(Level::TRACE, "foo").enter(|| { span!(Level::TRACE, "foo").in_scope(|| {
span!(Level::TRACE, "bar"); span!(Level::TRACE, "bar");
}) })
}); });