core: fix incorrect max level filter calculation (#908)

## Motivation

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 — it means that the fast path will
not be taken in may cases where it *should* be.

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.

Whoopsie!

## Solution

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.

I've also added new tests to ensure that the global max level filter is
used when provided, by asserting that `enabled` is not called with spans
that would be excluded by the max level. These tests fail on master, but
pass after this change.

Additionally, note that fixing this bug revealed a separate issue in
`tracing-subscriber`'s implementation of `max_level_hint` for
`EnvFilter`. When the `EnvFilter` includes directives that filter on
span field values, it will enable all spans with fields with that name,
so that events *within* the span can be enabled up to the filtering
directive's level. This may not be the ideal behavior, but it's what
we're doing currently, and we have tests for it. Therefore, it was
necessary to change the `max_level_hint` implementation to take this
into account by always returning `TRACE` when there are field value
filters. 

That means that this branch requires #907 order for the
`tracing-subscriber` tests to pass.

Fixes: #906 

Signed-off-by: Eliza Weisman <[email protected]>

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/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();