core: fix incorrect max level filter calculation

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 {

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 ===

tracing-subscriber/src/filter/env/mod.rs

@@ -278,6 +278,12 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
     }
 
     fn max_level_hint(&self) -> Option<LevelFilter> {
+        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(),

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();
+}

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();
+}

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<F: Fn(&Metadata<'_>) -> bool> {
     expected: Arc<Mutex<VecDeque<Expect>>>,
     current: Mutex<Vec<Id>>,
     ids: AtomicUsize,
+    max_level: Option<LevelFilter>,
     filter: F,
 }
 
 pub struct MockSubscriber<F: Fn(&Metadata<'_>) -> bool> {
     expected: VecDeque<Expect>,
+    max_level: Option<LevelFilter>,
     filter: F,
 }
 
@@ -54,6 +57,7 @@ pub fn mock() -> MockSubscriber<fn(&Metadata<'_>) -> 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<LevelFilter>) -> 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<LevelFilter> {
+        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();