Panic after reloading layer, combined with .with_filter

[Flowneee]

Bug Report

Version

├── tracing v0.1.29
│   ├── tracing-attributes v0.1.18 (proc-macro)
│   └── tracing-core v0.1.21
└── tracing-subscriber v0.2.25
    ├── tracing v0.1.29 (*)
    ├── tracing-core v0.1.21 (*)
    ├── tracing-log v0.1.2
    │   └── tracing-core v0.1.21 (*)
    └── tracing-serde v0.1.2
        └── tracing-core v0.1.21 (*)

Platform

Linux pc 5.14.2-arch1-2 #1 SMP PREEMPT Thu, 09 Sep 2021 09:42:35 +0000 x86_64 GNU/Linux

Description

When layer, wrapped in reload::Layer, have a filter, set with .with_filter (my_layer.with_filter(my_filter)), it will panic on next call to event! (info! in my case). But if layer built as my_filter.and_then(my_layer), everything works:

use tracing_subscriber::{filter::LevelFilter, fmt, layer::SubscriberExt, reload, Layer};

fn main() {
    // This version works
    // let reloadable_layer_fn = || LevelFilter::TRACE.and_then(fmt::Layer::new());

    // This version doesn't work
    let reloadable_layer_fn = || fmt::Layer::new().with_filter(LevelFilter::TRACE);

    let (layer, handle) = reload::Layer::new(reloadable_layer_fn());
    let subscriber = tracing_subscriber::registry().with(layer);
    tracing::subscriber::set_global_default(subscriber).unwrap();

    tracing::info!("Before reload");

    handle.reload(reloadable_layer_fn()).unwrap();

    // Panics here
    tracing::info!("After reload");
}

I am not sure, whether both implementations of reloadable_layer_fn equal or not, but they both seems work in this case.

I expected: After reload is printed

Instead, this happened: panic on printing After reload

Oct 09 14:59:12.383  INFO tracing_test: Before reload
thread 'main' panicked at 'a `Filtered` layer was used, but it had no `FilterId`; was it registered with the subscriber?', /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/filter/layer_filters.rs:239:9
stack backtrace:
   0: std::panicking::begin_panic
             at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/panicking.rs:541:12
   1: tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::id
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/filter/layer_filters.rs:239:9
   2: tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::did_enable::{{closure}}
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/filter/layer_filters.rs:248:57
   3: std::thread::local::LocalKey<T>::try_with
             at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/thread/local.rs:399:16
   4: std::thread::local::LocalKey<T>::with
             at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/thread/local.rs:375:9
   5: tracing_subscriber::filter::layer_filters::Filtered<L,F,S>::did_enable
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/filter/layer_filters.rs:248:9
   6: <tracing_subscriber::filter::layer_filters::Filtered<L,F,S> as tracing_subscriber::layer::Layer<S>>::on_event
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/filter/layer_filters.rs:349:9
   7: <tracing_subscriber::reload::Layer<L,S> as tracing_subscriber::layer::Layer<S>>::on_event
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/reload.rs:96:9
   8: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::event
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-subscriber-0.2.25/src/layer/layered.rs:116:9
   9: <alloc::sync::Arc<dyn tracing_core::subscriber::Subscriber+core::marker::Send+core::marker::Sync> as tracing_core::subscriber::Subscriber>::event
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.21/src/subscriber.rs:715:9
  10: tracing_core::dispatcher::Dispatch::event
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.21/src/dispatcher.rs:517:9
  11: tracing_core::event::Event::dispatch::{{closure}}
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.21/src/event.rs:35:13
  12: tracing_core::dispatcher::get_default::{{closure}}
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.21/src/dispatcher.rs:331:24
  13: std::thread::local::LocalKey<T>::try_with
             at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/std/src/thread/local.rs:399:16
  14: tracing_core::dispatcher::get_default
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.21/src/dispatcher.rs:328:5
  15: tracing_core::event::Event::dispatch
             at /home/flowneee/.cargo/registry/src/github.com-1ecc6299db9ec823/tracing-core-0.1.21/src/event.rs:34:9
  16: tracing_test::main
             at ./src/main.rs:165:5
  17: core::ops::function::FnOnce::call_once
             at /rustc/c8dfcfe046a7680554bf4eb612bad840e7631c4b/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

