None-layers resets loglevel

[fredr]

Bug Report

Version

❯ cargo tree | grep tracing
├── tracing v0.1.36
│   ├── tracing-attributes v0.1.22 (proc-macro)
│   └── tracing-core v0.1.29
└── tracing-subscriber v0.3.15
    ├── tracing-core v0.1.29 (*)
    └── tracing-log v0.1.3
        └── tracing-core v0.1.29 (*)

Platform

Linux runner 5.15.55-1-MANJARO #1 SMP PREEMPT Fri Jul 15 09:45:39 UTC 2022 x86_64 GNU/Linux

Crates

tracing-subscriber

Description

#2195 causes our log level to be set to off when having a None-layer in our chain. This is a bit of an edge case, and I might have a bit of an unholy setup. But I would expect the following code to print out debug and info, but it prints out nothing (in tracing-subscriber v0.3.11 this works as I expect it to).

Here is a minimal repro of my problem:

use tracing::{debug, dispatcher, info, trace};
use tracing_subscriber::{
    self, filter,
    layer::{Context, Filter},
    prelude::__tracing_subscriber_SubscriberExt,
    Layer, Registry,
};

pub struct SomeFilter;

impl<S> Filter<S> for SomeFilter {
    fn enabled(&self, _metadata: &tracing::Metadata<'_>, _ctx: &Context<'_, S>) -> bool {
        true
    }
}

fn main() {
    let layer = tracing_subscriber::fmt::layer()
        .with_filter(filter::LevelFilter::DEBUG)
        .with_filter(SomeFilter);

    let maybe_layer = false.then(|| tracing_subscriber::fmt::layer());

    let subscriber = Registry::default().with(layer).with(maybe_layer);
    dispatcher::set_global_default(dispatcher::Dispatch::new(subscriber)).unwrap();

    info!("info about yaks");
    debug!("debug about yaks");
    trace!("trace about yaks");
}

In reality the optional layer is a tokio console, and SomeFilter filters out things based on metadata, like target, and the loglevel is set via a cli flag.

If I change the Layer implementation of Option in tracing-subscriber to the following it all works as expected:

    #[inline]
    fn max_level_hint(&self) -> Option<LevelFilter> {
        match self {
            Some(ref inner) => inner.max_level_hint(),
            None => None, // <-- changed to None
        }
    }

However, that is the reverse of what the mentioned pr does, so I'm not sure what the solution is here. Is this a bug, or are we doing something strange with our setup?

[fredr]

Noted that if I change the order of these filters it works as expected:

    let layer = tracing_subscriber::fmt::layer()
        .with_filter(filter::LevelFilter::DEBUG)
        .with_filter(SomeFilter);

And it also works as expected(?) if I implement max_level_hint on SomeFilter and there set it to DEBUG or TRACE.

[fredr]

I should also mention that if I remove .with_filter(SomeFilter) it also works as expected 🤔

[fredr]

This actually seems to have to do with layers that have max_level_hint set to None (like SomeFilter in the previous example).

The same issue occurs with this code, here the outermost layer have log level set to OFF, then a middle layer where it is set to None, and an inner layer set to DEBUG. It will not print any log rows. But if we remove the middle layer, INFO and DEBUG logs are printed.

use tracing::{debug, dispatcher, info, metadata::LevelFilter, trace};
use tracing_subscriber::{
    self, filter, layer::Context, prelude::__tracing_subscriber_SubscriberExt, Layer, Registry,
};

pub struct MyLayer {
    level: Option<filter::LevelFilter>,
}

impl MyLayer {
    fn new(level: Option<filter::LevelFilter>) -> Self {
        Self { level }
    }
}

impl<S: tracing::Subscriber> Layer<S> for MyLayer {
    fn enabled(&self, _metadata: &tracing::Metadata<'_>, _ctx: Context<'_, S>) -> bool {
        true
    }

    fn max_level_hint(&self) -> Option<filter::LevelFilter> {
        self.level
    }
}

fn main() {
    let layer = tracing_subscriber::fmt::layer().with_filter(filter::LevelFilter::DEBUG);

    let subscriber = Registry::default()
        .with(layer)
        .with(MyLayer::new(None))
        .with(MyLayer::new(Some(LevelFilter::OFF)));

    dispatcher::set_global_default(dispatcher::Dispatch::new(subscriber)).unwrap();

    info!("info about yaks");
    debug!("debug about yaks");
    trace!("trace about yaks");
}

