Skip to content

Commit

Permalink
subscriber: clear per-subscriber interest when short circuiting (#1569)
Browse files Browse the repository at this point in the history 
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 <[email protected]>
  • Loading branch information
@hawkw
hawkw committed Mar 23, 2022
1 parent ee4cd44 commit ea667ab
Show file tree
Hide file tree
Showing 2 changed files with 37 additions and 63 deletions.
94 changes: 31 additions & 63 deletions tracing-subscriber/src/subscribe/context.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -185,7 +187,7 @@ where
///
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <strong>Note</strong>: This requires the wrapped collector to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
Expand Down Expand Up @@ -225,7 +227,7 @@ where
///
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <strong>Note</strong>: This requires the wrapped collector to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
Expand All @@ -250,7 +252,7 @@ where
///
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <strong>Note</strong>: This requires the wrapped collector to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
Expand All @@ -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.
///
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <strong>Note</strong>: This requires the wrapped collector to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
Expand All @@ -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
Expand All @@ -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.
Expand All @@ -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.
///
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
/// </pre></div>
///
/// [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.
Expand All @@ -391,7 +359,7 @@ where
/// </div>
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <strong>Note</strong>: This requires the wrapped collector to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
Expand Down Expand Up @@ -419,7 +387,7 @@ where
///
/// <div class="example-wrap" style="display:inline-block">
/// <pre class="ignore" style="white-space:normal;font:inherit;">
/// <strong>Note</strong>: This requires the wrapped subscriber to implement the
/// <strong>Note</strong>: This requires the wrapped collector to implement the
/// <a href="../registry/trait.LookupSpan.html"><code>LookupSpan</code></a> trait.
/// See the documentation on <a href="./struct.Context.html"><code>Context</code>'s
/// declaration</a> for details.
Expand Down
6 changes: 6 additions & 0 deletions tracing-subscriber/src/subscribe/layered.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down

0 comments on commit ea667ab

Please sign in to comment.