How to preserve fields when spans are filtered out by EnvFilter?

[gdesmott]

See this test app:

use tracing::instrument;
use tracing_subscriber::{prelude::*, EnvFilter};

fn main() {
    let env_filter = EnvFilter::try_from_env("TEST").unwrap();
    let (non_blocking, _non_block_guard) = tracing_appender::non_blocking(std::io::stdout());
    let mut fmt_layer = tracing_subscriber::fmt::layer()
        .with_thread_ids(true)
        .with_target(true)
        .with_writer(non_blocking);
    fmt_layer = fmt_layer.with_span_events(
        tracing_subscriber::fmt::format::FmtSpan::ENTER
            | tracing_subscriber::fmt::format::FmtSpan::CLOSE,
    );

    let subscriber = tracing_subscriber::Registry::default()
        .with(env_filter)
        .with(fmt_layer);

    tracing::subscriber::set_global_default(subscriber).expect("Failed to set subscriber");

    test();
}

#[instrument(name = "function span", level = "debug", fields(badger = "mushroom"))]
fn test() {
    tracing::debug!("debug");
    tracing::info!("info");
}

When running with TEST=debug it works as expected:

12342024-01-09T08:29:31.898879Z DEBUG ThreadId(01) function span{badger="mushroom"}: test_tracing: enter
2024-01-09T08:29:31.898902Z DEBUG ThreadId(01) function span{badger="mushroom"}: test_tracing: debug
2024-01-09T08:29:31.898908Z  INFO ThreadId(01) function span{badger="mushroom"}: test_tracing: info
2024-01-09T08:29:31.898917Z DEBUG ThreadId(01) function span{badger="mushroom"}: test_tracing: close time.busy=40.9µs time.idle=6.39µs

But with TEST=info we no longer have the span variable in the logging! message:

12024-01-09T08:29:28.610985Z  INFO ThreadId(01) test_tracing: info

That's because the span is level=debug but that's quite annoying as I'd still like to get the full context when displaying only info logs.

Is there any way to do that? Thanks!

[hawkw]

If you disable the DEBUG level with filtering, then spans at the DEBUG level will not be recorded. If you want your span to be recorded when DEBUG is disabled, consider changing the level of your span to INFO or higher.

[gdesmott]

I get that the ENTER and CLOSE events are not recorded when disabling the DEBUG level, but I would have expected their fields would still be passed over INFO events.

Is there any way to do that?

[hawkw]

No, if the DEBUG level is disabled, then DEBUG spans will never be recorded. Filtering in tracing is not just a mechanism for determining what is displayed; instead, the purpose purpose of filtering is to prevent unneeded spans and events from being recorded at all, in order to avoid the performance cost of recording them.

The primary way the fmt subscriber displays a recorded span is by using that span as context for events that occur within the span. If a span is disabled, then no events are considered to be occurring "inside" that span, because the span does not exist. Displaying the ENTER/EXIT/CLOSE events is just an additional, optional behavior of the fmt subscriber.

[gdesmott]

Filtering in tracing is not just a mechanism for determining what is displayed; instead, the purpose purpose of filtering is to prevent unneeded spans and events from being recorded at all, in order to avoid the performance cost of recording them.

Thanks for the clarification, that makes sense then.

It's a bit unfortunate as it means that one always has to use the highest level for high level spans holding the context fields (like #[instrument]) and so will always have those displayed when using ENTER/EXIT/CLOSE.

Is there a popular pattern I could use to mitigate this problem?