From d1c0afafba59d406bd584449f1c0e363375537e6 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 17 Sep 2021 12:06:18 -0700 Subject: [PATCH 1/5] add repro this is a minimization of https://github.com/tokio-rs/tracing/issues/1563#issuecomment-922000851 Signed-off-by: Eliza Weisman --- tracing-subscriber/tests/noah_repro.rs | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) create mode 100644 tracing-subscriber/tests/noah_repro.rs diff --git a/tracing-subscriber/tests/noah_repro.rs b/tracing-subscriber/tests/noah_repro.rs new file mode 100644 index 0000000000..1595f92048 --- /dev/null +++ b/tracing-subscriber/tests/noah_repro.rs @@ -0,0 +1,19 @@ +use tracing_subscriber::{ + filter::{LevelFilter, Targets}, + fmt, + prelude::*, + Layer, +}; + +#[test] +fn noah_repro() { + // reproduces https://github.com/tokio-rs/tracing/issues/1563#issuecomment-921363629 + let layer: Box + Send + Sync + 'static> = + Box::new(fmt::layer().with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); + + tracing_subscriber::registry().with(layer).init(); + + for i in 0..1 { + tracing::info!(target: "Hello", message = "Log hello", i); + } +} From 253c26623dec4f7fc244dcaf59c73678cba73552 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 17 Sep 2021 12:19:48 -0700 Subject: [PATCH 2/5] nicer repro now that i know what the bug is Signed-off-by: Eliza Weisman --- .../tests/layer_filters/boxed.rs | 79 +++++++++++++++++++ .../tests/layer_filters/main.rs | 1 + tracing-subscriber/tests/noah_repro.rs | 19 ----- 3 files changed, 80 insertions(+), 19 deletions(-) create mode 100644 tracing-subscriber/tests/layer_filters/boxed.rs delete mode 100644 tracing-subscriber/tests/noah_repro.rs diff --git a/tracing-subscriber/tests/layer_filters/boxed.rs b/tracing-subscriber/tests/layer_filters/boxed.rs new file mode 100644 index 0000000000..0c86d63d66 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/boxed.rs @@ -0,0 +1,79 @@ +use super::*; +use std::sync::Arc; +use tracing_subscriber::{ + filter::{LevelFilter, Targets}, + prelude::*, + Layer, +}; + +fn layer() -> (ExpectLayer, subscriber::MockHandle) { + layer::mock() + .event(event::mock().with_fields(field::mock("i").with_value(&0))) + .event(event::mock().with_fields(field::mock("i").with_value(&1))) + .done() + .run_with_handle() +} + +/// 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(Targets::new().with_target("hello", LevelFilter::DEBUG))); + + let _guard = tracing_subscriber::registry().with(layer).set_default(); + + for i in 0..1 { + tracing::info!(target: "Hello", message = "hello", 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 + Send + Sync + 'static> = + Box::new(layer.with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); + + let _guard = tracing_subscriber::registry().with(layer).set_default(); + + for i in 0..1 { + tracing::info!(target: "Hello", message = "hello", 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(Targets::new().with_target("hello", LevelFilter::DEBUG))); + + let _guard = tracing_subscriber::registry().with(layer).set_default(); + + for i in 0..1 { + tracing::info!(target: "Hello", message = "hello", 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 + Send + Sync + 'static> = + Arc::new(layer.with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); + + let _guard = tracing_subscriber::registry().with(layer).set_default(); + + for i in 0..1 { + tracing::info!(target: "Hello", message = "hello", i); + } + + handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/layer_filters/main.rs b/tracing-subscriber/tests/layer_filters/main.rs index ccc4ef2679..dfe3309c62 100644 --- a/tracing-subscriber/tests/layer_filters/main.rs +++ b/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; diff --git a/tracing-subscriber/tests/noah_repro.rs b/tracing-subscriber/tests/noah_repro.rs deleted file mode 100644 index 1595f92048..0000000000 --- a/tracing-subscriber/tests/noah_repro.rs +++ /dev/null @@ -1,19 +0,0 @@ -use tracing_subscriber::{ - filter::{LevelFilter, Targets}, - fmt, - prelude::*, - Layer, -}; - -#[test] -fn noah_repro() { - // reproduces https://github.com/tokio-rs/tracing/issues/1563#issuecomment-921363629 - let layer: Box + Send + Sync + 'static> = - Box::new(fmt::layer().with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); - - tracing_subscriber::registry().with(layer).init(); - - for i in 0..1 { - tracing::info!(target: "Hello", message = "Log hello", i); - } -} From 251ecfac43f482ae4b836e48d1963d58bffd3824 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 17 Sep 2021 12:32:30 -0700 Subject: [PATCH 3/5] fix test crosstalk Signed-off-by: Eliza Weisman --- .../tests/layer_filters/boxed.rs | 46 ++++++++----------- 1 file changed, 20 insertions(+), 26 deletions(-) diff --git a/tracing-subscriber/tests/layer_filters/boxed.rs b/tracing-subscriber/tests/layer_filters/boxed.rs index 0c86d63d66..4788490a80 100644 --- a/tracing-subscriber/tests/layer_filters/boxed.rs +++ b/tracing-subscriber/tests/layer_filters/boxed.rs @@ -1,30 +1,27 @@ use super::*; use std::sync::Arc; -use tracing_subscriber::{ - filter::{LevelFilter, Targets}, - prelude::*, - Layer, -}; +use tracing_subscriber::{filter, prelude::*, Layer}; fn layer() -> (ExpectLayer, subscriber::MockHandle) { - layer::mock() - .event(event::mock().with_fields(field::mock("i").with_value(&0))) - .event(event::mock().with_fields(field::mock("i").with_value(&1))) - .done() - .run_with_handle() + layer::mock().done().run_with_handle() +} + +fn filter() -> filter::DynFilterFn { + // 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(Targets::new().with_target("hello", LevelFilter::DEBUG))); + let layer = Box::new(layer.with_filter(filter())); let _guard = tracing_subscriber::registry().with(layer).set_default(); - for i in 0..1 { - tracing::info!(target: "Hello", message = "hello", i); + for i in 0..2 { + tracing::info!(i); } handle.assert_finished(); @@ -34,13 +31,12 @@ fn box_works() { #[test] fn dyn_box_works() { let (layer, handle) = layer(); - let layer: Box + Send + Sync + 'static> = - Box::new(layer.with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); + let layer: Box + Send + Sync + 'static> = Box::new(layer.with_filter(filter())); let _guard = tracing_subscriber::registry().with(layer).set_default(); - for i in 0..1 { - tracing::info!(target: "Hello", message = "hello", i); + for i in 0..2 { + tracing::info!(i); } handle.assert_finished(); @@ -50,13 +46,12 @@ fn dyn_box_works() { #[test] fn arc_works() { let (layer, handle) = layer(); - let layer = - Box::new(layer.with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); + let layer = Box::new(layer.with_filter(filter())); let _guard = tracing_subscriber::registry().with(layer).set_default(); - for i in 0..1 { - tracing::info!(target: "Hello", message = "hello", i); + for i in 0..2 { + tracing::info!(i); } handle.assert_finished(); @@ -66,13 +61,12 @@ fn arc_works() { #[test] fn dyn_arc_works() { let (layer, handle) = layer(); - let layer: Arc + Send + Sync + 'static> = - Arc::new(layer.with_filter(Targets::new().with_target("hello", LevelFilter::DEBUG))); + let layer: Arc + Send + Sync + 'static> = Arc::new(layer.with_filter(filter())); let _guard = tracing_subscriber::registry().with(layer).set_default(); - for i in 0..1 { - tracing::info!(target: "Hello", message = "hello", i); + for i in 0..2 { + tracing::info!(i); } handle.assert_finished(); From 211b9b02350cf85440a17737ba6d45e3813dbdca Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 17 Sep 2021 12:35:48 -0700 Subject: [PATCH 4/5] subscriber: fix missing `on_layer` for `Box` and `Arc` layer impls The `Layer::on_layer` method on `Layer` was added in PR #1523. PR #1536, which added `Layer` implementations to `Box + ...>` and `Arc + ...>`, 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 (https://github.com/tokio-rs/tracing/issues/1563#issuecomment-922014777). Signed-off-by: Eliza Weisman --- tracing-subscriber/src/layer/mod.rs | 32 ++++++++++++++++++++++++++++- 1 file changed, 31 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index f3a87898e0..5ba89575b4 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/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,6 +1164,15 @@ where L: Layer, 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! {} } @@ -1167,6 +1180,15 @@ impl Layer for Arc + 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,6 +1197,10 @@ where L: Layer, S: Subscriber, { + fn on_layer(&mut self, subscriber: &mut S) { + self.deref_mut().on_layer(subscriber); + } + layer_impl_body! {} } @@ -1182,6 +1208,10 @@ impl Layer for Box + Send + Sync> where S: Subscriber, { + fn on_layer(&mut self, subscriber: &mut S) { + self.deref_mut().on_layer(subscriber); + } + layer_impl_body! {} } From 72f764225e4710a008da10da6bb306b5be03e424 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 17 Sep 2021 13:07:57 -0700 Subject: [PATCH 5/5] add assertion for a less confusing panic this would help if this ever happened again Signed-off-by: Eliza Weisman --- tracing-subscriber/src/filter/layer_filters.rs | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/tracing-subscriber/src/filter/layer_filters.rs b/tracing-subscriber/src/filter/layer_filters.rs index bc59125a9e..e3492ffefe 100644 --- a/tracing-subscriber/src/filter/layer_filters.rs +++ b/tracing-subscriber/src/filter/layer_filters.rs @@ -236,6 +236,11 @@ impl Filtered { #[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 {