`tracing/log` doesn't work with `tokio::spawn` / `.with_current_subscriber()`.

[Lorak-mmk]

Bug Report

Version

└── tracing v0.1.40 ├── tracing-attributes v0.1.27 (proc-macro) └── tracing-core v0.1.32

Platform

Fedora 39

uname -a: Linux scyllaptop 6.7.9-200.fc39.x86_64 #1 SMP PREEMPT_DYNAMIC Wed Mar 6 19:35:04 UTC 2024 x86_64 GNU/Linux

Description

Let me start by saying that I'm not 100% it's a bug - it may be be lack of knowledge in regards to usage of tracing. I'm one of maintainters of a library ( https://github.com/scylladb/scylla-rust-driver ) that uses tokio and tracing. We call .with_current_subscriber() on each future passed to tokio::spawn which according to docs ( https://docs.rs/tracing/latest/tracing/instrument/trait.WithSubscriber.html#method.with_current_subscriber ) seems like what we should do as a library.

This works as intended when using tracing subscriber. Example: Consider a crate with the following Cargo.toml (it will be used for another example later, thus unused dependencies):

[package]
name = "reproducer"
version = "1.0.0"
edition = "2021"

[dependencies]
env_logger = "0.10"
log = "0.4"
tracing = { version = "0.1.36", features = [ "log" ] }
tracing-subscriber = "0.3"
tokio = { version = "1.27", features = [ "full" ] }

and the following main.rs:

use tracing::instrument::WithSubscriber;

#[tokio::main]
async fn main() {
    let subscriber = tracing_subscriber::FmtSubscriber::new();
    tracing::subscriber::set_global_default(subscriber).unwrap();

    log::info!("info log");
    tracing::info!("info tracing");

    tokio::spawn(
        async move {
            log::info!("spawned info log");
            tracing::info!("spawned info tracing")
        }
        .with_current_subscriber(),
    )
    .await
    .unwrap();

    log::info!("another info log");
    tracing::info!("another info tracing");
}

After cargo run traces are printed and logs are not, as expected:

cargo run
   Compiling reproducer v1.0.0 (/tmp/tracing_issue)
    Finished dev [unoptimized + debuginfo] target(s) in 0.56s
     Running `target/debug/reproducer`
2024-03-18T15:48:35.651650Z  INFO reproducer: info tracing
2024-03-18T15:48:35.651700Z  INFO reproducer: spawned info tracing
2024-03-18T15:48:35.651727Z  INFO reproducer: another info tracing

Now let's switch tracing subscriber for env_logger. As far as I understand from tracing's docs env_logger should print my traces because I enabled log feature on tracing crate. New main.rs:

use tracing::instrument::WithSubscriber;

#[tokio::main]
async fn main() {
    env_logger::init_from_env(env_logger::Env::new().default_filter_or("info"));

    log::info!("info log");
    tracing::info!("info tracing");

    tokio::spawn(
        async move {
            log::info!("spawned info log");
            tracing::info!("spawned info tracing")
        }
        .with_current_subscriber(),
    )
    .await
    .unwrap();

    log::info!("another info log");
    tracing::info!("another info tracing");
}

Output:

cargo run
   Compiling reproducer v1.0.0 (/tmp/tracing_issue)
    Finished dev [unoptimized + debuginfo] target(s) in 0.78s
     Running `target/debug/reproducer`
[2024-03-18T15:53:43Z INFO  reproducer] info log
[2024-03-18T15:53:43Z INFO  reproducer] info tracing
[2024-03-18T15:53:43Z INFO  reproducer] spawned info log
[2024-03-18T15:53:43Z INFO  reproducer] another info log

As you can see, no traces are printed after the tokio::spawn call - interestingly it affects even the tracing call in the same function. It's not the problem with log calls - issue persists even if I remove them.

This results in our library not being usable with log loggers like env_logger even if we enable log feature :(

[Lorak-mmk]

Note: log-always works correctly and gives following output with env_logger:

cargo run
   Compiling tracing v0.1.40
   Compiling reproducer v1.0.0 (/tmp/tracing_issue)
    Finished dev [unoptimized + debuginfo] target(s) in 0.87s
     Running `target/debug/reproducer`
[2024-03-18T15:59:20Z INFO  reproducer] info log
[2024-03-18T15:59:20Z INFO  reproducer] info tracing
[2024-03-18T15:59:20Z INFO  reproducer] spawned info log
[2024-03-18T15:59:20Z INFO  reproducer] spawned info tracing
[2024-03-18T15:59:20Z INFO  reproducer] another info log
[2024-03-18T15:59:20Z INFO  reproducer] another info tracing

But this is not something I want to enable in the library - IIUC it adds overhead as it generates 2 event for each tracing call.

[kaffarell]

Hmm, this is interesting... I think the .with_current_subscriber call creates a NoSubscriber in case a default subscriber doesn't exist. Then afterwards, every event is pushed to the NoSubscriber (which discards them) instead of being forwarded as a log event.

But I can't seem to find the code that decides whether to log or not @hawkw ?

[hawkw]

The log feature only emits log records if no tracing Subscriber has ever been set. Your calls to with_current_subscriber are setting a subscriber, disabling the log crate output. This is why it works with log-always, but not with log.

A library should not generally enable the log or log-always feature flags, and generally should never be responsible for setting the default subscriber. Instead, user code that depends on the library should enable tracing's log crate support if it wants to, and set the default subscriber if it wishes to use tracing. I don't think the calls to with_current_subscriber are necessary in a library in general.

[hawkw]

With that said, we probably could fix this by having with_current_subscriber check if the current subscriber is NoSubscriber, and if it is, having its future do nothing, rather than setting the subscriber as default.

[Lorak-mmk]

I don't think the calls to with_current_subscriber are necessary in a library in general.

What should the library do instead? It seemed reasonable that when spawning a task we want it to use current subscriber, not some default one.