[hawkw]

Thanks for the report, I'll take a look at this!

[hawkw]

This issue occurs because, when a Layer containing per-layer filters is added to a Subscriber, the Filtered layer with the per-layer filter uses the on_layer callback to register itself with the Subscriber and generate a filter ID. However, when reload is called, the per-layer filter is replaced with a new one without calling the on_layer method, so no filter ID is ever generated for the new filter. Thus, the panic.

Unfortunately, we cannot easily change reload to call on_layer. This is because on_layer currently takes a mutable reference to the Subscriber, but at the point where reload is called, the Subscriber can no longer be mutated, as it is shared (due to being set as the default). We could change on_layer to take &Subscriber instead, and increment the counter of filter IDs using an atomic, but changing the function prototype would be a breaking change, so we can't do that until 0.4.

[hawkw]

An alternative approach is to add APIs to the Filtered layer to allow modifying the filter in place. We could add a filter_mut() function which would allow replacing the FilterFn inside the Filtered layer with a different value, while retaining the generated filter ID. Similarly, we could also expose mutable access to the layer, so that it, too, can be replaced without losing the ID.

This approach isn't a breaking change. It would mean, though, that we should document clearly that reload cannot be used to replace an entire Filtered layer, and that users must instead replace the values inside the Filtered layer.

[swsnr]

I had the same issue, and eventually used a different approach without per-layer filters: I added the level filter as separate reloadable layer, in order to control the global log level dynamically, and made a separate reloadable layer which chains a few different Option<…> layers, which lets me turn individual log targets on or off dynamically (what was previously a per-layer filter with LevelFilter::OFF):

    let (level, level_handle) = reload::Layer::new(LevelFilter::from_level(default_level));
    let (target, target_handle) = reload::Layer::new(make_target_layer(default_target).unwrap());

    let subscriber = Registry::default()
        .with(env_filter)
        .with(level)
        .with(target);
    tracing::subscriber::set_global_default(subscriber).unwrap();

[tfreiberg-fastly]

The workaround from the OP (using filter.and_then(layer) instead of layer.with_filter(filter)) seems to make it impossible to have different filters for other layers.

I have a custom type StatsLayer and a reloadable fmt::Layer where env filters can be changed during runtime.
The env filters must not apply to the StatsLayer.

I've tried several permutations and it seems this is currently not possible because of this bug, but maybe I've missed something and there are possible workarounds available on the currently released version?

I can confirm that a Filtered::filter_mut method would solve the issue, using handle.modify with tfreiberg-fastly@3e7cfe1 works perfectly.

---

Enumerating the different ways I combined the two layers:

When using env_filters.and_then(fmt_layer) as the reloadable_layer, reload works but:

Registry::default().with(reloadable_layer).with(stats_layer).init() applies the env filters to stats_layer.
Same for stats_layer.and_then(reloadable_layer).with_subscriber(Registry::default()).init(); - the order of composing the layers doesn't seem to matter.

(Registry::default().with(stats_layer).with(reloadable_layer).init() doesn't compile, because of the L: Layer<Self> bound in SubscriberExt::with I guess?)

When using fmt_layer.with_filter(env_filters) as the reloadable_layer, the reload doesn't work anymore, but stats_layer only works properly in this variant (and with the reload commented out to prevent the panic)

Are there other workarounds?

[tj12961]

I have a feeling what I want to do doesn't presently have a workaround but since there are proposed changes to support this (#2101) I thought I'd throw my hat in the ring.

I am trying to permit a client to dynamically trace (with runtime-created filtering) an in-progress service over a local socket. This works perfectly and I can receive log messages over my socket however I encounter panics when I to introduce server-side filtering where I encounter the same problems.

I currently have a reload::Layer composed of a Vec<Layer> which is reloaded whenever a new networked subscriber connects - I am currently using the reload::Handle::modify method to replace the whole vector in-place.

Is there something I have missed or am I stuck waiting until the proposed atomic FilterId changes have been made?