subscriber: clear per-layer interest when short circuiting (tokio-rs#…

…1569)

Currently, when evaluating `register_callsite` for a stack containing
per-layer filters, the intermediate `Interest` from combining the per
layer filters' `Interest`s is stored in the thread-local `FilterState`.
When all per-layer filters have been evaluated, we reach the `Registry`,
which clears the `FilterState` and bubbles the `Interest` back up.
However, when a _global_ filter in the stack returns `Interest::never`,
we short-circuit, and don't reach the `Registry`. This means the
`Interest` state is not cleared.

This branch adds code in `Layered` to ensure the per-layer filter state
is cleared when a global filter short circuits `Interest` evaluation.

This fixes tokio-rs#1563.

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

tracing-subscriber/src/layer/layered.rs

@@ -374,6 +374,12 @@ where
         // If the outer layer has disabled the callsite, return now so that
         // the inner layer/subscriber doesn't get its hopes up.
         if outer.is_never() {
+            // If per-layer filters are in use, and we are short-circuiting
+            // (rather than calling into the inner type), clear the current
+            // per-layer filter interest state.
+            #[cfg(feature = "registry")]
+            drop(filter::FilterState::take_interest());
+
             return outer;
         }
 

tracing-subscriber/tests/layer_filters/main.rs

@@ -3,6 +3,7 @@
 mod support;
 use self::support::*;
 mod filter_scopes;
+mod targets;
 mod trees;
 
 use tracing::{level_filters::LevelFilter, Level};

tracing-subscriber/tests/layer_filters/targets.rs

@@ -0,0 +1,59 @@
+use super::*;
+use tracing_subscriber::{
+    filter::{filter_fn, Targets},
+    prelude::*,
+};
+
+#[test]
+#[cfg_attr(not(feature = "tracing-log"), ignore)]
+fn log_events() {
+    // Reproduces https://github.com/tokio-rs/tracing/issues/1563
+    mod inner {
+        pub(super) const MODULE_PATH: &str = module_path!();
+
+        #[tracing::instrument]
+        pub(super) fn logs() {
+            log::debug!("inner");
+        }
+    }
+
+    let filter = Targets::new()
+        .with_default(LevelFilter::DEBUG)
+        .with_target(inner::MODULE_PATH, LevelFilter::WARN);
+
+    let layer =
+        tracing_subscriber::layer::Identity::new().with_filter(filter_fn(move |_meta| true));
+
+    let _guard = tracing_subscriber::registry()
+        .with(filter)
+        .with(layer)
+        .set_default();
+
+    inner::logs();
+}
+
+#[test]
+fn inner_layer_short_circuits() {
+    // This test ensures that when a global filter short-circuits `Interest`
+    // evaluation, we aren't left with a "dirty" per-layer filter state.
+
+    let (layer, handle) = layer::mock()
+        .event(event::msg("hello world"))
+        .done()
+        .run_with_handle();
+
+    let filter = Targets::new().with_target("magic_target", LevelFilter::DEBUG);
+
+    let _guard = tracing_subscriber::registry()
+        // Note: we don't just use a `LevelFilter` for the global filter here,
+        // because it will just return a max level filter, and the chain of
+        // `register_callsite` calls that would trigger the bug never happens...
+        .with(filter::filter_fn(|meta| meta.level() <= &Level::INFO))
+        .with(layer.with_filter(filter))
+        .set_default();
+
+    tracing::debug!("skip me please!");
+    tracing::info!(target: "magic_target", "hello world");
+
+    handle.assert_finished();
+}