Event macros not behaving as expected with more complex message formatting with filter layers

[pitoniak32]

Bug Report

Version

❯ cargo tree | rg tracing 
│   │   │   │   ├── tracing-core v0.1.32
│   │   │   │   └── tracing-error v0.2.0
│   │   │   │       ├── tracing v0.1.40
│   │   │   │       │   ├── tracing-attributes v0.1.27 (proc-macro)
│   │   │   │       │   └── tracing-core v0.1.32 (*)
│   │   │   │       └── tracing-subscriber v0.3.18
│   │   │   │           ├── tracing-core v0.1.32 (*)
│   │   │   │           └── tracing-log v0.2.0
│   │   │   │               └── tracing-core v0.1.32 (*)
│   │   │   └── tracing-error v0.2.0 (*)
│   │   ├── tracing v0.1.40 (*)
│   │       │   │   │   │   └── tracing v0.1.40 (*)
│   │       │   │   │   └── tracing v0.1.40 (*)
│   │       │   │   ├── tracing v0.1.40 (*)
│   │       │   │   └── tracing v0.1.40 (*)
│   │       └── tracing v0.1.40 (*)
├── tracing v0.1.40 (*)
├── tracing-log v0.2.0 (*)
├── tracing-opentelemetry v0.22.0
│   ├── tracing v0.1.40 (*)
│   ├── tracing-core v0.1.32 (*)
│   ├── tracing-log v0.2.0 (*)
│   └── tracing-subscriber v0.3.18 (*)
├── tracing-subscriber v0.3.18 (*)

Platform

❯ uname -a          
Linux d 5.15.133.1-microsoft-standard-WSL2 #1 SMP Thu Oct 5 21:02:42 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Crates

these are the crates in my Cargo.toml. I am suspecting the issue is in tracing because its dealing with the event level macros.

tracing = "0.1"
tracing-log = "0.2.0"
tracing-subscriber = { version = "0.3", features = ["env-filter", "registry"] }
tracing-opentelemetry = "0.22.0"

Description

I am setting up a project that is using 2 subscribers in a Registry.

• tracing_subscriber::fmt::layer().pretty().with_filter(log_filter)
• tracing_opentelemetry::layer().with_tracer(...).with_filter(LevelFilter::TRACE)

So I can ship at different filter levels to each. I noticed that one of my info!() calls was still showing in the logs no mater what I had the level of the fmt subscriber. I was able to reproduce it.

This is the behavior I am seeing:

use tracing::{error, info_span, metadata::LevelFilter, info, trace, event, Level};
...
let test = Project::new(&PathBuf::from("test"), "test".to_owned(), "".to_string());

info!("info! no formatting");
info!("info! static str formatting: {}", "formatted");
let name = test.get_safe_name();
info!("info! variable object formatting: {}", name);
info!("info! inline object formatting: {}", test.get_safe_name());

trace!("trace! no formatting");
trace!("trace! static str formatting: {}", "formatted");
let name = test.get_safe_name();
trace!("trace! variable object formatting: {}", name);
trace!("trace! inline object formatting: {}", test.get_safe_name());

event!(Level::INFO, "event! no formatting");
event!(Level::INFO, "event! static str formatting: {}", "formatted");
let name = test.get_safe_name();
event!(Level::INFO, "event! variable object formatting: {}", name);
event!(Level::INFO, "event! inline object formatting: {}", test.get_safe_name());

results in:

[src/main.rs:21:24] &cli.args.verbosity.log_level_filter().as_trace() = LevelFilter::ERROR
  2024-02-18T17:24:22.385856Z  INFO axl: info! inline object formatting: test
    at src/main.rs:44

  2024-02-18T17:24:22.386022Z TRACE axl: trace! inline object formatting: test
    at src/main.rs:50

  2024-02-18T17:24:22.386157Z  INFO axl: event! inline object formatting: test
    at src/main.rs:56

I am expecting to see none of these events in the logs because the filter level is ERROR, and it behaves like that other than when calling the function to get name directly in the macro.

Its not a huge deal for me to just use a variable, I just wanted to bring attention to this. It was very confusing at first, and I thought it was something to do with my layer filters.

Please let me know if you need any other details! I am willing to give more code, or even make a minimal reproduction if needed. Thank you for working on such an amazing project :)

[kaffarell]

Seems to be working for me... Can you post the setup of the registry and layers?

[pitoniak32]

I call this from main after parsing the clap-cli for the verbosity, and before the code

fn configure_tracing(log_filter: LevelFilter) -> Result<()> {
    tracing_subscriber::registry()
        .with(
            // set layer for log subscriber
            tracing_subscriber::fmt::layer()
                .pretty()
                .with_filter(log_filter),
        )
        .with(std::env::var("OTEL_COLLECTOR_URL").map_or_else(
            |_| None,
            |url| {
                Some(
                    tracing_opentelemetry::layer()
                        .with_tracer(
                            opentelemetry_otlp::new_pipeline()
                                .tracing()
                                .with_exporter(
                                    opentelemetry_otlp::new_exporter()
                                        .tonic()
                                        .with_endpoint(url),
                                )
                                .with_trace_config(
                                    opentelemetry_sdk::trace::config().with_resource(
                                        Resource::new(vec![KeyValue::new(
                                        opentelemetry_semantic_conventions::resource::SERVICE_NAME
                                            .to_string(),
                                        env!("CARGO_PKG_NAME"),
                                    )]),
                                    ),
                                )
                                .install_batch(opentelemetry_sdk::runtime::Tokio)
                                .expect("Failed creating the tracer!"),
                        )
                        .with_filter(
                            // If no `RUST_LOG` is provided use info.
                            tracing_subscriber::EnvFilter::try_from_default_env()
                                .unwrap_or_else(|_| "info".into()),
                        ),
                )
            },
        ))
        .init();

    Ok(())
}

[kaffarell]

Works for me with this code... could you maybe post a minimal example without the opentel layer?

[pitoniak32]

Works for me with this code... could you maybe post a minimal example without the opentel layer?

for sure, I will try and recreate when I get out of work today 👍🏼

[pitoniak32]

So I tried making a min reproduction, and am not seeing the issue anymore. I started playing around with the way I setup to get the error, and it seems like my .with_filter(...) on the otel layer is bleeding into the fmt layer 🤔

but it only happens with the inline function calls for the event macros 😓