debug in trace fails to compile with log feature enabled

[snejugal]

Bug Report

Version

└── tracing v0.1.16
    ├── tracing-attributes v0.1.9
    └── tracing-core v0.1.11

Platform

Linux snejugal 4.15.0-111-generic #112-Ubuntu SMP Thu Jul 9 20:32:34 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

Description

This is the minimal reproducible example:

use tracing::trace;

fn main() {
    trace!(foo = debug(42));
}

When tracing is compiled with default features, this code compiled. However, if tracing is compiled with the log feature, it fails to compile:

error[E0425]: cannot find function `debug` in this scope
 --> src/main.rs:4:18
  |
4 |     trace!(foo = debug(42));
  |                  ^^^^^ not found in this scope
  |
help: possible candidate is found in another module, you can import it into scope
  |
1 | use tracing::field::debug;
  |

This happens because tracing emits a use for tracing::field::debug when logging through itself, but it doesn't when logging through log:

expanded code

use tracing::trace;
fn main() {
    {
        {
            if !::tracing::dispatcher::has_been_set() {
                {
                    use ::tracing::log;
                    let level = match *&::tracing::Level::TRACE {
                        ::tracing::Level::ERROR => ::tracing::log::Level::Error,
                        ::tracing::Level::WARN => ::tracing::log::Level::Warn,
                        ::tracing::Level::INFO => ::tracing::log::Level::Info,
                        ::tracing::Level::DEBUG => ::tracing::log::Level::Debug,
                        _ => ::tracing::log::Level::Trace,
                    };
                    if level <= log::STATIC_MAX_LEVEL {
                        let log_meta = log::Metadata::builder()
                            .level(level)
                            .target("tracing_bug")
                            .build();
                        let logger = log::logger();
                        if logger.enabled(&log_meta) {
                            logger.log(
                                &log::Record::builder()
                                    .file(Some("src/main.rs"))
                                    .module_path(Some("tracing_bug"))
                                    .line(Some(4u32))
                                    .metadata(log_meta)
                                    .args({
                                        ::core::fmt::Arguments::new_v1(
                                            &["foo=", " "],
                                            &match (&debug(42),) { // <=========
                                                (arg0,) => [::core::fmt::ArgumentV1::new(
                                                    arg0,
                                                    ::core::fmt::Debug::fmt,
                                                )],
                                            },
                                        )
                                    })
                                    .build(),
                            );
                        }
                    }
                }
            } else {
                {}
            };
            if ::tracing::dispatcher::has_been_set()
                && ::tracing::Level::TRACE <= ::tracing::level_filters::STATIC_MAX_LEVEL
            {
                #[allow(unused_imports)]
                use ::tracing::{
                    callsite, Event,
                    field::{Value, ValueSet},
                };
                use ::tracing::callsite::Callsite;
                let callsite = {
                    use ::tracing::{callsite, subscriber::Interest, Metadata, __macro_support::*};
                    struct MyCallsite;
                    static META: Metadata<'static> = {
                        ::tracing_core::metadata::Metadata::new(
                            "event src/main.rs:4",
                            "tracing_bug",
                            ::tracing::Level::TRACE,
                            Some("src/main.rs"),
                            Some(4u32),
                            Some("tracing_bug"),
                            ::tracing_core::field::FieldSet::new(
                                &["foo"],
                                ::tracing_core::callsite::Identifier(&MyCallsite),
                            ),
                            ::tracing::metadata::Kind::EVENT,
                        )
                    };
                    static INTEREST: AtomicUsize = AtomicUsize::new(0);
                    static REGISTRATION: Once = Once::new();
                    impl MyCallsite {
                        #[inline]
                        fn interest(&self) -> Interest {
                            match INTEREST.load(Ordering::Relaxed) {
                                0 => Interest::never(),
                                2 => Interest::always(),
                                _ => Interest::sometimes(),
                            }
                        }
                    }
                    impl callsite::Callsite for MyCallsite {
                        fn set_interest(&self, interest: Interest) {
                            let interest = match () {
                                _ if interest.is_never() => 0,
                                _ if interest.is_always() => 2,
                                _ => 1,
                            };
                            INTEREST.store(interest, Ordering::SeqCst);
                        }
                        fn metadata(&self) -> &Metadata {
                            &META
                        }
                    }
                    REGISTRATION.call_once(|| {
                        callsite::register(&MyCallsite);
                    });
                    &MyCallsite
                };
                if {
                    let interest = callsite.interest();
                    if interest.is_never() {
                        false
                    } else if interest.is_always() {
                        true
                    } else {
                        let meta = callsite.metadata();
                        ::tracing::is_enabled(meta)
                    }
                } {
                    let meta = callsite.metadata();
                    Event::dispatch(meta, &{
                        #[allow(unused_imports)]
                        use ::tracing::field::{debug, display, Value}; // <=========
                        let mut iter = meta.fields().iter();
                        meta.fields().value_set(&[(
                            &iter.next().expect("FieldSet corrupted (this is a bug)"),
                            Some(&debug(42) as &Value), // <=========
                        )])
                    });
                }
            }
        }
    };
}

