Unexpected behavior with layered filters in tracing Registry #3364
Description
Bug Report
Version
Platform
all platform
Crates
tracing-subscriber
Description
When I have multiple layers on the Registry, and one layer has a configured layered filter, the filter behavior is not as expected.
Minimum reproducible example
struct MyDummyLayer;
impl<S> Layer<S> for MyDummyLayer
where
S: Subscriber + 'static + for<'a> LookupSpan<'a>,
{
}
#[tokio::main]
async fn main() {
let filter = EnvFilter::from_default_env().add_directive(Level::INFO.into());
tracing_subscriber::registry()
.with(MyDummyLayer)
.with(
tracing_subscriber::fmt::layer()
.with_filter(filter))
.init();
do_sth().await;
}
async fn do_sth() {
debug!("xxxxxxxxx before do_sth {:?}", inner());
}
fn inner() -> String {
debug!(foo = "bar");
"inner".into()
}
The issue I met
The following code demonstrates the case:
I set up a Registry with two layers:
1. A dummy layer that I expect to collect all levels of events.
2. An fmt layer configured to collect only INFO level events.
I then found that when using a function call inside the trace::info! / trace::debug! macros (e.g. do_sth()), the layer filter behavior is unexpected.
Expected behavior
No logs should be printed, since I only want events at INFO level or higher.
Actual behavior
A debug! log still gets printed:
then after I changed the code, it works as expected
async fn do_sth() {
let res = inner();
debug!("xxxxxxxxx before do_sth {:?}", res);
}
Investigation
After expanding the macro and digging into the implementation, I suspect the issue may be related to the thread-local FilterState.
It looks like the second event emitted from inner resets the filter bit, and then when the first event comes, it finds the filter bit is not set, so it bypasses the filter.
This behavior is very confusing. I’m not sure if this is expected behavior or if I’m using the filters or tracing incorrectly.