tokio-rs / tracing

Application level tracing for Rust.
https://tracing.rs
MIT License
5.15k stars 673 forks source link

macros: Fix if_log_enabled condition. #2916

Closed jevolk closed 3 months ago

jevolk commented 3 months ago

Prior to this patch the feature 'max_level_info' failed to prevent codegen from the expansion of debug! and trace! macros. Indeed their logging output was muted as expected, but code was still being generated for them; explaining how this could remain unnoticed.

Furthermore, after this patch without 'max_level_info' featured, the macros expand to approximately half the amount of code than before.

Motivation

Solution

kaffarell commented 3 months ago

This changes the behavior... For example when using max_level_info it now outputs only trace and debug logs.

jevolk commented 3 months ago

This changes the behavior... For example when using max_level_info it now outputs only trace and debug logs.

Was this observed after building with the rust toolchain or the eyeball nightly?

kaffarell commented 3 months ago

Was this observed after building with the rust toolchain or the eyeball nightly?

What do you mean by eyeball nightly? Latest stable and nightly return the same results.

jevolk commented 3 months ago

Did you build this code or are you reviewing it at a glance? What versions of the relevant crates such as tracing-core did you build it against? Have the values of the log level enumeration changed very recently to moot this patch? I would surmise the level values changed at some point in the past and caused this regression.

I am open to learning that I built this package wrong. Short of that, there is absolutely a bug in this code, exactly as I described.

kaffarell commented 3 months ago

Did you build this code or are you reviewing it at a glance?

I built it with nightly and stable. Also applied this patch on master and v0.1.x, both generating the same result.

What versions of the relevant crates such as tracing-core did you build it against? Have the values of the log level enumeration changed very recently to moot this patch? I would surmise the level values changed at some point in the past and caused this regression.

I used all the versions from the latest master branch. I don't think the log level values have changed recently...

But do you get the same output with this patch applied as with the current master? Take this example code:

// I quickly used simple_logger, although every `log` implementation should work
use simple_logger::SimpleLogger;

fn main() {
    SimpleLogger::new().init().unwrap();
    tracing::trace!("trace");
    tracing::debug!("debug");
    tracing::info!("info");
    tracing::warn!("warn");
    tracing::error!("error");
}

and cargo.toml:

...
tracing = { path = "../tracing", version = "0.2", features = ["log"]}
log = { version = "0.4.17", features = ["max_level_info"] }
...

On master this prints:

2024-03-25T14:58:59.150Z INFO  [fmt] info
2024-03-25T14:58:59.150Z WARN  [fmt] warn
2024-03-25T14:58:59.150Z ERROR [fmt] error

Instead on master + this patch, it prints:

2024-03-25T14:59:55.475Z TRACE [fmt] trace
2024-03-25T14:59:55.475Z DEBUG [fmt] debug

Maybe I did something wrong or didn't understand the PR correctly, so please correct me!

jevolk commented 3 months ago

Thanks. It looks like I've stumbled on a conflict between values in tracing-core and log-0.4. Consider in tracing-core the enumeration starts with Trace as 0 https://github.com/tokio-rs/tracing/blob/908cc432a5994f6e17c8f36e13c217dc40085704/tracing-core/src/metadata.rs#L580-L601 while in log-0.4 the enumeration increases with verbosity. Investigating this further I came across this error:

= note: `tracing_core::Level` and `log::Level` have similar names, but are actually distinct types                                                                                                                                                                                                                        
note: `tracing_core::Level` is defined in crate `tracing_core`                                                                                                                                                                                                                                                                 
--> /home/jason/tracing/tracing-core/src/metadata.rs:221:1                                                                                                                                                                                                                                                                 
 |                                                                                                                                                         
221  | pub struct Level(LevelInner);                                                                                                                                                                                                                                                                                           
 |      ^^^^^^^^^^^^^^^^                                                                                                                                        
note: `log::Level` is defined in crate `log`                                                                                                                   
 -> /home/jason/.cargo/registry/src/index.crates.io-6f17d22bba15001f/log-0.4.21/src/lib.rs:439:1                                                                                                                                                                                                                           
 |                                                                                                                                                                                                                                                                                                                         
439  | pub enum Level {   

but I had no such error in my project. For the record I couldn't reproduce the result you had above either, and I'm not yet clear why. Nevertheless this PR is ceasing to make sense so I'm inclined to close it. I'd just like to document what I observed, since this is still a problem for me to fix eventually:

A debug!() with max_level_debug prior to this patch (expanded between the fences): trace!_enabled

A debug!() with max_level_info prior to this patch (expanded between the fences): Screenshot from 2024-03-22 08-32-08

A debug!() with max_level_debug after this patch: Screenshot from 2024-03-24 05-14-52

A debug!() with max_level_info after this patch: Screenshot from 2024-03-22 07-31-51