This actually broke my crate tbot, for which today I had to release a new version adding the needed use. It compiled just fine until hyper and h2, which tbot depends on, switched from log to tracing with the log feature enabled in their latest releases.

[hawkw]

Agh, that's pretty bad, thanks for the report. I'll make sure to fix that right away!

We'll have to double-check why the compilation checks with various feature flags enabled (including the log feature) didn't catch that...

[hawkw]

Hmm. This is an interesting issue, because it's kind of in competition with the change in #806, which actually removed the import in the general case (without the log feature). This was to allow recording fields whose names collide with the imported types (such as debug). I don't think @sirwindfield or I realized at the time that people were actually relying on the macros generating these imports to use field::debug/field::display without importing them explicitly.

I'm not sure off the top of my head what the right solution is to handle these two competing needs. IMO, the existence of the imports for debug and display was not a guaranteed part of the API for the macros, as they were only intended to be used internally. The imports were never documented, and exposing these names to the namespace of all expressions in the macro is kind of a bug. But, I also want to bias against breaking existing code whenever possible, and if a significant number of users like using these forms (and prefer them over the shorthand ? and % for Debug and Display` fields), I'd definitely consider putting them back and making part of the documented API.

@snejugal and @sirwindfield, any opinions on the best compromise here?

[snejugal]

In my crate the import is already explicit, so removing the internal import won't break it. But my concern is, just as yours, that there's likely code that depends on this (by mistake?)

[d-e-s-o]

I've got seven published crates that got broken by this issue.

Investigation has shown that I can still compile with an old Cargo.lock that effectively pins hyper at 0.13.6. The moment I remove Cargo.lock and hyper in version 0.13.7 gets pulled in all experience build failures. It so happens that this minor version bump of this dependency in turn added a dependency to tracing with feature "log".

This is an untenable situation. What are the options here? Irrespective of whether I could publish new versions that fix the issues in each crate, I am not willing to have all crates that I published in the past that depend on tracing to be at risk of failing to build.

[d-e-s-o]

IMO, the existence of the imports for debug and display was not a guaranteed part of the API for the macros, as they were only intended to be used internally. The imports were never documented, and exposing these names to the namespace of all expressions in the macro is kind of a bug

Perhaps they were unintentional, but I claim that nobody would ever have added explicit imports for them, because the compiler warned about unused imports (in my code!) when doing that.

use tracing::trace;
use tracing::field::debug;

fn main() {
    trace!(foo = debug(42));
}

warning: unused import: `tracing::field::debug`
 --> src/main.rs:2:5
  |
2 | use tracing::field::debug;
  |     ^^^^^^^^^^^^^^^^^^^^^
  |
  = note: `#[warn(unused_imports)]` on by default

warning: 1 warning emitted

So no, this is not a valid argument, in my opinion.

[hawkw]

because the compiler warned about unused imports (in my code!) when doing that.

@d-e-s-o this is a good point, I hadn't thought of that. The compiler warning about explicit imports of these names suggests that the use of the implicit imports is probably more widespread than I'd hoped initially.

In that case, it seems like we're probably going to have to revert commit e3b3a3a and publish a new point release (possibly yanking the non-semver-compatible 0.1.16?).

@sirwindfield, sorry about that — when we're preparing to release tracing 0.2, you should definitely re-open PR #806, since it will be fine to make this change as part of a breaking release. Ideally, we'd find a way to emit deprecation warnings for the implicit imports, but I'm not totally sure if that's possible.

In the meantime, merging PR #790 should provide a solution for recording fields with names that collide with debug/display.

[mainrs]

Ah I just say the notifications haha :)
I do agree on the fact that relying on the import (which is not part of the public API) is not a good practice. However, the compiler doesn't generate a warning (rightfully so, the import is in scope).

The macro should have used the fully qualified names of all imports anyway, which is good API design from an objective point of view and prevents situations like these.

I didn't think about people actually "using" it so the version should have been pushed to denote a breaking change instead of just a minor.

@hawkw Feel free to re-open the old PR in the case for v0.2. I'll just rebase it in that case :).

[mainrs]

@hawkw Not sure if there is actually a way to generate some compiler warning on the import, something that denotes that the import is exposed as public API but meant to be private, generating a warning from the compiler. If yes, it would probably still collide with the warning @d-e-s-o showed.

[mainrs]

On that note, sorry @d-e-s-o. It just didn't cross my mind that it would break builds to be honest. Should have thought about it a little bit more :(

[hawkw]

@hawkw Not sure if there is actually a way to generate some compiler warning on the import, something that denotes that the import is exposed as public API but meant to be private, generating a warning from the compiler. If yes, it would probably still collide with the warning @d-e-s-o showed.

