Dynamic level support

[Ralith]

Feature Request

Motivation

Foreign libraries often (e.g. Vulkan, OpenGL, libpng) expose callbacks to report diagnostics. Piping these into tracing events provides pleasant user experience, but when severity is specified in an argument, generating an event of the corresponding level is difficult, as the event macro requires a constant argument. Additionally, it should be possible for API users to skip e.g. formatting work for structured arguments if it can be determined that an event at a certain level would not be logged.

Proposal

Introduce a new form of the event macro that permits a dynamic level, and allow the relevance of a level to be queried dynamically.

Alternatives

Continue requiring the user to write out several near-duplicate macro invocations in this case

[arthurprs]

Another motivation: Sometimes you want the pattern

event!(if result.is_ok() { tracing::Level::INFO } else { tracing::Level::WARN }, ...)

[whatisaphone]

Here's a drop-in replacement event! macro that supports dynamic levels. I stuck this at the top of my crate and I'm using it instead of importing the real event!.

macro_rules! event {
    ($level:expr, $($args:tt)*) => {{
        use ::tracing::Level;

        match $level {
            Level::ERROR => ::tracing::event!(Level::ERROR, $($args)*),
            Level::WARN => ::tracing::event!(Level::WARN, $($args)*),
            Level::INFO => ::tracing::event!(Level::INFO, $($args)*),
            Level::DEBUG => ::tracing::event!(Level::DEBUG, $($args)*),
            Level::TRACE => ::tracing::event!(Level::TRACE, $($args)*),
        }
    }};
}

It's probably not great when it comes to code size, but at least it works!

[CAD97]

#2048 would fix this, though using a dynamic level is advised against in the current shape, as

Although it is possible to override the level, it is generally advisable to make the initial target as accurate as possible, as static filtering is done with the static metadata's level.

We could ignore register_callsite caching and always emit the event, but this has a cost to it.

My FFI callback hookup currently looks like this, not using #2048:

/// Debug callback (after idiomatic binding bridging)
fn log(
    flags: DebugFlags,
    file: Option<&str>,
    line: i32,
    func: Option<&str>,
    message: Option<&str>,
) -> Result<()> {
    if flags.is_set(DebugFlags::TypeMemory) {
        tracing::trace!(target: "fmod::memory", parent: crate::span(), file, line, func, message)
    } else if flags.is_set(DebugFlags::TypeFile) {
        tracing::trace!(target: "fmod::file", parent: crate::span(), file, line, func, message)
    } else if flags.is_set(DebugFlags::TypeCodec) {
        tracing::trace!(target: "fmod::codec", parent: crate::span(), file, line, func, message)
    } else if flags.is_set(DebugFlags::TypeTrace) {
        tracing::trace!(target: "fmod::trace", parent: crate::span(), file, line, func, message)
    } else if flags.is_set(DebugFlags::LevelLog) {
        tracing::info!(target: "fmod", parent: crate::span(), file, line, func, message)
    } else if flags.is_set(DebugFlags::LevelWarning) {
        tracing::warn!(target: "fmod", parent: crate::span(), file, line, func, message)
    } else if flags.is_set(DebugFlags::LevelError) {
        tracing::error!(target: "fmod", parent: crate::span(), file, line, func, message)
    } else {
        tracing::error!(
            parent: crate::span(),
            debug_flags = ?flags,
            file,
            line,
            func,
            message,
        );
        return Err(Error::InternalRs);
    };
    Ok(())
}

/// FFI lib-side filtering
pub fn ideal_debug_flags() -> DebugFlags {
    use tracing::{enabled, Level};
    let mut debug_flags = DebugFlags::LevelNone;

    if enabled!(target: "fmod", Level::ERROR, { file, line, func, message }) {
        debug_flags = DebugFlags::LevelError;
    }
    if enabled!(target: "fmod", Level::WARN, { file, line, func, message }) {
        debug_flags = DebugFlags::LevelWarning;
    }
    if enabled!(target: "fmod", Level::INFO, { file, line, func, message }) {
        debug_flags = DebugFlags::LevelLog;
    }
    if enabled!(target: "fmod::trace", Level::TRACE, { file, line, func, message }) {
        debug_flags |= DebugFlags::TypeTrace;
    }
    if enabled!(target: "fmod::memory", Level::TRACE, { file, line, func, message }) {
        debug_flags |= DebugFlags::TypeMemory;
    }
    if enabled!(target: "fmod::file", Level::TRACE, { file, line, func, message }) {
        debug_flags |= DebugFlags::TypeFile;
    }
    if enabled!(target: "fmod::codec", Level::TRACE, { file, line, func, message }) {
        debug_flags |= DebugFlags::TypeCodec;
    }

    debug_flags
}

[jjant]

I also need this, we maintain an http framework, and we have a middleware to instrument operations, InstrumentOperation, that opens tracing spans for requests and responses.

I wanted to add a tracing::Level argument to make that configurable, and not have the hardcoded debug_span!/Level::DEBUG but this is not currently possible because of the constant value restriction on span!.

[RReverser]

We also need this for gphoto2-rs where libgphoto2 invokes provided callback with logging scope, level and message and we want to translate those to tracing events.

[Ralith]

Branching between multiple events with static levels as in #372 (comment) has worked well for me in practice, FWIW. It's a bit boilerplatey but it's only needed in one place.

[RReverser]

Yeah that's what we're going to go with for now, but 1) proper solution would be still nice and 2) that doesn't solve dynamic target case, only dynamic level. That comment shows branching over targets too, but in our case we only get target as a string and can't feasibly enumerate all possible targets so it will have to go into an event variable which is kind of ugly and doesn't allow filtering.

[CAD97]

If you don't need to control span membership (i.e. the contextual span is fine) and aren't piping in structured key/value pairs, using the log crate and tracing-log to bridge to tracing's plumbing works perfectly well. (In fact I switched to using log rather than tracing in the code that sample comes from.) Most FFI provided logging metadata will slot into just file+line+module+target+level fine and doesn't provide anything else that would require using a tracing entrypoint instead of log.

Would I prefer if tracing-core natively had support for dynamic event metadata instead of tracing-log sidechanneling it in by conspiring with roughly everyone? Yeah, absolutely; I even wrote a patch to enable such. But doing so would be a fairly impactful breaking change (making &'static things not static) and still requires the set of fields to be known statically, while using log works today.

[RReverser]

Will using log work correctly with [tracing::instrument] and manual spans? If so, yeah that's an option too and probably easier one.

But now I'm curious, in that case how does tracing itself translate log messages to tracing events if the former supports dynamic targets but the latter one doesn't?

[davidbarsky]

Will using log work correctly with [tracing::instrument] and manual spans? If so, yeah that's an option too and probably easier one.

It should, if you're forwarding log-formatted events to a tracing-subscriber with LogTracer to a tracing subscriber.

But now I'm curious, in that case how does tracing itself translate log messages to tracing events if the former supports dynamic targets but the latter one doesn't?

The short answer is "macros to emulate a 'static environment and hard-coded strings where that isn't possible. I'd take a look at how tracing-log's internals are implemented to understand how the two are put together.