tracing: simplify common case of immediately entering the span (#1252)

tracing/src/span.rs

@@ -318,6 +318,9 @@ pub use tracing_core::span::{Attributes, Id, Record};
 use crate::stdlib::{
     cmp, fmt,
     hash::{Hash, Hasher},
+    marker::PhantomData,
+    mem,
+    ops::Deref,
 };
 use crate::{
     dispatcher::{self, Dispatch},
@@ -381,6 +384,28 @@ pub struct Entered<'a> {
     span: &'a Span,
 }
 
+/// An owned version of [`Entered`], a guard representing a span which has been
+/// entered and is currently executing.
+///
+/// When the guard is dropped, the span will be exited.
+///
+/// This is returned by the [`Span::entered`] function.
+///
+/// [`Span::entered`]: super::Span::entered()
+#[derive(Debug)]
+#[must_use = "once a span has been entered, it should be exited"]
+pub struct EnteredSpan {
+    span: Span,
+
+    /// ```compile_fail
+    /// use tracing::span::*;
+    /// trait AssertSend: Send {}
+    ///
+    /// impl AssertSend for EnteredSpan {}
+    /// ```
+    _not_send: PhantomNotSend,
+}
+
 /// `log` target for all span lifecycle (creation/enter/exit/close) records.
 #[cfg(feature = "log")]
 const LIFECYCLE_LOG_TARGET: &str = "tracing::span";
@@ -745,8 +770,132 @@ impl Span {
     /// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
     /// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
     /// [`Id`]: ../struct.Id.html
+    #[inline]
     pub fn enter(&self) -> Entered<'_> {
-        if let Some(ref inner) = self.inner.as_ref() {
+        self.do_enter();
+        Entered { span: self }
+    }
+
+    /// Enters this span, consuming it and returning a [guard][`EnteredSpan`]
+    /// 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.
+    ///
+    /// This is similar to the [`Span::enter`] method, except that it moves the
+    /// span by value into the returned guard, rather than borrowing it.
+    /// Therefore, this method can be used to create and enter a span in a
+    /// single expression, without requiring a `let`-binding. For example:
+    ///
+    /// ```
+    /// # use tracing::info_span;
+    /// let _span = info_span!("something_interesting").entered();
+    /// ```
+    /// rather than:
+    /// ```
+    /// # use tracing::info_span;
+    /// let span = info_span!("something_interesting");
+    /// let _e = span.enter();
+    /// ```
+    ///
+    /// Furthermore, `entered` may be used when the span must be stored in some
+    /// other struct or be passed to a function while remaining entered.
+    ///
+    /// <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;">
+    ///
+    /// **Note**: The returned [`EnteredSpan`] guard does not
+    /// implement `Send`. Dropping the guard will exit *this* span,
+    /// and if the guard is sent to another thread and dropped there, that thread may
+    /// never have entered this span. Thus, `EnteredSpan`s should not be sent
+    /// between threads.
+    ///
+    /// </pre></div>
+    ///
+    /// **Warning**: in asynchronous code that uses [async/await syntax][syntax],
+    /// [`Span::entered`] should be used very carefully or avoided entirely. Holding
+    /// the drop guard returned by `Span::entered` across `.await` points will
+    /// result in incorrect traces. See the documentation for the
+    /// [`Span::enter`] method for details.
+    ///
+    /// [syntax]: https://rust-lang.github.io/async-book/01_getting_started/04_async_await_primer.html
+    ///
+    /// # Examples
+    ///
+    /// The returned guard can be [explicitly exited][EnteredSpan::exit],
+    /// returning the un-entered span:
+    ///
+    /// ```
+    /// # use tracing::{Level, span};
+    /// let span = span!(Level::INFO, "doing_something").entered();
+    ///
+    /// // code here is within the span
+    ///
+    /// // explicitly exit the span, returning it
+    /// let span = span.exit();
+    ///
+    /// // code here is no longer within the span
+    ///
+    /// // enter the span again
+    /// let span = span.entered();
+    ///
+    /// // now we are inside the span once again
+    /// ```
+    ///
+    /// Guards need not be explicitly dropped:
+    ///
+    /// ```
+    /// # use tracing::trace_span;
+    /// fn my_function() -> String {
+    ///     // enter a span for the duration of this function.
+    ///     let span = trace_span!("my_function").entered();
+    ///
+    ///     // 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() {
+    ///     // ...
+    /// }
+    /// ```
+    ///
+    /// Since the [`EnteredSpan`] guard can dereference to the [`Span`] itself,
+    /// the span may still be accessed while entered. For example:
+    ///
+    /// ```rust
+    /// # use tracing::info_span;
+    /// use tracing::field;
+    ///
+    /// // create the span with an empty field, and enter it.
+    /// let span = info_span!("my_span", some_field = field::Empty).entered();
+    ///
+    /// // we can still record a value for the field while the span is entered.
+    /// span.record("some_field", &"hello world!");
+    /// ```
+    ///
+    /// [`Subscriber::enter`]: ../subscriber/trait.Subscriber.html#method.enter
+    /// [`Subscriber::exit`]: ../subscriber/trait.Subscriber.html#method.exit
+    /// [`Id`]: ../struct.Id.html
+    #[inline]
+    pub fn entered(self) -> EnteredSpan {
+        self.do_enter();
+        EnteredSpan {
+            span: self,
+            _not_send: PhantomNotSend,
+        }
+    }
+
+    #[inline]
+    fn do_enter(&self) {
+        if let Some(inner) = self.inner.as_ref() {
             inner.subscriber.enter(&inner.id);
         }
 
@@ -755,8 +904,23 @@ impl Span {
                 self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name()));
             }
         }}
