Events missing using tracing-core 0.1.24 but works using 0.1.23

[davidpdrsn]

Bug Report

Version

tracing-core v0.1.24

Platform

Darwin Davids-MacBook-Air.local 20.4.0 Darwin Kernel Version 20.4.0: Thu Apr 22 21:46:41 PDT 2021;
root:xnu-7195.101.2~1/RELEASE_ARM64_T8101 x86_64

The bug is also there on Linux and Windows.

Crates

tracing-core, maybe tracing-subscriber?

Description

At Embark Studios we noticed that our volume of logs was significantly lower after updating to tracing-core 0.1.24. Turns out we were loosing events emitted after a certain point in out bootstrap process. No events were being sent to the subscriber. Downgrading to tracing-core 0.1.23 fixes it.

Reproducing it:

fn main() {
    // our final subscriber requires a bunch of dependencies and is created quite late in our app's
    // bootstrap process. So we create a very simple "early subscriber" to still get events from before
    // the final subscriber is created.
    //
    // This `early_log_guard` represents that.
    let early_log_guard = tracing::dispatcher::set_default(&tracing::dispatcher::Dispatch::new(
        tracing_subscriber::fmt::fmt().finish(),
    ));

    // log something while the "early subscriber" is active
    tracing::info!("from early subscriber");

    // create the final subscriber. This is much more involved in our actual code but this is
    // enough to reproduce the bug
    let subscriber = tracing_subscriber::fmt::fmt().finish();

    // set the final logger as the global subscriber
    tracing::dispatcher::set_global_default(tracing::dispatcher::Dispatch::new(subscriber))
        .expect("logger already set");

    // log something
    tracing::info!("set global subscriber");

    // remove the early log guard
    drop(early_log_guard);

    // log something else
    tracing::info!("dropped early subscriber");
}

Cargo.toml:

[package]
name = "foo"
version = "0.1.0"
edition = "2021"

[dependencies]
tracing-core = "=0.1.23"
tracing = "0.1"
tracing-subscriber = "0.3"

Running this works as expected and we see the three log events printed:

2022-04-06T09:28:24.721223Z  INFO foo: from early subscriber
2022-04-06T09:28:24.721793Z  INFO foo: set global subscriber
2022-04-06T09:28:24.721845Z  INFO foo: dropped early subscriber

However changing tracing-core = "=0.1.23" to tracing-core = "=0.1.24" causes the final "dropped early subscriber" event to not be printed. Instead we just see

2022-04-06T09:30:04.342320Z  INFO foo: from early subscriber
2022-04-06T09:30:04.342492Z  INFO foo: set global subscriber

I would expect both of these to work the same.

[shaun-cox]

I'm seeing this behavior too and can confirm that locking to tracing-core = "=0.1.23" is a work around. Thanks @davidpdrsn for spotting it and giving a nice repro.

[hawkw]

Yup, that's definitely a bug --- I think this was almost certainly introduced in #2001.

[hawkw]

PR #2065 fixes this.

[hawkw]

Fixed by #2065