So I wonder if this actually have to do with the Layered::pick_level_hint, should that maybe return the inner hint instead of None here? https://github.com/tokio-rs/tracing/blob/master/tracing-subscriber/src/subscribe/layered.rs#L489

Something like this https://github.com/tokio-rs/tracing/compare/master...EmbarkStudios:tracing:fredr/layered-pick-inner-hint?expand=1

That at least seems to solve my edge case, and tests seems to pass, but I'm in over my head a bit here

Edit: This was a bit of a side track, while it solves the problem for the repro above, it doesnt for our real application.

[guswynn]

@fredr do you mind telling me what LevelFilter::current() is in the latest repro (the MyLayer one), as well as in your real application?

[fredr]

Hey @guswynn, sorry for making this issue more complicated than it needed to be. The maybe_layer code is more close to the real app than the MyLayer code, but maybe they are still related somehow.

A difference in the result between our real app and the example code is that the example code gets reset to OFF while the real app gets reset to INFO. (This was ran from before the dispatch is installed and just after it was installed, did you want me to run it at some other point?)

LevelFilter::current() for the real app is info, and for the repros it is off, so it seems the level is reset to that at some point? 🤔

[YaLTeR]

I believe I'm hitting the same issue. I have the following code:

    let profiling_layer = if env::var_os("BXT_RS_PROFILE").is_some() {
        let (chrome_layer, guard) = tracing_chrome::ChromeLayerBuilder::new()
            .file("trace.json")
            .include_args(true)
            .include_locations(false)
            .build();

        Box::leak(Box::new(guard));

        Some(chrome_layer)
    } else {
        None
    };

    tracing_subscriber::registry()
        .with(file_layer)
        .with(profiling_layer)
        // Term layer must be last, otherwise the log file will have some ANSI codes:
        // https://github.com/tokio-rs/tracing/issues/1817
        .with(term_layer)
        .init();

When profiling_layer is None no tracing events are emitted at all now--this used to work fine a few versions back.

[guswynn]

@YaLTeR do you mind posting what LevelFilter::current() is with the profiling layer None and Some(_)? I have a hunch this is a similar bug to #2193 (also, what versions are tracing-subscriber are you using?)

[YaLTeR]

I'm using:

tracing = "0.1.36"
tracing-chrome = "0.6.0"
tracing-subscriber = "0.3.15"

None gives me LevelFilter::current() = off, Some(_) gives me LevelFilter::current() = trace.

[pimeys]

We have this exact problem in Prisma. All logs disappeared when doing a routine cargo update. Spent a few hours, found the culprit was tracing-subscriber going from 0.3.11 to 0.3.15.

Our logger code is kind of complex, and I haven't found a workaround yet:

https://github.com/prisma/prisma-engines/blob/main/query-engine/query-engine-node-api/src/logger.rs

For now, I'm downgrading to 0.3.11. I'd be happy to find a workaround, but also would be great if breaking changes like this would actually change the major version, so we can still cargo update without worrying too much.

[guswynn]

Sorry about the delayed response here eveyone:

I did find time to look deeper into this and believe to have found the culprit broken code in the Layered impl. My fix works, but breaks a subtle corner of the fmt layer, so I'll need to talk to the tracing devs this week

I believe there is also a simple-ish workaround (attaching a blank filter), but I will need to test this sometime this week.

[hawkw]

@guswynn any updates on the fix for this? Happy to help get it through!

[guswynn]

@hawkw the fix is basically to add ? on the 2 values here before comparing them https://github.com/tokio-rs/tracing/blob/master/tracing-subscriber/src/subscribe/layered.rs#L497

this passes all tests except for 1 test on the fmt layer, which is that fmt_sets_max_level_hint breaks, because the fmt layer implements Collect (Subscriber on 0.1), I suspect its cause we lack this: https://docs.rs/tracing-subscriber/latest/src/tracing_subscriber/layer/layered.rs.html#474-476, but I'm not sure

[guswynn]

@hawkw here is my test branch:https://github.com/guswynn/tracing/tree/option-test