Leveled logging is ignoring RUST_LOG

[abatilo]

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]

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

tracing/README.md

Lines 63 to 64 in 382ee01

	// install global collector configured based on RUST_LOG env var.
	tracing_subscriber::fmt::init();

[mladedav]

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]

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]

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

[iTrooz]

@mladedav Hello !
I'd like to propose an alternative solution. How about changing the default behaviour (to read RUST_LOG), and adding an option to disable it with something like .with_env_var(None) ?

You already enable some things by default, like with_target() being true, and time is also enabled by default and has to be disabled with .without_time(). Why not have a similar mechanism here, and have expected (IMO) behaviour of reading RUST_LOG by default ?