tokio-rs / tracing

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

Leveled logging is ignoring RUST_LOG #2993

Open abatilo opened 4 months ago

abatilo commented 4 months ago

Bug Report

Version

aaron@Aarons-MacBook-Pro:~/temp/trace-example|main⚡ ⇒  cat Cargo.toml
[package]
name = "trace-example"
version = "0.1.0"
edition = "2021"

[dependencies]
tracing = "0.1.40"
tracing-subscriber = { version = "0.3.18", features = ["json"] }

Platform

⇒  uname -a
Darwin Aarons-MacBook-Pro.local 23.5.0 Darwin Kernel Version 23.5.0: Wed May  1 20:14:38 PDT 2024; root:xnu-10063.121.3~5/RELEASE_ARM64_T6020 arm64

Description

Here is my sample code where I try to print both info and debug logs:

use tracing::{debug, info};
use tracing_subscriber;

fn main() {
    tracing_subscriber::fmt().json().init();
    info!("INFO Hello World!");
    debug!("DEBUG Hello World!");
}

And here are the outputs. With RUST_LOG=info, I see the info log:

⇒  RUST_LOG=info cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/trace-example`
{"timestamp":"2024-06-02T16:43:10.361401Z","level":"INFO","fields":{"message":"INFO Hello World!"},"target":"trace_example"}

And with RUST_LOG=debug, I still only see the info log:

⇒  RUST_LOG=debug cargo run
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.01s
     Running `target/debug/trace-example`
{"timestamp":"2024-06-02T16:43:25.109736Z","level":"INFO","fields":{"message":"INFO Hello World!"},"target":"trace_example"}
abatilo commented 4 months ago

After doing some more debugging:

use tracing::{debug, info};
use tracing_subscriber::EnvFilter;

fn main() {
    tracing_subscriber::fmt()
        .with_env_filter(EnvFilter::from_default_env())
        .init();
    info!("INFO Hello World!");
    debug!("DEBUG Hello World!");
}

Explicitly calling with_env_filter makes this work:

⇒  RUST_LOG=debug cargo run
   Compiling trace-example v0.1.0 (/Users/aaron/temp/trace-example)
    Finished `dev` profile [unoptimized + debuginfo] target(s) in 0.16s
     Running `target/debug/trace-example`
2024-06-02T17:03:28.774980Z  INFO trace_example: INFO Hello World!
2024-06-02T17:03:28.774997Z DEBUG trace_example: DEBUG Hello World!

But this is in direct conflict with what the README.md states about the global collector already being configured by RUST_LOG https://github.com/tokio-rs/tracing/blob/382ee01dc1cf428c071cad1e3f2e6c6427e70f87/README.md#L63-L64

mladedav commented 4 months ago

You're right that this is a big. I'd say it's a documentation bug though as it never worked as in the example with env filter being loaded by default.

abatilo commented 4 months ago

Thanks @mladedav. This was my first day looking into Rust and that was a very confusing experience 😅.

I'm happy to make the contribution but I'm not sure if I should update the docs to include the EnvFilter and mention the required feature on the dep, or if I should just remove the comment, etc. Thoughts?

mladedav commented 4 months ago

Sorry for mystifying you here, I didn't notice the two inits either.