diff options
author | Eliza Weisman <eliza@buoyant.io> | 2019-05-24 15:24:13 -0700 |
---|---|---|
committer | GitHub <noreply@github.com> | 2019-05-24 15:24:13 -0700 |
commit | 84d5a7f5a0660dbe1e2be0e831e715f13cb59a2b (patch) | |
tree | a7a7d6e37702656e68be718dfd9291bc9b0d97b2 | |
parent | 1b498e8aa23b53528a5a2d6e6aad2fe41f37ff60 (diff) |
trace: Change `Span::enter` to return a guard, add `Span::in_scope` (#1076)
## 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 <eliza@buoyant.io>
-rw-r--r-- | tokio-trace/README.md | 4 | ||||
-rw-r--r-- | tokio-trace/benches/subscriber.rs | 2 | ||||
-rw-r--r-- | tokio-trace/examples/counters.rs | 4 | ||||
-rw-r--r-- | tokio-trace/examples/sloggish/main.rs | 12 | ||||
-rw-r--r-- | tokio-trace/src/lib.rs | 107 | ||||
-rw-r--r-- | tokio-trace/src/macros.rs | 14 | ||||
-rw-r--r-- | tokio-trace/src/span.rs | 190 | ||||
-rw-r--r-- | tokio-trace/test-log-support/tests/log_no_trace.rs | 2 | ||||
-rw-r--r-- | tokio-trace/tests/filter_caching_is_lexically_scoped.rs | 4 | ||||
-rw-r--r-- | tokio-trace/tests/filters_are_not_reevaluated_for_the_same_span.rs | 8 | ||||
-rw-r--r-- | tokio-trace/tests/filters_are_reevaluated_for_different_call_sites.rs | 10 | ||||
-rw-r--r-- | tokio-trace/tests/span.rs | 60 |
12 files changed, 285 insertions, 132 deletions
diff --git a/tokio-trace/README.md b/tokio-trace/README.md index 09c1fb7e..1a94b369 100644 --- a/tokio-trace/README.md +++ b/tokio-trace/README.md @@ -56,7 +56,7 @@ to indicate that some code takes place within the context of that `Span`: ```rust // Construct a new span named "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 // the span. }); @@ -88,7 +88,7 @@ use tokio_trace::field; pub fn shave_the_yak(yak: &mut Yak) { // Create a new span for this invocation of `shave_the_yak`, annotated // 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 // 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. diff --git a/tokio-trace/benches/subscriber.rs b/tokio-trace/benches/subscriber.rs index 7f2a32f5..c342a84d 100644 --- a/tokio-trace/benches/subscriber.rs +++ b/tokio-trace/benches/subscriber.rs @@ -107,7 +107,7 @@ fn span_no_fields(b: &mut Bencher) { fn enter_span(b: &mut Bencher) { tokio_trace::subscriber::with_default(EnabledSubscriber, || { let span = span!(Level::TRACE, "span"); - b.iter(|| test::black_box(span.enter(|| {}))) + b.iter(|| test::black_box(span.in_scope(|| {}))) }); } diff --git a/tokio-trace/examples/counters.rs b/tokio-trace/examples/counters.rs index 4c5b3583..dad02bb8 100644 --- a/tokio-trace/examples/counters.rs +++ b/tokio-trace/examples/counters.rs @@ -125,7 +125,7 @@ fn main() { tokio_trace::subscriber::with_default(subscriber, || { 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; info!({ yak_shaved = true, yak_count = 1 }, "hi from inside my span"); span!( @@ -134,7 +134,7 @@ fn main() { foo_count = &foo, baz_count = 5 ) - .enter(|| { + .in_scope(|| { warn!({ yak_shaved = false, yak_count = -1 }, "failed to shave yak"); }); }); diff --git a/tokio-trace/examples/sloggish/main.rs b/tokio-trace/examples/sloggish/main.rs index 4aa7cf18..00c465d6 100644 --- a/tokio-trace/examples/sloggish/main.rs +++ b/tokio-trace/examples/sloggish/main.rs @@ -22,25 +22,25 @@ fn main() { let subscriber = SloggishSubscriber::new(2); tokio_trace::subscriber::with_default(subscriber, || { - span!(Level::TRACE, "", version = &field::display(5.0)).enter(|| { - span!(Level::TRACE, "server", host = "localhost", port = 8080).enter(|| { + span!(Level::TRACE, "", version = &field::display(5.0)).in_scope(|| { + span!(Level::TRACE, "server", host = "localhost", port = 8080).in_scope(|| { info!("starting"); info!("listening"); let peer1 = span!(Level::TRACE, "conn", peer_addr = "82.9.9.9", port = 42381); - peer1.enter(|| { + peer1.in_scope(|| { debug!("connected"); debug!({ length = 2 }, "message received"); }); let peer2 = span!(Level::TRACE, "conn", peer_addr = "8.8.8.8", port = 18230); - peer2.enter(|| { + peer2.in_scope(|| { debug!("connected"); }); - peer1.enter(|| { + peer1.in_scope(|| { warn!({ algo = "xor" }, "weak encryption requested"); debug!({ length = 8 }, "response sent"); debug!("disconnected"); }); - peer2.enter(|| { + peer2.in_scope(|| { debug!({ length = 5 }, "message received"); debug!({ length = 8 }, "response sent"); debug!("disconnected"); diff --git a/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs index 62c77ab9..08d594c5 100644 --- a/tokio-trace/src/lib.rs +++ b/tokio-trace/src/lib.rs @@ -43,8 +43,22 @@ //! use tokio_trace::Level; //! //! # fn main() { -//! span!(Level::TRACE, "my_span").enter(|| { -//! // perform some work in the context of `my_span`... +//! let span = span!(Level::TRACE, "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; //! # fn main() { //! // 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 //! // 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 //! // child of "root": -//! span!(Level::TRACE, "inner_child").enter(|| { +//! span!(Level::TRACE, "inner_child").in_scope(|| { //! // and so on... //! }); //! }); @@ -143,12 +157,12 @@ //! # use tokio_trace::Level; //! # fn main() { //! # let n = 1; -//! span!(Level::TRACE, "my loop").enter(|| { -//! for i in 0..n { -//! # let _ = i; -//! // ... -//! } -//! }) +//! let span = span!(Level::TRACE, "my_loop"); +//! let _enter = span.enter(); +//! for i in 0..n { +//! # let _ = i; +//! // ... +//! } //! # } //! ``` //! Or, should we create a new span for each iteration of the loop, as in: @@ -158,10 +172,9 @@ //! # fn main() { //! # let n = 1u64; //! for i in 0..n { -//! # let _ = i; -//! span!(Level::TRACE, "my loop", iteration = i).enter(|| { -//! // ... -//! }) +//! let span = span!(Level::TRACE, "my_loop", iteration = i); +//! let _enter = span.enter(); +//! // ... //! } //! # } //! ``` @@ -189,7 +202,7 @@ //! // records an event outside of any span context: //! event!(Level::INFO, "something happened"); //! -//! span!(Level::INFO, "my_span").enter(|| { +//! span!(Level::INFO, "my_span").in_scope(|| { //! // records an event within "my_span". //! event!(Level::DEBUG, "something happened inside my_span"); //! }); @@ -257,11 +270,14 @@ //! # fn main() { //! // Construct a new span named "my span" with trace log level. //! let span = span!(Level::TRACE, "my span"); -//! span.enter(|| { -//! // Any trace events in this closure or code called by it will occur within -//! // the span. -//! }); -//! // Dropping the span will close it, indicating that it has ended. +//! +//! // Enter the span, returning a guard object. +//! let _enter = span.enter(); +//! +//! // 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 main() { //! pub fn shave_the_yak(yak: &mut Yak) { -//! // Create a new span for this invocation of `shave_the_yak`, annotated -//! // with the yak being shaved as a *field* on the span. -//! 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 { -//! match find_a_razor() { -//! Ok(razor) => { -//! // We can add the razor as a field rather than formatting it -//! // as part of the message, allowing subscribers to consume it -//! // in a more structured manner: -//! info!({ razor = %razor }, "Razor located"); -//! yak.shave(razor); -//! break; -//! } -//! 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); -//! } +//! let span = span!(Level::TRACE, "shave_the_yak", yak = ?yak); +//! let _enter = span.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 { +//! match find_a_razor() { +//! Ok(razor) => { +//! // We can add the razor as a field rather than formatting it +//! // as part of the message, allowing subscribers to consume it +//! // in a more structured manner: +//! info!({ razor = %razor }, "Razor located"); +//! yak.shave(razor); +//! break; +//! } +//! 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/ -//! [`Span`]: span/struct.Span +//! [`Span`]: span/struct.Span.html +//! [`in_scope`]: span/struct.Span.html#method.in_scope //! [`Event`]: struct.Event.html //! [`Subscriber`]: subscriber/trait.Subscriber.html //! [`observe_event`]: subscriber/trait.Subscriber.html#tymethod.observe_event diff --git a/tokio-trace/src/macros.rs b/tokio-trace/src/macros.rs index 7a44038b..6311a831 100644 --- a/tokio-trace/src/macros.rs +++ b/tokio-trace/src/macros.rs @@ -9,7 +9,7 @@ /// # use tokio_trace::Level; /// # fn main() { /// let span = span!(Level::TRACE, "my span"); -/// span.enter(|| { +/// span.in_scope(|| { /// // do work inside the span... /// }); /// # } @@ -21,7 +21,7 @@ /// # extern crate tokio_trace; /// # use tokio_trace::Level; /// # 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... /// }); /// # } @@ -240,7 +240,7 @@ macro_rules! span { /// # extern crate tokio_trace; /// # fn main() { /// let span = trace_span!("my span"); -/// span.enter(|| { +/// span.in_scope(|| { /// // do work inside the span... /// }); /// # } @@ -301,7 +301,7 @@ macro_rules! trace_span { /// # extern crate tokio_trace; /// # fn main() { /// let span = debug_span!("my span"); -/// span.enter(|| { +/// span.in_scope(|| { /// // do work inside the span... /// }); /// # } @@ -362,7 +362,7 @@ macro_rules! debug_span { /// # extern crate tokio_trace; /// # fn main() { /// let span = info_span!("my span"); -/// span.enter(|| { +/// span.in_scope(|| { /// // do work inside the span... /// }); /// # } @@ -423,7 +423,7 @@ macro_rules! info_span { /// # extern crate tokio_trace; /// # fn main() { /// let span = warn_span!("my span"); -/// span.enter(|| { +/// span.in_scope(|| { /// // do work inside the span... /// }); /// # } @@ -483,7 +483,7 @@ macro_rules! warn_span { /// # extern crate tokio_trace; /// # fn main() { /// let span = error_span!("my span"); -/// span.enter(|| { +/// span.in_scope(|| { /// // do work inside the span... /// }); /// # } diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs index dfdaa5ec..4c4cb9f5 100644 --- a/tokio-trace/src/span.rs +++ b/tokio-trace/src/span.rs @@ -4,12 +4,10 @@ //! //! 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 -//! entered through the [`enter`] method, which enters the target span, -//! performs a given function (either a closure or a function pointer), exits -//! the span, and then returns the result. +//! entered through the [`enter`] and [`in_scope`] methods. //! -//! Calling `enter` on a span handle enters the span that handle corresponds to, -//! if the span exists: +//! The `enter` method enters a span, returning a [guard] that exits the span +//! when dropped //! ``` //! # #[macro_use] extern crate tokio_trace; //! # use tokio_trace::Level; @@ -17,18 +15,36 @@ //! let my_var: u64 = 5; //! 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 outside of the context of `my_span`... //! -//! my_span.enter(|| { +//! my_span.in_scope(|| { //! // Perform some more work in the context of `my_span`. //! }); //! # } //! ``` //! +//! //! # The Span Lifecycle //! //! Execution may enter and exit a span multiple times before that @@ -48,7 +64,7 @@ //! type Error = (); //! //! fn poll(&mut self) -> Poll<Self::Item, Self::Error> { -//! self.span.enter(|| { +//! self.span.in_scope(|| { //! // Do actual future work //! # Ok(Async::Ready(())) //! }) @@ -81,7 +97,7 @@ //! # use tokio_trace::Level; //! # fn main() { //! { -//! span!(Level::TRACE, "my_span").enter(|| { +//! span!(Level::TRACE, "my_span").in_scope(|| { //! // perform some work in the context of `my_span`... //! }); // --> Subscriber::exit(my_span) //! @@ -116,6 +132,8 @@ //! [`Subscriber`]: ../subscriber/trait.Subscriber.html //! [`Attributes`]: struct.Attributes.html //! [`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}; use std::{ @@ -166,15 +184,15 @@ pub(crate) struct Inner { /// A guard representing a span which has been entered and is currently /// executing. /// -/// This guard may be used to exit the span, returning an `Enter` to -/// re-enter it. +/// When the guard is dropped, the span will be exited. +/// +/// This is returned by the [`Span::enter`] function. /// -/// This type is primarily used for implementing span handles; users should -/// typically not need to interact with it directly. +/// [`Span::enter`]: ../struct.Span.html#method.enter #[derive(Debug)] #[must_use = "once a span has been entered, it should be exited"] -struct Entered<'a> { - inner: &'a Inner, +pub struct Entered<'a> { + span: &'a Span, } // ===== impl Span ===== @@ -254,20 +272,131 @@ impl 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. /// - /// 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 /// invoked, but in the context of the currently-executing span (if there is /// one). /// /// Returns the result of evaluating `f`. - pub fn enter<F: FnOnce() -> T, T>(&self, f: F) -> T { - self.log(format_args!("-> {}", self.meta.name)); - let _enter = self.inner.as_ref().map(Inner::enter); - let result = f(); - self.log(format_args!("<- {}", self.meta.name)); - result + /// + /// # Examples + /// + /// ``` + /// # #[macro_use] extern crate tokio_trace; + /// # 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 @@ -435,18 +564,6 @@ impl fmt::Debug for Span { // ===== 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 /// 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 // 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)); } } diff --git a/tokio-trace/test-log-support/tests/log_no_trace.rs b/tokio-trace/test-log-support/tests/log_no_trace.rs index 2c3b7f1d..93cf9ab6 100644 --- a/tokio-trace/test-log-support/tests/log_no_trace.rs +++ b/tokio-trace/test-log-support/tests/log_no_trace.rs @@ -44,7 +44,7 @@ fn test_always_log() { let mut foo = span!(Level::TRACE, "foo"); last(&a, "foo;"); - foo.enter(|| { + foo.in_scope(|| { last(&a, "-> foo"); trace!({foo = 3, bar = 4}, "hello {};", "san francisco"); diff --git a/tokio-trace/tests/filter_caching_is_lexically_scoped.rs b/tokio-trace/tests/filter_caching_is_lexically_scoped.rs index d66e7d4f..72c07299 100644 --- a/tokio-trace/tests/filter_caching_is_lexically_scoped.rs +++ b/tokio-trace/tests/filter_caching_is_lexically_scoped.rs @@ -20,11 +20,11 @@ use std::sync::{ #[test] fn filter_caching_is_lexically_scoped() { 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 { - span!(Level::TRACE, "frank").enter(|| true) + span!(Level::TRACE, "frank").in_scope(|| true) } let count = Arc::new(AtomicUsize::new(0)); diff --git a/tokio-trace/tests/filters_are_not_reevaluated_for_the_same_span.rs b/tokio-trace/tests/filters_are_not_reevaluated_for_the_same_span.rs index c96fe35a..3feb766f 100644 --- a/tokio-trace/tests/filters_are_not_reevaluated_for_the_same_span.rs +++ b/tokio-trace/tests/filters_are_not_reevaluated_for_the_same_span.rs @@ -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 // not "alice." let alice = span!(Level::TRACE, "alice"); - let bob = alice.enter(|| { + let bob = alice.in_scope(|| { let bob = span!(Level::TRACE, "bob"); - bob.enter(|| ()); + bob.in_scope(|| ()); bob }); @@ -54,14 +54,14 @@ fn filters_are_not_reevaluated_for_the_same_span() { assert_eq!(alice_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 // been called. assert_eq!(alice_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!(bob_count.load(Ordering::Relaxed), 1); }); diff --git a/tokio-trace/tests/filters_are_reevaluated_for_different_call_sites.rs b/tokio-trace/tests/filters_are_reevaluated_for_different_call_sites.rs index 3a0fa186..a773354f 100644 --- a/tokio-trace/tests/filters_are_reevaluated_for_different_call_sites.rs +++ b/tokio-trace/tests/filters_are_reevaluated_for_different_call_sites.rs @@ -47,9 +47,9 @@ fn filters_are_reevaluated_for_different_call_sites() { // Enter "charlie" and then "dave". The dispatcher expects to see "dave" but // not "charlie." let charlie = span!(Level::TRACE, "charlie"); - let dave = charlie.enter(|| { + let dave = charlie.in_scope(|| { let dave = span!(Level::TRACE, "dave"); - dave.enter(|| {}); + dave.in_scope(|| {}); dave }); @@ -57,7 +57,7 @@ fn filters_are_reevaluated_for_different_call_sites() { assert_eq!(charlie_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 // 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 // should cause the filter to be reapplied. let charlie2 = span!(Level::TRACE, "charlie"); - charlie.enter(|| {}); + charlie.in_scope(|| {}); assert_eq!(charlie_count.load(Ordering::Relaxed), 2); assert_eq!(dave_count.load(Ordering::Relaxed), 1); // But, the filter should not be re-evaluated for the new "charlie" span // 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!(dave_count.load(Ordering::Relaxed), 2); }); diff --git a/tokio-trace/tests/span.rs b/tokio-trace/tests/span.rs index 5c3bdd61..aedba833 100644 --- a/tokio-trace/tests/span.rs +++ b/tokio-trace/tests/span.rs @@ -67,12 +67,12 @@ fn spans_always_go_to_the_subscriber_that_tagged_them() { let foo = with_default(subscriber1, || { let foo = span!(Level::TRACE, "foo"); - foo.enter(|| {}); + foo.in_scope(|| {}); foo }); // Even though we enter subscriber 2's context, the subscriber that // tagged the span should see the enter/exit. - with_default(subscriber2, move || foo.enter(|| {})); + with_default(subscriber2, move || foo.in_scope(|| {})); } #[test] @@ -87,7 +87,7 @@ fn spans_always_go_to_the_subscriber_that_tagged_them_even_across_threads() { .run(); let foo = with_default(subscriber1, || { let foo = span!(Level::TRACE, "foo"); - foo.enter(|| {}); + foo.in_scope(|| {}); 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. thread::spawn(move || { with_default(subscriber::mock().run(), || { - foo.enter(|| {}); + foo.in_scope(|| {}); }) }) .join() @@ -112,7 +112,7 @@ fn dropping_a_span_calls_drop_span() { .run_with_handle(); with_default(subscriber, || { let span = span!(Level::TRACE, "foo"); - span.enter(|| {}); + span.in_scope(|| {}); drop(span); }); @@ -129,7 +129,7 @@ fn span_closes_after_event() { .done() .run_with_handle(); with_default(subscriber, || { - span!(Level::TRACE, "foo").enter(|| { + span!(Level::TRACE, "foo").in_scope(|| { event!(Level::DEBUG, {}, "my event!"); }); }); @@ -150,10 +150,10 @@ fn new_span_after_event() { .done() .run_with_handle(); with_default(subscriber, || { - span!(Level::TRACE, "foo").enter(|| { + span!(Level::TRACE, "foo").in_scope(|| { event!(Level::DEBUG, {}, "my event!"); }); - span!(Level::TRACE, "bar").enter(|| {}); + span!(Level::TRACE, "bar").in_scope(|| {}); }); handle.assert_finished(); @@ -170,7 +170,7 @@ fn event_outside_of_span() { .run_with_handle(); with_default(subscriber, || { debug!("my event!"); - span!(Level::TRACE, "foo").enter(|| {}); + span!(Level::TRACE, "foo").in_scope(|| {}); }); 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 = span!(Level::TRACE, "foo"); - foo.enter(|| {}); + foo.in_scope(|| {}); foo }); // Even though we enter subscriber 2's context, the subscriber that // tagged the span should see the enter/exit. with_default(subscriber2, move || { let foo2 = foo.clone(); - foo.enter(|| {}); + foo.in_scope(|| {}); drop(foo); drop(foo2); }); @@ -246,7 +246,7 @@ fn span_closes_when_exited() { with_default(subscriber, || { let foo = span!(Level::TRACE, "foo"); - foo.enter(|| {}); + foo.in_scope(|| {}); drop(foo); }); @@ -255,6 +255,24 @@ fn span_closes_when_exited() { } #[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] fn moved_field() { let (subscriber, handle) = subscriber::mock() .new_span( @@ -276,7 +294,7 @@ fn moved_field() { "foo", bar = display(format!("hello from {}", from)) ); - span.enter(|| {}); + span.in_scope(|| {}); }); handle.assert_finished(); @@ -319,7 +337,7 @@ fn borrowed_field() { let from = "my span"; let mut message = format!("hello from {}", from); let span = span!(Level::TRACE, "foo", bar = display(&message)); - span.enter(|| { + span.in_scope(|| { 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 bar = span!(Level::TRACE, "bar", position = debug(pos)); - foo.enter(|| {}); - bar.enter(|| {}); + foo.in_scope(|| {}); + bar.in_scope(|| {}); }); handle.assert_finished(); @@ -394,7 +412,7 @@ fn add_field_after_new_span() { with_default(subscriber, || { let span = span!(Level::TRACE, "foo", bar = 5, baz); span.record("baz", &true); - span.enter(|| {}) + span.in_scope(|| {}) }); handle.assert_finished(); @@ -422,7 +440,7 @@ fn add_fields_only_after_new_span() { let span = span!(Level::TRACE, "foo", bar, baz); span.record("bar", &5); span.record("baz", &true); - span.enter(|| {}) + span.in_scope(|| {}) }); |