Bug: `color_eyre` interference with `tracing` in some cases

lroux-at-jellysmack commented 2 years ago

Hello, I've been using color_eyre on a work project, and had experienced troubles with the logging (using tracing/tracing_subscriber).

What happening and what should happen ?

Observed Behavior: Creating a eyre::Report before initializing the tracing_subscriber even if we're ignoring it makes subsequent logs disappear. Expected Behavior: The logs should still be printed, wether or not a eyre::Report is created.

Why is this issue on `color_eyre` and not on `tracing_subscriber` ?

While testing and trying to know what was happening, I switched to stable_eyre, and the issue fixed itself, so this must come from color_eyre.

Here is a minimal reproduction of the bug:

fn main() {
    // Initialize the `color_eyre` Handler
    color_eyre::install().unwrap();

    // If any [`eyre::Report`] is created (not even returned) at any point before
    // the initialization of the `tracing_subscriber`, the tracing logs never output
    let _ = color_eyre::eyre::eyre!("A very ignorable error, so we ignore it");
    // ^ If we were to comment this line, the log would appear

    // Initialize the `tracing_subscriber` Subscriber
    tracing_subscriber::fmt::init();

    tracing::info!("This log never appears in the console");
}

and I'm using the following versions of crates in my Cargo.toml:

[dependencies]
tracing = "0.1.35"
tracing-subscriber = "0.3.11"
color-eyre = "0.6.1"

Don't hesitate to ask any question :) Thanks !

yaahc commented 2 years ago

wow, that's uuuh, interesting... I'll look into what's causing that. For now is installing the subscriber first possible? I'm just trying to get a sense of this issue's urgency.

lroux-at-jellysmack commented 2 years ago

I switched to stable_eyre until color_eyre works, it's a matter of a search-and-replace, but it's less fancy unfortunately :)

It's not that urgent, but we can't move the initialization of tracing_subscriber before the said eyre::Report, because it's where we load our configuration from the env variables (which can raise a eyre::Report) and it contains some parameters we use to initialize our tracing_subscriber that are optional (so they raise a eyre::Report, but we simply .unwrap_or(...) on them to set a default value).

alcroito commented 1 year ago

This still happens with color-eyre 0.6.2 and tracing-subscriber 0.3.16 / tracing-core 0.1.30.

I tried looking into why this is happening, and the short version is that creation of an eyre::Report tries to capture a SpanTrace at

https://github.com/yaahc/color-eyre/blob/v0.6.2/src/config.rs#L1047

which in turns creates a NoSubscriber::default() Subscriber at

https://github.com/tokio-rs/tracing/blob/tracing-0.1.37/tracing-core/src/dispatcher.rs#L371

and stores that no-op subscriber as the current thread dispatcher, which has a tracing_core::subscriber::InterestKind::Never interest for call sites.

Later when the info event is logged, despite a real dispatcher already being installed, the cached no-op dispatcher is queried which has no interest in logging the event.

The stack trace where the interest is evaluated looks as follows.

tracing_core::callsite::rebuild_callsite_interest::{{closure}} (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/callsite.rs:507)
tracing_core::dispatcher::get_default::{{closure}} (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/dispatcher.rs:371)
std::thread::local::LocalKey<T>::try_with (@std::thread::local::LocalKey<T>::try_with:68)
tracing_core::dispatcher::get_default (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/dispatcher.rs:368)
tracing_core::callsite::dispatchers::Rebuilder::for_each (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/callsite.rs:568)
tracing_core::callsite::rebuild_callsite_interest (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/callsite.rs:501)
tracing_core::callsite::DefaultCallsite::register (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/callsite.rs:322)
tracing_core::callsite::DefaultCallsite::interest (~/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.30/src/callsite.rs:356)

I'm not very familiar with tracing internals, but it sounds like an issue in tracing instead of color-eyre, which should signal an error or ensure creation of SpanTraces before a dispatcher is installed, does not result in the current behavior.

The issue is also somewhat (but not quite) similar to https://github.com/tokio-rs/tracing/issues/2400

A partial / interim workaround is to disable span trace capturing with env vars, until the default dispatcher is installed.

std::env::set_var("RUST_SPANTRACE", "0");
color_eyre::install().unwrap();
let _ = color_eyre::eyre::eyre!("A very ignorable error, so we ignore it");
tracing_subscriber::fmt::init();
std::env::set_var("RUST_SPANTRACE", "1");
tracing::event!(tracing::Level::ERROR, "something happened");

alcroito commented 1 year ago

Filed https://github.com/tokio-rs/tracing/issues/2436