From 9f1e803838b38bb387a0df4fb71df711b99a67fc Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 15 Sep 2021 19:45:23 -0700 Subject: [PATCH] subscriber: clear per-subscriber interest when short circuiting (#1569) Currently, when evaluating `register_callsite` for a stack containing per-subscriber filters, the intermediate `Interest` from combining the per-subscriber filters' `Interest`s is stored in the thread-local `FilterState`. When all per-subscriber filters have been evaluated, we reach the `Registry`, which clears the `FilterState` and bubbles the `Interest` back up. However, when a _global_ filter in the stack returns `Interest::never`, we short-circuit, and don't reach the `Registry`. This means the `Interest` state is not cleared. This branch adds code in `Layered` to ensure the per-subscriber filter state is cleared when a global filter short circuits `Interest` evaluation. This fixes #1563. Signed-off-by: Eliza Weisman --- tracing-subscriber/src/subscribe/context.rs | 94 +++++++-------------- tracing-subscriber/src/subscribe/layered.rs | 6 ++ 2 files changed, 37 insertions(+), 63 deletions(-) diff --git a/tracing-subscriber/src/subscribe/context.rs b/tracing-subscriber/src/subscribe/context.rs index 6690645280..6a649bf947 100644 --- a/tracing-subscriber/src/subscribe/context.rs +++ b/tracing-subscriber/src/subscribe/context.rs @@ -3,11 +3,11 @@ use tracing_core::{collect::Collect, metadata::Metadata, span, Event}; use crate::registry::{self, LookupSpan, SpanRef}; #[cfg(feature = "registry")] use crate::{filter::FilterId, registry::Registry}; -/// Represents information about the current context provided to [`Layer`]s by the -/// wrapped [`Subscriber`]. +/// Represents information about the current context provided to [subscribers]s by the +/// wrapped [collector]. /// -/// To access [stored data] keyed by a span ID, implementors of the `Layer` -/// trait should ensure that the `Subscriber` type parameter is *also* bound by the +/// To access [stored data] keyed by a span ID, implementors of the [`Subscribe`] +/// trait should ensure that the [`Collect`] type parameter is *also* bound by the /// [`LookupSpan`]: /// /// ```rust @@ -24,19 +24,21 @@ use crate::{filter::FilterId, registry::Registry}; /// } /// ``` /// -/// [`Layer`]: ../layer/trait.Layer.html -/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html +/// [subscriber]: crate::subscribe::Subscribe +/// [collector]: tracing_core::Collect +/// [`Subscribe`]: crate::subscribe::Subscribe +/// [`Collect`]: tracing_core::Collect /// [stored data]: ../registry/struct.SpanRef.html /// [`LookupSpan`]: "../registry/trait.LookupSpan.html #[derive(Debug)] pub struct Context<'a, S> { subscriber: Option<&'a S>, - /// The bitmask of all [`Filtered`] layers that currently apply in this - /// context. If there is only a single [`Filtered`] wrapping the layer that + /// The bitmask of all [`Filtered`] subscribers that currently apply in this + /// context. If there is only a single [`Filtered`] wrapping the subscriber that /// produced this context, then this is that filter's ID. Otherwise, if we /// are in a nested tree with multiple filters, this is produced by /// [`and`]-ing together the [`FilterId`]s of each of the filters that wrap - /// the current layer. + /// the current subscriber. /// /// [`Filtered`]: crate::filter::Filtered /// [`FilterId`]: crate::filter::FilterId @@ -86,7 +88,7 @@ where } } - /// Returns the wrapped subscriber's view of the current span. + /// Returns the wrapped collector's view of the current span. #[inline] pub fn current_span(&self) -> span::Current { self.subscriber @@ -96,32 +98,32 @@ where .unwrap_or_else(span::Current::none) } - /// Returns whether the wrapped subscriber would enable the current span. + /// Returns whether the wrapped collector would enable the current span. #[inline] pub fn enabled(&self, metadata: &Metadata<'_>) -> bool { self.subscriber .map(|subscriber| subscriber.enabled(metadata)) // If this context is `None`, we are registering a callsite, so - // return `true` so that the layer does not incorrectly assume that - // the inner subscriber has disabled this metadata. + // return `true` so that the subscriber does not incorrectly assume that + // the inner collector has disabled this metadata. // TODO(eliza): would it be more correct for this to return an `Option`? .unwrap_or(true) } - /// Records the provided `event` with the wrapped subscriber. + /// Records the provided `event` with the wrapped collector. /// /// # Notes /// - /// - The subscriber is free to expect that the event's callsite has been + /// - The collector is free to expect that the event's callsite has been /// [registered][register], and may panic or fail to observe the event if this is /// not the case. The `tracing` crate's macros ensure that all events are /// registered, but if the event is constructed through other means, the /// user is responsible for ensuring that [`register_callsite`][register] /// has been called prior to calling this method. - /// - This does _not_ call [`enabled`] on the inner subscriber. If the - /// caller wishes to apply the wrapped subscriber's filter before choosing + /// - This does _not_ call [`enabled`] on the inner collector. If the + /// caller wishes to apply the wrapped collector's filter before choosing /// whether to record the event, it may first call [`Context::enabled`] to - /// check whether the event would be enabled. This allows `Layer`s to + /// check whether the event would be enabled. This allows subscriberss to /// elide constructing the event if it would not be recorded. /// /// [register]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html#method.register_callsite @@ -185,7 +187,7 @@ where /// ///
/// 
-    /// Note: This requires the wrapped subscriber to implement the
+    /// Note: This requires the wrapped collector to implement the
     /// LookupSpan trait.
     /// See the documentation on Context's
     /// declaration for details.
@@ -225,7 +227,7 @@ where
     ///
     /// 

     /// 
-    /// Note: This requires the wrapped subscriber to implement the
+    /// Note: This requires the wrapped collector to implement the
     /// LookupSpan trait.
     /// See the documentation on Context's
     /// declaration for details.
@@ -250,7 +252,7 @@ where
     ///
     /// 

     /// 
-    /// Note: This requires the wrapped subscriber to implement the
+    /// Note: This requires the wrapped collector to implement the
     /// LookupSpan trait.
     /// See the documentation on Context's
     /// declaration for details.
@@ -263,14 +265,14 @@ where
         self.subscriber.as_ref().and_then(|s| s.span(id)).is_some()
     }
 
