From 76355a6b2d1d5ad1001065c97aa8a9bf854fe0f9 Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Wed, 15 Sep 2021 19:45:23 -0700
Subject: [PATCH] subscriber: clear per-layer interest when short circuiting
 (#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 #1563.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 tracing-subscriber/src/layer/layered.rs       |  6 ++
 .../tests/layer_filters/main.rs               |  1 +
 .../tests/layer_filters/targets.rs            | 59 +++++++++++++++++++
 3 files changed, 66 insertions(+)
 create mode 100644 tracing-subscriber/tests/layer_filters/targets.rs

diff --git a/tracing-subscriber/src/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs
index ee9d61ad5b..dae885269d 100644
--- a/tracing-subscriber/src/layer/layered.rs
+++ b/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;
         }
 
diff --git a/tracing-subscriber/tests/layer_filters/main.rs b/tracing-subscriber/tests/layer_filters/main.rs
index 445b029cf6..ccc4ef2679 100644
--- a/tracing-subscriber/tests/layer_filters/main.rs
+++ b/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};
diff --git a/tracing-subscriber/tests/layer_filters/targets.rs b/tracing-subscriber/tests/layer_filters/targets.rs
new file mode 100644
index 0000000000..c8133044b1
--- /dev/null
+++ b/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();
+}