[Bug] the tracing_subscriber with_filter method causes a panic

[ufoscout]

Bug Report

The following code panics when the inner::log_smt(11111); function is called:

use std::str::FromStr;
use log::*;
use tracing_subscriber::{filter::{Targets, filter_fn}, prelude::*};

mod inner {
    use super::*;

    #[tracing::instrument(fields(yak))]
    pub fn log_smt(yak: u32) {
        debug!("inner - yak: {} - this is debug", yak);
        info!("inner - yak: {} - this is info", yak);
        warn!("inner - yak: {} - this is warn", yak);
    }
}

#[test]
fn should_log() -> Result<(), std::io::Error> {

    let filter = Targets::from_str("debug,tracing_test::inner=warn").unwrap();

    let fmt_layer = tracing_subscriber::fmt::layer()
    .with_filter(filter_fn(move |_meta| true ));

    tracing_subscriber::registry().with(filter).with(fmt_layer).init();

    debug!("before inner");
    inner::log_smt(11111);
    debug!("after inner");

    Ok(())
}

The bug disappears if the .with_filter(filter_fn(move |_meta| true )) call is removed.
The bug disappears also if the Target filter is set to debug instead of debug,tracing_test::inner=warn.

Error message

If you launch the test, it panics with this message:

thread 'should_log' panicked at 'assertion failed: `(left == right)`
  left: `1`,
 right: `0`: if we are in or starting a filter pass, we must not be in an interest pass.', /home/ufo/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.22/src/filter/layer_filters.rs:611:13

Version

Here is the cargo.toml file:

[package]
name = "tracing_test"
version = "0.1.0"
edition = "2018"

[dependencies]
log = "0.4"
tracing = "0.1.27"
tracing-subscriber = "0.2.22"

Platform

$ uname -a
Linux ufo-lap-1 5.11.0-34-generic #36-Ubuntu SMP Thu Aug 26 19:22:09 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

Reproducer

Here you can find a minimal reproducer for the issue: https://github.com/ufoscout/tracing_test

[hawkw]

Thanks for the minimal reproduction, I'll try to take a look at this as soon as possible!

[hawkw]

Experimenting with the repro you've provided, it looks like this only occurs when consuming log records emitted by the log crate as events. If I replace the log macros with tracing, I don't get the panic.

This fails:

