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 { 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(), diff --git a/tracing/tests/max_level_hint.rs b/tracing/tests/max_level_hint.rs new file mode 100644 index 0000000000..22c81ac061 --- /dev/null +++ b/tracing/tests/max_level_hint.rs @@ -0,0 +1,38 @@ +mod support; + +use self::support::*; +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| { + 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(); + + 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"); + 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..c35533b639 --- /dev/null +++ b/tracing/tests/multiple_max_level_hints.rs @@ -0,0 +1,67 @@ +#![cfg(feature = "std")] +mod support; + +use self::support::*; +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"); + 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| { + let level = dbg!(meta.level()); + assert!( + level <= &Level::DEBUG, + "a TRACE event was dynamically filtered by subscriber1" + ); + level <= &Level::INFO + }) + .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::DEBUG) + .with_filter(|meta| { + let level = dbg!(meta.level()); + assert!( + level <= &Level::DEBUG, + "a TRACE event was dynamically filtered by subscriber2" + ); + level <= &Level::DEBUG + }) + .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); + + 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(); +} 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();