`tracing::enabled` false positives when using Reload layer

[howardjohn]

Bug Report

Version

Built from main e4df7612

Platform

Linux zen 6.15.5-arch1-1

Crates

tracing-subscriber

Description

When Reload is used, tracing::enabled!() returns a false positive (true when the log is not actually enabled).

Reproducer:

#![deny(rust_2018_idioms)]

use std::env;
use std::str::FromStr;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;
use tracing_subscriber::{filter, reload, Layer};

#[path = "fmt/yak_shave.rs"]
mod yak_shave;

fn default_filter() -> filter::Targets {
    let var: String = env::var("RUST_LOG")
        .map_err(|_| ())
        .unwrap_or("info".to_string());
    filter::Targets::from_str(&var).expect("static filter should build")
}

fn main() {
    use tracing_subscriber::{fmt, EnvFilter};
    let (layer, reload) = reload::Layer::new(
        Box::new(tracing_subscriber::fmt::layer()).with_filter(default_filter()),
    );
    tracing_subscriber::registry()
        .with(layer)
        //.with(tracing_subscriber::fmt::layer().with_filter(default_filter()))
        .init();

    let enabled = tracing::enabled!(target: "request", tracing::Level::INFO);
    let enabled_warn = tracing::enabled!(target: "request", tracing::Level::WARN);
    // let enabled_warn = false;
    println!("enabled={enabled} warn={enabled_warn}");
    let number_of_yaks = 3;
    tracing::info!(target: "request", "log at info level");

    let number_shaved = yak_shave::shave_all(number_of_yaks);

    tracing::warn!(
        target: "request",
        message = "log at warn level",
        all_yaks_shaved = number_shaved == number_of_yaks,
    );
}

Here we see info is marked as "enabled"; the log will NOT be logged

$ RUST_LOG=request=warn,info cargo run --example subscriber-filter
enabled=true warn=true

Here it is properly handled:

$ RUST_LOG=request=warn cargo run --example subscriber-filter
enabled=false warn=true

[thomaseizinger]

I am also hitting this. This leads to quite the performance regression for us as I have some trace! logs in the hot path of our application and profiling it showed that this is consuming about 15% of CPU time.

[howardjohn]

We worked around this via

static LOG_HANDLE: OnceCell<LogHandle>  = ...
pub fn enabled(target: &'static str, level: &tracing::Level) -> bool {
	if let Some(handle) = LOG_HANDLE.get() {
		handle
			.with_current(|f| f.filter().would_enable(target, level))
			.unwrap_or_default()
	} else {
		false
	}
}

(where we set LOG_HANDLE from the reload layer)