```rust
#[test]
fn repro_1563() -> Result<(), std::io::Error> {
    // Reproduces https://github.com/tokio-rs/tracing/issues/1563

    mod inner {
        use super::*;

        #[tracing::instrument]
        pub fn log(yak: u32) {
            log::debug!("inner - yak: {} - this is debug", yak);
            log::info!("inner - yak: {} - this is info", yak);
            log::warn!("inner - yak: {} - this is warn", yak);
        }
    }

    let filter = Targets::from_str("debug,layer_filters::targets::inner=warn").unwrap();

    let fmt_layer =
        tracing_subscriber::layer::Identity::new().with_filter(filter_fn(move |_meta| true));

    tracing_subscriber::registry()
        .with(filter)
        .with(fmt_layer)
        .init();

    log::debug!("before inner");

    inner::events(11111);

    log::debug!("after inner");

    Ok(())
}

But this passes:

#[test]
fn repro_1563() -> Result<(), std::io::Error> {
    // Reproduces https://github.com/tokio-rs/tracing/issues/1563

    mod inner {
        use super::*;

        #[tracing::instrument]
        pub fn events(yak: u32) {
            tracing::debug!("inner - yak: {} - this is debug", yak);
            tracing::info!("inner - yak: {} - this is info", yak);
            tracing::warn!("inner - yak: {} - this is warn", yak);
        }
    }

    let filter = Targets::from_str("debug,layer_filters::targets::inner=warn").unwrap();

    let fmt_layer =
        tracing_subscriber::layer::Identity::new().with_filter(filter_fn(move |_meta| true));

    tracing_subscriber::registry()
        .with(filter)
        .with(fmt_layer)
        .init();

    tracing::debug!("before inner");

    inner::events(11111);

    tracing::debug!("after inner");

    Ok(())
}

[ufoscout]

@hawkw are you proposing that the issue is somewhere in the log crate? Or in tracing_log?
Unluckily for us, replacing the log macro with the tracing one is not an option because log is used by external crates that we depend on.

[hawkw]

@hawkw are you proposing that the issue is somewhere in the log crate? Or in tracing_log?
Unluckily for us, replacing the log macro with the tracing one is an option because log is used by external crates that we depend on.

No, it's definitely a tracing issue, it just only occurs when using tracing's log support. I was just trying to narrow down what causes it.

I actually have a fix that should be pushed shortly!

[Noah-Kennedy]

I'm still getting this issue after updating to 0.2.23. I can try and get an MRE up tomorrow, but its getting late where I'm at.

[Noah-Kennedy]

For me, it takes several minutes for the bug to manifest.

[hawkw]

I'm still getting this issue after updating to 0.2.23. I can try and get an MRE up tomorrow, but its getting late where I'm at.

Any luck with a minimal reproduction for this? I have a guess for a potential fix, so if you can't easily minimize the issue, I can put a branch together for you to test in your application?

[hawkw]

@Noah-Kennedy if you're able to just try this branch #1575 with a Git dependency or something, I'd be interested to know if that fixes your issue?

I'd still really appreciate a minimal repro; it would be nice if we could have a test for this...but, it's not a hard blocker if the code in your program is too complicated to easily minimize.

[Noah-Kennedy]

I'll try and get an MRE up then.

[hawkw]

I'll try and get an MRE up then.

Don't worry about it if it's hard to reproduce; I'd be more interested in knowing whether that commit fixes the issue for you!

[Noah-Kennedy]

I've got an MRE, will post in a moment.

[Noah-Kennedy]

@hawkw MRE:

use std::thread::sleep;
use std::time::Duration;

use tracing_subscriber::{EnvFilter, Layer};

use tracing::level_filters::LevelFilter;
use tracing::Subscriber;
use tracing_subscriber::prelude::*;

pub fn setup_logger() {
    let universal_filter = EnvFilter::from_default_env()
        .add_directive(tracing::Level::DEBUG.into());

    let layer = get_layer();

    tracing_subscriber::registry()
        .with(layer)
        .with(universal_filter)
        .init();
}

/// This is here to get rustc to not immediately die due to type length limitations.
fn get_layer<T>() -> Box<dyn Layer<T> + Send + Sync + 'static>
    where T: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span> + Send + Sync,
{
    Box::new(
        tracing_subscriber::fmt::layer()
            .with_writer(|| std::io::stdout())
            .with_filter(
                tracing_subscriber::filter::Targets::new()
                    .with_target("hello", LevelFilter::DEBUG),
            ),
    )
}

fn main() {
    let _guard = setup_logger();

    loop {
        tracing::info!(target: "Hello", message = "Log hello");
        sleep(Duration::from_millis(20))
    }
}

Hilariously, getting rid of the Box stuff causes it to work.

[Noah-Kennedy]

For the record, rustc wont immediately die if you get rid of that right now, but it will if you start adding more output layers for different files.

[Noah-Kennedy]

I'll test it with the new fix candidate.

[Noah-Kennedy]

Can't get that branch to compile. MRE was made with v0.2.23 by the way.

[Noah-Kennedy]

Managed to get it to compile. Also simplified the MRE a bit. New MRE:

use std::thread::sleep;
use std::time::Duration;

use tracing_subscriber::Layer;

use tracing::level_filters::LevelFilter;
use tracing::Subscriber;
use tracing_subscriber::prelude::*;

pub fn setup_logger() {
    let layer = get_layer();

    tracing_subscriber::registry()
        .with(layer)
        .init();
}

/// This is here to get rustc to not immediately die due to type length limitations.
fn get_layer<T>() -> Box<dyn Layer<T> + Send + Sync + 'static>
    where T: Subscriber + for<'span> tracing_subscriber::registry::LookupSpan<'span> + Send + Sync,
{
    Box::new(
        tracing_subscriber::fmt::layer()
            .with_writer(|| std::io::stdout())
            .with_filter(
                tracing_subscriber::filter::Targets::new()
                    .with_target("hello", LevelFilter::DEBUG),
            ),
    )
}

fn main() {
    let _guard = setup_logger();

    loop {
        tracing::info!(target: "Hello", message = "Log hello");
        sleep(Duration::from_millis(20))
    }
}