From be9b70914456ac3c2febbbd297e3aafe34655e7c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 10:13:28 -0700 Subject: [PATCH 1/7] add tests for filter leaks across subscribers Signed-off-by: Eliza Weisman --- tracing/tests/filters_dont_leak.rs | 63 ++++++++++++++++++++++++++++++ 1 file changed, 63 insertions(+) create mode 100644 tracing/tests/filters_dont_leak.rs diff --git a/tracing/tests/filters_dont_leak.rs b/tracing/tests/filters_dont_leak.rs new file mode 100644 index 0000000000..912ec09263 --- /dev/null +++ b/tracing/tests/filters_dont_leak.rs @@ -0,0 +1,63 @@ +#![cfg(feature = "std")] + +mod support; +use self::support::*; + +#[test] +fn spans_dont_leak() { + fn do_span() { + tracing::debug_span!("alice"); + } + + let (subscriber, handle) = subscriber::mock() + .with_filter(|_| false) + .done() + .run_with_handle(); + + let _guard = tracing::subscriber::set_default(subscriber); + + do_span(); + + let (subscriber2, handle2) = subscriber::mock() + .with_filter(|_| true) + .new_span(span::mock().named("alice")) + .drop_span(span::mock().named("alice")) + .done() + .run_with_handle(); + + tracing::subscriber::with_default(subscriber2, do_span); + + do_span(); + + handle.assert_finished(); + handle2.assert_finished(); +} + +#[test] +fn events_dont_leak() { + fn do_event() { + tracing::debug!("alice"); + } + + let (subscriber, handle) = subscriber::mock() + .with_filter(|_| false) + .done() + .run_with_handle(); + + let _guard = tracing::subscriber::set_default(subscriber); + + do_event(); + + let (subscriber2, handle2) = subscriber::mock() + .with_filter(|_| true) + .event(event::mock()) + .done() + .run_with_handle(); + + tracing::subscriber::with_default(subscriber2, do_event); + + do_event(); + + handle.assert_finished(); + handle2.assert_finished(); +} From 62c4c086065745a01fa03d7a9c1aa14c204b174f Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 11:01:20 -0700 Subject: [PATCH 2/7] fix tests Signed-off-by: Eliza Weisman --- tracing/tests/filters_dont_leak.rs | 27 ++++++++++++++++++++++----- 1 file changed, 22 insertions(+), 5 deletions(-) diff --git a/tracing/tests/filters_dont_leak.rs b/tracing/tests/filters_dont_leak.rs index 912ec09263..31a5c93c66 100644 --- a/tracing/tests/filters_dont_leak.rs +++ b/tracing/tests/filters_dont_leak.rs @@ -6,10 +6,12 @@ use self::support::*; #[test] fn spans_dont_leak() { fn do_span() { - tracing::debug_span!("alice"); + 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(); @@ -18,15 +20,23 @@ fn spans_dont_leak() { do_span(); + let alice = span::mock().named("alice"); let (subscriber2, handle2) = subscriber::mock() + .named("spans/subscriber2") .with_filter(|_| true) - .new_span(span::mock().named("alice")) - .drop_span(span::mock().named("alice")) + .new_span(alice.clone()) + .enter(alice.clone()) + .exit(alice.clone()) + .drop_span(alice.clone()) .done() .run_with_handle(); - tracing::subscriber::with_default(subscriber2, do_span); + tracing::subscriber::with_default(subscriber2, || { + println!("--- subscriber 2 is default ---"); + do_span() + }); + println!("--- subscriber 1 is default ---"); do_span(); handle.assert_finished(); @@ -40,6 +50,7 @@ fn events_dont_leak() { } let (subscriber, handle) = subscriber::mock() + .named("events/subscriber1") .with_filter(|_| false) .done() .run_with_handle(); @@ -49,12 +60,18 @@ fn events_dont_leak() { 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, do_event); + tracing::subscriber::with_default(subscriber2, || { + println!("--- subscriber 2 is default ---"); + do_event() + }); + + println!("--- subscriber 1 is default ---"); do_event(); From acfb8e904255992cda1a3d4893ff185ab797c7d3 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 11:24:15 -0700 Subject: [PATCH 3/7] core: fix incorrect `Interest` combining Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 22 +++++++++++++++------- tracing-core/src/subscriber.rs | 17 ++++++++++------- 2 files changed, 25 insertions(+), 14 deletions(-) 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..828e28befa 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -560,19 +560,22 @@ impl Interest { /// interest is `never` and the other is `always` the common interest is /// `always`. pub(crate) fn and(self, rhs: Interest) -> Self { - match rhs.0 { + match (rhs.0, self.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, + (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, + (InterestKind::Sometimes, InterestKind::Never) => rhs, + // If both `Interests` are always, then the interest is `Always`. + (InterestKind::Always, InterestKind::Always) => rhs, + // If either interest is `Always`, but the other is *not*, then the + // result is always `Sometimes` --- we will have to ask the current + // subscriber, since whether or not the callsite is enabled depends + // which subscriber is active. + (InterestKind::Always, _) | (_, InterestKind::Always) => Interest::sometimes(), _ => self, } } From cb8371adbbc45230036f87b1d9743373ef1d64ab Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 14:20:35 -0700 Subject: [PATCH 4/7] core: make `Interest::and` simpler Signed-off-by: Eliza Weisman --- tracing-core/src/subscriber.rs | 28 ++++++++-------------------- 1 file changed, 8 insertions(+), 20 deletions(-) diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 828e28befa..3b8aa3d2c8 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -556,27 +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, self.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, InterestKind::Never) => rhs, - // If both `Interests` are always, then the interest is `Always`. - (InterestKind::Always, InterestKind::Always) => rhs, - // If either interest is `Always`, but the other is *not*, then the - // result is always `Sometimes` --- we will have to ask the current - // subscriber, since whether or not the callsite is enabled depends - // which subscriber is active. - (InterestKind::Always, _) | (_, InterestKind::Always) => Interest::sometimes(), - _ => self, + if dbg!(self.0) == dbg!(rhs.0) { + self + } else { + Interest::sometimes() } } } From b107d0ec58df4c4293ec0228acd3d9c9fc2257ba Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 14:21:43 -0700 Subject: [PATCH 5/7] subscriber: make EnvFilter handle spans in enabled Signed-off-by: Eliza Weisman --- tracing-subscriber/src/filter/env/mod.rs | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) 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); } From 795ca09608744580b8fc7f40db44c94a889eaf76 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 14:22:32 -0700 Subject: [PATCH 6/7] rm dbg Signed-off-by: Eliza Weisman --- tracing-core/src/subscriber.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 3b8aa3d2c8..2b56f8d483 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -561,7 +561,7 @@ impl Interest { /// `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 { - if dbg!(self.0) == dbg!(rhs.0) { + if self.0 == rhs.0 { self } else { Interest::sometimes() From 6d1b96ef65487ab397a58ad7f8bac0e86dcf5287 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 12 Aug 2020 15:27:21 -0700 Subject: [PATCH 7/7] fix unnecessary clone Signed-off-by: Eliza Weisman --- tracing/tests/filters_dont_leak.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing/tests/filters_dont_leak.rs b/tracing/tests/filters_dont_leak.rs index 31a5c93c66..5f8f559717 100644 --- a/tracing/tests/filters_dont_leak.rs +++ b/tracing/tests/filters_dont_leak.rs @@ -27,7 +27,7 @@ fn spans_dont_leak() { .new_span(alice.clone()) .enter(alice.clone()) .exit(alice.clone()) - .drop_span(alice.clone()) + .drop_span(alice) .done() .run_with_handle();