+    }
 
-        Entered { span: self }
+    // Called from [`Entered`] and [`EnteredSpan`] drops.
+    //
+    // Running this behaviour on drop rather than with an explicit function
+    // call means that spans may still be exited when unwinding.
+    #[inline]
+    fn do_exit(&self) {
+        if let Some(inner) = self.inner.as_ref() {
+            inner.subscriber.exit(&inner.id);
+        }
+
+        if_log_enabled! { crate::Level::TRACE, {
+            if let Some(ref _meta) = self.meta {
+                self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
+            }
+        }}
     }
 
     /// Executes the given function in the context of this span.
@@ -1221,25 +1385,66 @@ impl Clone for Inner {
 
 // ===== impl Entered =====
 
+impl EnteredSpan {
+    /// Exits this span, returning the underlying [`Span`].
+    #[inline]
+    pub fn exit(mut self) -> Span {
+        // One does not simply move out of a struct with `Drop`.
+        let span = mem::replace(&mut self.span, Span::none());
+        span.do_exit();
+        span
+    }
+}
+
+impl Deref for EnteredSpan {
+    type Target = Span;
+
+    #[inline]
+    fn deref(&self) -> &Span {
+        &self.span
+    }
+}
+
 impl<'a> Drop for Entered<'a> {
     #[inline]
     fn drop(&mut self) {
-        // Dropping the guard exits the span.
-        //
-        // Running this behaviour on drop rather than with an explicit function
-        // call means that spans may still be exited when unwinding.
-        if let Some(inner) = self.span.inner.as_ref() {
-            inner.subscriber.exit(&inner.id);
-        }
+        self.span.do_exit()
+    }
+}
 
-        if let Some(ref _meta) = self.span.meta {
-            if_log_enabled! { crate::Level::TRACE, {
-                self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
-            }}
-        }
+impl Drop for EnteredSpan {
+    #[inline]
+    fn drop(&mut self) {
+        self.span.do_exit()
     }
 }
 
+/// Technically, `EnteredSpan` _can_ implement both `Send` *and*
+/// `Sync` safely. It doesn't, because it has a `PhantomNotSend` field,
+/// specifically added in order to make it `!Send`.
+///
+/// Sending an `EnteredSpan` guard between threads cannot cause memory unsafety.
+/// However, it *would* result in incorrect behavior, so we add a
+/// `PhantomNotSend` to prevent it from being sent between threads. This is
+/// because it must be *dropped* on the same thread that it was created;
+/// otherwise, the span will never be exited on the thread where it was entered,
+/// and it will attempt to exit the span on a thread that may never have entered
+/// it. However, we still want them to be `Sync` so that a struct holding an
+/// `Entered` guard can be `Sync`.
+///
+/// Thus, this is totally safe.
+#[derive(Debug)]
+struct PhantomNotSend {
+    ghost: PhantomData<*mut ()>,
+}
+#[allow(non_upper_case_globals)]
+const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData };
+
+/// # Safety
+///
+/// Trivially safe, as `PhantomNotSend` doesn't have any API.
+unsafe impl Sync for PhantomNotSend {}
+
 #[cfg(feature = "log")]
 struct FmtValues<'a>(&'a Record<'a>);
 
@@ -1281,4 +1486,6 @@ mod test {
 
     trait AssertSync: Sync {}
     impl AssertSync for Span {}
+    impl AssertSync for Entered<'_> {}
+    impl AssertSync for EnteredSpan {}
 }

tracing/tests/span.rs

@@ -297,6 +297,44 @@ fn enter() {
     handle.assert_finished();
 }
 
+#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
+#[test]
+fn entered() {
+    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 _span = span!(Level::TRACE, "foo").entered();
+        debug!("dropping guard...");
+    });
+
+    handle.assert_finished();
+}
+
+#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
+#[test]
+fn entered_api() {
+    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 span = span!(Level::TRACE, "foo").entered();
+        let _derefs_to_span = span.id();
+        debug!("exiting span...");
+        let _: Span = span.exit();
+    });
+
+    handle.assert_finished();
+}
+
 #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
 #[test]
 fn moved_field() {