From d7f72fcdda6c3e397d0ea430cd368f9fb06131f2 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Tue, 27 Sep 2022 10:52:26 -0700 Subject: [PATCH] subscriber: fix `None` layers setting the max level to `OFF` (#2321) ## Motivation Currently, when using the `Layer` impl for `Option>`, the `Layer::max_level_hint` returns `Some(LevelFilter::OFF)`. This was intended to allow totally disabling output in the case where a `Subscriber` is composed entirely of `None` `Layer`s. However, when other `Layer`s *do* exist but return `None` from their `max_level_hint` implementations to indicate that they don't care what the max level is, the presence of a single `None` layer will globally disable everything, which is not the wanted behavior. Fixes #2265 ## Solution This branch introduces a special downcast marker that can be used to detect when a `Layer` in a `Layered` is `None`. This allows the `pick_level_hint` method to short-circuit when a `Layer` implementation which is `None` returns `Some(LevelFilter::OFF)` from its `max_level_hint` if the other half of the `Layered` is not `None`. The tests I added should be pretty thorough! Additionally, the downcast marker is special-cased in the `reload` `Layer`. Normally, this `Layer` doesn't support downcasting, but it can in the case of the special marker value. Co-authored-by: Eliza Weisman --- tracing-subscriber/src/layer/layered.rs | 38 ++++- tracing-subscriber/src/layer/mod.rs | 43 +++++ tracing-subscriber/tests/option.rs | 205 ++++++++++++++++++++++++ 3 files changed, 284 insertions(+), 2 deletions(-) diff --git a/tracing-subscriber/src/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs index 91e475f631..f09c58c97c 100644 --- a/tracing-subscriber/src/layer/layered.rs +++ b/tracing-subscriber/src/layer/layered.rs @@ -115,7 +115,11 @@ where } fn max_level_hint(&self) -> Option { - self.pick_level_hint(self.layer.max_level_hint(), self.inner.max_level_hint()) + self.pick_level_hint( + self.layer.max_level_hint(), + self.inner.max_level_hint(), + super::subscriber_is_none(&self.inner), + ) } fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { @@ -267,7 +271,11 @@ where } fn max_level_hint(&self) -> Option { - self.pick_level_hint(self.layer.max_level_hint(), self.inner.max_level_hint()) + self.pick_level_hint( + self.layer.max_level_hint(), + self.inner.max_level_hint(), + super::layer_is_none(&self.inner), + ) } #[inline] @@ -470,6 +478,7 @@ where &self, outer_hint: Option, inner_hint: Option, + inner_is_none: bool, ) -> Option { if self.inner_is_registry { return outer_hint; @@ -487,6 +496,31 @@ where return None; } + // If the layer is `Option::None`, then we + // want to short-circuit the layer underneath, if it + // returns `None`, to override the `None` layer returning + // `Some(OFF)`, which should ONLY apply when there are + // no other layers that return `None`. Note this + // `None` does not == `Some(TRACE)`, it means + // something more like: "whatever all the other + // layers agree on, default to `TRACE` if none + // have an opinion". We also choose do this AFTER + // we check for per-layer filters, which + // have their own logic. + // + // Also note that this does come at some perf cost, but + // this function is only called on initialization and + // subscriber reloading. + if super::layer_is_none(&self.layer) { + return cmp::max(outer_hint, Some(inner_hint?)); + } + + // Similarly, if the layer on the inside is `None` and it returned an + // `Off` hint, we want to override that with the outer hint. + if inner_is_none && inner_hint == Some(LevelFilter::OFF) { + return outer_hint; + } + cmp::max(outer_hint, inner_hint) } } diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index 0b4992ff27..b4533771c5 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/tracing-subscriber/src/layer/mod.rs @@ -1497,6 +1497,47 @@ pub struct Identity { // === impl Layer === +#[derive(Clone, Copy)] +pub(crate) struct NoneLayerMarker(()); +static NONE_LAYER_MARKER: NoneLayerMarker = NoneLayerMarker(()); + +/// Is a type implementing `Layer` `Option::<_>::None`? +pub(crate) fn layer_is_none(layer: &L) -> bool +where + L: Layer, + S: Subscriber, +{ + unsafe { + // Safety: we're not actually *doing* anything with this pointer --- + // this only care about the `Option`, which is essentially being used + // as a bool. We can rely on the pointer being valid, because it is + // a crate-private type, and is only returned by the `Layer` impl + // for `Option`s. However, even if the layer *does* decide to be + // evil and give us an invalid pointer here, that's fine, because we'll + // never actually dereference it. + layer.downcast_raw(TypeId::of::()) + } + .is_some() +} + +/// Is a type implementing `Subscriber` `Option::<_>::None`? +pub(crate) fn subscriber_is_none(subscriber: &S) -> bool +where + S: Subscriber, +{ + unsafe { + // Safety: we're not actually *doing* anything with this pointer --- + // this only care about the `Option`, which is essentially being used + // as a bool. We can rely on the pointer being valid, because it is + // a crate-private type, and is only returned by the `Layer` impl + // for `Option`s. However, even if the subscriber *does* decide to be + // evil and give us an invalid pointer here, that's fine, because we'll + // never actually dereference it. + subscriber.downcast_raw(TypeId::of::()) + } + .is_some() +} + impl Layer for Option where L: Layer, @@ -1605,6 +1646,8 @@ where unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { if id == TypeId::of::() { Some(self as *const _ as *const ()) + } else if id == TypeId::of::() && self.is_none() { + Some(&NONE_LAYER_MARKER as *const _ as *const ()) } else { self.as_ref().and_then(|inner| inner.downcast_raw(id)) } diff --git a/tracing-subscriber/tests/option.rs b/tracing-subscriber/tests/option.rs index 92585e700b..d3abdcd400 100644 --- a/tracing-subscriber/tests/option.rs +++ b/tracing-subscriber/tests/option.rs @@ -50,6 +50,7 @@ fn just_option_some_subscriber() { assert_eq!(collector.max_level_hint(), Some(LevelFilter::OFF)); } +/// Tests that the logic tested in `doesnt_override_none` works through the reload subscriber #[test] fn just_option_none_subscriber() { let collector = tracing_subscriber::registry().with(Some(LevelFilter::ERROR)); @@ -261,3 +262,207 @@ fn reload_works_with_none() { .unwrap(); assert_eq!(subscriber.max_level_hint(), Some(LevelFilter::DEBUG)); } + +// Test that the `None` max level hint only applies if its the only layer +#[test] +fn none_outside_doesnt_override_max_level() { + // None means the other layer takes control + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(None)) + .with(None::); + assert_eq!( + subscriber.max_level_hint(), + None, + "\n stack: {:#?}", + subscriber + ); + + // The `None`-returning layer still wins + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(None)) + .with(Some(LevelFilter::ERROR)); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::ERROR), + "\n stack: {:#?}", + subscriber + ); + + // Check that we aren't doing anything truly wrong + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(Some(LevelFilter::DEBUG))) + .with(None::); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + + // Test that per-subscriber filters aren't affected + + // One layer is None so it "wins" + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(None)) + .with(None::.with_filter(LevelFilter::DEBUG)); + assert_eq!( + subscriber.max_level_hint(), + None, + "\n stack: {:#?}", + subscriber + ); + + // The max-levels wins + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(Some(LevelFilter::INFO))) + .with(None::.with_filter(LevelFilter::DEBUG)); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + + // Test filter on the other layer + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(Some(LevelFilter::INFO)).with_filter(LevelFilter::DEBUG)) + .with(None::); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(None).with_filter(LevelFilter::DEBUG)) + .with(None::); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + + // The `OFF` from `None` over overridden. + let subscriber = tracing_subscriber::registry() + .with(BasicLayer(Some(LevelFilter::INFO))) + .with(None::); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::INFO), + "\n stack: {:#?}", + subscriber + ); +} + +// Test that the `None` max level hint only applies if its the only layer +#[test] +fn none_inside_doesnt_override_max_level() { + // None means the other layer takes control + let subscriber = tracing_subscriber::registry() + .with(None::) + .with(BasicLayer(None)); + assert_eq!( + subscriber.max_level_hint(), + None, + "\n stack: {:#?}", + subscriber + ); + + // The `None`-returning layer still wins + let subscriber = tracing_subscriber::registry() + .with(Some(LevelFilter::ERROR)) + .with(BasicLayer(None)); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::ERROR), + "\n stack: {:#?}", + subscriber + ); + + // Check that we aren't doing anything truly wrong + let subscriber = tracing_subscriber::registry() + .with(None::) + .with(BasicLayer(Some(LevelFilter::DEBUG))); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + + // Test that per-subscriber filters aren't affected + + // One layer is None so it "wins" + let subscriber = tracing_subscriber::registry() + .with(None::.with_filter(LevelFilter::DEBUG)) + .with(BasicLayer(None)); + assert_eq!( + subscriber.max_level_hint(), + None, + "\n stack: {:#?}", + subscriber + ); + + // The max-levels wins + let subscriber = tracing_subscriber::registry() + .with(None::.with_filter(LevelFilter::DEBUG)) + .with(BasicLayer(Some(LevelFilter::INFO))); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + + // Test filter on the other layer + let subscriber = tracing_subscriber::registry() + .with(None::) + .with(BasicLayer(Some(LevelFilter::INFO)).with_filter(LevelFilter::DEBUG)); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + let subscriber = tracing_subscriber::registry() + .with(None::) + .with(BasicLayer(None).with_filter(LevelFilter::DEBUG)); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::DEBUG), + "\n stack: {:#?}", + subscriber + ); + + // The `OFF` from `None` over overridden. + let subscriber = tracing_subscriber::registry() + .with(None::) + .with(BasicLayer(Some(LevelFilter::INFO))); + assert_eq!( + subscriber.max_level_hint(), + Some(LevelFilter::INFO), + "\n stack: {:#?}", + subscriber + ); +} + +/// Tests that the logic tested in `doesnt_override_none` works through the reload layer +#[test] +fn reload_works_with_none() { + let (layer1, handle1) = tracing_subscriber::reload::Layer::new(None::); + let (layer2, _handle2) = tracing_subscriber::reload::Layer::new(None::); + + let subscriber = tracing_subscriber::registry().with(layer1).with(layer2); + assert_eq!(subscriber.max_level_hint(), Some(LevelFilter::OFF)); + + // reloading one should pass through correctly. + handle1.reload(Some(BasicLayer(None))).unwrap(); + assert_eq!(subscriber.max_level_hint(), None); + + // Check pass-through of an actual level as well + handle1 + .reload(Some(BasicLayer(Some(LevelFilter::DEBUG)))) + .unwrap(); + assert_eq!(subscriber.max_level_hint(), Some(LevelFilter::DEBUG)); +}