Filter `field=value` doesn't work.

[wllenyj]

Bug Report

Version

master branch cargo build --exmaples

$ cargo --version cargo 1.47.0 (f3c7e066a 2020-08-28)

Platform

Linux 4.9

Crates

Description

When I run the subscriber-filter example like this, it doesn't work like I thought it would.

RUST_LOG=[shave{yak=2}] ../target/debug/examples/subscriber-filter 

Output nothing.

Run like this, it work:

$ RUST_LOG=[shave{yak}] ../target/debug/examples/subscriber-filter 
Jan 10 23:28:31.626 TRACE shave{yak=1}: subscriber_filter::yak_shave: hello! I'm gonna shave a yak excitement="yay!"
Jan 10 23:28:31.626 TRACE shave{yak=1}: subscriber_filter::yak_shave: yak shaved successfully
Jan 10 23:28:31.626 TRACE shave{yak=2}: subscriber_filter::yak_shave: hello! I'm gonna shave a yak excitement="yay!"
Jan 10 23:28:31.626 TRACE shave{yak=2}: subscriber_filter::yak_shave: yak shaved successfully
Jan 10 23:28:31.626 TRACE shave{yak=3}: subscriber_filter::yak_shave: hello! I'm gonna shave a yak excitement="yay!"
Jan 10 23:28:31.627  WARN shave{yak=3}: subscriber_filter::yak_shave: could not locate yak

I tried :

RUST_LOG=[shave{yak=\"2\"}] 
RUST_LOG=[shave{yak='2'}]
RUST_LOG="[shave{yak=\"2\"}]"

none of them worked.

Thanks all.

[hawkw]

Ah, I see the issue --- this is an interaction between how the filter is interpreted and the span generated by the #[instrument] macro. #[instrument] records all fields as fmt::Debug, but [shave{yak=2}] creates a filter that expects the numeric value 2, not a value whose fmt::Debug implementation produces the string 2. On the other hand, the filters with quotes expect a string value, not a fmt::Debug value.

To demonstrate the issue, you can try changing the shave function from

#[tracing::instrument]
pub fn shave(yak: usize) -> Result<(), Box<dyn Error + 'static>> {
   // ...
}

to

pub fn shave(yak: usize) -> Result<(), Box<dyn Error + 'static>> {
    let span = tracing::trace_span!("shave", yak);
    let _e = span.enter();
    // ...
}

With the manually created span, yak is recorded as a number. Then, the filter behaves as expected:

$ RUST_LOG="[shave{yak=2}]" cargo run --example subscriber-filter 
    Finished dev [unoptimized + debuginfo] target(s) in 0.10s
     Running `target/debug/examples/subscriber-filter`
Jan 10 10:44:28.502 TRACE shave{yak=2}: subscriber_filter::yak_shave: hello! I'm gonna shave a yak excitement="yay!"
Jan 10 10:44:28.502 TRACE shave{yak=2}: subscriber_filter::yak_shave: yak shaved successfully

We should improve how EnvFilter handles cases like this. It would probably be good to always try matching fmt::Debug output when a Debug value is recorded, even when a primitive type is expected.

[Yamakaky]

Additional faulty case:

    tracing_subscriber::fmt()
        .with_env_filter(tracing_subscriber::EnvFilter::new("[{x}]=debug"))
        .init();
    tracing::debug!(x="a", "test");

shows the DEBUG log line, but the following doesn't print anything:

    tracing_subscriber::fmt()
        .with_env_filter(tracing_subscriber::EnvFilter::new("[{x=a}]=debug"))
        .init();
    tracing::debug!(x="a", "test");

I tried using x="a", same result.

[matklad]

I am seeing the same effect, but looks like the root cause might be different. Seems filters with value somehow don't enable spans?

Ie, if I have a single filter, it doesnit work. If, however, I add a dummy fiter which matches noting, I get output:

EDIT: this might be just wrong? seems like {nope} just enables all infos

[maddiemort]

I think I'm seeing the same issue as in the original report, where the value recorded for a field comes from a type alias for u64, and I can't seem to filter on that field value with any syntax I've tried.

Has there been any progress on this issue? I see that there's a note about matching on Debug representations vs. literal values in the EnvFilter documentation, but I'm not sure if that's been around since before this issue was filed.

[davidbarsky]

I haven't been able to dig into this properly—and Eliza would probably be able to correct me on this—but most of the progress has gone to https://github.com/CAD97/tracing-filter/, which will be the successor to EnvFilter. I would try and see if you still have this issue with tracing-filter.

[msdrigg]

I've had the same issue as the original issue, but my recorded field is actually the debug representation -- not anything special with numbers or bools. No regex I can use matches the value, and even disabling regex (using EnvFilter::builder) and matching with the exact value fails.

You can see I also tried this with the tracing-filter crate, and I am seeing the same issue there

[maddiemort]

I would try and see if you still have this issue with tracing-filter.

Unfortunately it looks like tracing-filter only has two filtering implementations at the moment: simple filters, which are too simple to be able to do the kind of filtering that triggers the bug for me; and legacy filters, which are described as "100% bug-for-bug compatible" with the original, and in my testing that held true (this bug appeared there too). So that's not a solution for me, for the time being.

[juancampa]

Here's a minimal reproducible example of the filtering issue:

https://github.com/juancampa/tracing-field-filtering-repro

[farnoy]

Has anyone found a good solution to this? My workaround is this:

1. use a span! macro manually
2. event!(parent: &span, ...)

3. let env_filter =
       EnvFilter::try_from_default_env().unwrap_or_else(|_| EnvFilter::new("warn"));
   let log_file = File::create(concat!(env!("CARGO_MANIFEST_DIR"), "/log.txt")).unwrap();
   let fmt_layer = fmt::layer()
       .with_span_events(tracing_subscriber::fmt::format::FmtSpan::NONE) // this is the default
       .with_writer(log_file);

Filtering on field values only works for spans, not events, but not the enter & exit events of each span. So the only solution I could find is to output events after nesting them in a span which has the fields I want to filter on.

[seunlanlege]

I encountered this issue and this syntax worked for me

RUST_LOG="module[span{field=value}]" ./binary

Basically, don't quote the value

[pielgrzym]

Can someone modify EnvFilter docs (or other apropriate docs) to warn people that this feature is broken? This will hopefully spare someone time debugging.

[rustonaut]

Basically, don't quote the value

the doesn't work in a lot of situations

[cattingcat]

Is there any plans to fix it? Any workaround?

fn main() {
    let filter = EnvFilter::new("info,[my_span_1]=off");

    tracing_subscriber::fmt()
        .with_env_filter(filter)
        .init();

    tracing::info!("logged 1");

    let span_1 = tracing::span!(Level::INFO, "my_span_1");
    let _enter = span_1.enter();

    tracing::info!("not logged");
    tracing::warn!("logged 2");
}

2024-10-23T19:10:22.998649Z  INFO tracing2: logged 1
2024-10-23T19:10:22.998827Z  INFO my_span_1: tracing2: not logged
2024-10-23T19:10:22.998847Z  WARN my_span_1: tracing2: logged 2