Nested event generation bypasses level filtering

[nilfit]

Bug Report

Version

tracing v0.1.37
tracing-attributes v0.1.23
tracing-core v0.1.30
tracing-subscriber v0.3.16
tracing-log v0.1.3

Description

When a formatting argument of a tracing event macro (e.g. debug!) itself produces a tracing event, level filtering for the outer event is ignored. The level of the inner event does not seem to make a difference.

use tracing_subscriber::{filter::LevelFilter, prelude::*, Layer};

fn main() {
    let everything_layer = tracing_subscriber::fmt::layer().with_writer(std::io::sink);
    let stdout_layer = tracing_subscriber::fmt::layer()
        .without_time()
        .with_filter(LevelFilter::ERROR);
    tracing_subscriber::registry()
        .with(stdout_layer)
        .with(everything_layer)
        .init();

    tracing::error!("just an error");
    tracing::debug!("just debug");
    tracing::debug!("instrumented {:?}", instrumented());
    tracing::debug!("tracing in callee {:?}", nested());
    tracing::debug!("directly nested {:?}", tracing::trace!(""));
}

#[tracing::instrument()]
fn instrumented() {}

fn nested() {
    tracing::warn!("nested");
}

Actual stdout:

ERROR tracing_bug: just an error
DEBUG tracing_bug: instrumented ()
DEBUG tracing_bug: tracing in callee ()
DEBUG tracing_bug: directly nested ()

Expected stdout:

ERROR tracing_bug: just an error

[davidbarsky]

I'm able to reproduce the intended behavior with the following:

use tracing_subscriber::{filter::LevelFilter, prelude::*, Layer};

fn main() {
    let stdout_layer = tracing_subscriber::fmt::layer()
        .without_time()
        .with_filter(LevelFilter::ERROR);

    tracing_subscriber::registry()
        // .with(tracing_subscriber::fmt::layer().with_writer(std::io::sink))
        .with(stdout_layer)
        .init();

    tracing::error!("just an error");
    tracing::debug!("instrumented {:?}", instrumented());
    tracing::debug!("tracing in callee {:?}", nested());
    tracing::debug!("directly nested {:?}", tracing::trace!(""));
}

#[tracing::instrument()]
fn instrumented() {}

fn nested() {
    tracing::warn!("nested");
}

Uncommenting // .with(tracing_subscriber::fmt::layer().with_writer(std::io::sink)) will result in the behavior you're reporting, but the absence of a second layer makes things work. Similarly:

tracing_subscriber::registry()
    .with(tracing_subscriber::fmt::layer().with_writer(std::io::sink))
    .with(stdout_layer)
    .with(LevelFilter::ERROR)
    .init();

...will result in the intended output.

I assumed this was related to both fmt::Layers having the same underlying type, but then I realized that changing the writer would result in a different type for the Layer.

I haven't yet attached a debugger to dig in further, but I'm a bit puzzled at the moment!

[hds]

I independently discovered the root cause of this issue after investigating the real cause behind the supposed need for #3392.

I can repro using 2 events and only a single filtered layer (with a minimal filter). It's important that the filter is dynamic (so that the registry doesn't just return Interest.none()), but then it doesn't need to enable anything.

An example of a dynamic filter is an EnvFilter with a span name filter (e.g. [span_name]=info), because in this case, the EnvFilter enables all events and spans which occur while span_name is entered (and that are at or below info verbosity). For this reason, it can't statically disable any callsites with Interest::none(). That's the reproduction case used in rustc investigating the PR above.

Root cause

The root cause is the way per-layer filtering is implemented. It expects a first pass calling enable, and will set the FilterState (thread-local) based on the values returned by each filter.

The FilterState bits will then be used on the subsequent call to event (on_event) or new_span (on_new_span). After receiving this call, the bits of FilterState are reset.

When an event (or span) is emitted as part of the creation of the value for a field on some other event (or span), the inner event effectively destroys the FilterState set by the enable pass.

It goes something like the the following, where the outer event has a field value which, when calculated, emits the inner event.

1. Outer event enabled called
2. FilterState set with bits for filtering outer event
3. Out event's fields are created, emitting inner event
   a. Inner event enabled called
   b. FilterState set with bits for filtering inner event
   c. Inner event on_event called
   d. FilterState bits used to propergate inner event to layers
   e. FilterState bits are reset (default is enabled)
4. Outer event on_event called
5. FilterState bits used to propergate outer event to layers (but the bits have been cleared, so event is propergated to all layers)
6. FilterState bits are reset (this does nothing because they had already been reset)

Reproduction

use tracing::{
    subscriber::{with_default, Interest},
    Metadata, Subscriber,
};
use tracing_subscriber::{
    layer::{Context, Filter},
    prelude::*,
};

struct DynFilter {}

impl<S> Filter<S> for DynFilter
where
    S: Subscriber,
{
    fn enabled(&self, _meta: &Metadata<'_>, _cx: &Context<'_, S>) -> bool {
        // We disable all callsites dynamically by returning `false` here.
        false
    }

    fn callsite_enabled(&self, _meta: &'static Metadata<'static>) -> Interest {
        // We make this filter dynamic for all callsites by returning `Interest::sometimes()` here.
        // If we returned `Interest::none()` then tracing could short-circuit and avoid
        // calling `enabled`.
        Interest::sometimes()
    }
}

fn main() {
    let filter = DynFilter {};
    let layer = tracing_subscriber::fmt::layer();
    let subscriber = tracing_subscriber::registry()
        .with(layer.with_filter(filter));

    fn event_and_value() -> &'static str {
        tracing::info!("This inner event breaks per-layer filtering");
        "whoops"
    }

    with_default(subscriber, || {
        tracing::info!("This event will be recorded: {}", event_and_value());
    });
}