I think it might be possible by adding a doc(hidden) re-export of the functions in a separate module, deprecating that, and having the macros use the full path to the functions when actually calling them ($crate::field::debug etc), but generate a use $crate::implicit_imports::{debug, display}; where only the re-export in implicit_imports is deprecated. I am not sure if this works off the top of my head, since I can't remember whether the use statement on its own will generate the deprecation warnings...

[mainrs]

@hawkw Probably worth an investigation ;)

[hawkw]

@hawkw Not sure if there is actually a way to generate some compiler warning on the import, something that denotes that the import is exposed as public API but meant to be private, generating a warning from the compiler. If yes, it would probably still collide with the warning @d-e-s-o showed.

I think it might be possible by adding a doc(hidden) re-export of the functions in a separate module, deprecating that, and having the macros use the full path to the functions when actually calling them ($crate::field::debug etc), but generate a use $crate::implicit_imports::{debug, display}; where only the re-export in implicit_imports is deprecated. I am not sure if this works off the top of my head, since I can't remember whether the use statement on its own will generate the deprecation warnings...

I tried it out. It turns out that if we import the types by name (e.g. use $crate::implicit_imports::debug;), it will generate a deprecation warning for the import even when they are not used. However, if we import them with a glob import, it will only emit the warning if the function is actually used by the user code inside the macro. See this playground for an example: https://play.rust-lang.org/?version=stable&mode=debug&edition=2018&gist=6506eb6a306bb463b99f0fb76b02ca98

This approach would work fine, provided that we ensure the module containing the deprecated functions only contains the functions we intend to deprecate.

[hawkw]

OTOH, figuring out the correct way to deprecate these could be a moot point, if folks who are currently using this, like @snejugal and @d-e-s-o, have a significant preference for having these names imported implicitly ("it's a feature, not a bug!")....

[mainrs]

I mean, it's up to the maintainers anyway, but as it seems it's something that we both didn't expect to happen. It either has to be documented properly or removed in v0.2 (which I would favor for).

[d-e-s-o]

On that note, sorry @d-e-s-o. It just didn't cross my mind that it would break builds to be honest. Should have thought about it a little bit more :(

No worries. I am just happy that we rolled back without push back. On that note: thanks @hawkw for the quick fix! (haven't tested yet or checked whether a new released has been cut already, but I am sure it will come eventually)

OTOH, figuring out the correct way to deprecate these could be a moot point, if folks who are currently using this, like @snejugal and @d-e-s-o, have a significant preference for having these names imported implicitly ("it's a feature, not a bug!")....

I have no problem with requiring an import for used functionality, conceptually. I.e., I absolutely could live with having to use

use tracing::trace;
use tracing::field::debug;

fn main() {
    trace!(foo = debug(42));
}

My problem is solely with breakages of code (that abides to Rust's semver rules) published in the past. I.e., e3b3a3a is bad because it breaks code published that earlier was building fine. I feel very strongly that once published it should continue building (well, and working).
Deprecating it is fine by me, as it would just result in a warning (though, it would break users that have #![deny(warning)] somewhere, but they have other problems as well ;)), which I can easily address with the next point release. So once you reach 0.2 requiring an explicit import is not an issue for me.

[hawkw]

Wait a minute...I just took another look at look at the git history, and I don't actually think yanking 0.1.16 is necessary. It looks like @sirwindfield's commit e3b3a3a only merged after 0.1.16 was released. We did need to revert that commit, as it would cause a breaking change if published, but it wasn't part of the 0.1.16 release.

Instead, this specific issue is caused by an interaction with the log feature. When the log feature is enabled, the expressions provided for field values are passed into two separate macros: one which prepares the tracing structured value set that is used to construct the tracing event, and another which formats a textual message to send to log, if emitting a log record for the event is enabled. The issue is that the macro that generates the tracing value set generates a block containing an import for tracing::field::debug and tracing::field::display, while the block generated by the log message formatting macro does not import those functions. Therefore, the block where the log message is formatted fails to compile, since the functions are not present in the scope it expands to.

It turns out this is not, in fact, an accidental breaking change in 0.1.16, but a long-standing bug that has existed since commit 76b5e80, which predates tracing 0.1.0. This issue existed as far back as when the library was still called tokio-trace!

However, the issue only exists when the log feature flag is enabled --- and it's disabled by default. The bug hadn't caused any issues in the past, since use of the log feature flag was not widespread enough to be coincident with an instance of someone relying on the implicitly-imported function names. The breakage happened specifically because hyper 0.13.7 enables tracing's log feature by default, so everyone depending on hyper suddenly had that feature enabled --- now, the set of people enabling the log feature is suddenly much larger!

So, while we did need to revert e3b3a3a, we don't need to yank 0.1.16, and we need to make an additional change to fix this in the case where the log feature is enabled. Sorry about that --- I misremembered, and incorrectly thought that e3b3a3a had made it into the release (it merged that same day, but right after the release)...

[mainrs]

Ah, good to hear that it wasn't me who broke it haha :) I do have to say though, I like my short hash 👌

[hawkw]

Okay, published tracing 0.1.17 which should fix this!