From 631d4245dacbb97760980ba4ffdfdfdb8d51a980 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 12:05:48 -0700 Subject: [PATCH 1/9] tracing: add tests for max level hints Signed-off-by: Eliza Weisman --- tracing/tests/max_level_hint.rs | 33 ++++++++++++++ tracing/tests/multiple_max_level_hints.rs | 53 +++++++++++++++++++++++ tracing/tests/support/subscriber.rs | 19 +++++++- 3 files changed, 104 insertions(+), 1 deletion(-) create mode 100644 tracing/tests/max_level_hint.rs create mode 100644 tracing/tests/multiple_max_level_hints.rs diff --git a/tracing/tests/max_level_hint.rs b/tracing/tests/max_level_hint.rs new file mode 100644 index 0000000000..61a90181cd --- /dev/null +++ b/tracing/tests/max_level_hint.rs @@ -0,0 +1,33 @@ +mod support; + +use self::support::*; +use tracing::Level; + +#[test] +fn max_level_hints() { + let (subscriber, handle) = subscriber::mock() + .with_max_level_hint(Level::INFO) + .with_filter(|meta| { + assert!( + dbg!(meta).level() <= &Level::INFO, + "a TRACE or DEBUG event was dynamically filtered: " + ); + true + }) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let _guard = tracing::subscriber::set_default(subscriber); + tracing::info!("doing a thing that you might care about"); + tracing::debug!("charging turboencabulator with interocitor"); + tracing::warn!("extremely serious warning, pay attention"); + tracing::trace!("interocitor charge level is 10%"); + tracing::error!("everything is on fire"); + handle.assert_finished(); +} + + + diff --git a/tracing/tests/multiple_max_level_hints.rs b/tracing/tests/multiple_max_level_hints.rs new file mode 100644 index 0000000000..72284459da --- /dev/null +++ b/tracing/tests/multiple_max_level_hints.rs @@ -0,0 +1,53 @@ +mod support; + +use self::support::*; +use tracing::Level; + +#[test] +fn multiple_max_level_hints() { + fn do_events() { + tracing::info!("doing a thing that you might care about"); + tracing::debug!("charging turboencabulator with interocitor"); + tracing::warn!("extremely serious warning, pay attention"); + tracing::trace!("interocitor charge level is 10%"); + tracing::error!("everything is on fire"); + } + + let (subscriber1, handle1) = subscriber::mock() + .with_max_level_hint(Level::INFO) + .with_filter(|meta| { + assert!( + dbg!(meta).level() <= &Level::DEBUG, + "a TRACE event was dynamically filtered by subscriber1: " + ); + true + }) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + let (subscriber2, handle2) = subscriber::mock() + .with_max_level_hint(Level::INFO) + .with_filter(|meta| { + assert!( + dbg!(meta).level() <= &Level::DEBUG, + "a TRACE event was dynamically filtered by subscriber2: " + ); + true + }) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let dispatch1 = tracing::Dispatch::new(subscriber1); + let dispatch2 = tracing::Dispatch::new(subscriber2); + + tracing::dispatcher::with_default(&dispatch1, do_events); + handle1.assert_finished(); + tracing::dispatcher::with_default(&dispatch2, do_events); + handle2.assert_finished(); +} diff --git a/tracing/tests/support/subscriber.rs b/tracing/tests/support/subscriber.rs index e10d363395..5734bfe15a 100644 --- a/tracing/tests/support/subscriber.rs +++ b/tracing/tests/support/subscriber.rs @@ -14,6 +14,7 @@ use std::{ }, }; use tracing::{ + level_filters::LevelFilter, span::{self, Attributes, Id}, Event, Metadata, Subscriber, }; @@ -40,11 +41,13 @@ struct Running) -> bool> { expected: Arc>>, current: Mutex>, ids: AtomicUsize, + max_level: Option, filter: F, } pub struct MockSubscriber) -> bool> { expected: VecDeque, + max_level: Option, filter: F, } @@ -54,6 +57,7 @@ pub fn mock() -> MockSubscriber) -> bool> { MockSubscriber { expected: VecDeque::new(), filter: (|_: &Metadata<'_>| true) as for<'r, 's> fn(&'r Metadata<'s>) -> _, + max_level: None, } } @@ -113,8 +117,16 @@ where G: Fn(&Metadata<'_>) -> bool + 'static, { MockSubscriber { - filter, expected: self.expected, + filter, + max_level: self.max_level, + } + } + + pub fn with_max_level_hint(self, hint: impl Into) -> Self { + Self { + max_level: Some(hint.into()), + ..self } } @@ -132,6 +144,7 @@ where current: Mutex::new(Vec::new()), ids: AtomicUsize::new(1), filter: self.filter, + max_level: self.max_level, }; (subscriber, handle) } @@ -145,6 +158,10 @@ where (self.filter)(meta) } + fn max_level_hint(&self) -> Option { + self.max_level.clone() + } + fn record(&self, id: &Id, values: &span::Record<'_>) { let spans = self.spans.lock().unwrap(); let mut expected = self.expected.lock().unwrap(); From c28105e3d38edb0fa1d30dd97b178bf9cba31f4f Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 12:05:48 -0700 Subject: [PATCH 2/9] tracing: add tests for max level hints Signed-off-by: Eliza Weisman --- tracing/tests/max_level_hint.rs | 3 --- 1 file changed, 3 deletions(-) diff --git a/tracing/tests/max_level_hint.rs b/tracing/tests/max_level_hint.rs index 61a90181cd..16a44026fd 100644 --- a/tracing/tests/max_level_hint.rs +++ b/tracing/tests/max_level_hint.rs @@ -28,6 +28,3 @@ fn max_level_hints() { tracing::error!("everything is on fire"); handle.assert_finished(); } - - - From bc344a70adaa4e4af309f399f94ea9b478bc247e Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 11:33:18 -0700 Subject: [PATCH 3/9] core: fix incorrect max level calculation Currently, when rebuilding the interest cache, the max level is calculated by tracking a max level, and comparing it with each active `Subscriber`'s max level hint, and setting the max value to the hint if the hint is higher than the current value. This is correct. However, the max level in this calculation starts at `TRACE`. This means that regardless of what any subscriber returns for its hint, after rebuilding the interest cache, the max level will *always* be `TRACE`. This is wrong. The max level calculation was started at `TRACE` rather than `OFF`, because when this code was written with it starting at `OFF`, all the tests broke, because the test subscribers don't provide hints. This was the incorrect solution to that problem, however. This caused the tests to break because we were *ignoring* all `None` hints, and not changing the current max value when a subscriber returns `None`. This means that if all subscribers returned `None` for their max level hint, the max would remain `OFF`. However, what we *should* have done is assume that if a subscriber doesn't provide a hint, it won't be filtering based on levels, and assume that the max level is `TRACE` for that subscriber. Now, the max level should be calculated correctly for subscribers that *do* provide hints, and should still be `TRACE` if a subscriber does not have a hint. Whoopsie! Signed-off-by: Eliza Weisman --- tracing-core/src/callsite.rs | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 05d703d0e4..9c6e6b31ad 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -40,13 +40,14 @@ impl Registry { } fn rebuild_interest(&mut self) { - let mut max_level = LevelFilter::TRACE; + let mut max_level = LevelFilter::OFF; self.dispatchers.retain(|registrar| { if let Some(dispatch) = registrar.upgrade() { - if let Some(level) = dispatch.max_level_hint() { - if level > max_level { - max_level = level; - } + // If the subscriber did not provide a max level hint, assume + // that it may enable every level. + let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE); + if level_hint > max_level { + max_level = level_hint; } true } else { From c9d39f91160ca2fca3bd24996298be174e7e6e9a Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 12:32:39 -0700 Subject: [PATCH 4/9] fix wrong test Signed-off-by: Eliza Weisman --- tracing/tests/multiple_max_level_hints.rs | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/tracing/tests/multiple_max_level_hints.rs b/tracing/tests/multiple_max_level_hints.rs index 72284459da..4c941708fb 100644 --- a/tracing/tests/multiple_max_level_hints.rs +++ b/tracing/tests/multiple_max_level_hints.rs @@ -16,11 +16,12 @@ fn multiple_max_level_hints() { let (subscriber1, handle1) = subscriber::mock() .with_max_level_hint(Level::INFO) .with_filter(|meta| { + let level = dbg!(meta.level()); assert!( - dbg!(meta).level() <= &Level::DEBUG, - "a TRACE event was dynamically filtered by subscriber1: " + level <= &Level::DEBUG, + "a TRACE event was dynamically filtered by subscriber1" ); - true + level <= &Level::INFO }) .event(event::mock().at_level(Level::INFO)) .event(event::mock().at_level(Level::WARN)) @@ -28,26 +29,28 @@ fn multiple_max_level_hints() { .done() .run_with_handle(); let (subscriber2, handle2) = subscriber::mock() - .with_max_level_hint(Level::INFO) + .with_max_level_hint(Level::DEBUG) .with_filter(|meta| { + let level = dbg!(meta.level()); assert!( - dbg!(meta).level() <= &Level::DEBUG, - "a TRACE event was dynamically filtered by subscriber2: " + level <= &Level::DEBUG, + "a TRACE event was dynamically filtered by subscriber2" ); - true + level <= &Level::DEBUG }) - .event(event::mock().at_level(Level::TRACE)) .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::DEBUG)) .event(event::mock().at_level(Level::WARN)) .event(event::mock().at_level(Level::ERROR)) .done() .run_with_handle(); let dispatch1 = tracing::Dispatch::new(subscriber1); - let dispatch2 = tracing::Dispatch::new(subscriber2); tracing::dispatcher::with_default(&dispatch1, do_events); handle1.assert_finished(); + + let dispatch2 = tracing::Dispatch::new(subscriber2); tracing::dispatcher::with_default(&dispatch2, do_events); handle2.assert_finished(); } From e1c8642bcbe77cc38b8de6d9c35ba5ce795093fb Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 12:47:02 -0700 Subject: [PATCH 5/9] subscriber: fix level hint not considering value filters This fixes an issue with `EnvFilter`'s `max_level_hint` not considering that span field value filters may enable *any* span, regardless of the level enabled inside that span. This is because the field value must be recorded to be known. We may wish to change this behavior to only check spans up to the selected level, but this isn't what it does currently. This branch fixes the wrong max level hint. This bug was not caught due to an issue where hinting was too permissive, but fixing that bug uncovers this issue. Signed-off-by: Eliza Weisman --- tracing-subscriber/src/filter/env/directive.rs | 6 ++++++ tracing-subscriber/src/filter/env/mod.rs | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/tracing-subscriber/src/filter/env/directive.rs b/tracing-subscriber/src/filter/env/directive.rs index 8e85c7361a..e4ed5d0c7c 100644 --- a/tracing-subscriber/src/filter/env/directive.rs +++ b/tracing-subscriber/src/filter/env/directive.rs @@ -476,6 +476,12 @@ impl Dynamics { None } } + + pub(crate) fn has_value_filters(&self) -> bool { + self.directives + .iter() + .any(|d| !d.fields.iter().any(|f| f.value.is_some())) + } } // === impl Statics === diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index ea85a8a9ff..2e7d5e821b 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -278,6 +278,12 @@ impl Layer for EnvFilter { } fn max_level_hint(&self) -> Option { + if self.dynamics.has_value_filters() { + // If we perform any filtering on span field *values*, we will + // enable *all* spans, because their field values are not known + // until recording. + return Some(LevelFilter::TRACE); + } std::cmp::max( self.statics.max_level.clone().into(), self.dynamics.max_level.clone().into(), From a88b9550b4e2fdbaa34abaead1550e329ed8e9d1 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 12:47:02 -0700 Subject: [PATCH 6/9] subscriber: fix level hint not considering value filters This fixes an issue with `EnvFilter`'s `max_level_hint` not considering that span field value filters may enable *any* span, regardless of the level enabled inside that span. This is because the field value must be recorded to be known. We may wish to change this behavior to only check spans up to the selected level, but this isn't what it does currently. This branch fixes the wrong max level hint. This bug was not caught due to an issue where hinting was too permissive, but fixing that bug uncovers this issue. Signed-off-by: Eliza Weisman --- tracing-subscriber/src/filter/env/directive.rs | 6 ++++++ tracing-subscriber/src/filter/env/mod.rs | 6 ++++++ 2 files changed, 12 insertions(+) diff --git a/tracing-subscriber/src/filter/env/directive.rs b/tracing-subscriber/src/filter/env/directive.rs index 8e85c7361a..c6e5e71b6c 100644 --- a/tracing-subscriber/src/filter/env/directive.rs +++ b/tracing-subscriber/src/filter/env/directive.rs @@ -476,6 +476,12 @@ impl Dynamics { None } } + + pub(crate) fn has_value_filters(&self) -> bool { + self.directives + .iter() + .any(|d| d.fields.iter().any(|f| f.value.is_some())) + } } // === impl Statics === diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index ea85a8a9ff..2e7d5e821b 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -278,6 +278,12 @@ impl Layer for EnvFilter { } fn max_level_hint(&self) -> Option { + if self.dynamics.has_value_filters() { + // If we perform any filtering on span field *values*, we will + // enable *all* spans, because their field values are not known + // until recording. + return Some(LevelFilter::TRACE); + } std::cmp::max( self.statics.max_level.clone().into(), self.dynamics.max_level.clone().into(), From 5d23a669932e93e5d5e4747deb72d368d3bc120e Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 13:42:14 -0700 Subject: [PATCH 7/9] fix tests that require std Signed-off-by: Eliza Weisman --- tracing/tests/max_level_hint.rs | 3 ++- tracing/tests/multiple_max_level_hints.rs | 1 + 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/tracing/tests/max_level_hint.rs b/tracing/tests/max_level_hint.rs index 16a44026fd..09b89530d4 100644 --- a/tracing/tests/max_level_hint.rs +++ b/tracing/tests/max_level_hint.rs @@ -20,7 +20,8 @@ fn max_level_hints() { .done() .run_with_handle(); - let _guard = tracing::subscriber::set_default(subscriber); + tracing::subscriber::set_global_default(subscriber).unwrap(); + tracing::info!("doing a thing that you might care about"); tracing::debug!("charging turboencabulator with interocitor"); tracing::warn!("extremely serious warning, pay attention"); diff --git a/tracing/tests/multiple_max_level_hints.rs b/tracing/tests/multiple_max_level_hints.rs index 4c941708fb..027bb57e08 100644 --- a/tracing/tests/multiple_max_level_hints.rs +++ b/tracing/tests/multiple_max_level_hints.rs @@ -1,3 +1,4 @@ +#![cfg(feature = "std")] mod support; use self::support::*; From 7e21c866999a432cdf772cd21ce1376e1eaccf83 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 8 Aug 2020 13:55:43 -0700 Subject: [PATCH 8/9] Update tracing-subscriber/src/filter/env/directive.rs --- tracing-subscriber/src/filter/env/directive.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-subscriber/src/filter/env/directive.rs b/tracing-subscriber/src/filter/env/directive.rs index e4ed5d0c7c..c6e5e71b6c 100644 --- a/tracing-subscriber/src/filter/env/directive.rs +++ b/tracing-subscriber/src/filter/env/directive.rs @@ -480,7 +480,7 @@ impl Dynamics { pub(crate) fn has_value_filters(&self) -> bool { self.directives .iter() - .any(|d| !d.fields.iter().any(|f| f.value.is_some())) + .any(|d| d.fields.iter().any(|f| f.value.is_some())) } } From cabca0d77f93810672c98f91b2b70086d2e8ef61 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Mon, 10 Aug 2020 11:26:59 -0700 Subject: [PATCH 9/9] add comments explaining tests Signed-off-by: Eliza Weisman --- tracing/tests/max_level_hint.rs | 7 +++++++ tracing/tests/multiple_max_level_hints.rs | 10 ++++++++++ 2 files changed, 17 insertions(+) diff --git a/tracing/tests/max_level_hint.rs b/tracing/tests/max_level_hint.rs index 09b89530d4..22c81ac061 100644 --- a/tracing/tests/max_level_hint.rs +++ b/tracing/tests/max_level_hint.rs @@ -5,6 +5,13 @@ use tracing::Level; #[test] fn max_level_hints() { + // This test asserts that when a subscriber provides us with the global + // maximum level that it will enable (by implementing the + // `Subscriber::max_level_hint` method), we will never call + // `Subscriber::enabled` for events above that maximum level. + // + // In this case, we test that by making the `enabled` method assert that no + // `Metadata` for spans or events at the `TRACE` or `DEBUG` levels. let (subscriber, handle) = subscriber::mock() .with_max_level_hint(Level::INFO) .with_filter(|meta| { diff --git a/tracing/tests/multiple_max_level_hints.rs b/tracing/tests/multiple_max_level_hints.rs index 027bb57e08..c35533b639 100644 --- a/tracing/tests/multiple_max_level_hints.rs +++ b/tracing/tests/multiple_max_level_hints.rs @@ -6,6 +6,16 @@ use tracing::Level; #[test] fn multiple_max_level_hints() { + // This test ensures that when multiple subscribers are active, their max + // level hints are handled correctly. The global max level should be the + // maximum of the level filters returned by the two `Subscriber`'s + // `max_level_hint` method. + // + // In this test, we create a subscriber whose max level is `INFO`, and + // another whose max level is `DEBUG`. We then add an assertion to both of + // those subscribers' `enabled` method that no metadata for `TRACE` spans or + // events are filtered, since they are disabled by the global max filter. + fn do_events() { tracing::info!("doing a thing that you might care about"); tracing::debug!("charging turboencabulator with interocitor");