From 906608a6c14ec9a1ffff2cd91206dd09a0d0870c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 21:19:50 -0700 Subject: [PATCH] core: change `Interest`-combining to play nicer with multiple subscribers (#920) ## Motivation Currently, when multiple subscribers are in use, the way that `Interest` values are combined results in surprising behavior. If _any_ subscriber returns `Interest::always` for a callsite, that interest currently takes priority over any other `Interest`s. This means that if two threads have separate subscribers, one of which enables a callsite `always`, and the other `never`, _both_ subscribers will always record that callsite, without the option to disable it. This is not quite right. Instead, we should check whether the current subscriber will enable that callsite in this case. ## Solution This branch changes the rules for combining `Interest`s so that `always` is only returned if _both_ `Interest`s are `always`. If only _one_ is `always`, the combined interest is now `sometimes`, instead. This means that when multiple subscribers exist, `enabled` will always be called on the _current_ subscriber, except when _all_ subscribers have indicated that they are `always` or `never` interested in a callsite. I've added tests that reproduce the issues with leaky filters. Fixing this revealed an additional issue where `tracing-subscriber`'s `EnvFilter` assumes that `enabled` is only called for events, and never for spans, because it always returns either `always` or `never` from `register_callsite` for spans. Therefore, the dynamic span matching directives that might enable a span were never checked in `enabled`. However, under the new interest-combining rules, `enabled` *may* still be called even if a subscriber returns an `always` or `never` interest, if *another* subscriber exists that returned an incompatible interest. This PR fixes that, as well. Depends on #919 Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 22 ++++--- tracing-core/src/subscriber.rs | 25 +++----- tracing-subscriber/src/filter/env/mod.rs | 16 ++++- tracing/tests/filters_dont_leak.rs | 80 ++++++++++++++++++++++++ 4 files changed, 116 insertions(+), 27 deletions(-) create mode 100644 tracing/tests/filters_dont_leak.rs diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 9c6e6b31ad..f6904befda 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -28,13 +28,21 @@ impl Registry { fn rebuild_callsite_interest(&self, callsite: &'static dyn Callsite) { let meta = callsite.metadata(); - let mut interest = Interest::never(); - - for registrar in &self.dispatchers { - if let Some(sub_interest) = registrar.try_register(meta) { - interest = interest.and(sub_interest); - } - } + // Iterate over the subscribers in the registry, and — if they are + // active — register the callsite with them. + let mut interests = self + .dispatchers + .iter() + .filter_map(|registrar| registrar.try_register(meta)); + + // Use the first subscriber's `Interest` as the base value. + let interest = if let Some(interest) = interests.next() { + // Combine all remaining `Interest`s. + interests.fold(interest, Interest::and) + } else { + // If nobody was interested in this thing, just return `never`. + Interest::never() + }; callsite.set_interest(interest) } diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 2c8911d90f..2b56f8d483 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -556,24 +556,15 @@ impl Interest { /// Returns the common interest between these two Interests. /// - /// The common interest is defined as the least restrictive, so if one - /// interest is `never` and the other is `always` the common interest is - /// `always`. + /// If both interests are the same, this propagates that interest. + /// Otherwise, if they differ, the result must always be + /// `Interest::sometimes` --- if the two subscribers differ in opinion, we + /// will have to ask the current subscriber what it thinks, no matter what. pub(crate) fn and(self, rhs: Interest) -> Self { - match rhs.0 { - // If the added interest is `never()`, don't change anything — - // either a different subscriber added a higher interest, which we - // want to preserve, or the interest is 0 anyway (as it's - // initialized to 0). - InterestKind::Never => self, - // If the interest is `sometimes()`, that overwrites a `never()` - // interest, but doesn't downgrade an `always()` interest. - InterestKind::Sometimes if self.0 == InterestKind::Never => rhs, - // If the interest is `always()`, we overwrite the current interest, - // as always() is the highest interest level and should take - // precedent. - InterestKind::Always => rhs, - _ => self, + if self.0 == rhs.0 { + self + } else { + Interest::sometimes() } } } diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index 2e7d5e821b..92a4665992 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -297,6 +297,19 @@ impl Layer for EnvFilter { // if not, we can avoid the thread local access + iterating over the // spans in the current scope. if self.has_dynamics && self.dynamics.max_level >= *level { + if metadata.is_span() { + // If the metadata is a span, see if we care about its callsite. + let enabled_by_cs = self + .by_cs + .read() + .ok() + .map(|by_cs| by_cs.contains_key(&metadata.callsite())) + .unwrap_or(false); + if enabled_by_cs { + return true; + } + } + let enabled_by_scope = SCOPE.with(|scope| { for filter in scope.borrow().iter() { if filter >= level { @@ -314,9 +327,6 @@ impl Layer for EnvFilter { if self.statics.max_level >= *level { // Otherwise, fall back to checking if the callsite is // statically enabled. - // TODO(eliza): we *might* want to check this only if the `log` - // feature is enabled, since if this is a `tracing` event with a - // real callsite, it would already have been statically enabled... return self.statics.enabled(metadata); } diff --git a/tracing/tests/filters_dont_leak.rs b/tracing/tests/filters_dont_leak.rs new file mode 100644 index 0000000000..5f8f559717 --- /dev/null +++ b/tracing/tests/filters_dont_leak.rs @@ -0,0 +1,80 @@ +#![cfg(feature = "std")] + +mod support; +use self::support::*; + +#[test] +fn spans_dont_leak() { + fn do_span() { + let span = tracing::debug_span!("alice"); + let _e = span.enter(); + } + + let (subscriber, handle) = subscriber::mock() + .named("spans/subscriber1") + .with_filter(|_| false) + .done() + .run_with_handle(); + + let _guard = tracing::subscriber::set_default(subscriber); + + do_span(); + + let alice = span::mock().named("alice"); + let (subscriber2, handle2) = subscriber::mock() + .named("spans/subscriber2") + .with_filter(|_| true) + .new_span(alice.clone()) + .enter(alice.clone()) + .exit(alice.clone()) + .drop_span(alice) + .done() + .run_with_handle(); + + tracing::subscriber::with_default(subscriber2, || { + println!("--- subscriber 2 is default ---"); + do_span() + }); + + println!("--- subscriber 1 is default ---"); + do_span(); + + handle.assert_finished(); + handle2.assert_finished(); +} + +#[test] +fn events_dont_leak() { + fn do_event() { + tracing::debug!("alice"); + } + + let (subscriber, handle) = subscriber::mock() + .named("events/subscriber1") + .with_filter(|_| false) + .done() + .run_with_handle(); + + let _guard = tracing::subscriber::set_default(subscriber); + + do_event(); + + let (subscriber2, handle2) = subscriber::mock() + .named("events/subscriber2") + .with_filter(|_| true) + .event(event::mock()) + .done() + .run_with_handle(); + + tracing::subscriber::with_default(subscriber2, || { + println!("--- subscriber 2 is default ---"); + do_event() + }); + + println!("--- subscriber 1 is default ---"); + + do_event(); + + handle.assert_finished(); + handle2.assert_finished(); +}