subscriber: fix missing on_layer for Box/Arc layer impls (#1576)

The `Layer::on_layer` method on `Layer` was added in PR #1523. PR #1536,
which added `Layer` implementations to `Box<dyn Layer<...> + ...>` and
`Arc<dyn Layer<...> + ...>`, merged prior to #1523. However, when
merging #1523, I didn't think to update the `Layer` impl for `Box`ed and
`Arc`ed layers to forward `on_layer` to the inner `Layer`. This means
that when a `Layer` is wrapped in an `Arc` or a `Box`, the `on_layer`
method never gets called.

When per-layer filters are in use, the `on_layer` method is necessary to
ensure the filter is registered with the inner subscriber and has a
valid ID. This bug means that when per-layer filters are wrapped in a
`Box` or `Arc`, they won't be registered, and per-layer filtering
breaks.

This PR fixes the bug by adding `on_layer` implementations to the
`Layer` impls for `Arc`ed and `Box`ed layers. I also added some tests
--- thanks to @Noah-Kennedy for the original repro that these were based
on (#1563 (comment)).

I also added a nicer debug assertion to `Filtered` for cases where
`Layer` impls don't call `on_layer`, so that this fails less confusingly
in the future.

Signed-off-by: Eliza Weisman <[email protected]>

tracing-subscriber/src/filter/layer_filters.rs

@@ -236,6 +236,11 @@ impl<L, F, S> Filtered<L, F, S> {
 
     #[inline(always)]
     fn id(&self) -> FilterId {
+        debug_assert!(
+            !self.id.0.is_disabled(),
+            "a `Filtered` layer was used, but it had no `FilterId`; \
+            was it registered with the subscriber?"
+        );
         self.id.0
     }
 
@@ -504,6 +509,10 @@ impl FilterId {
 
         Self(self.0 | other)
     }
+
+    fn is_disabled(self) -> bool {
+        self.0 == Self::disabled().0
+    }
 }
 
 impl fmt::Debug for FilterId {

tracing-subscriber/src/layer/mod.rs

@@ -414,7 +414,11 @@
 //! [`LevelFilter`]: crate::filter::LevelFilter
 //! [feat]: crate#feature-flags
 use crate::filter;
-use std::{any::TypeId, ops::Deref, sync::Arc};
+use std::{
+    any::TypeId,
+    ops::{Deref, DerefMut},
+    sync::Arc,
+};
 use tracing_core::{
     metadata::Metadata,
     span,
@@ -1160,13 +1164,31 @@ where
     L: Layer<S>,
     S: Subscriber,
 {
+    fn on_layer(&mut self, subscriber: &mut S) {
+        if let Some(inner) = Arc::get_mut(self) {
+            // XXX(eliza): this may behave weird if another `Arc` clone of this
+            // layer is layered onto a _different_ subscriber...but there's no
+            // good solution for that...
+            inner.on_layer(subscriber);
+        }
+    }
+
     layer_impl_body! {}
 }
 
 impl<S> Layer<S> for Arc<dyn Layer<S> + Send + Sync>
 where
     S: Subscriber,
 {
+    fn on_layer(&mut self, subscriber: &mut S) {
+        if let Some(inner) = Arc::get_mut(self) {
+            // XXX(eliza): this may behave weird if another `Arc` clone of this
+            // layer is layered onto a _different_ subscriber...but there's no
+            // good solution for that...
+            inner.on_layer(subscriber);
+        }
+    }
+
     layer_impl_body! {}
 }
 
@@ -1175,13 +1197,21 @@ where
     L: Layer<S>,
     S: Subscriber,
 {
+    fn on_layer(&mut self, subscriber: &mut S) {
+        self.deref_mut().on_layer(subscriber);
+    }
+
     layer_impl_body! {}
 }
 
 impl<S> Layer<S> for Box<dyn Layer<S> + Send + Sync>
 where
     S: Subscriber,
 {
+    fn on_layer(&mut self, subscriber: &mut S) {
+        self.deref_mut().on_layer(subscriber);
+    }
+
     layer_impl_body! {}
 }
 

tracing-subscriber/tests/layer_filters/boxed.rs

@@ -0,0 +1,73 @@
+use super::*;
+use std::sync::Arc;
+use tracing_subscriber::{filter, prelude::*, Layer};
+
+fn layer() -> (ExpectLayer, subscriber::MockHandle) {
+    layer::mock().done().run_with_handle()
+}
+
+fn filter<S>() -> filter::DynFilterFn<S> {
+    // Use dynamic filter fn to disable interest caching and max-level hints,
+    // allowing us to put all of these tests in the same file.
+    filter::dynamic_filter_fn(|_, _| false)
+}
+
+/// reproduces https://github.com/tokio-rs/tracing/issues/1563#issuecomment-921363629
+#[test]
+fn box_works() {
+    let (layer, handle) = layer();
+    let layer = Box::new(layer.with_filter(filter()));
+
+    let _guard = tracing_subscriber::registry().with(layer).set_default();
+
+    for i in 0..2 {
+        tracing::info!(i);
+    }
+
+    handle.assert_finished();
+}
+
+/// the same as `box_works` but with a type-erased `Box`.
+#[test]
+fn dyn_box_works() {
+    let (layer, handle) = layer();
+    let layer: Box<dyn Layer<_> + Send + Sync + 'static> = Box::new(layer.with_filter(filter()));
+
+    let _guard = tracing_subscriber::registry().with(layer).set_default();
+
+    for i in 0..2 {
+        tracing::info!(i);
+    }
+
+    handle.assert_finished();
+}
+
+/// the same as `box_works` but with an `Arc`.
+#[test]
+fn arc_works() {
+    let (layer, handle) = layer();
+    let layer = Box::new(layer.with_filter(filter()));
+
+    let _guard = tracing_subscriber::registry().with(layer).set_default();
+
+    for i in 0..2 {
+        tracing::info!(i);
+    }
+
+    handle.assert_finished();
+}
+
+/// the same as `box_works` but with a type-erased `Arc`.
+#[test]
+fn dyn_arc_works() {
+    let (layer, handle) = layer();
+    let layer: Arc<dyn Layer<_> + Send + Sync + 'static> = Arc::new(layer.with_filter(filter()));
+
+    let _guard = tracing_subscriber::registry().with(layer).set_default();
+
+    for i in 0..2 {
+        tracing::info!(i);
+    }
+
+    handle.assert_finished();
+}

tracing-subscriber/tests/layer_filters/main.rs

@@ -2,6 +2,7 @@
 #[path = "../support.rs"]
 mod support;
 use self::support::*;
+mod boxed;
 mod filter_scopes;
 mod targets;
 mod trees;