Querying "enabled" from the log crate makes tracing swallow the next event

[rtimush]

Bug Report

Version

├── tracing v0.1.37
│   ├── tracing-attributes v0.1.23 (proc-macro)
│   └── tracing-core v0.1.30
└── tracing-subscriber v0.3.16
    ├── tracing v0.1.37 (*)
    ├── tracing-core v0.1.30 (*)
    └── tracing-log v0.1.3
        └── tracing-core v0.1.30 (*)

Platform

Darwin roman.timushev-MacBookPro 22.3.0 Darwin Kernel Version 22.3.0: Mon Jan 30 20:38:37 PST 2023; root:xnu-8792.81.3~2/RELEASE_ARM64_T6000 arm64 arm Darwin

Description

Querying "enabled" from the log crate in some cases makes tracing swallow the next event. Example code:

use tracing_subscriber::{fmt, prelude::*, EnvFilter};

fn main() {
    tracing_subscriber::registry()
        .with(fmt::layer().with_filter(EnvFilter::from_default_env()))
        .init();

    tracing::info!("this is logged");
    let _ = log::logger().enabled(&log::Metadata::builder().level(log::Level::Debug).build());
    tracing::info!("this is not logged");
    tracing::info!("this is logged again");
}

If executed with RUST_LOG=<crate_name>=debug,info, the second info! is not logged.

This doesn't happen if:

• the filter is applied not to the logging layer but to the whole subscriber
• RUST_LOG is set to debug or <crate_name>=info,info

The Cargo.toml dependencies section:

[dependencies]
log = "0.4.17"
tracing = "0.1.37"
tracing-subscriber = { version = "0.3.16", features = ["env-filter"] }

[scottlamb]

Thanks for filing this! I was on the trail of one of my spans getting swallowed, realized commenting out tracing_log::LogTracer::init() "fixed" it, searched, and found this timely bug report with a nice minimal repro.

[scottlamb]

I'd love to get this fixed, and have been reading the code a bit, but I'm really confused about how per-layer filtering is supposed to work. E.g., starting from the basics:

https://github.com/tokio-rs/tracing/blob/a0126b2e2d465e8e6d514acdf128fcef5b863d27/tracing-subscriber/src/registry/sharded.rs#L229-L232

<Registry as Subscriber>::enabled returns some pre-set state from a thread local. Is there some contract that something else should have been called first? From reading tracing::Subscriber docs, it sounds like it's more common to go through register_callsite, but this isn't actually required? So I don't understand how this enabled implementation can work? am I missing something?

[hds]

I've reproduced this without log. It seems that Dispatch::enabled() affects the next call-site to be registered.

Cargo.toml:

[package]
name = "tracing-lost-callsite"
version = "0.1.0"
edition = "2021"

[dependencies]
tracing = "0.1.37"
tracing-core = "0.1.31"
tracing-subscriber = "0.3.17"

src/main.rs:

fn main() {
    use tracing_subscriber::prelude::*;

    // Change this to DEBUG and the supressed INFO event will be recorded.
    let filter = tracing_core::LevelFilter::INFO;
    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::layer().with_filter(filter))
        .init();

    tracing::info!("this event is unaffected");

    let metadata = make_metadata_with_level(tracing_core::Level::DEBUG);
    let enabled = tracing::dispatcher::get_default(|dispatch| dispatch.enabled(&metadata));

    tracing::info!("this event gets suppressed");
    tracing::info!("The callsite was enabled? {}", enabled);
}

fn make_metadata_with_level(level: tracing_core::Level) -> tracing::Metadata<'static> {
    struct Cs;
    impl tracing_core::Callsite for Cs {
        fn set_interest(&self, _interest: tracing_core::Interest) {}
        fn metadata(&self) -> &tracing_core::Metadata<'_> {
            unimplemented!()
        }
    }

    tracing::Metadata::new(
        "",
        "app",
        level,
        None,
        None,
        None,
        tracing::field::FieldSet::new(&[], tracing_core::identify_callsite!(&Cs)),
        tracing::metadata::Kind::EVENT,
    )
}

[hawkw]

I've reproduced this without log. It seems that Dispatch::enabled() affects the next call-site to be registered.

Cargo.toml:

[package]
name = "tracing-lost-callsite"
version = "0.1.0"
edition = "2021"

[dependencies]
tracing = "0.1.37"
tracing-core = "0.1.31"
tracing-subscriber = "0.3.17"

src/main.rs:

fn main() {
    use tracing_subscriber::prelude::*;

    // Change this to DEBUG and the supressed INFO event will be recorded.
    let filter = tracing_core::LevelFilter::INFO;
    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::layer().with_filter(filter))
        .init();

    tracing::info!("this event is unaffected");

    let metadata = make_metadata_with_level(tracing_core::Level::DEBUG);
    let enabled = tracing::dispatcher::get_default(|dispatch| dispatch.enabled(&metadata));

    tracing::info!("this event gets suppressed");
    tracing::info!("The callsite was enabled? {}", enabled);
}

fn make_metadata_with_level(level: tracing_core::Level) -> tracing::Metadata<'static> {
    struct Cs;
    impl tracing_core::Callsite for Cs {
        fn set_interest(&self, _interest: tracing_core::Interest) {}
        fn metadata(&self) -> &tracing_core::Metadata<'_> {
            unimplemented!()
        }
    }

    tracing::Metadata::new(
        "",
        "app",
        level,
        None,
        None,
        None,
        tracing::field::FieldSet::new(&[], tracing_core::identify_callsite!(&Cs)),
        tracing::metadata::Kind::EVENT,
    )
}

Thanks for the repro, this is great. We could add this as a regression test for a fix.

Is constructing a Metadata with None location, filename, and module path necessary to trigger this issue?

[hds]

@hawkw I don't believe so, this was just supposed to be minimal. Another repro is via tracing-log. This is the one described in this issue, but I don't know whether the Metadata created from tracing-log has no location, filename, etc (I just haven't had a chance to check).

use tracing_subscriber::prelude::*;

fn main() {
    let env_filter = tracing_subscriber::filter::EnvFilter::new("other_mod=debug,debug");
    let fmt_layer = tracing_subscriber::fmt::layer().with_filter(env_filter);
    tracing_subscriber::registry().with(fmt_layer).init();

    tracing::error!("this error is unaffected");
    _ = log::log_enabled!(target: "other_mod", log::Level::Debug);
    tracing::error!("this error gets suppressed");
}

[hawkw]

Cool, I think you're right, but I was just checking to make sure.

[svix-aaron1011]

This issue appears to be with the FILTERING thread-local used by the Filtered layer. When enabled is called, it updates it with the underlying filter result:

https://github.com/tokio-rs/tracing/blob/bac25085fcea68ca30b8e19b8981fbd689f53735/tracing-subscriber/src/filter/subscriber_filters/mod.rs#L749-L750

This expects a matching call to on_new_span or on_event , which call did_enabled to reset the FILTERING state:

https://github.com/tokio-rs/tracing/blob/bac25085fcea68ca30b8e19b8981fbd689f53735/tracing-subscriber/src/filter/subscriber_filters/mod.rs#L1161-L1166

However, when enabled is manually called (e.g. from log::log_enabled), there isn't a matching call, which will cause an unrelated span/event to get ignored.