Filter fails to match when matching on field contents

[wmmc88]

Bug Report

Version

├── tracing v0.1.40
│   ├── tracing-attributes v0.1.27 (proc-macro)
│   └── tracing-core v0.1.32
└── tracing-subscriber v0.3.18
    ├── tracing v0.1.40 (*)
    ├── tracing-core v0.1.32 (*)
    ├── tracing-log v0.2.0
    │   └── tracing-core v0.1.32 (*)
    └── tracing-serde v0.1.3
        └── tracing-core v0.1.32 (*)

Platform

Windows 11 Enterprise(10.0.22631)

Description

It seems that when matching the contents of a field in a filter, the filter fails to work. When only matching the field name in the working function, the subscriber exhibits the expected behavior of no printed logs. When matching the contents of the fields in the broken function, the subscriber fails to filter out the two logs.

use tracing::{event, level_filters::LevelFilter, warn, Level};
use tracing_subscriber::filter::EnvFilter;

fn broken() {
    let tracing_filter = EnvFilter::default()
        .add_directive(LevelFilter::TRACE.into())
        .add_directive("[{message=hello}]=off".parse().unwrap())
        .add_directive("[{number=1337}]=off".parse().unwrap());

    tracing_subscriber::fmt()
        .json()
        .with_env_filter(tracing_filter)
        .init();

    warn!("hello");
    event!(Level::INFO, number = 1337);
}

fn working() {
    let tracing_filter = EnvFilter::default()
        .add_directive(LevelFilter::TRACE.into())
        .add_directive("[{message}]=off".parse().unwrap())
        .add_directive("[{number}]=off".parse().unwrap());

    tracing_subscriber::fmt()
        .json()
        .with_env_filter(tracing_filter)
        .init();

    warn!("hello");
    event!(Level::INFO, number = 1337);
}

fn main() {}

mod tests {
    use super::*;

    #[test]
    fn test_broken() {
        broken();
    }

    #[test]
    fn test_working() {
        working();
    }
}

The repro code is also available here in the tracing-field-filter-bug branch: https://github.com/wmmc88/minimal-repros/tree/tracing-field-filter-bug.

Output:

🪟 Windows 11 Enterprise(10.0.22631) (pwsh) tracing-field-filter-bug on  tracing-field-filter-bug is 📦 v0.1.0 via 🦀 v1.75.0 
at 09:33:09 AM ❯ cargo test broken 
   Compiling tracing-field-filter-bug v0.1.0 (D:\git-repos\github\tracing-field-filter-bug)
    Finished test [unoptimized + debuginfo] target(s) in 1.10s
     Running unittests src\main.rs (target\debug\deps\tracing_field_filter_bug-9c0ff772881a3859.exe)

running 1 test
{"timestamp":"2024-01-04T17:33:21.159651Z","level":"WARN","fields":{"message":"hello"},"target":"tracing_field_filter_bug"}
{"timestamp":"2024-01-04T17:33:21.159956Z","level":"INFO","fields":{"number":1337},"target":"tracing_field_filter_bug"}
test tests::test_broken ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 1 filtered out; finished in 0.01s

🪟 Windows 11 Enterprise(10.0.22631) (pwsh) tracing-field-filter-bug on  tracing-field-filter-bug is 📦 v0.1.0 via 🦀 v1.75.0 took 2s
at 09:33:21 AM ❯ cargo test working
    Finished test [unoptimized + debuginfo] target(s) in 0.05s
     Running unittests src\main.rs (target\debug\deps\tracing_field_filter_bug-9c0ff772881a3859.exe)

running 1 test
test tests::test_working ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 1 filtered out; finished in 0.01s

I would have expected both tests to not print any of the 2 logs since the filter should set the level of those logs to off.

[kaffarell]

Hmm afaik the matching for field values only works with spans...

 let tracing_filter = EnvFilter::default()
    .add_directive(LevelFilter::ERROR.into())
    .add_directive("[{number=1337}]=trace".parse().unwrap());

let _guard = tracing::span!(Level::INFO, "test", number = 1337).entered();
tracing::event!(Level::INFO, "hello");
_guard.exit();

let _guard = tracing::span!(Level::INFO, "test", number = 1437).entered();
tracing::event!(Level::INFO, "hello1");
_guard.exit();