-    /// Returns [stored data] for the span that the wrapped subscriber considers
+    /// Returns [stored data] for the span that the wrapped collector considers
     /// to be the current.
     ///
     /// If this returns `None`, then we are not currently within a span.
     ///
     /// 

     /// 
-    /// Note: This requires the wrapped subscriber to implement the
+    /// Note: This requires the wrapped collector to implement the
     /// LookupSpan trait.
     /// See the documentation on Context's
     /// declaration for details.
@@ -292,18 +294,18 @@ where
             id,
         );
 
-        // If we found a span, and our per-layer filter enables it, return that
+        // If we found a span, and our per-subscriber filter enables it, return that
         // span!
         #[cfg(feature = "registry")]
         if let Some(span) = span?.try_with_filter(self.filter) {
             Some(span)
         } else {
             // Otherwise, the span at the *top* of the stack is disabled by
-            // per-layer filtering, but there may be additional spans in the stack.
+            // per-subscriber filtering, but there may be additional spans in the stack.
             //
             // Currently, `LookupSpan` doesn't have a nice way of exposing access to
             // the whole span stack. However, if we can downcast the innermost
-            // subscriber to a a `Registry`, we can iterate over its current span
+            // collector to a a `Registry`, we can iterate over its current span
             // stack.
             //
             // TODO(eliza): when https://github.com/tokio-rs/tracing/issues/1459 is
@@ -317,7 +319,7 @@ where
 
     /// Slow path for when the current span is disabled by PLF and we have a
     /// registry.
-    // This is called by `lookup_current` in the case that per-layer filtering
+    // This is called by `lookup_current` in the case that per-subscriber filtering
     // is in use. `lookup_current` is allowed to be inlined, but this method is
     // factored out to prevent the loop and (potentially-recursive) subscriber
     // downcasting from being inlined if `lookup_current` is inlined.
@@ -337,40 +339,6 @@ where
             .find_map(|id| subscriber.span(id)?.try_with_filter(self.filter))
     }
 
-    /// Returns an iterator over the [stored data] for all the spans in the
-    /// current context, starting the root of the trace tree and ending with
-    /// the current span.
-    ///
-    /// If this iterator is empty, then there are no spans in the current context.
-    ///
-    /// 

-    /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    /// 

-    ///
-    /// [stored data]: ../registry/struct.SpanRef.html
-    #[deprecated(
-        note = "equivalent to `self.current_span().id().and_then(|id| self.span_scope(id).from_root())` but consider passing an explicit ID instead of relying on the contextual span",
-        since = "0.2.19"
-    )]
-    #[allow(deprecated)]
-    pub fn scope(&self) -> Scope<'_, C>
-    where
-        C: for<'lookup> LookupSpan<'lookup>,
-    {
-        Scope(
-            self.lookup_current()
-                .as_ref()
-                .map(registry::SpanRef::scope)
-                .map(registry::Scope::from_root)
-                .into_iter()
-                .flatten(),
-        )
-    }
-
     /// Returns an iterator over the [stored data] for all the spans in the
     /// current context, starting with the specified span and ending with the
     /// root of the trace tree and ending with the current span.
@@ -391,7 +359,7 @@ where
     /// 

     /// 

     /// 
-    /// Note: This requires the wrapped subscriber to implement the
+    /// Note: This requires the wrapped collector to implement the
     /// LookupSpan trait.
     /// See the documentation on Context's
     /// declaration for details.
@@ -419,7 +387,7 @@ where
     ///
     /// 

     /// 
-    /// Note: This requires the wrapped subscriber to implement the
+    /// Note: This requires the wrapped collector to implement the
     /// LookupSpan trait.
     /// See the documentation on Context's
     /// declaration for details.
diff --git a/tracing-subscriber/src/subscribe/layered.rs b/tracing-subscriber/src/subscribe/layered.rs
index 8241f0d64c..cce97c6861 100644
--- a/tracing-subscriber/src/subscribe/layered.rs
+++ b/tracing-subscriber/src/subscribe/layered.rs
@@ -380,6 +380,12 @@ where
         // If the outer subscriber has disabled the callsite, return now so that
         // the inner subscriber/subscriber doesn't get its hopes up.
         if outer.is_never() {
+            // If per-layer filters are in use, and we are short-circuiting
+            // (rather than calling into the inner type), clear the current
+            // per-layer filter interest state.
+            #[cfg(feature = "registry")]
+            drop(filter::FilterState::take_interest());
+
             return outer;
         }