Skip to content

Commit

Permalink
subscriber: fix None layers setting the max level to OFF (#2321)
Browse files Browse the repository at this point in the history
## Motivation

Currently, when using the `Layer` impl for `Option<S: Layer<...>>`, 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 <eliza@buoyant.io>
  • Loading branch information
guswynn and hawkw committed Sep 30, 2022
1 parent c542120 commit 130c499
Show file tree
Hide file tree
Showing 4 changed files with 323 additions and 5 deletions.
38 changes: 36 additions & 2 deletions tracing-subscriber/src/layer/layered.rs
Original file line number Diff line number Diff line change
Expand Up @@ -115,7 +115,11 @@ where
}

fn max_level_hint(&self) -> Option<LevelFilter> {
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 {
Expand Down Expand Up @@ -267,7 +271,11 @@ where
}

fn max_level_hint(&self) -> Option<LevelFilter> {
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]
Expand Down Expand Up @@ -470,6 +478,7 @@ where
&self,
outer_hint: Option<LevelFilter>,
inner_hint: Option<LevelFilter>,
inner_is_none: bool,
) -> Option<LevelFilter> {
if self.inner_is_registry {
return outer_hint;
Expand All @@ -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)
}
}
Expand Down
43 changes: 43 additions & 0 deletions tracing-subscriber/src/layer/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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<L, S>(layer: &L) -> bool
where
L: Layer<S>,
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::<NoneLayerMarker>())
}
.is_some()
}

/// Is a type implementing `Subscriber` `Option::<_>::None`?
pub(crate) fn subscriber_is_none<S>(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::<NoneLayerMarker>())
}
.is_some()
}

impl<L, S> Layer<S> for Option<L>
where
L: Layer<S>,
Expand Down Expand Up @@ -1605,6 +1646,8 @@ where
unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> {
if id == TypeId::of::<Self>() {
Some(self as *const _ as *const ())
} else if id == TypeId::of::<NoneLayerMarker>() && self.is_none() {
Some(&NONE_LAYER_MARKER as *const _ as *const ())
} else {
self.as_ref().and_then(|inner| inner.downcast_raw(id))
}
Expand Down
20 changes: 20 additions & 0 deletions tracing-subscriber/src/reload.rs
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,7 @@
use crate::layer;
use crate::sync::RwLock;

use core::any::TypeId;
use std::{
error, fmt,
marker::PhantomData,
Expand Down Expand Up @@ -182,6 +183,25 @@ where
fn max_level_hint(&self) -> Option<LevelFilter> {
try_lock!(self.inner.read(), else return None).max_level_hint()
}

#[doc(hidden)]
unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> {
// Safety: it is generally unsafe to downcast through a reload, because
// the pointer can be invalidated after the lock is dropped.
// `NoneLayerMarker` is a special case because it
// is never dereferenced.
//
// Additionally, even if the marker type *is* dereferenced (which it
// never will be), the pointer should be valid even if the subscriber
// is reloaded, because all `NoneLayerMarker` pointers that we return
// actually point to the global static singleton `NoneLayerMarker`,
// rather than to a field inside the lock.
if id == TypeId::of::<layer::NoneLayerMarker>() {
return try_lock!(self.inner.read(), else return None).downcast_raw(id);
}

None
}
}

// ===== impl Filter =====
Expand Down
227 changes: 224 additions & 3 deletions tracing-subscriber/tests/option.rs
Original file line number Diff line number Diff line change
@@ -1,7 +1,23 @@
#![cfg(feature = "registry")]
use tracing::level_filters::LevelFilter;
use tracing::Subscriber;
use tracing_subscriber::prelude::*;
use tracing_core::{subscriber::Interest, LevelFilter, Metadata, Subscriber};
use tracing_subscriber::{layer, prelude::*};

// A basic layer that returns its inner for `max_level_hint`
#[derive(Debug)]
struct BasicLayer(Option<LevelFilter>);
impl<S: Subscriber> tracing_subscriber::Layer<S> for BasicLayer {
fn register_callsite(&self, _m: &Metadata<'_>) -> Interest {
Interest::sometimes()
}

fn enabled(&self, _m: &Metadata<'_>, _: layer::Context<'_, S>) -> bool {
true
}

fn max_level_hint(&self) -> Option<LevelFilter> {
self.0
}
}

// This test is just used to compare to the tests below
#[test]
Expand Down Expand Up @@ -34,8 +50,213 @@ fn just_option_some_layer() {
assert_eq!(subscriber.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_layer() {
let subscriber = tracing_subscriber::registry().with(Some(LevelFilter::ERROR));
assert_eq!(subscriber.max_level_hint(), Some(LevelFilter::ERROR));
}

// 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::<LevelFilter>);
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::<LevelFilter>);
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::<LevelFilter>.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::<LevelFilter>.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::<LevelFilter>);
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::<LevelFilter>);
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::<LevelFilter>);
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::<LevelFilter>)
.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::<LevelFilter>)
.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::<LevelFilter>.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::<LevelFilter>.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::<LevelFilter>)
.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::<LevelFilter>)
.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::<LevelFilter>)
.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::<BasicLayer>);
let (layer2, _handle2) = tracing_subscriber::reload::Layer::new(None::<BasicLayer>);

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));
}

0 comments on commit 130c499

Please sign in to comment.