Instrument attribute spans do not appear using log feature

[detly]

Bug Report

Version

0.1.37

Platform

• Rust explorer
• Ubuntu 22.10

Description

I would like to use tracing and its #[instrument] attribute while also using env_logger. We might eventually use a proper subscriber approach, but we've done some work to get env_logger working the way we want it in our system and this is a good way to incrementally migrate over to tracing.

The documentation says:

Additionally, log records are also generated when spans are entered, exited, and closed.

With this code:

/*
[dependencies]
env_logger = { version = "0.10" }
log = "0.4"
tracing = { version = "0.1", features = ["log"] }
*/

#[tracing::instrument]
fn check(x: u32) -> Option<u32> {
    log::trace!("{x}");
    Some(x)
}
    
fn main() {
    env_logger::Builder::new()
        .filter_level(log::LevelFilter::Trace)
        .filter_module("tracing::span", log::LevelFilter::Trace)
        .filter_module("tracing::span::active", log::LevelFilter::Trace)
        .format_timestamp(None)
        .init();

    let _s = tracing::span!(tracing::Level::TRACE, "main").entered();
    
    let r = check(5);
    log::trace!("Check {:?}", r);
}

I get this output (running with no Rust or Tracing related env vars set):

[TRACE tracing::span] main;
[TRACE tracing::span::active] -> main;
[TRACE playground] 5
[TRACE playground] Check Some(5)
[TRACE tracing::span::active] <- main;
[TRACE tracing::span] -- main;

Here's a demo in the Rust Explorer.

I am confused by seeing the main span but not the check span. I would expect both to be present or absent depending on the log level.

I also noted this in the docs:

Since these additional span lifecycle logs have the potential to be very verbose, and don’t include additional fields, they will always be emitted at the Trace level, rather than inheriting the level of the span that generated them. Furthermore, they are are categorized under a separate log target, “tracing::span” (and its sub-target, “tracing::span::active”, for the logs on entering and exiting a span), which may be enabled or disabled separately from other log records emitted by tracing.

Hence the extra filter_module() filters in there. I don't think they affect it though. It is also not a level problem, as the other trace messages appear.

The example works as expected using a fmt() subscriber.

[hawkw]

Huh, that seems quite weird. I would also expect the check span to generate span activity logs. This definitely seems like a bug to me...

[miwig]

I believe the problem is this line. As I understand it, level_enabled! only returns true if a subscriber is set, but the log feature doesn't use a subscriber, as seen here in the span! macro. There, level_enabled! is equipped with an else-block that checks if_log_enabled!. But in the code generated by instrument, that check is never reached due to the problematic line.