Skip to content

Commit

Permalink
subscriber: clear per-layer interest when short circuiting (#1569)
Browse files Browse the repository at this point in the history
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 <[email protected]>
  • Loading branch information
hawkw authored and davidbarsky committed Nov 29, 2021
1 parent eca8d07 commit 133be44
Show file tree
Hide file tree
Showing 3 changed files with 66 additions and 0 deletions.
6 changes: 6 additions & 0 deletions tracing-subscriber/src/layer/layered.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down
1 change: 1 addition & 0 deletions tracing-subscriber/tests/layer_filters/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@
mod support;
use self::support::*;
mod filter_scopes;
mod targets;
mod trees;

use tracing::{level_filters::LevelFilter, Level};
Expand Down
59 changes: 59 additions & 0 deletions tracing-subscriber/tests/layer_filters/targets.rs
Original file line number Diff line number Diff line change
@@ -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();
}

0 comments on commit 133be44

Please sign in to comment.