diff --git a/tracing-mock/src/collector.rs b/tracing-mock/src/collector.rs index c153664..48c8bb4 100644 --- a/tracing-mock/src/collector.rs +++ b/tracing-mock/src/collector.rs @@ -3,7 +3,6 @@ use super::{ event::MockEvent, field as mock_field, span::{MockSpan, NewSpan}, - Parent, }; use std::{ collections::{HashMap, VecDeque}, @@ -22,7 +21,7 @@ use tracing::{ }; #[derive(Debug, Eq, PartialEq)] -enum Expect { +pub enum Expect { Event(MockEvent), Enter(MockSpan), Exit(MockSpan), @@ -221,7 +220,8 @@ where if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - let mut checker = expected_values.checker(format!("span {}: ", span.name)); + let context = format!("span {}: ", span.name); + let mut checker = expected_values.checker(&context, &self.name); values.record(&mut checker); checker.finish(); } @@ -234,69 +234,18 @@ where match self.expected.lock().unwrap().pop_front() { None => {} Some(Expect::Event(mut expected)) => { - let spans = self.spans.lock().unwrap(); - expected.check(event); - match expected.parent { - Some(Parent::ExplicitRoot) => { - assert!( - event.is_root(), - "[{}] expected {:?} to be an explicit root event", - self.name, - name - ); - } - Some(Parent::Explicit(expected_parent)) => { - let actual_parent = - event.parent().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have explicit parent {:?}", - self.name, - name, - expected_parent, - ); - } - Some(Parent::ContextualRoot) => { - assert!( - event.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - assert!( - self.current.lock().unwrap().last().is_none(), - "[{}] expected {:?} to be a root, but we were inside a span", - self.name, - name - ); - } - Some(Parent::Contextual(expected_parent)) => { - assert!( - event.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - let stack = self.current.lock().unwrap(); - let actual_parent = - stack.last().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have contextual parent {:?}", - self.name, - name, - expected_parent, - ); - } - None => {} - } + let get_parent_name = || { + let stack = self.current.lock().unwrap(); + let spans = self.spans.lock().unwrap(); + event + .parent() + .and_then(|id| spans.get(id)) + .or_else(|| stack.last().and_then(|id| spans.get(id))) + .map(|s| s.name.to_string()) + }; + expected.check(event, get_parent_name, &self.name); } - Some(ex) => ex.bad( - &self.name, - format_args!("[{}] observed event {:?}", self.name, event), - ), + Some(ex) => ex.bad(&self.name, format_args!("observed event {:#?}", event)), } } @@ -320,70 +269,14 @@ where let mut spans = self.spans.lock().unwrap(); if was_expected { if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { - let name = meta.name(); - expected - .span - .metadata - .check(meta, format_args!("span `{}`", name)); - let mut checker = expected.fields.checker(name.to_string()); - span.record(&mut checker); - checker.finish(); - match expected.parent { - Some(Parent::ExplicitRoot) => { - assert!( - span.is_root(), - "[{}] expected {:?} to be an explicit root span", - self.name, - name - ); - } - Some(Parent::Explicit(expected_parent)) => { - let actual_parent = - span.parent().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have explicit parent {:?}", - self.name, - name, - expected_parent, - ); - } - Some(Parent::ContextualRoot) => { - assert!( - span.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - assert!( - self.current.lock().unwrap().last().is_none(), - "[{}] expected {:?} to be a root, but we were inside a span", - self.name, - name - ); - } - Some(Parent::Contextual(expected_parent)) => { - assert!( - span.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - let stack = self.current.lock().unwrap(); - let actual_parent = - stack.last().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have contextual parent {:?}", - self.name, - name, - expected_parent, - ); - } - None => {} - } + let get_parent_name = || { + let stack = self.current.lock().unwrap(); + span.parent() + .and_then(|id| spans.get(id)) + .or_else(|| stack.last().and_then(|id| spans.get(id))) + .map(|s| s.name.to_string()) + }; + expected.check(span, get_parent_name, &self.name); } } spans.insert( @@ -537,11 +430,15 @@ where } impl MockHandle { + pub fn new(expected: Arc>>, name: String) -> Self { + Self(expected, name) + } + pub fn assert_finished(&self) { if let Ok(ref expected) = self.0.lock() { assert!( !expected.iter().any(|thing| thing != &Expect::Nothing), - "[{}] more notifications expected: {:?}", + "\n[{}] more notifications expected: {:#?}", self.1, **expected ); @@ -550,26 +447,44 @@ impl MockHandle { } impl Expect { - fn bad(&self, name: impl AsRef, what: fmt::Arguments<'_>) { + pub fn bad(&self, name: impl AsRef, what: fmt::Arguments<'_>) { let name = name.as_ref(); match self { - Expect::Event(e) => panic!("[{}] expected event {}, but {} instead", name, e, what,), - Expect::Enter(e) => panic!("[{}] expected to enter {} but {} instead", name, e, what,), - Expect::Exit(e) => panic!("[{}] expected to exit {} but {} instead", name, e, what,), + Expect::Event(e) => panic!( + "\n[{}] expected event {}\n[{}] but instead {}", + name, e, name, what, + ), + Expect::Enter(e) => panic!( + "\n[{}] expected to enter {}\n[{}] but instead {}", + name, e, name, what, + ), + Expect::Exit(e) => panic!( + "\n[{}] expected to exit {}\n[{}] but instead {}", + name, e, name, what, + ), Expect::CloneSpan(e) => { - panic!("[{}] expected to clone {} but {} instead", name, e, what,) + panic!( + "\n[{}] expected to clone {}\n[{}] but instead {}", + name, e, name, what, + ) } Expect::DropSpan(e) => { - panic!("[{}] expected to drop {} but {} instead", name, e, what,) + panic!( + "\n[{}] expected to drop {}\n[{}] but instead {}", + name, e, name, what, + ) } Expect::Visit(e, fields) => panic!( - "[{}] expected {} to record {} but {} instead", - name, e, fields, what, + "\n[{}] expected {} to record {}\n[{}] but instead {}", + name, e, fields, name, what, + ), + Expect::NewSpan(e) => panic!( + "\n[{}] expected {}\n[{}] but instead {}", + name, e, name, what ), - Expect::NewSpan(e) => panic!("[{}] expected {} but {} instead", name, e, what), Expect::Nothing => panic!( - "[{}] expected nothing else to happen, but {} instead", - name, what, + "\n[{}] expected nothing else to happen\n[{}] but {} instead", + name, name, what, ), } } diff --git a/tracing-mock/src/event.rs b/tracing-mock/src/event.rs index 8ce36a2..d16f276 100644 --- a/tracing-mock/src/event.rs +++ b/tracing-mock/src/event.rs @@ -1,5 +1,5 @@ #![allow(missing_docs)] -use super::{field, metadata, Parent}; +use super::{field, metadata, span, Parent}; use std::fmt; @@ -7,10 +7,11 @@ use std::fmt; /// /// This is intended for use with the mock subscriber API in the /// `subscriber` module. -#[derive(Debug, Default, Eq, PartialEq)] +#[derive(Default, Eq, PartialEq)] pub struct MockEvent { pub fields: Option, pub(crate) parent: Option, + in_spans: Vec, metadata: metadata::Expect, } @@ -20,6 +21,10 @@ pub fn mock() -> MockEvent { } } +pub fn msg(message: impl fmt::Display) -> MockEvent { + mock().with_fields(field::msg(message)) +} + impl MockEvent { pub fn named(self, name: I) -> Self where @@ -78,17 +83,49 @@ impl MockEvent { } } - pub(crate) fn check(&mut self, event: &tracing::Event<'_>) { + pub fn check( + &mut self, + event: &tracing::Event<'_>, + get_parent_name: impl FnOnce() -> Option, + collector_name: &str, + ) { let meta = event.metadata(); let name = meta.name(); self.metadata - .check(meta, format_args!("event \"{}\"", name)); - assert!(meta.is_event(), "expected {}, but got {:?}", self, event); + .check(meta, format_args!("event \"{}\"", name), collector_name); + assert!( + meta.is_event(), + "[{}] expected {}, but got {:?}", + collector_name, + self, + event + ); if let Some(ref mut expected_fields) = self.fields { - let mut checker = expected_fields.checker(name.to_string()); + let mut checker = expected_fields.checker(name, collector_name); event.record(&mut checker); checker.finish(); } + + if let Some(ref expected_parent) = self.parent { + let actual_parent = get_parent_name(); + expected_parent.check_parent_name( + actual_parent.as_deref(), + event.parent().cloned(), + event.metadata().name(), + collector_name, + ) + } + } + + pub fn in_scope(self, spans: impl IntoIterator) -> Self { + Self { + in_spans: spans.into_iter().collect(), + ..self + } + } + + pub fn scope_mut(&mut self) -> &mut [span::MockSpan] { + &mut self.in_spans[..] } } @@ -97,3 +134,35 @@ impl fmt::Display for MockEvent { write!(f, "an event{}", self.metadata) } } + +impl fmt::Debug for MockEvent { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("MockEvent"); + + if let Some(ref name) = self.metadata.name { + s.field("name", name); + } + + if let Some(ref target) = self.metadata.target { + s.field("target", target); + } + + if let Some(ref level) = self.metadata.level { + s.field("level", &format_args!("{:?}", level)); + } + + if let Some(ref fields) = self.fields { + s.field("fields", fields); + } + + if let Some(ref parent) = self.parent { + s.field("parent", &format_args!("{:?}", parent)); + } + + if !self.in_spans.is_empty() { + s.field("in_spans", &self.in_spans); + } + + s.finish() + } +} diff --git a/tracing-mock/src/field.rs b/tracing-mock/src/field.rs index 0e7799f..45a17bf 100644 --- a/tracing-mock/src/field.rs +++ b/tracing-mock/src/field.rs @@ -65,6 +65,13 @@ where } } +pub fn msg(message: impl fmt::Display) -> MockField { + MockField { + name: "message".to_string(), + value: MockValue::Debug(message.to_string()), + } +} + impl MockField { /// Expect a field with the given name and value. pub fn with_value(self, value: &dyn Value) -> Self { @@ -113,13 +120,14 @@ impl Expect { Self { only: true, ..self } } - fn compare_or_panic(&mut self, name: &str, value: &dyn Value, ctx: &str) { + fn compare_or_panic(&mut self, name: &str, value: &dyn Value, ctx: &str, collector_name: &str) { let value = value.into(); match self.fields.remove(name) { Some(MockValue::Any) => {} Some(expected) => assert!( expected == value, - "\nexpected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + "\n[{}] expected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + collector_name, ctx, name, expected, @@ -127,15 +135,19 @@ impl Expect { value ), None if self.only => panic!( - "\nexpected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", - ctx, self, name, value + "[{}]expected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", + collector_name, ctx, self, name, value ), _ => {} } } - pub fn checker(&mut self, ctx: String) -> CheckVisitor<'_> { - CheckVisitor { expect: self, ctx } + pub fn checker<'a>(&'a mut self, ctx: &'a str, collector_name: &'a str) -> CheckVisitor<'a> { + CheckVisitor { + expect: self, + ctx, + collector_name, + } } pub fn is_empty(&self) -> bool { @@ -159,38 +171,43 @@ impl fmt::Display for MockValue { pub struct CheckVisitor<'a> { expect: &'a mut Expect, - ctx: String, + ctx: &'a str, + collector_name: &'a str, } impl<'a> Visit for CheckVisitor<'a> { fn record_f64(&mut self, field: &Field, value: f64) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_i64(&mut self, field: &Field, value: i64) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_u64(&mut self, field: &Field, value: u64) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_bool(&mut self, field: &Field, value: bool) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_str(&mut self, field: &Field, value: &str) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { - self.expect - .compare_or_panic(field.name(), &field::debug(value), &self.ctx) + self.expect.compare_or_panic( + field.name(), + &field::debug(value), + self.ctx, + self.collector_name, + ) } } @@ -198,7 +215,8 @@ impl<'a> CheckVisitor<'a> { pub fn finish(self) { assert!( self.expect.fields.is_empty(), - "{}missing {}", + "[{}] {}missing {}", + self.collector_name, self.expect, self.ctx ); diff --git a/tracing-mock/src/lib.rs b/tracing-mock/src/lib.rs index f860f3b..eefc409 100644 --- a/tracing-mock/src/lib.rs +++ b/tracing-mock/src/lib.rs @@ -10,7 +10,7 @@ mod metadata; pub mod span; #[derive(Debug, Eq, PartialEq)] -pub(crate) enum Parent { +pub enum Parent { ContextualRoot, Contextual(String), ExplicitRoot, @@ -23,6 +23,76 @@ pub struct PollN { polls: usize, } +impl Parent { + pub fn check_parent_name( + &self, + parent_name: Option<&str>, + provided_parent: Option, + ctx: impl std::fmt::Display, + collector_name: &str, + ) { + match self { + Parent::ExplicitRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to be an explicit root, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + } + Parent::Explicit(expected_parent) => { + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have explicit parent {}, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + expected_parent, + provided_parent, + parent_name, + ); + } + Parent::ContextualRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to have a contextual parent, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert!( + parent_name.is_none(), + "[{}] expected {} to be contextual a root, but we were inside span {:?}", + collector_name, + ctx, + parent_name, + ); + } + Parent::Contextual(expected_parent) => { + assert!(provided_parent.is_none(), + "[{}] expected {} to have a contextual parent\nbut its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have contextual parent {:?}, but got {:?}", + collector_name, + ctx, + expected_parent, + parent_name, + ); + } + } + } +} + impl std::future::Future for PollN where T: Unpin, diff --git a/tracing-mock/src/metadata.rs b/tracing-mock/src/metadata.rs index f648c46..6655e32 100644 --- a/tracing-mock/src/metadata.rs +++ b/tracing-mock/src/metadata.rs @@ -1,5 +1,5 @@ use std::fmt; -use tracing::Metadata; +use tracing_core::Metadata; #[derive(Clone, Debug, Eq, PartialEq, Default)] pub struct Expect { @@ -9,12 +9,18 @@ pub struct Expect { } impl Expect { - pub(crate) fn check(&self, actual: &Metadata<'_>, ctx: fmt::Arguments<'_>) { + pub(crate) fn check( + &self, + actual: &Metadata<'_>, + ctx: fmt::Arguments<'_>, + collector_name: &str, + ) { if let Some(ref expected_name) = self.name { let name = actual.name(); assert!( expected_name == name, - "expected {} to be named `{}`, but got one named `{}`", + "\n[{}] expected {} to be named `{}`, but got one named `{}`", + collector_name, ctx, expected_name, name @@ -25,7 +31,8 @@ impl Expect { let level = actual.level(); assert!( expected_level == level, - "expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + "\n[{}] expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + collector_name, ctx, expected_level, level, @@ -36,7 +43,8 @@ impl Expect { let target = actual.target(); assert!( expected_target == target, - "expected {} to have target `{}`, but it had target `{}` instead", + "\n[{}] expected {} to have target `{}`, but it had target `{}` instead", + collector_name, ctx, expected_target, target, diff --git a/tracing-mock/src/span.rs b/tracing-mock/src/span.rs index 5b9ce7d..1a19350 100644 --- a/tracing-mock/src/span.rs +++ b/tracing-mock/src/span.rs @@ -6,12 +6,12 @@ use std::fmt; /// /// This is intended for use with the mock subscriber API in the /// `subscriber` module. -#[derive(Clone, Debug, Default, Eq, PartialEq)] +#[derive(Clone, Default, Eq, PartialEq)] pub struct MockSpan { pub(crate) metadata: metadata::Expect, } -#[derive(Debug, Default, Eq, PartialEq)] +#[derive(Default, Eq, PartialEq)] pub struct NewSpan { pub(crate) span: MockSpan, pub(crate) fields: field::Expect, @@ -86,6 +86,14 @@ impl MockSpan { self.metadata.name.as_ref().map(String::as_ref) } + pub fn level(&self) -> Option { + self.metadata.level + } + + pub fn target(&self) -> Option<&str> { + self.metadata.target.as_deref() + } + pub fn with_field(self, fields: I) -> NewSpan where I: Into, @@ -98,6 +106,26 @@ impl MockSpan { } } +impl fmt::Debug for MockSpan { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("MockSpan"); + + if let Some(name) = self.name() { + s.field("name", &name); + } + + if let Some(level) = self.level() { + s.field("level", &format_args!("{:?}", level)); + } + + if let Some(target) = self.target() { + s.field("target", &target); + } + + s.finish() + } +} + impl fmt::Display for MockSpan { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { if self.metadata.name.is_some() { @@ -149,6 +177,32 @@ impl NewSpan { ..self } } + + pub fn check( + &mut self, + span: &tracing_core::span::Attributes<'_>, + get_parent_name: impl FnOnce() -> Option, + collector_name: &str, + ) { + let meta = span.metadata(); + let name = meta.name(); + self.span + .metadata + .check(meta, format_args!("span `{}`", name), collector_name); + let mut checker = self.fields.checker(name, collector_name); + span.record(&mut checker); + checker.finish(); + + if let Some(expected_parent) = self.parent.as_ref() { + let actual_parent = get_parent_name(); + expected_parent.check_parent_name( + actual_parent.as_deref(), + span.parent().cloned(), + format_args!("span `{}`", name), + collector_name, + ) + } + } } impl fmt::Display for NewSpan { @@ -160,3 +214,31 @@ impl fmt::Display for NewSpan { Ok(()) } } + +impl fmt::Debug for NewSpan { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("NewSpan"); + + if let Some(name) = self.span.name() { + s.field("name", &name); + } + + if let Some(level) = self.span.level() { + s.field("level", &format_args!("{:?}", level)); + } + + if let Some(target) = self.span.target() { + s.field("target", &target); + } + + if let Some(ref parent) = self.parent { + s.field("parent", &format_args!("{:?}", parent)); + } + + if !self.fields.is_empty() { + s.field("fields", &self.fields); + } + + s.finish() + } +} diff --git a/tracing-subscriber/src/filter/mod.rs b/tracing-subscriber/src/filter/mod.rs index 9d63ff3..af8bfb3 100644 --- a/tracing-subscriber/src/filter/mod.rs +++ b/tracing-subscriber/src/filter/mod.rs @@ -1,13 +1,53 @@ -//! [`Subscriber`]s that control which spans and events are enabled by the wrapped -//! subscriber. +//! [Subscribers](crate::subscribe) that control which spans and events are +//! enabled by the wrapped collector. //! -//! [`Subscriber`]: crate::fmt::Subscriber +//! This module contains a number of types that provide implementations of +//! various strategies for filtering which spans and events are enabled. For +//! details on filtering spans and events using [`Subscribe`] implementations, +//! see the [`subscribe` module documentation]. +//! +//! [`subscribe` module documentation]: crate::subscribe#filtering-with-subscribers +//! [`Subscribe`]: crate::subscribe +#[cfg(feature = "env-filter")] +mod env; mod level; +#[cfg(feature = "registry")] +mod subscriber_filters; + +#[cfg(not(feature = "registry"))] +pub(crate) use self::has_psf_stubs::*; +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub use self::subscriber_filters::*; pub use self::level::{LevelFilter, ParseError as LevelParseError}; -feature! { - #![all(feature = "env-filter", feature = "std")] - mod env; - pub use self::env::*; +#[cfg(feature = "env-filter")] +#[cfg_attr(docsrs, doc(cfg(feature = "env-filter")))] +pub use self::env::*; + +/// Stub implementations of the per-subscriber-fitler detection functions for +/// when the `registry` feature is disabled. +#[cfg(not(feature = "registry"))] +mod has_psf_stubs { + pub(crate) fn is_psf_downcast_marker(_: std::any::TypeId) -> bool { + false + } + + /// Does a type implementing `Collect` contain any per-subscriber filters? + pub(crate) fn collector_has_psf(_: &C) -> bool + where + C: tracing_core::Collect, + { + false + } + + /// Does a type implementing `Subscribe` contain any per-subscriber filters? + pub(crate) fn subscriber_has_psf(_: &S) -> bool + where + S: crate::Subscribe, + C: tracing_core::Collect, + { + false + } } diff --git a/tracing-subscriber/src/filter/subscriber_filters.rs b/tracing-subscriber/src/filter/subscriber_filters.rs new file mode 100644 index 0000000..5767316 --- /dev/null +++ b/tracing-subscriber/src/filter/subscriber_filters.rs @@ -0,0 +1,1452 @@ +//! ## Per-Subscriber Filtering +//! +//! Per-subscriber filters permit individual `Subscribe`s to have their own filter +//! configurations without interfering with other `Subscribe`s. +//! +//! This module is not public; the public APIs defined in this module are +//! re-exported in the top-level `filter` module. Therefore, this documentation +//! primarily concerns the internal implementation details. For the user-facing +//! public API documentation, see the individual public types in this module, as +//! well as the, see the `Subscribe` trait documentation's [per-subscriber filtering +//! section]][1]. +//! +//! ## How does per-subscriber filtering work? +//! +//! As described in the API documentation, the [`Filter`] trait defines a +//! filtering strategy for a per-subscriber filter. We expect there will be a variety +//! of implementations of [`Filter`], both in `tracing-subscriber` and in user +//! code. +//! +//! To actually *use* a [`Filter`] implementation, it is combined with a +//! [`Subscribe`] by the [`Filtered`] struct defined in this module. [`Filtered`] +//! implements [`Subscribe`] by calling into the wrapped [`Subscribe`], or not, based on +//! the filtering strategy. While there will be a variety of types that implement +//! [`Filter`], all actual *uses* of per-subscriber filtering will occur through the +//! [`Filtered`] struct. Therefore, most of the implementation details live +//! there. +//! +//! [1]: crate::subscribe#per-subscriber-filtering +//! [`Filter`]: crate::subscribe::Filter +use crate::{ + filter::LevelFilter, + registry, + subscribe::{self, Context, Subscribe}, +}; +use std::{ + any::{type_name, TypeId}, + cell::{Cell, RefCell}, + fmt, + marker::PhantomData, + ptr::NonNull, + sync::Arc, + thread_local, +}; +use tracing_core::{ + collect::{Collect, Interest}, + span, Event, Metadata, +}; + +/// A [`Subscribe`] that wraps an inner [`Subscribe`] and adds a [`Filter`] which +/// controls what spans and events are enabled for that subscriber. +/// +/// This is returned by the [`Subscribe::with_filter`] method. See the +/// [documentation on per-subscriber filtering][psf] for details. +/// +/// [`Filter`]: crate::subscribe::Filter +/// [psf]: crate::subscribe#per-subscriber-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Clone)] +pub struct Filtered { + filter: F, + subscriber: S, + id: MagicPsfDowncastMarker, + _s: PhantomData, +} + +/// A per-subscriber [`Filter`] implemented by a closure or function pointer that +/// determines whether a given span or event is enabled _dynamically_, +/// potentially based on the current [span context]. +/// +/// See the [documentation on per-subscriber filtering][psf] for details. +/// +/// [span context]: crate::subscribe::Context +/// [`Filter`]: crate::subscribe::Filter +/// [psf]: crate::subscribe#per-subscriber-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub struct DynFilterFn< + C, + // TODO(eliza): should these just be boxed functions? + F = fn(&Metadata<'_>, &Context<'_, C>) -> bool, + R = fn(&'static Metadata<'static>) -> Interest, +> { + enabled: F, + register_callsite: Option, + max_level_hint: Option, + _s: PhantomData, +} + +/// A per-subscriber [`Filter`] implemented by a closure or function pointer that +/// determines whether a given span or event is enabled, based on its +/// [`Metadata`]. +/// +/// See the [documentation on per-subscriber filtering][psf] for details. +/// +/// [`Metadata`]: tracing_core::Metadata +/// [`Filter`]: crate::subscribe::Filter +/// [psf]: crate::subscribe#per-subscriber-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Clone)] +pub struct FilterFn) -> bool> { + enabled: F, + max_level_hint: Option, +} + +/// Uniquely identifies an individual [`Filter`] instance in the context of +/// a [collector]. +/// +/// When adding a [`Filtered`] [`Subscribe`] to a [collector], the [collector]] +/// generates a `FilterId` for that [`Filtered`] subscriber. The [`Filtered`] subscriber +/// will then use the generated ID to query whether a particular span was +/// previously enabled by that subscriber's [`Filter`]. +/// +/// **Note**: Currently, the [`Registry`] type provided by this crate is the +/// **only** [`Collect`][collector] implementation capable of participating in per-subscriber +/// filtering. Therefore, the `FilterId` type cannot currently be constructed by +/// code outside of `tracing-subscriber`. In the future, new APIs will be added to `tracing-subscriber` to +/// allow non-Registry [collector]s to also participate in per-subscriber +/// filtering. When those APIs are added, subscribers will be responsible +/// for generating and assigning `FilterId`s. +/// +/// [`Filter`]: crate::subscribe::Filter +/// [collector]: tracing_core::Collect +/// [`Subscribe`]: crate::subscribe::Subscribe +/// [`Registry`]: crate::registry::Registry +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Copy, Clone)] +pub struct FilterId(u64); + +/// A bitmap tracking which [`FilterId`]s have enabled a given span or +/// event. +/// +/// This is currently a private type that's used exclusively by the +/// [`Registry`]. However, in the future, this may become a public API, in order +/// to allow user subscribers to host [`Filter`]s. +/// +/// [`Registry`]: crate::Registry +/// [`Filter`]: crate::subscribe::Filter +#[derive(Default, Copy, Clone, Eq, PartialEq)] +pub(crate) struct FilterMap { + bits: u64, +} + +/// The current state of `enabled` calls to per-subscriber filters on this +/// thread. +/// +/// When `Filtered::enabled` is called, the filter will set the bit +/// corresponding to its ID if the filter will disable the event/span being +/// filtered. When the event or span is recorded, the per-subscriber filter will +/// check its bit to determine if it disabled that event or span, and skip +/// forwarding the event or span to the inner subscriber if the bit is set. Once +/// a span or event has been skipped by a per-subscriber filter, it unsets its +/// bit, so that the `FilterMap` has been cleared for the next set of +/// `enabled` calls. +/// +/// FilterState is also read by the `Registry`, for two reasons: +/// +/// 1. When filtering a span, the Registry must store the `FilterMap` +/// generated by `Filtered::enabled` calls for that span as part of the +/// span's per-span data. This allows `Filtered` subscribers to determine +/// whether they had previously disabled a given span, and avoid showing it +/// to the wrapped subscriber if it was disabled. +/// +/// This allows `Filtered` subscribers to also filter out the spans they +/// disable from span traversals (such as iterating over parents, etc). +/// 2. If all the bits are set, then every per-subscriber filter has decided it +/// doesn't want to enable that span or event. In that case, the +/// `Registry`'s `enabled` method will return `false`, so that +/// recording a span or event can be skipped entirely. +#[derive(Debug)] +pub(crate) struct FilterState { + enabled: Cell, + // TODO(eliza): `Interest`s should _probably_ be `Copy`. The only reason + // they're not is our Obsessive Commitment to Forwards-Compatibility. If + // this changes in tracing-core`, we can make this a `Cell` rather than + // `RefCell`... + interest: RefCell>, + + #[cfg(debug_assertions)] + counters: DebugCounters, +} + +/// Extra counters added to `FilterState` used only to make debug assertions. +#[cfg(debug_assertions)] +#[derive(Debug, Default)] +struct DebugCounters { + /// How many per-subscriber filters have participated in the current `enabled` + /// call? + in_filter_pass: Cell, + + /// How many per-subscriber filters have participated in the current `register_callsite` + /// call? + in_interest_pass: Cell, +} + +thread_local! { + pub(crate) static FILTERING: FilterState = FilterState::new(); +} + +// === impl Filter === +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +impl subscribe::Filter for LevelFilter { + fn enabled(&self, meta: &Metadata<'_>, _: &Context<'_, C>) -> bool { + meta.level() <= self + } + + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + if meta.level() <= self { + Interest::always() + } else { + Interest::never() + } + } + + fn max_level_hint(&self) -> Option { + Some(*self) + } +} + +impl subscribe::Filter for Arc + Send + Sync + 'static> { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, C>) -> bool { + (**self).enabled(meta, cx) + } + + #[inline] + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + (**self).callsite_enabled(meta) + } + + #[inline] + fn max_level_hint(&self) -> Option { + (**self).max_level_hint() + } +} + +impl subscribe::Filter for Box + Send + Sync + 'static> { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, C>) -> bool { + (**self).enabled(meta, cx) + } + + #[inline] + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + (**self).callsite_enabled(meta) + } + + #[inline] + fn max_level_hint(&self) -> Option { + (**self).max_level_hint() + } +} + +// === impl Filtered === + +impl Filtered { + /// Wraps the provided [`Subscribe`] so that it is filtered by the given + /// [`Filter`]. + /// + /// This is equivalent to calling the [`Subscribe::with_filter`] method. + /// + /// See the [documentation on per-subscriber filtering][psf] for details. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [psf]: crate::subscribe#per-subscriber-filtering + pub fn new(subscriber: S, filter: F) -> Self { + Self { + subscriber, + filter, + id: MagicPsfDowncastMarker(FilterId::disabled()), + _s: PhantomData, + } + } + + #[inline(always)] + fn id(&self) -> FilterId { + self.id.0 + } + + fn did_enable(&self, f: impl FnOnce()) { + FILTERING.with(|filtering| filtering.did_enable(self.id(), f)) + } +} + +impl Subscribe for Filtered +where + C: Collect + for<'span> registry::LookupSpan<'span> + 'static, + F: subscribe::Filter + 'static, + S: Subscribe, +{ + fn on_subscribe(&mut self, collector: &mut C) { + self.id = MagicPsfDowncastMarker(collector.register_filter()); + self.subscriber.on_subscribe(collector); + } + + // TODO(eliza): can we figure out a nice way to make the `Filtered` subscriber + // not call `is_enabled_for` in hooks that the inner subscriber doesn't actually + // have real implementations of? probably not... + // + // it would be cool if there was some wild rust reflection way of checking + // if a trait impl has the default impl of a trait method or not, but that's + // almsot certainly impossible...right? + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + let interest = self.filter.callsite_enabled(metadata); + + // If the filter didn't disable the callsite, allow the inner subscriber to + // register it — since `register_callsite` is also used for purposes + // such as reserving/caching per-callsite data, we want the inner subscriber + // to be able to perform any other registration steps. However, we'll + // ignore its `Interest`. + if !interest.is_never() { + self.subscriber.register_callsite(metadata); + } + + // Add our `Interest` to the current sum of per-subscriber filter `Interest`s + // for this callsite. + FILTERING.with(|filtering| filtering.add_interest(interest)); + + // don't short circuit! if the stack consists entirely of `Subscribe`s with + // per-subscriber filters, the `Registry` will return the actual `Interest` + // value that's the sum of all the `register_callsite` calls to those + // per-subscriber filters. if we returned an actual `never` interest here, a + // `Subscribeed` subscriber would short-circuit and not allow any `Filtered` + // subscribers below us if _they_ are interested in the callsite. + Interest::always() + } + + fn enabled(&self, metadata: &Metadata<'_>, cx: Context<'_, C>) -> bool { + let cx = cx.with_filter(self.id()); + let enabled = self.filter.enabled(metadata, &cx); + FILTERING.with(|filtering| filtering.set(self.id(), enabled)); + + if enabled { + // If the filter enabled this metadata, ask the wrapped subscriber if + // _it_ wants it --- it might have a global filter. + self.subscriber.enabled(metadata, cx) + } else { + // Otherwise, return `true`. The _per-subscriber_ filter disabled this + // metadata, but returning `false` in `Subscribe::enabled` will + // short-circuit and globally disable the span or event. This is + // *not* what we want for per-subscriber filters, as other subscribers may + // still want this event. Returning `true` here means we'll continue + // asking the next subscriber in the stack. + // + // Once all per-subscriber filters have been evaluated, the `Registry` + // at the root of the stack will return `false` from its `enabled` + // method if *every* per-subscriber filter disabled this metadata. + // Otherwise, the individual per-subscriber filters will skip the next + // `new_span` or `on_event` call for their subscriber if *they* disabled + // the span or event, but it was not globally disabled. + true + } + } + + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, cx: Context<'_, C>) { + self.did_enable(|| { + self.subscriber + .on_new_span(attrs, id, cx.with_filter(self.id())); + }) + } + + #[doc(hidden)] + fn max_level_hint(&self) -> Option { + self.filter.max_level_hint() + } + + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(span, self.id()) { + self.subscriber.on_record(span, values, cx) + } + } + + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, cx: Context<'_, C>) { + // only call `on_follows_from` if both spans are enabled by us + if cx.is_enabled_for(span, self.id()) && cx.is_enabled_for(follows, self.id()) { + self.subscriber + .on_follows_from(span, follows, cx.with_filter(self.id())) + } + } + + fn on_event(&self, event: &Event<'_>, cx: Context<'_, C>) { + self.did_enable(|| { + self.subscriber.on_event(event, cx.with_filter(self.id())); + }) + } + + fn on_enter(&self, id: &span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(id, self.id()) { + self.subscriber.on_enter(id, cx) + } + } + + fn on_exit(&self, id: &span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(id, self.id()) { + self.subscriber.on_exit(id, cx) + } + } + + fn on_close(&self, id: span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(&id, self.id()) { + self.subscriber.on_close(id, cx) + } + } + + // XXX(eliza): the existence of this method still makes me sad... + fn on_id_change(&self, old: &span::Id, new: &span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(old, self.id()) { + self.subscriber.on_id_change(old, new, cx) + } + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + match id { + id if id == TypeId::of::() => Some(NonNull::from(self).cast()), + id if id == TypeId::of::() => Some(NonNull::from(&self.subscriber).cast()), + id if id == TypeId::of::() => Some(NonNull::from(&self.filter).cast()), + id if id == TypeId::of::() => { + Some(NonNull::from(&self.id).cast()) + } + _ => None, + } + } +} + +impl fmt::Debug for Filtered +where + F: fmt::Debug, + L: fmt::Debug, +{ + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("Filtered") + .field("filter", &self.filter) + .field("subscriber", &self.subscriber) + .field("id", &self.id) + .finish() + } +} + +// === impl FilterFn === + +/// Constructs a [`FilterFn`], which implements the [`Filter`] trait, from +/// a function or closure that returns `true` if a span or event should be enabled. +/// +/// This is equivalent to calling [`FilterFn::new`]. +/// +/// See the [documentation on per-subscriber filtering][psf] for details on using +/// [`Filter`]s. +/// +/// [`Filter`]: crate::subscribe::Filter +/// [psf]: crate::subscribe#per-subscriber-filtering +/// +/// # Examples +/// +/// ``` +/// use tracing_subscriber::{ +/// subscribe::{Subscribe, CollectExt}, +/// filter, +/// util::SubscriberInitExt, +/// }; +/// +/// let my_filter = filter::filter_fn(|metadata| { +/// // Only enable spans or events with the target "interesting_things" +/// metadata.target() == "interesting_things" +/// }); +/// +/// let my_subscriber = tracing_subscriber::fmt::subscriber(); +/// +/// tracing_subscriber::registry() +/// .with(my_subscriber.with_filter(my_filter)) +/// .init(); +/// +/// // This event will not be enabled. +/// tracing::warn!("something important but uninteresting happened!"); +/// +/// // This event will be enabled. +/// tracing::debug!(target: "interesting_things", "an interesting minor detail..."); +/// ``` +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub fn filter_fn(f: F) -> FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + FilterFn::new(f) +} + +/// Constructs a [`DynFilterFn`], which implements the [`Filter`] trait, from +/// a function or closure that returns `true` if a span or event should be +/// enabled within a particular [span context][`Context`]. +/// +/// This is equivalent to calling [`DynFilterFn::new`]. +/// +/// Unlike [`filter_fn`], this function takes a closure or function pointer +/// taking the [`Metadata`] for a span or event *and* the current [`Context`]. +/// This means that a [`DynFilterFn`] can choose whether to enable spans or +/// events based on information about the _current_ span (or its parents). +/// +/// If this is *not* necessary, use [`filter_fn`] instead. +/// +/// See the [documentation on per-subscriber filtering][psf] for details on using +/// [`Filter`]s. +/// +/// # Examples +/// +/// ``` +/// use tracing_subscriber::{ +/// subscribe::{Subscribe, CollectExt}, +/// filter, +/// util::SubscriberInitExt, +/// }; +/// +/// // Only enable spans or events within a span named "interesting_span". +/// let my_filter = filter::dynamic_filter_fn(|metadata, cx| { +/// // If this *is* "interesting_span", make sure to enable it. +/// if metadata.is_span() && metadata.name() == "interesting_span" { +/// return true; +/// } +/// +/// // Otherwise, are we in an interesting span? +/// if let Some(current_span) = cx.lookup_current() { +/// return current_span.name() == "interesting_span"; +/// } +/// +/// false +/// }); +/// +/// let my_subscriber = tracing_subscriber::fmt::subscriber(); +/// +/// tracing_subscriber::registry() +/// .with(my_subscriber.with_filter(my_filter)) +/// .init(); +/// +/// // This event will not be enabled. +/// tracing::info!("something happened"); +/// +/// tracing::info_span!("interesting_span").in_scope(|| { +/// // This event will be enabled. +/// tracing::debug!("something else happened"); +/// }); +/// ``` +/// +/// [`Filter`]: crate::subscribe::Filter +/// [psf]: crate::subscribe#per-subscriber-filtering +/// [`Context`]: crate::subscribe::Context +/// [`Metadata`]: tracing_core::Metadata +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub fn dynamic_filter_fn(f: F) -> DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + DynFilterFn::new(f) +} + +impl FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + /// Constructs a [`Filter`] from a function or closure that returns `true` + /// if a span or event should be enabled, based on its [`Metadata`]. + /// + /// If determining whether a span or event should be enabled also requires + /// information about the current span context, use [`DynFilterFn`] instead. + /// + /// See the [documentation on per-subscriber filtering][psf] for details on using + /// [`Filter`]s. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [psf]: crate::subscribe#per-subscriber-filtering + /// [`Metadata`]: tracing_core::Metadata + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::FilterFn, + /// util::SubscriberInitExt, + /// }; + /// + /// let my_filter = FilterFn::new(|metadata| { + /// // Only enable spans or events with the target "interesting_things" + /// metadata.target() == "interesting_things" + /// }); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// + /// // This event will not be enabled. + /// tracing::warn!("something important but uninteresting happened!"); + /// + /// // This event will be enabled. + /// tracing::debug!(target: "interesting_things", "an interesting minor detail..."); + /// ``` + pub fn new(enabled: F) -> Self { + Self { + enabled, + max_level_hint: None, + } + } + + /// Sets the highest verbosity [`Level`] the filter function will enable. + /// + /// The value passed to this method will be returned by this `FilterFn`'s + /// [`Filter::max_level_hint`] method. + /// + /// If the provided function will not enable all levels, it is recommended + /// to call this method to configure it with the most verbose level it will + /// enable. + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::{filter_fn, LevelFilter}, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::Level; + /// + /// let my_filter = filter_fn(|metadata| { + /// // Only enable spans or events with targets starting with `my_crate` + /// // and levels at or below `INFO`. + /// metadata.level() <= &Level::INFO && metadata.target().starts_with("my_crate") + /// }) + /// // Since the filter closure will only enable the `INFO` level and + /// // below, set the max level hint + /// .with_max_level_hint(LevelFilter::INFO); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [`Level`]: tracing_core::Level + /// [`Filter::max_level_hint`]: crate::subscribe::Filter::max_level_hint + pub fn with_max_level_hint(self, max_level_hint: impl Into) -> Self { + Self { + max_level_hint: Some(max_level_hint.into()), + ..self + } + } + + fn is_below_max_level(&self, metadata: &Metadata<'_>) -> bool { + self.max_level_hint + .as_ref() + .map(|hint| metadata.level() <= hint) + .unwrap_or(true) + } +} + +impl subscribe::Filter for FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + fn enabled(&self, metadata: &Metadata<'_>, _: &Context<'_, S>) -> bool { + let enabled = (self.enabled)(metadata); + debug_assert!( + !enabled || self.is_below_max_level(metadata), + "FilterFn<{}> claimed it would only enable {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + + enabled + } + + fn callsite_enabled(&self, metadata: &'static Metadata<'static>) -> Interest { + // Because `self.enabled` takes a `Metadata` only (and no `Context` + // parameter), we can reasonably assume its results are cachable, and + // just return `Interest::always`/`Interest::never`. + if (self.enabled)(metadata) { + debug_assert!( + self.is_below_max_level(metadata), + "FilterFn<{}> claimed it was only interested in {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + return Interest::always(); + } + + Interest::never() + } + + fn max_level_hint(&self) -> Option { + self.max_level_hint + } +} + +impl From for FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + fn from(enabled: F) -> Self { + Self::new(enabled) + } +} + +impl fmt::Debug for FilterFn { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("FilterFn") + .field("enabled", &format_args!("{}", type_name::())) + .field("max_level_hint", &self.max_level_hint) + .finish() + } +} + +// === impl DynFilterFn == + +impl DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + /// Constructs a [`Filter`] from a function or closure that returns `true` + /// if a span or event should be enabled in the current [span + /// context][`Context`]. + /// + /// Unlike [`FilterFn`], a `DynFilterFn` is constructed from a closure or + /// function pointer that takes both the [`Metadata`] for a span or event + /// *and* the current [`Context`]. This means that a [`DynFilterFn`] can + /// choose whether to enable spans or events based on information about the + /// _current_ span (or its parents). + /// + /// If this is *not* necessary, use [`FilterFn`] instead. + /// + /// See the [documentation on per-subscriber filtering][psf] for details on using + /// [`Filter`]s. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [psf]: crate::subscribe#per-subscriber-filtering + /// [`Context`]: crate::subscribe::Context + /// [`Metadata`]: tracing_core::Metadata + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::DynFilterFn, + /// util::SubscriberInitExt, + /// }; + /// + /// // Only enable spans or events within a span named "interesting_span". + /// let my_filter = DynFilterFn::new(|metadata, cx| { + /// // If this *is* "interesting_span", make sure to enable it. + /// if metadata.is_span() && metadata.name() == "interesting_span" { + /// return true; + /// } + /// + /// // Otherwise, are we in an interesting span? + /// if let Some(current_span) = cx.lookup_current() { + /// return current_span.name() == "interesting_span"; + /// } + /// + /// false + /// }); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// + /// // This event will not be enabled. + /// tracing::info!("something happened"); + /// + /// tracing::info_span!("interesting_span").in_scope(|| { + /// // This event will be enabled. + /// tracing::debug!("something else happened"); + /// }); + /// ``` + pub fn new(enabled: F) -> Self { + Self { + enabled, + register_callsite: None, + max_level_hint: None, + _s: PhantomData, + } + } +} + +impl DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + /// Sets the highest verbosity [`Level`] the filter function will enable. + /// + /// The value passed to this method will be returned by this `DynFilterFn`'s + /// [`Filter::max_level_hint`] method. + /// + /// If the provided function will not enable all levels, it is recommended + /// to call this method to configure it with the most verbose level it will + /// enable. + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::{DynFilterFn, LevelFilter}, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::Level; + /// + /// // Only enable spans or events with levels at or below `INFO`, if + /// // we are inside a span called "interesting_span". + /// let my_filter = DynFilterFn::new(|metadata, cx| { + /// // If the level is greater than INFO, disable it. + /// if metadata.level() > &Level::INFO { + /// return false; + /// } + /// + /// // If any span in the current scope is named "interesting_span", + /// // enable this span or event. + /// for span in cx.lookup_current().iter().flat_map(|span| span.scope()) { + /// if span.name() == "interesting_span" { + /// return true; + /// } + /// } + /// + /// // Otherwise, disable it. + /// false + /// }) + /// // Since the filter closure will only enable the `INFO` level and + /// // below, set the max level hint + /// .with_max_level_hint(LevelFilter::INFO); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [`Level`]: tracing_core::Level + /// [`Filter::max_level_hint`]: crate::subscribe::Filter::max_level_hint + pub fn with_max_level_hint(self, max_level_hint: impl Into) -> Self { + Self { + max_level_hint: Some(max_level_hint.into()), + ..self + } + } + + /// Adds a function for filtering callsites to this filter. + /// + /// When this filter's [`Filter::callsite_enabled`][cse] method is called, + /// the provided function will be used rather than the default. + /// + /// By default, `DynFilterFn` assumes that, because the filter _may_ depend + /// dynamically on the current [span context], its result should never be + /// cached. However, some filtering strategies may require dynamic information + /// from the current span context in *some* cases, but are able to make + /// static filtering decisions from [`Metadata`] alone in others. + /// + /// For example, consider the filter given in the example for + /// [`DynFilterFn::new`]. That filter enables all spans named + /// "interesting_span", and any events and spans that occur inside of an + /// interesting span. Since the span's name is part of its static + /// [`Metadata`], the "interesting_span" can be enabled in + /// [`callsite_enabled`][cse]: + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::DynFilterFn, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::collect::Interest; + /// + /// // Only enable spans or events within a span named "interesting_span". + /// let my_filter = DynFilterFn::new(|metadata, cx| { + /// // If this *is* "interesting_span", make sure to enable it. + /// if metadata.is_span() && metadata.name() == "interesting_span" { + /// return true; + /// } + /// + /// // Otherwise, are we in an interesting span? + /// if let Some(current_span) = cx.lookup_current() { + /// return current_span.name() == "interesting_span"; + /// } + /// + /// false + /// }).with_callsite_filter(|metadata| { + /// // If this is an "interesting_span", we know we will always + /// // enable it. + /// if metadata.is_span() && metadata.name() == "interesting_span" { + /// return Interest::always(); + /// } + /// + /// // Otherwise, it depends on whether or not we're in an interesting + /// // span. You'll have to ask us again for each span/event! + /// Interest::sometimes() + /// }); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [cse]: crate::subscribe::Filter::callsite_enabled + /// [`enabled`]: crate::subscribe::Filter::enabled + /// [`Metadata`]: tracing_core::Metadata + /// [span context]: crate::subscribe::Context + pub fn with_callsite_filter(self, callsite_enabled: R2) -> DynFilterFn + where + R2: Fn(&'static Metadata<'static>) -> Interest, + { + let register_callsite = Some(callsite_enabled); + let DynFilterFn { + enabled, + max_level_hint, + _s, + .. + } = self; + DynFilterFn { + enabled, + register_callsite, + max_level_hint, + _s, + } + } + + fn default_callsite_enabled(&self, metadata: &Metadata<'_>) -> Interest { + // If it's below the configured max level, assume that `enabled` will + // never enable it... + if !is_below_max_level(&self.max_level_hint, metadata) { + debug_assert!( + !(self.enabled)(metadata, &Context::none()), + "DynFilterFn<{}> claimed it would only enable {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + return Interest::never(); + } + + // Otherwise, since this `enabled` function is dynamic and depends on + // the current context, we don't know whether this span or event will be + // enabled or not. Ask again every time it's recorded! + Interest::sometimes() + } +} + +impl subscribe::Filter for DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, + R: Fn(&'static Metadata<'static>) -> Interest, +{ + fn enabled(&self, metadata: &Metadata<'_>, cx: &Context<'_, S>) -> bool { + let enabled = (self.enabled)(metadata, cx); + debug_assert!( + !enabled || is_below_max_level(&self.max_level_hint, metadata), + "DynFilterFn<{}> claimed it would only enable {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + + enabled + } + + fn callsite_enabled(&self, metadata: &'static Metadata<'static>) -> Interest { + let interest = self + .register_callsite + .as_ref() + .map(|callsite_enabled| callsite_enabled(metadata)) + .unwrap_or_else(|| self.default_callsite_enabled(metadata)); + debug_assert!( + interest.is_never() || is_below_max_level(&self.max_level_hint, metadata), + "DynFilterFn<{}, {}> claimed it was only interested in {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + + interest + } + + fn max_level_hint(&self) -> Option { + self.max_level_hint + } +} + +impl fmt::Debug for DynFilterFn { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("DynFilterFn"); + s.field("enabled", &format_args!("{}", type_name::())); + if self.register_callsite.is_some() { + s.field( + "register_callsite", + &format_args!("Some({})", type_name::()), + ); + } else { + s.field("register_callsite", &format_args!("None")); + } + + s.field("max_level_hint", &self.max_level_hint).finish() + } +} + +impl Clone for DynFilterFn +where + F: Clone, + R: Clone, +{ + fn clone(&self) -> Self { + Self { + enabled: self.enabled.clone(), + register_callsite: self.register_callsite.clone(), + max_level_hint: self.max_level_hint, + _s: PhantomData, + } + } +} + +impl From for DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + fn from(f: F) -> Self { + Self::new(f) + } +} + +// === impl FilterId === + +impl FilterId { + const fn disabled() -> Self { + Self(u64::MAX) + } + + /// Returns a `FilterId` that will consider _all_ spans enabled. + pub(crate) const fn none() -> Self { + Self(0) + } + + pub(crate) fn new(id: u8) -> Self { + assert!(id < 64, "filter IDs may not be greater than 64"); + Self(1 << id as usize) + } + + /// Combines two `FilterId`s, returning a new `FilterId` that will match a + /// [`FilterMap`] where the span was disabled by _either_ this `FilterId` + /// *or* the combined `FilterId`. + /// + /// This method is called by [`Context`]s when adding the `FilterId` of a + /// [`Filtered`] subscriber to the context. + /// + /// This is necessary for cases where we have a tree of nested [`Filtered`] + /// subscribers, like this: + /// + /// ```text + /// Filtered { + /// filter1, + /// Subscribeed { + /// subscriber1, + /// Filtered { + /// filter2, + /// subscriber2, + /// }, + /// } + /// ``` + /// + /// We want `subscriber2` to be affected by both `filter1` _and_ `filter2`. + /// Without combining `FilterId`s, this works fine when filtering + /// `on_event`/`new_span`, because the outer `Filtered` subscriber (`filter1`) + /// won't call the inner subscriber's `on_event` or `new_span` callbacks if it + /// disabled the event/span. + /// + /// However, it _doesn't_ work when filtering span lookups and traversals + /// (e.g. `scope`). This is because the [`Context`] passed to `subscriber2` + /// would set its filter ID to the filter ID of `filter2`, and would skip + /// spans that were disabled by `filter2`. However, what if a span was + /// disabled by `filter1`? We wouldn't see it in `new_span`, but we _would_ + /// see it in lookups and traversals...which we don't want. + /// + /// When a [`Filtered`] subscriber adds its ID to a [`Context`], it _combines_ it + /// with any previous filter ID that the context had, rather than replacing + /// it. That way, `subscriber2`'s context will check if a span was disabled by + /// `filter1` _or_ `filter2`. The way we do this, instead of representing + /// `FilterId`s as a number number that we shift a 1 over by to get a mask, + /// we just store the actual mask,so we can combine them with a bitwise-OR. + /// + /// For example, if we consider the following case (pretending that the + /// masks are 8 bits instead of 64 just so i don't have to write out a bunch + /// of extra zeroes): + /// + /// - `filter1` has the filter id 1 (`0b0000_0001`) + /// - `filter2` has the filter id 2 (`0b0000_0010`) + /// + /// A span that gets disabled by filter 1 would have the [`FilterMap`] with + /// bits `0b0000_0001`. + /// + /// If the `FilterId` was internally represented as `(bits to shift + 1), + /// when `subscriber2`'s [`Context`] checked if it enabled the span, it would + /// make the mask `0b0000_0010` (`1 << 1`). That bit would not be set in the + /// [`FilterMap`], so it would see that it _didn't_ disable the span. Which + /// is *true*, it just doesn't reflect the tree-like shape of the actual + /// subscriber. + /// + /// By having the IDs be masks instead of shifts, though, when the + /// [`Filtered`] with `filter2` gets the [`Context`] with `filter1`'s filter ID, + /// instead of replacing it, it ors them together: + /// + /// ```ignore + /// 0b0000_0001 | 0b0000_0010 == 0b0000_0011; + /// ``` + /// + /// We then test if the span was disabled by seeing if _any_ bits in the + /// mask are `1`: + /// + /// ```ignore + /// filtermap & mask != 0; + /// 0b0000_0001 & 0b0000_0011 != 0; + /// 0b0000_0001 != 0; + /// true; + /// ``` + /// + /// [`Context`]: crate::subscribe::Context + pub(crate) fn and(self, FilterId(other): Self) -> Self { + // If this mask is disabled, just return the other --- otherwise, we + // would always see that every span is disabled. + if self.0 == Self::disabled().0 { + return Self(other); + } + + Self(self.0 | other) + } +} + +impl fmt::Debug for FilterId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + // don't print a giant set of the numbers 0..63 if the filter ID is disabled. + if self.0 == Self::disabled().0 { + return f + .debug_tuple("FilterId") + .field(&format_args!("DISABLED")) + .finish(); + } + + if f.alternate() { + f.debug_struct("FilterId") + .field("ids", &format_args!("{:?}", FmtBitset(self.0))) + .field("bits", &format_args!("{:b}", self.0)) + .finish() + } else { + f.debug_tuple("FilterId").field(&FmtBitset(self.0)).finish() + } + } +} + +impl fmt::Binary for FilterId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_tuple("FilterId") + .field(&format_args!("{:b}", self.0)) + .finish() + } +} + +// === impl FilterMap === + +impl FilterMap { + pub(crate) fn set(self, FilterId(mask): FilterId, enabled: bool) -> Self { + if mask == u64::MAX { + return self; + } + + if enabled { + Self { + bits: self.bits & (!mask), + } + } else { + Self { + bits: self.bits | mask, + } + } + } + + #[inline] + pub(crate) fn is_enabled(self, FilterId(mask): FilterId) -> bool { + self.bits & mask == 0 + } + + #[inline] + pub(crate) fn any_enabled(self) -> bool { + self.bits != u64::MAX + } +} + +impl fmt::Debug for FilterMap { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let alt = f.alternate(); + let mut s = f.debug_struct("FilterMap"); + s.field("disabled_by", &format_args!("{:?}", &FmtBitset(self.bits))); + + if alt { + s.field("bits", &format_args!("{:b}", self.bits)); + } + + s.finish() + } +} + +impl fmt::Binary for FilterMap { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("FilterMap") + .field("bits", &format_args!("{:b}", self.bits)) + .finish() + } +} + +// === impl FilterState === + +impl FilterState { + fn new() -> Self { + Self { + enabled: Cell::new(FilterMap::default()), + interest: RefCell::new(None), + + #[cfg(debug_assertions)] + counters: DebugCounters::default(), + } + } + + fn set(&self, filter: FilterId, enabled: bool) { + #[cfg(debug_assertions)] + { + let in_current_pass = self.counters.in_filter_pass.get(); + if in_current_pass == 0 { + debug_assert_eq!(self.enabled.get(), FilterMap::default()); + } + self.counters.in_filter_pass.set(in_current_pass + 1); + debug_assert_eq!( + self.counters.in_interest_pass.get(), + 0, + "if we are in or starting a filter pass, we must not be in an interest pass." + ) + } + + self.enabled.set(self.enabled.get().set(filter, enabled)) + } + + fn add_interest(&self, interest: Interest) { + let mut curr_interest = self.interest.borrow_mut(); + + #[cfg(debug_assertions)] + { + let in_current_pass = self.counters.in_interest_pass.get(); + if in_current_pass == 0 { + debug_assert!(curr_interest.is_none()); + } + self.counters.in_interest_pass.set(in_current_pass + 1); + } + + if let Some(curr_interest) = curr_interest.as_mut() { + if (curr_interest.is_always() && !interest.is_always()) + || (curr_interest.is_never() && !interest.is_never()) + { + *curr_interest = Interest::sometimes(); + } + // If the two interests are the same, do nothing. If the current + // interest is `sometimes`, stay sometimes. + } else { + *curr_interest = Some(interest); + } + } + + pub(crate) fn event_enabled() -> bool { + FILTERING + .try_with(|this| { + let enabled = this.enabled.get().any_enabled(); + #[cfg(debug_assertions)] + { + if this.counters.in_filter_pass.get() == 0 { + debug_assert_eq!(this.enabled.get(), FilterMap::default()); + } + + // Nothing enabled this event, we won't tick back down the + // counter in `did_enable`. Reset it. + if !enabled { + this.counters.in_filter_pass.set(0); + } + } + enabled + }) + .unwrap_or(true) + } + + /// Executes a closure if the filter with the provided ID did not disable + /// the current span/event. + /// + /// This is used to implement the `on_event` and `new_span` methods for + /// `Filtered`. + fn did_enable(&self, filter: FilterId, f: impl FnOnce()) { + let map = self.enabled.get(); + if map.is_enabled(filter) { + // If the filter didn't disable the current span/event, run the + // callback. + f(); + } else { + // Otherwise, if this filter _did_ disable the span or event + // currently being processed, clear its bit from this thread's + // `FilterState`. The bit has already been "consumed" by skipping + // this callback, and we need to ensure that the `FilterMap` for + // this thread is reset when the *next* `enabled` call occurs. + self.enabled.set(map.set(filter, true)); + } + #[cfg(debug_assertions)] + { + let in_current_pass = self.counters.in_filter_pass.get(); + if in_current_pass <= 1 { + debug_assert_eq!(self.enabled.get(), FilterMap::default()); + } + self.counters + .in_filter_pass + .set(in_current_pass.saturating_sub(1)); + debug_assert_eq!( + self.counters.in_interest_pass.get(), + 0, + "if we are in a filter pass, we must not be in an interest pass." + ) + } + } + + pub(crate) fn take_interest() -> Option { + FILTERING + .try_with(|filtering| { + #[cfg(debug_assertions)] + { + if filtering.counters.in_interest_pass.get() == 0 { + debug_assert!(filtering.interest.try_borrow().ok()?.is_none()); + } + filtering.counters.in_interest_pass.set(0); + } + filtering.interest.try_borrow_mut().ok()?.take() + }) + .ok()? + } + + pub(crate) fn filter_map(&self) -> FilterMap { + let map = self.enabled.get(); + #[cfg(debug_assertions)] + if self.counters.in_filter_pass.get() == 0 { + debug_assert_eq!(map, FilterMap::default()); + } + + map + } +} +/// This is a horrible and bad abuse of the downcasting system to expose +/// *internally* whether a subscriber has per-subscriber filtering, within +/// `tracing-subscriber`, without exposing a public API for it. +/// +/// If a `Subscribe` has per-subscriber filtering, it will downcast to a +/// `MagicPsfDowncastMarker`. Since subscribers which contain other subscribers permit +/// downcasting to recurse to their children, this will do the Right Thing with +/// subscribers like Reload, Option, etc. +/// +/// Why is this a wrapper around the `FilterId`, you may ask? Because +/// downcasting works by returning a pointer, and we don't want to risk +/// introducing UB by constructing pointers that _don't_ point to a valid +/// instance of the type they claim to be. In this case, we don't _intend_ for +/// this pointer to be dereferenced, so it would actually be fine to return one +/// that isn't a valid pointer...but we can't guarantee that the caller won't +/// (accidentally) dereference it, so it's better to be safe than sorry. We +/// could, alternatively, add an additional field to the type that's used only +/// for returning pointers to as as part of the evil downcasting hack, but I +/// thought it was nicer to just add a `repr(transparent)` wrapper to the +/// existing `FilterId` field, since it won't make the struct any bigger. +/// +/// Don't worry, this isn't on the test. :) +#[derive(Clone, Copy)] +#[repr(transparent)] +struct MagicPsfDowncastMarker(FilterId); +impl fmt::Debug for MagicPsfDowncastMarker { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + // Just pretend that `MagicPsfDowncastMarker` doesn't exist for + // `fmt::Debug` purposes...if no one *sees* it in their `Debug` output, + // they don't have to know I thought this code would be a good idea. + fmt::Debug::fmt(&self.0, f) + } +} + +pub(crate) fn is_psf_downcast_marker(type_id: TypeId) -> bool { + type_id == TypeId::of::() +} + +/// Does a type implementing `Collect` contain any per-subscriber filters? +pub(crate) fn collector_has_psf(collector: &C) -> bool +where + C: Collect, +{ + (collector as &dyn Collect).is::() +} + +/// Does a type implementing `Subscriber` contain any per-subscriber filters? +pub(crate) fn subscriber_has_psf(subscriber: &S) -> bool +where + S: Subscribe, + C: Collect, +{ + unsafe { + // Safety: we're not actually *doing* anything with this pointer --- we + // only care about the `Option`, which we're turning into a `bool`. So + // even if the subscriber decides to be evil and give us some kind of invalid + // pointer, we don't ever dereference it, so this is always safe. + subscriber.downcast_raw(TypeId::of::()) + } + .is_some() +} + +struct FmtBitset(u64); + +impl fmt::Debug for FmtBitset { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut set = f.debug_set(); + for bit in 0..64 { + // if the `bit`-th bit is set, add it to the debug set + if self.0 & (1 << bit) != 0 { + set.entry(&bit); + } + } + set.finish() + } +} + +fn is_below_max_level(hint: &Option, metadata: &Metadata<'_>) -> bool { + hint.as_ref() + .map(|hint| metadata.level() <= hint) + .unwrap_or(true) +} diff --git a/tracing-subscriber/src/lib.rs b/tracing-subscriber/src/lib.rs index 34b17d4..07f5ec2 100644 --- a/tracing-subscriber/src/lib.rs +++ b/tracing-subscriber/src/lib.rs @@ -14,9 +14,34 @@ //! //! [msrv]: #supported-rust-versions //! -//! ## Included Subscribers -//! -//! The following `Collector`s are provided for application authors: +//! ## Subscribers and Filters +//! +//! The most important component of the `tracing-subscriber` API is the +//! [`Subscribe`] trait, which provides a composable abstraction for building +//! [collector]s. Like the [`Collect`] trait, [`Subscribe`] defines a +//! particular behavior for collecting trace data. Unlike [`Collect`], +//! which implements a *complete* strategy for how trace data is collected, +//! [`Subscribe`] provide *modular* implementations of specific behaviors. +//! Therefore, they can be [composed together] to form a [collector] which is +//! capable of recording traces in a variety of ways. See the [`subscribe` module's +//! documentation][subscribe] for details on using [subscribers]. +//! +//! In addition, the [`Filter`] trait defines an interface for filtering what +//! spans and events are recorded by a particular subscriber. This allows different +//! [`Subscribe`] implementationss to handle separate subsets of the trace data +//! emitted by a program. See the [documentation on per-subscriber +//! filtering][psf] for more information on using [`Filter`]s. +//! +//! [`Subscribe`]: crate::subscribe::Subscribe +//! [composed together]: crate::subscribe#composing-subscribers +//! [subscribe]: crate::subscribe +//! [subscribers]: crate::subscribe +//! [`Filter`]: crate::subscribe::Filter +//! [psf]: crate::subscribe#per-subscriber-filtering +//! +//! ## Included Collectors +//! +//! The following [ollectors] are provided for application authors: //! //! - [`fmt`] - Formats and logs tracing data (requires the `fmt` feature flag) //! @@ -95,6 +120,7 @@ //! [`fmt`]: mod@fmt //! [`registry`]: mod@registry //! [`Collect`]: tracing_core::collect::Collect +//! [collector]: tracing_core::collect::Collect //! [`EnvFilter`]: filter::EnvFilter //! [`tracing-log`]: https://crates.io/crates/tracing-log //! [`smallvec`]: https://crates.io/crates/smallvec @@ -109,7 +135,15 @@ html_favicon_url = "https://raw.githubusercontent.com/tokio-rs/tracing/master/assets/favicon.ico", issue_tracker_base_url = "https://github.com/tokio-rs/tracing/issues/" )] -#![cfg_attr(docsrs, feature(doc_cfg))] +#![cfg_attr( + docsrs, + // Allows displaying cfgs/feature flags in the documentation. + feature(doc_cfg), + // Allows adding traits to RustDoc's list of "notable traits" + feature(doc_notable_trait), + // Fail the docs build if any intra-docs links are broken + deny(rustdoc::broken_intra_doc_links), +)] #![warn( missing_debug_implementations, missing_docs, diff --git a/tracing-subscriber/src/registry/mod.rs b/tracing-subscriber/src/registry/mod.rs index 334cd0b..0ac77f0 100644 --- a/tracing-subscriber/src/registry/mod.rs +++ b/tracing-subscriber/src/registry/mod.rs @@ -60,6 +60,8 @@ //! [lookup]: crate::subscribe::Context::span() use core::fmt::Debug; +#[cfg(feature = "registry")] +use crate::filter::FilterId; use tracing_core::{field::FieldSet, span::Id, Metadata}; feature! { @@ -126,8 +128,34 @@ pub trait LookupSpan<'a> { Some(SpanRef { registry: self, data, + #[cfg(feature = "registry")] + filter: FilterId::none(), }) } + + /// Registers a [`Filter`] for [per-subscriber filtering] with this + /// [collector]. + /// + /// The [`Filter`] can then use the returned [`FilterId`] to + /// [check if it previously enabled a span][check]. + /// + /// # Panics + /// + /// If this collector does not support [per-subscriber filtering]. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [per-subscriber filtering]: crate::subscribe#per-subscriber-filtering + /// [collector]: tracing_core::Collect + /// [`FilterId`]: crate::filter::FilterId + /// [check]: SpanData::is_enabled_for + #[cfg(feature = "registry")] + #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] + fn register_filter(&mut self) -> FilterId { + panic!( + "{} does not currently support filters", + std::any::type_name::() + ) + } } /// A stored representation of data associated with a span. @@ -156,6 +184,23 @@ pub trait SpanData<'a> { #[cfg(feature = "std")] #[cfg_attr(docsrs, doc(cfg(feature = "std")))] fn extensions_mut(&self) -> ExtensionsMut<'_>; + + /// Returns `true` if this span is enabled for the [per-subscriber filter][psf] + /// corresponding to the provided [`FilterId`]. + /// + /// ## Default Implementation + /// + /// By default, this method assumes that the [`LookupSpan`] implementation + /// does not support [per-subscriber filtering][psf], and always returns `true`. + /// + /// [psf]: crate::subscribe#per-subscriber-filtering + /// [`FilterId`]: crate::filter::FilterId + #[cfg(feature = "registry")] + #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] + fn is_enabled_for(&self, filter: FilterId) -> bool { + let _ = filter; + true + } } /// A reference to [span data] and the associated [registry]. @@ -170,6 +215,9 @@ pub trait SpanData<'a> { pub struct SpanRef<'a, R: LookupSpan<'a>> { registry: &'a R, data: R::Data, + + #[cfg(feature = "registry")] + filter: FilterId, } /// An iterator over the parents of a span, ordered from leaf to root. @@ -179,10 +227,18 @@ pub struct SpanRef<'a, R: LookupSpan<'a>> { pub struct Scope<'a, R> { registry: &'a R, next: Option, + + #[cfg(feature = "registry")] + filter: FilterId, } feature! { - #![feature = "std"] + #![any(feature = "alloc", feature = "std")] + + #[cfg(not(feature = "smallvec"))] + use alloc::vec::{self, Vec}; + + use core::{fmt,iter}; /// An iterator over the parents of a span, ordered from root to leaf. /// @@ -192,9 +248,9 @@ feature! { R: LookupSpan<'a>, { #[cfg(feature = "smallvec")] - spans: std::iter::Rev>>, + spans: iter::Rev>>, #[cfg(not(feature = "smallvec"))] - spans: std::iter::Rev>>, + spans: iter::Rev>>, } #[cfg(feature = "smallvec")] @@ -243,11 +299,11 @@ feature! { } } - impl<'a, R> Debug for ScopeFromRoot<'a, R> + impl<'a, R> fmt::Debug for ScopeFromRoot<'a, R> where R: LookupSpan<'a>, { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.pad("ScopeFromRoot { .. }") } } @@ -260,9 +316,25 @@ where type Item = SpanRef<'a, R>; fn next(&mut self) -> Option { - let curr = self.registry.span(self.next.as_ref()?)?; - self.next = curr.parent_id().cloned(); - Some(curr) + loop { + let curr = self.registry.span(self.next.as_ref()?)?; + + #[cfg(feature = "registry")] + let curr = curr.with_filter(self.filter); + self.next = curr.data.parent().cloned(); + + // If the `Scope` is filtered, check if the current span is enabled + // by the selected filter ID. + + #[cfg(feature = "registry")] + if !curr.is_enabled_for(self.filter) { + // The current span in the chain is disabled for this + // filter. Try its parent. + continue; + } + + return Some(curr); + } } } @@ -294,15 +366,69 @@ where /// Returns the ID of this span's parent, or `None` if this span is the root /// of its trace tree. + #[deprecated( + note = "this method cannot properly support per-subscriber filtering, and may \ + return the `Id` of a disabled span if per-subscriber filtering is in \ + use. use `.parent().map(SpanRef::id)` instead.", + since = "0.2.21" + )] pub fn parent_id(&self) -> Option<&Id> { + // XXX(eliza): this doesn't work with PSF because the ID is potentially + // borrowed from a parent we got from the registry, rather than from + // `self`, so we can't return a borrowed parent. so, right now, we just + // return the actual parent ID, and ignore PSF. which is not great. + // + // i think if we want this to play nice with PSF, we should just change + // it to return the `Id` by value instead of `&Id` (which we ought to do + // anyway since an `Id` is just a word) but that's a breaking change. + // alternatively, we could deprecate this method since it can't support + // PSF in its current form (which is what we would want to do if we want + // to release PSF in a minor version)... + + // let mut id = self.data.parent()?; + // loop { + // // Is this parent enabled by our filter? + // if self + // .filter + // .map(|filter| self.registry.is_enabled_for(id, filter)) + // .unwrap_or(true) + // { + // return Some(id); + // } + // id = self.registry.span_data(id)?.parent()?; + // } self.data.parent() } /// Returns a `SpanRef` describing this span's parent, or `None` if this /// span is the root of its trace tree. + pub fn parent(&self) -> Option { let id = self.data.parent()?; let data = self.registry.span_data(id)?; + + #[cfg(feature = "registry")] + { + // move these into mut bindings if the registry feature is enabled, + // since they may be mutated in the loop. + let mut data = data; + loop { + // Is this parent enabled by our filter? + if data.is_enabled_for(self.filter) { + return Some(Self { + registry: self.registry, + filter: self.filter, + data, + }); + } + + // It's not enabled. If the disabled span has a parent, try that! + let id = data.parent()?; + data = self.registry.span_data(id)?; + } + } + + #[cfg(not(feature = "registry"))] Some(Self { registry: self.registry, data, @@ -380,6 +506,9 @@ where Scope { registry: self.registry, next: Some(self.id()), + + #[cfg(feature = "registry")] + filter: self.filter, } } @@ -402,6 +531,27 @@ where pub fn extensions_mut(&self) -> ExtensionsMut<'_> { self.data.extensions_mut() } + + #[cfg(feature = "registry")] + pub(crate) fn try_with_filter(self, filter: FilterId) -> Option { + if self.is_enabled_for(filter) { + return Some(self.with_filter(filter)); + } + + None + } + + #[inline] + #[cfg(feature = "registry")] + pub(crate) fn is_enabled_for(&self, filter: FilterId) -> bool { + self.data.is_enabled_for(filter) + } + + #[inline] + #[cfg(feature = "registry")] + fn with_filter(self, filter: FilterId) -> Self { + Self { filter, ..self } + } } #[cfg(all(test, feature = "registry", feature = "std"))] diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index b6ee290..c0618c9 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -3,6 +3,7 @@ use thread_local::ThreadLocal; use super::stack::SpanStack; use crate::{ + filter::{FilterId, FilterMap, FilterState}, registry::{ extensions::{Extensions, ExtensionsInner, ExtensionsMut}, LookupSpan, SpanData, @@ -10,7 +11,7 @@ use crate::{ sync::RwLock, }; use std::{ - cell::{Cell, RefCell}, + cell::{self, Cell, RefCell}, sync::atomic::{fence, AtomicUsize, Ordering}, }; use tracing_core::{ @@ -90,6 +91,7 @@ use tracing_core::{ pub struct Registry { spans: Pool, current_spans: ThreadLocal>, + next_filter_id: u8, } /// Span data stored in a [`Registry`]. @@ -115,6 +117,7 @@ pub struct Data<'a> { /// implementations for this type are load-bearing. #[derive(Debug)] struct DataInner { + filter_map: FilterMap, metadata: &'static Metadata<'static>, parent: Option, ref_count: AtomicUsize, @@ -130,6 +133,7 @@ impl Default for Registry { Self { spans: Pool::new(), current_spans: ThreadLocal::new(), + next_filter_id: 0, } } } @@ -191,6 +195,14 @@ impl Registry { is_closing: false, } } + + pub(crate) fn has_per_subscriber_filters(&self) -> bool { + self.next_filter_id > 0 + } + + pub(crate) fn span_stack(&self) -> cell::Ref<'_, SpanStack> { + self.current_spans.get_or_default().borrow() + } } thread_local! { @@ -203,10 +215,17 @@ thread_local! { impl Collect for Registry { fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + if self.has_per_subscriber_filters() { + return FilterState::take_interest().unwrap_or_else(Interest::always); + } + Interest::always() } fn enabled(&self, _: &Metadata<'_>) -> bool { + if self.has_per_subscriber_filters() { + return FilterState::event_enabled(); + } true } @@ -229,6 +248,14 @@ impl Collect for Registry { .create_with(|data| { data.metadata = attrs.metadata(); data.parent = parent; + data.filter_map = crate::filter::FILTERING.with(|filtering| filtering.filter_map()); + #[cfg(debug_assertions)] + { + if data.filter_map != FilterMap::default() { + debug_assert!(self.has_per_subscriber_filters()); + } + } + let refs = data.ref_count.get_mut(); debug_assert_eq!(*refs, 0); *refs = 1; @@ -331,6 +358,12 @@ impl<'a> LookupSpan<'a> for Registry { let inner = self.get(id)?; Some(Data { inner }) } + + fn register_filter(&mut self) -> FilterId { + let id = FilterId::new(self.next_filter_id); + self.next_filter_id += 1; + id + } } // === impl CloseGuard === @@ -388,6 +421,11 @@ impl<'a> SpanData<'a> for Data<'a> { fn extensions_mut(&self) -> ExtensionsMut<'_> { ExtensionsMut::new(self.inner.extensions.write().expect("Mutex poisoned")) } + + #[inline] + fn is_enabled_for(&self, filter: FilterId) -> bool { + self.inner.filter_map.is_enabled(filter) + } } // === impl DataInner === @@ -428,6 +466,7 @@ impl Default for DataInner { }; Self { + filter_map: FilterMap::default(), metadata: &NULL_METADATA, parent: None, ref_count: AtomicUsize::new(0), @@ -471,6 +510,8 @@ impl Clear for DataInner { l.into_inner() }) .clear(); + + self.filter_map = FilterMap::default(); } } @@ -489,6 +530,10 @@ mod tests { Collect, }; + #[derive(Debug)] + struct DoesNothing; + impl Subscribe for DoesNothing {} + struct AssertionSubscriber; impl Subscribe for AssertionSubscriber where diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index b0b372c..4a3f7e5 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -17,14 +17,14 @@ pub(crate) struct SpanStack { impl SpanStack { #[inline] - pub(crate) fn push(&mut self, id: Id) -> bool { + pub(super) fn push(&mut self, id: Id) -> bool { let duplicate = self.stack.iter().any(|i| i.id == id); self.stack.push(ContextId { id, duplicate }); !duplicate } #[inline] - pub(crate) fn pop(&mut self, expected_id: &Id) -> bool { + pub(super) fn pop(&mut self, expected_id: &Id) -> bool { if let Some((idx, _)) = self .stack .iter() @@ -39,12 +39,16 @@ impl SpanStack { } #[inline] - pub(crate) fn current(&self) -> Option<&Id> { + pub(crate) fn iter(&self) -> impl Iterator { self.stack .iter() .rev() - .find(|context_id| !context_id.duplicate) - .map(|context_id| &context_id.id) + .filter_map(|ContextId { id, duplicate }| if !*duplicate { Some(id) } else { None }) + } + + #[inline] + pub(crate) fn current(&self) -> Option<&Id> { + self.iter().next() } } diff --git a/tracing-subscriber/src/reload.rs b/tracing-subscriber/src/reload.rs index d245731..5827165 100644 --- a/tracing-subscriber/src/reload.rs +++ b/tracing-subscriber/src/reload.rs @@ -58,6 +58,10 @@ where S: crate::Subscribe + 'static, C: Collect, { + fn on_subscribe(&mut self, collector: &mut C) { + try_lock!(self.inner.write(), else return).on_subscribe(collector); + } + #[inline] fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { try_lock!(self.inner.read(), else return Interest::sometimes()).register_callsite(metadata) diff --git a/tracing-subscriber/src/subscribe.rs b/tracing-subscriber/src/subscribe.rs deleted file mode 100644 index 85d96d4..0000000 --- a/tracing-subscriber/src/subscribe.rs +++ /dev/null @@ -1,1468 +0,0 @@ -//! A composable abstraction for building [collector]s. -//! -//! [collector]: tracing_core::Collect -use tracing_core::{ - collect::{Collect, Interest}, - metadata::Metadata, - span, Event, LevelFilter, -}; - -#[cfg(all(feature = "std", feature = "registry"))] -use crate::registry::Registry; -use crate::registry::{self, LookupSpan, SpanRef}; -use core::{any::TypeId, cmp, marker::PhantomData, ptr::NonNull}; - -feature! { - #![feature = "alloc"] - use alloc::boxed::Box; - use core::ops::Deref; -} - -/// A composable handler for `tracing` events. -/// -/// The [`Collect`] trait in `tracing-core` represents the _complete_ set of -/// functionality required to consume `tracing` instrumentation. This means that -/// a single [collector] instance is a self-contained implementation of a -/// complete strategy for collecting traces; but it _also_ means that the -/// `Collect` trait cannot easily be composed with other `Collect`s. -/// -/// In particular, collectors are responsible for generating [span IDs] and -/// assigning them to spans. Since these IDs must uniquely identify a span -/// within the context of the current trace, this means that there may only be -/// a single [collector] for a given thread at any point in time — -/// otherwise, there would be no authoritative source of span IDs. -/// -/// [collector]: tracing_core::Collect -/// -/// On the other hand, the majority of the [`Collect`] trait's functionality -/// is composable: any number of collectors may _observe_ events, span entry -/// and exit, and so on, provided that there is a single authoritative source of -/// span IDs. The `Subscribe` trait represents this composable subset of the -/// [`Collect`]'s behavior; it can _observe_ events and spans, but does not -/// assign IDs. -/// -/// ## Composing Subscribers -/// -/// Since `Subscribe` does not implement a complete strategy for collecting -/// traces, it must be composed with a `Collect` in order to be used. The -/// `Subscribe` trait is generic over a type parameter (called `C` in the trait -/// definition), representing the types of `Collect` they can be composed -/// with. Thus, a subscriber may be implemented that will only compose with a -/// particular `Collect` implementation, or additional trait bounds may be -/// added to constrain what types implementing `Collect` a subscriber can wrap. -/// -/// Subscribers may be added to a `Collect` by using the [`CollectExt::with`] -/// method, which is provided by `tracing-subscriber`'s [prelude]. This method -/// returns a [`Layered`] struct that implements `Collect` by composing the -/// subscriber with the collector. -/// -/// For example: -/// ```rust -/// use tracing_subscriber::Subscribe; -/// use tracing_subscriber::subscribe::CollectExt; -/// use tracing::Collect; -/// use tracing_core::span::Current; -/// -/// pub struct MySubscriber { -/// // ... -/// } -/// -/// impl Subscribe for MySubscriber { -/// // ... -/// } -/// -/// pub struct MyCollector { -/// // ... -/// } -/// -/// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; -/// impl Collect for MyCollector { -/// // ... -/// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } -/// # fn record(&self, _: &Id, _: &Record) {} -/// # fn event(&self, _: &Event) {} -/// # fn record_follows_from(&self, _: &Id, _: &Id) {} -/// # fn enabled(&self, _: &Metadata) -> bool { false } -/// # fn enter(&self, _: &Id) {} -/// # fn exit(&self, _: &Id) {} -/// # fn current_span(&self) -> Current { Current::unknown() } -/// } -/// # impl MySubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyCollector { -/// # fn new() -> Self { Self { }} -/// # } -/// -/// let collector = MyCollector::new() -/// .with(MySubscriber::new()); -/// -/// tracing::collect::set_global_default(collector); -/// ``` -/// -/// Multiple `Subscriber`s may be composed in the same manner: -/// ```rust -/// # use tracing_subscriber::Subscribe; -/// # use tracing_subscriber::subscribe::CollectExt; -/// # use tracing::Collect; -/// # use tracing_core::span::Current; -/// pub struct MyOtherSubscriber { -/// // ... -/// } -/// -/// impl Subscribe for MyOtherSubscriber { -/// // ... -/// } -/// -/// pub struct MyThirdSubscriber { -/// // ... -/// } -/// -/// impl Subscribe for MyThirdSubscriber { -/// // ... -/// } -/// # pub struct MySubscriber {} -/// # impl Subscribe for MySubscriber {} -/// # pub struct MyCollector { } -/// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; -/// # impl Collect for MyCollector { -/// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } -/// # fn record(&self, _: &Id, _: &Record) {} -/// # fn event(&self, _: &Event) {} -/// # fn record_follows_from(&self, _: &Id, _: &Id) {} -/// # fn enabled(&self, _: &Metadata) -> bool { false } -/// # fn enter(&self, _: &Id) {} -/// # fn exit(&self, _: &Id) {} -/// # fn current_span(&self) -> Current { Current::unknown() } -/// } -/// # impl MySubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyOtherSubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyThirdSubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyCollector { -/// # fn new() -> Self { Self { }} -/// # } -/// -/// let collector = MyCollector::new() -/// .with(MySubscriber::new()) -/// .with(MyOtherSubscriber::new()) -/// .with(MyThirdSubscriber::new()); -/// -/// tracing::collect::set_global_default(collector); -/// ``` -/// -/// The [`Subscribe::with_collector` method][with-col] constructs the `Layered` -/// type from a `Subscribe` and `Collect`, and is called by -/// [`CollectExt::with`]. In general, it is more idiomatic to use -/// `CollectExt::with`, and treat `Subscribe::with_collector` as an -/// implementation detail, as `with_collector` calls must be nested, leading to -/// less clear code for the reader. However, subscribers which wish to perform -/// additional behavior when composed with a subscriber may provide their own -/// implementations of `SubscriberExt::with`. -/// -/// [prelude]: super::prelude -/// [with-col]: Subscribe::with_collector() -/// -/// ## Recording Traces -/// -/// The `Subscribe` trait defines a set of methods for consuming notifications from -/// tracing instrumentation, which are generally equivalent to the similarly -/// named methods on [`Collect`]. Unlike [`Collect`], the methods on -/// `Subscribe` are additionally passed a [`Context`] type, which exposes additional -/// information provided by the wrapped collector (such as [the current span]) -/// to the subscriber. -/// -/// ## Filtering with Subscribers -/// -/// As well as strategies for handling trace events, the `Subscriber` trait may also -/// be used to represent composable _filters_. This allows the determination of -/// what spans and events should be recorded to be decoupled from _how_ they are -/// recorded: a filtering subscriber can be applied to other subscribers or -/// collectors. A `Subscriber` that implements a filtering strategy should override the -/// [`register_callsite`] and/or [`enabled`] methods. It may also choose to implement -/// methods such as [`on_enter`], if it wishes to filter trace events based on -/// the current span context. -/// -/// Note that the [`Subscribe::register_callsite`] and [`Subscribe::enabled`] methods -/// determine whether a span or event is enabled *globally*. Thus, they should -/// **not** be used to indicate whether an individual subscriber wishes to record a -/// particular span or event. Instead, if a subscriber is only interested in a subset -/// of trace data, but does *not* wish to disable other spans and events for the -/// rest of the subscriber stack should ignore those spans and events in its -/// notification methods. -/// -/// The filtering methods on a stack of subscribers are evaluated in a top-down -/// order, starting with the outermost `Subscribe` and ending with the wrapped -/// [`Collect`]. If any subscriber returns `false` from its [`enabled`] method, or -/// [`Interest::never()`] from its [`register_callsite`] method, filter -/// evaluation will short-circuit and the span or event will be disabled. -/// -/// [`Collect`]: tracing_core::collect::Collect -/// [span IDs]: tracing_core::span::Id -/// [the current span]: Context::current_span() -/// [`register_callsite`]: Subscribe::register_callsite() -/// [`enabled`]: Subscribe::enabled() -/// [`on_enter`]: Subscribe::on_enter() -pub trait Subscribe -where - C: Collect, - Self: 'static, -{ - /// Registers a new callsite with this subscriber, returning whether or not - /// the subscriber is interested in being notified about the callsite, similarly - /// to [`Collect::register_callsite`]. - /// - /// By default, this returns [`Interest::always()`] if [`self.enabled`] returns - /// true, or [`Interest::never()`] if it returns false. - /// - ///
- /// 
-    ///
-    /// **Note**: This method (and [`Subscribe::enabled`]) determine whether a span or event is
-    /// globally enabled, *not* whether the individual subscriber will be notified about that
-    /// span or event.  This is intended to be used by subscribers that implement filtering for
-    /// the entire stack. Subscribers which do not wish to be notified about certain spans or
-    /// events but do not wish to globally disable them should ignore those spans or events in
-    /// their [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
-    /// and other notification methods.
-    ///
-    ///
- /// - /// See [the trait-level documentation] for more information on filtering - /// with `Subscriber`s. - /// - /// Subscribers may also implement this method to perform any behaviour that - /// should be run once per callsite. If the subscriber wishes to use - /// `register_callsite` for per-callsite behaviour, but does not want to - /// globally enable or disable those callsites, it should always return - /// [`Interest::always()`]. - /// - /// [`Interest`]: tracing_core::Interest - /// [`Collect::register_callsite`]: tracing_core::Collect::register_callsite() - /// [`self.enabled`]: Subscribe::enabled() - /// [the trait-level documentation]: #filtering-with-subscribers - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - if self.enabled(metadata, Context::none()) { - Interest::always() - } else { - Interest::never() - } - } - - /// Returns `true` if this subscriber is interested in a span or event with the - /// given `metadata` in the current [`Context`], similarly to - /// [`Collect::enabled`]. - /// - /// By default, this always returns `true`, allowing the wrapped collector - /// to choose to disable the span. - /// - ///
- /// 
-    ///
-    /// **Note**: This method (and [`register_callsite`][Self::register_callsite])
-    /// determine whether a span or event is
-    /// globally enabled, *not* whether the individual subscriber will be
-    /// notified about that span or event. This is intended to be used
-    /// by layers that implement filtering for the entire stack. Layers which do
-    /// not wish to be notified about certain spans or events but do not wish to
-    /// globally disable them should ignore those spans or events in their
-    /// [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
-    /// and other notification methods.
-    ///
-    ///
- /// - /// - /// See [the trait-level documentation] for more information on filtering - /// with `Subscriber`s. - /// - /// [`Interest`]: tracing_core::Interest - /// [the trait-level documentation]: #filtering-with-subscribers - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - let _ = (metadata, ctx); - true - } - - /// Notifies this subscriber that a new span was constructed with the given - /// `Attributes` and `Id`. - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - let _ = (attrs, id, ctx); - } - - // TODO(eliza): do we want this to be a public API? If we end up moving - // filtering subscribers to a separate trait, we may no longer want `Subscriber`s to - // be able to participate in max level hinting... - #[doc(hidden)] - fn max_level_hint(&self) -> Option { - None - } - - /// Notifies this subscriber that a span with the given `Id` recorded the given - /// `values`. - // Note: it's unclear to me why we'd need the current span in `record` (the - // only thing the `Context` type currently provides), but passing it in anyway - // seems like a good future-proofing measure as it may grow other methods later... - fn on_record(&self, _span: &span::Id, _values: &span::Record<'_>, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that a span with the ID `span` recorded that it - /// follows from the span with the ID `follows`. - // Note: it's unclear to me why we'd need the current span in `record` (the - // only thing the `Context` type currently provides), but passing it in anyway - // seems like a good future-proofing measure as it may grow other methods later... - fn on_follows_from(&self, _span: &span::Id, _follows: &span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that an event has occurred. - fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that a span with the given ID was entered. - fn on_enter(&self, _id: &span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that the span with the given ID was exited. - fn on_exit(&self, _id: &span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that the span with the given ID has been closed. - fn on_close(&self, _id: span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that a span ID has been cloned, and that the - /// subscriber returned a different ID. - fn on_id_change(&self, _old: &span::Id, _new: &span::Id, _ctx: Context<'_, C>) {} - - /// Composes this subscriber around the given collector, returning a `Layered` - /// struct implementing `Subscribe`. - /// - /// The returned subscriber will call the methods on this subscriber and then - /// those of the new subscriber, before calling the methods on the collector - /// it wraps. For example: - /// - /// ```rust - /// # use tracing_subscriber::subscribe::Subscribe; - /// # use tracing_core::Collect; - /// # use tracing_core::span::Current; - /// pub struct FooSubscriber { - /// // ... - /// } - /// - /// pub struct BarSubscriber { - /// // ... - /// } - /// - /// pub struct MyCollector { - /// // ... - /// } - /// - /// impl Subscribe for FooSubscriber { - /// // ... - /// } - /// - /// impl Subscribe for BarSubscriber { - /// // ... - /// } - /// - /// # impl FooSubscriber { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl BarSubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # impl MyCollector { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; - /// # impl tracing_core::Collect for MyCollector { - /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } - /// # fn record(&self, _: &Id, _: &Record) {} - /// # fn event(&self, _: &Event) {} - /// # fn record_follows_from(&self, _: &Id, _: &Id) {} - /// # fn enabled(&self, _: &Metadata) -> bool { false } - /// # fn enter(&self, _: &Id) {} - /// # fn exit(&self, _: &Id) {} - /// # fn current_span(&self) -> Current { Current::unknown() } - /// # } - /// let collector = FooSubscriber::new() - /// .and_then(BarSubscriber::new()) - /// .with_collector(MyCollector::new()); - /// ``` - /// - /// Multiple subscribers may be composed in this manner: - /// - /// ```rust - /// # use tracing_subscriber::subscribe::Subscribe; - /// # use tracing_core::{Collect, span::Current}; - /// # pub struct FooSubscriber {} - /// # pub struct BarSubscriber {} - /// # pub struct MyCollector {} - /// # impl Subscribe for FooSubscriber {} - /// # impl Subscribe for BarSubscriber {} - /// # impl FooSubscriber { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl BarSubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # impl MyCollector { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; - /// # impl tracing_core::Collect for MyCollector { - /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } - /// # fn record(&self, _: &Id, _: &Record) {} - /// # fn event(&self, _: &Event) {} - /// # fn record_follows_from(&self, _: &Id, _: &Id) {} - /// # fn enabled(&self, _: &Metadata) -> bool { false } - /// # fn enter(&self, _: &Id) {} - /// # fn exit(&self, _: &Id) {} - /// # fn current_span(&self) -> Current { Current::unknown() } - /// # } - /// pub struct BazSubscriber { - /// // ... - /// } - /// - /// impl Subscribe for BazSubscriber { - /// // ... - /// } - /// # impl BazSubscriber { fn new() -> Self { BazSubscriber {} } } - /// - /// let collector = FooSubscriber::new() - /// .and_then(BarSubscriber::new()) - /// .and_then(BazSubscriber::new()) - /// .with_collector(MyCollector::new()); - /// ``` - fn and_then(self, subscriber: S) -> Layered - where - S: Subscribe, - Self: Sized, - { - Layered { - subscriber, - inner: self, - _s: PhantomData, - } - } - - /// Composes this subscriber with the given collector, returning a - /// `Layered` struct that implements [`Collect`]. - /// - /// The returned `Layered` subscriber will call the methods on this subscriber - /// and then those of the wrapped collector. - /// - /// For example: - /// ```rust - /// # use tracing_subscriber::subscribe::Subscribe; - /// # use tracing_core::Collect; - /// # use tracing_core::span::Current; - /// pub struct FooSubscriber { - /// // ... - /// } - /// - /// pub struct MyCollector { - /// // ... - /// } - /// - /// impl Subscribe for FooSubscriber { - /// // ... - /// } - /// - /// # impl FooSubscriber { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl MyCollector { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata}; - /// # impl tracing_core::Collect for MyCollector { - /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(0) } - /// # fn record(&self, _: &Id, _: &Record) {} - /// # fn event(&self, _: &tracing_core::Event) {} - /// # fn record_follows_from(&self, _: &Id, _: &Id) {} - /// # fn enabled(&self, _: &Metadata) -> bool { false } - /// # fn enter(&self, _: &Id) {} - /// # fn exit(&self, _: &Id) {} - /// # fn current_span(&self) -> Current { Current::unknown() } - /// # } - /// let collector = FooSubscriber::new() - /// .with_collector(MyCollector::new()); - ///``` - /// - /// [`Collect`]: tracing_core::Collect - fn with_collector(self, inner: C) -> Layered - where - Self: Sized, - { - Layered { - subscriber: self, - inner, - _s: PhantomData, - } - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - Some(NonNull::from(self).cast()) - } else { - None - } - } -} - -/// Extension trait adding a `with(Subscriber)` combinator to `Collect`. -pub trait CollectExt: Collect + crate::sealed::Sealed { - /// Wraps `self` with the provided `subscriber`. - fn with(self, subscriber: S) -> Layered - where - S: Subscribe, - Self: Sized, - { - subscriber.with_collector(self) - } -} - -/// Represents information about the current context provided to [subscriber]s by the -/// wrapped [collector]. -/// -/// To access [stored data] keyed by a span ID, implementors of the `Subscribe` -/// trait should ensure that the `Collect` type parameter is *also* bound by the -/// [`LookupSpan`]: -/// -/// ```rust -/// use tracing::Collect; -/// use tracing_subscriber::{Subscribe, registry::LookupSpan}; -/// -/// pub struct MyCollector; -/// -/// impl Subscribe for MyCollector -/// where -/// C: Collect + for<'a> LookupSpan<'a>, -/// { -/// // ... -/// } -/// ``` -/// -/// [subscriber]: Subscribe -/// [collector]: tracing_core::Collect -/// [stored data]: super::registry::SpanRef -#[derive(Debug)] -pub struct Context<'a, C> { - collector: Option<&'a C>, -} - -/// A [collector] composed of a collector wrapped by one or more -/// [subscriber]s. -/// -/// [subscriber]: super::subscribe::Subscribe -/// [collector]: tracing_core::Collect -#[derive(Clone, Debug)] -pub struct Layered { - subscriber: S, - inner: I, - _s: PhantomData, -} - -/// A Subscriber that does nothing. -#[derive(Clone, Debug, Default)] -pub struct Identity { - _p: (), -} - -// === impl Layered === - -impl Collect for Layered -where - S: Subscribe, - C: Collect, -{ - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - let outer = self.subscriber.register_callsite(metadata); - if outer.is_never() { - // if the outer subscriber has disabled the callsite, return now so that - // the collector doesn't get its hopes up. - return outer; - } - - // The intention behind calling `inner.register_callsite()` before the if statement - // is to ensure that the inner subscriber is informed that the callsite exists - // regardless of the outer subscriber's filtering decision. - let inner = self.inner.register_callsite(metadata); - if outer.is_sometimes() { - // if this interest is "sometimes", return "sometimes" to ensure that - // filters are reevaluated. - outer - } else { - // otherwise, allow the inner subscriber or collector to weigh in. - inner - } - } - - fn enabled(&self, metadata: &Metadata<'_>) -> bool { - if self.subscriber.enabled(metadata, self.ctx()) { - // if the outer subscriber enables the callsite metadata, ask the collector. - self.inner.enabled(metadata) - } else { - // otherwise, the callsite is disabled by the subscriber - false - } - } - - fn max_level_hint(&self) -> Option { - cmp::max( - self.subscriber.max_level_hint(), - self.inner.max_level_hint(), - ) - } - - fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { - let id = self.inner.new_span(span); - self.subscriber.on_new_span(span, &id, self.ctx()); - id - } - - fn record(&self, span: &span::Id, values: &span::Record<'_>) { - self.inner.record(span, values); - self.subscriber.on_record(span, values, self.ctx()); - } - - fn record_follows_from(&self, span: &span::Id, follows: &span::Id) { - self.inner.record_follows_from(span, follows); - self.subscriber.on_follows_from(span, follows, self.ctx()); - } - - fn event(&self, event: &Event<'_>) { - self.inner.event(event); - self.subscriber.on_event(event, self.ctx()); - } - - fn enter(&self, span: &span::Id) { - self.inner.enter(span); - self.subscriber.on_enter(span, self.ctx()); - } - - fn exit(&self, span: &span::Id) { - self.inner.exit(span); - self.subscriber.on_exit(span, self.ctx()); - } - - fn clone_span(&self, old: &span::Id) -> span::Id { - let new = self.inner.clone_span(old); - if &new != old { - self.subscriber.on_id_change(old, &new, self.ctx()) - }; - new - } - - #[inline] - fn drop_span(&self, id: span::Id) { - self.try_close(id); - } - - fn try_close(&self, id: span::Id) -> bool { - #[cfg(all(feature = "registry", feature = "std"))] - let subscriber = &self.inner as &dyn Collect; - #[cfg(all(feature = "registry", feature = "std"))] - let mut guard = subscriber - .downcast_ref::() - .map(|registry| registry.start_close(id.clone())); - if self.inner.try_close(id.clone()) { - // If we have a registry's close guard, indicate that the span is - // closing. - #[cfg(all(feature = "registry", feature = "std"))] - { - if let Some(g) = guard.as_mut() { - g.is_closing() - }; - } - - self.subscriber.on_close(id, self.ctx()); - true - } else { - false - } - } - - #[inline] - fn current_span(&self) -> span::Current { - self.inner.current_span() - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - return Some(NonNull::from(self).cast()); - } - self.subscriber - .downcast_raw(id) - .or_else(|| self.inner.downcast_raw(id)) - } -} - -impl Subscribe for Layered -where - A: Subscribe, - B: Subscribe, - C: Collect, -{ - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - let outer = self.subscriber.register_callsite(metadata); - if outer.is_never() { - // if the outer subscriber has disabled the callsite, return now so that - // inner subscribers don't get their hopes up. - return outer; - } - - // The intention behind calling `inner.register_callsite()` before the if statement - // is to ensure that the inner subscriber is informed that the callsite exists - // regardless of the outer subscriber's filtering decision. - let inner = self.inner.register_callsite(metadata); - if outer.is_sometimes() { - // if this interest is "sometimes", return "sometimes" to ensure that - // filters are reevaluated. - outer - } else { - // otherwise, allow the inner subscriber or collector to weigh in. - inner - } - } - - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - if self.subscriber.enabled(metadata, ctx.clone()) { - // if the outer subscriber enables the callsite metadata, ask the inner subscriber. - self.inner.enabled(metadata, ctx) - } else { - // otherwise, the callsite is disabled by this subscriber - false - } - } - - #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - self.inner.on_new_span(attrs, id, ctx.clone()); - self.subscriber.on_new_span(attrs, id, ctx); - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { - self.inner.on_record(span, values, ctx.clone()); - self.subscriber.on_record(span, values, ctx); - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { - self.inner.on_follows_from(span, follows, ctx.clone()); - self.subscriber.on_follows_from(span, follows, ctx); - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { - self.inner.on_event(event, ctx.clone()); - self.subscriber.on_event(event, ctx); - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { - self.inner.on_enter(id, ctx.clone()); - self.subscriber.on_enter(id, ctx); - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { - self.inner.on_exit(id, ctx.clone()); - self.subscriber.on_exit(id, ctx); - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { - self.inner.on_close(id.clone(), ctx.clone()); - self.subscriber.on_close(id, ctx); - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { - self.inner.on_id_change(old, new, ctx.clone()); - self.subscriber.on_id_change(old, new, ctx); - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - return Some(NonNull::from(self).cast()); - } - self.subscriber - .downcast_raw(id) - .or_else(|| self.inner.downcast_raw(id)) - } -} - -impl Subscribe for Option -where - S: Subscribe, - C: Collect, -{ - #[inline] - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - match self { - Some(ref inner) => inner.register_callsite(metadata), - None => Interest::always(), - } - } - - #[inline] - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - match self { - Some(ref inner) => inner.enabled(metadata, ctx), - None => true, - } - } - - #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_new_span(attrs, id, ctx) - } - } - - #[inline] - fn max_level_hint(&self) -> Option { - match self { - Some(ref inner) => inner.max_level_hint(), - None => None, - } - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_record(span, values, ctx); - } - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_follows_from(span, follows, ctx); - } - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_event(event, ctx); - } - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_enter(id, ctx); - } - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_exit(id, ctx); - } - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_close(id, ctx); - } - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_id_change(old, new, ctx) - } - } - - #[doc(hidden)] - #[inline] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - Some(NonNull::from(self).cast()) - } else { - self.as_ref().and_then(|inner| inner.downcast_raw(id)) - } - } -} - -feature! { - #![any(feature = "std", feature = "alloc")] - - macro_rules! subscriber_impl_body { - () => { - #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - self.deref().on_new_span(attrs, id, ctx) - } - - #[inline] - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - self.deref().register_callsite(metadata) - } - - #[inline] - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - self.deref().enabled(metadata, ctx) - } - - #[inline] - fn max_level_hint(&self) -> Option { - self.deref().max_level_hint() - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { - self.deref().on_record(span, values, ctx) - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { - self.deref().on_follows_from(span, follows, ctx) - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { - self.deref().on_event(event, ctx) - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { - self.deref().on_enter(id, ctx) - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { - self.deref().on_exit(id, ctx) - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { - self.deref().on_close(id, ctx) - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { - self.deref().on_id_change(old, new, ctx) - } - - #[doc(hidden)] - #[inline] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - self.deref().downcast_raw(id) - } - }; - } - - impl Subscribe for Box - where - S: Subscribe, - C: Collect, - { - subscriber_impl_body! {} - } - - impl Subscribe for Box + Send + Sync> - where - C: Collect, - { - subscriber_impl_body! {} - } -} - -impl<'a, S, C> LookupSpan<'a> for Layered -where - C: Collect + LookupSpan<'a>, -{ - type Data = C::Data; - - fn span_data(&'a self, id: &span::Id) -> Option { - self.inner.span_data(id) - } -} - -impl Layered -where - C: Collect, -{ - fn ctx(&self) -> Context<'_, C> { - Context { - collector: Some(&self.inner), - } - } -} - -// impl Layered { -// // TODO(eliza): is there a compelling use-case for this being public? -// pub(crate) fn into_inner(self) -> S { -// self.inner -// } -// } - -// === impl CollectExt === - -impl crate::sealed::Sealed for C {} -impl CollectExt for C {} - -// === impl Context === - -impl<'a, C> Context<'a, C> -where - C: Collect, -{ - /// Returns the wrapped subscriber's view of the current span. - #[inline] - pub fn current_span(&self) -> span::Current { - self.collector - .map(Collect::current_span) - // TODO: this would be more correct as "unknown", so perhaps - // `tracing-core` should make `Current::unknown()` public? - .unwrap_or_else(span::Current::none) - } - - /// Returns whether the wrapped subscriber would enable the current span. - #[inline] - pub fn enabled(&self, metadata: &Metadata<'_>) -> bool { - self.collector - .map(|collector| collector.enabled(metadata)) - // If this context is `None`, we are registering a callsite, so - // return `true` so that the subscriber does not incorrectly assume that - // the inner collector has disabled this metadata. - // TODO(eliza): would it be more correct for this to return an `Option`? - .unwrap_or(true) - } - - /// Records the provided `event` with the wrapped collector. - /// - /// # Notes - /// - /// - The collector is free to expect that the event's callsite has been - /// [registered][register], and may panic or fail to observe the event if this is - /// not the case. The `tracing` crate's macros ensure that all events are - /// registered, but if the event is constructed through other means, the - /// user is responsible for ensuring that [`register_callsite`][register] - /// has been called prior to calling this method. - /// - This does _not_ call [`enabled`] on the inner collector. If the - /// caller wishes to apply the wrapped collector's filter before choosing - /// whether to record the event, it may first call [`Context::enabled`] to - /// check whether the event would be enabled. This allows `Collectors`s to - /// elide constructing the event if it would not be recorded. - /// - /// [register]: tracing_core::collect::Collect::register_callsite() - /// [`enabled`]: tracing_core::collect::Collect::enabled() - /// [`Context::enabled`]: ::enabled() - #[inline] - pub fn event(&self, event: &Event<'_>) { - if let Some(collector) = self.collector { - collector.event(event); - } - } - - /// Returns a [`SpanRef`] for the parent span of the given [`Event`], if - /// it has a parent. - /// - /// If the event has an explicitly overridden parent, this method returns - /// a reference to that span. If the event's parent is the current span, - /// this returns a reference to the current span, if there is one. If this - /// returns `None`, then either the event's parent was explicitly set to - /// `None`, or the event's parent was defined contextually, but no span - /// is currently entered. - /// - /// Compared to [`Context::current_span`] and [`Context::lookup_current`], - /// this respects overrides provided by the [`Event`]. - /// - /// Compared to [`Event::parent`], this automatically falls back to the contextual - /// span, if required. - /// - /// ```rust - /// use tracing::{Collect, Event}; - /// use tracing_subscriber::{ - /// subscribe::{Context, Subscribe}, - /// prelude::*, - /// registry::LookupSpan, - /// }; - /// - /// struct PrintingSubscriber; - /// impl Subscribe for PrintingSubscriber - /// where - /// C: Collect + for<'lookup> LookupSpan<'lookup>, - /// { - /// fn on_event(&self, event: &Event, ctx: Context) { - /// let span = ctx.event_span(event); - /// println!("Event in span: {:?}", span.map(|s| s.name())); - /// } - /// } - /// - /// tracing::collect::with_default(tracing_subscriber::registry().with(PrintingSubscriber), || { - /// tracing::info!("no span"); - /// // Prints: Event in span: None - /// - /// let span = tracing::info_span!("span"); - /// tracing::info!(parent: &span, "explicitly specified"); - /// // Prints: Event in span: Some("span") - /// - /// let _guard = span.enter(); - /// tracing::info!("contextual span"); - /// // Prints: Event in span: Some("span") - /// }); - /// ``` - /// - ///
- /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    ///
- #[inline] - pub fn event_span(&self, event: &Event<'_>) -> Option> - where - C: for<'lookup> LookupSpan<'lookup>, - { - if event.is_root() { - None - } else if event.is_contextual() { - self.lookup_current() - } else { - event.parent().and_then(|id| self.span(id)) - } - } - - /// Returns metadata for the span with the given `id`, if it exists. - /// - /// If this returns `None`, then no span exists for that ID (either it has - /// closed or the ID is invalid). - #[inline] - pub fn metadata(&self, id: &span::Id) -> Option<&'static Metadata<'static>> - where - C: for<'lookup> LookupSpan<'lookup>, - { - let span = self.collector.as_ref()?.span(id)?; - Some(span.metadata()) - } - - /// Returns [stored data] for the span with the given `id`, if it exists. - /// - /// If this returns `None`, then no span exists for that ID (either it has - /// closed or the ID is invalid). - /// - ///
- /// 
-    ///
-    /// **Note**: This requires the wrapped collector to implement the [`LookupSpan`] trait.
-    /// See the documentation on [`Context`]'s declaration for details.
-    ///
-    ///
- /// - /// [stored data]: super::registry::SpanRef - #[inline] - pub fn span(&self, id: &span::Id) -> Option> - where - C: for<'lookup> LookupSpan<'lookup>, - { - self.collector.as_ref()?.span(id) - } - - /// Returns `true` if an active span exists for the given `Id`. - /// - ///
- /// 
-    ///
-    /// **Note**: This requires the wrapped subscriber to implement the [`LookupSpan`] trait.
-    /// See the documentation on [`Context`]'s declaration for details.
-    ///
-    ///
- #[inline] - pub fn exists(&self, id: &span::Id) -> bool - where - C: for<'lookup> LookupSpan<'lookup>, - { - self.collector.as_ref().and_then(|s| s.span(id)).is_some() - } - - /// Returns [stored data] for the span that the wrapped collector considers - /// to be the current. - /// - /// If this returns `None`, then we are not currently within a span. - /// - ///
- /// 
-    ///
-    /// **Note**: This requires the wrapped subscriber to implement the [`LookupSpan`] trait.
-    /// See the documentation on [`Context`]'s declaration for details.
-    ///
-    ///
- /// - /// [stored data]: super::registry::SpanRef - #[inline] - pub fn lookup_current(&self) -> Option> - where - C: for<'lookup> LookupSpan<'lookup>, - { - let collector = self.collector.as_ref()?; - let current = collector.current_span(); - let id = current.id()?; - let span = collector.span(id); - debug_assert!( - span.is_some(), - "the subscriber should have data for the current span ({:?})!", - id, - ); - span - } - - /// Returns an iterator over the [stored data] for all the spans in the - /// current context, starting with the specified span and ending with the - /// root of the trace tree and ending with the current span. - /// - ///
- ///
ⓘNote
- ///
- ///
- /// 
-    /// Note: Compared to scope this
-    /// returns the spans in reverse order (from leaf to root). Use
-    /// Scope::from_root
-    /// in case root-to-leaf ordering is desired.
-    ///
- /// - ///
- /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    ///
- /// - /// [stored data]: ../registry/struct.SpanRef.html - pub fn span_scope(&self, id: &span::Id) -> Option> - where - C: for<'lookup> registry::LookupSpan<'lookup>, - { - Some(self.span(id)?.scope()) - } - - /// Returns an iterator over the [stored data] for all the spans in the - /// current context, starting with the parent span of the specified event, - /// and ending with the root of the trace tree and ending with the current span. - /// - ///
- /// 
-    /// Note: Compared to scope this
-    /// returns the spans in reverse order (from leaf to root). Use
-    /// Scope::from_root
-    /// in case root-to-leaf ordering is desired.
-    ///
- /// - ///
- /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    ///
- /// - /// [stored data]: ../registry/struct.SpanRef.html - pub fn event_scope(&self, event: &Event<'_>) -> Option> - where - C: for<'lookup> registry::LookupSpan<'lookup>, - { - Some(self.event_span(event)?.scope()) - } -} - -impl<'a, C> Context<'a, C> { - pub(crate) fn none() -> Self { - Self { collector: None } - } -} - -impl<'a, C> Clone for Context<'a, C> { - #[inline] - fn clone(&self) -> Self { - let collector = self.collector.as_ref().copied(); - Context { collector } - } -} - -// === impl Identity === -// -impl Subscribe for Identity {} - -impl Identity { - /// Returns a new `Identity` subscriber. - pub fn new() -> Self { - Self { _p: () } - } -} - -#[cfg(test)] -pub(crate) mod tests { - use super::*; - - pub(crate) struct NopCollector; - - impl Collect for NopCollector { - fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { - Interest::never() - } - - fn enabled(&self, _: &Metadata<'_>) -> bool { - false - } - - fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { - span::Id::from_u64(1) - } - - fn record(&self, _: &span::Id, _: &span::Record<'_>) {} - fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} - fn event(&self, _: &Event<'_>) {} - fn enter(&self, _: &span::Id) {} - fn exit(&self, _: &span::Id) {} - fn current_span(&self) -> span::Current { - span::Current::unknown() - } - } - - struct NopSubscriber; - impl Subscribe for NopSubscriber {} - - #[allow(dead_code)] - struct NopSubscriber2; - impl Subscribe for NopSubscriber2 {} - - /// A subscriber that holds a string. - /// - /// Used to test that pointers returned by downcasting are actually valid. - struct StringSubscriber(&'static str); - impl Subscribe for StringSubscriber {} - - struct StringSubscriber2(&'static str); - impl Subscribe for StringSubscriber2 {} - - struct StringSubscriber3(&'static str); - impl Subscribe for StringSubscriber3 {} - - pub(crate) struct StringCollector(&'static str); - - impl Collect for StringCollector { - fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { - Interest::never() - } - - fn enabled(&self, _: &Metadata<'_>) -> bool { - false - } - - fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { - span::Id::from_u64(1) - } - - fn record(&self, _: &span::Id, _: &span::Record<'_>) {} - fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} - fn event(&self, _: &Event<'_>) {} - fn enter(&self, _: &span::Id) {} - fn exit(&self, _: &span::Id) {} - fn current_span(&self) -> span::Current { - span::Current::unknown() - } - } - - fn assert_collector(_s: impl Collect) {} - - #[test] - fn subscriber_is_collector() { - let s = NopSubscriber.with_collector(NopCollector); - assert_collector(s) - } - - #[test] - fn two_subscribers_are_collector() { - let s = NopSubscriber - .and_then(NopSubscriber) - .with_collector(NopCollector); - assert_collector(s) - } - - #[test] - fn three_subscribers_are_collector() { - let s = NopSubscriber - .and_then(NopSubscriber) - .and_then(NopSubscriber) - .with_collector(NopCollector); - assert_collector(s) - } - - #[test] - fn downcasts_to_collector() { - let s = NopSubscriber - .and_then(NopSubscriber) - .and_then(NopSubscriber) - .with_collector(StringCollector("collector")); - let collector = - ::downcast_ref::(&s).expect("collector should downcast"); - assert_eq!(collector.0, "collector"); - } - - #[test] - fn downcasts_to_subscriber() { - let s = StringSubscriber("subscriber_1") - .and_then(StringSubscriber2("subscriber_2")) - .and_then(StringSubscriber3("subscriber_3")) - .with_collector(NopCollector); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber 2 should downcast"); - assert_eq!(subscriber.0, "subscriber_1"); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber 2 should downcast"); - assert_eq!(subscriber.0, "subscriber_2"); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber 3 should downcast"); - assert_eq!(subscriber.0, "subscriber_3"); - } - - #[test] - #[cfg(all(feature = "registry", feature = "std"))] - fn context_event_span() { - use std::sync::{Arc, Mutex}; - let last_event_span = Arc::new(Mutex::new(None)); - - struct RecordingSubscriber { - last_event_span: Arc>>, - } - - impl Subscribe for RecordingSubscriber - where - S: Collect + for<'lookup> LookupSpan<'lookup>, - { - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { - let span = ctx.event_span(event); - *self.last_event_span.lock().unwrap() = span.map(|s| s.name()); - } - } - - tracing::collect::with_default( - crate::registry().with(RecordingSubscriber { - last_event_span: last_event_span.clone(), - }), - || { - tracing::info!("no span"); - assert_eq!(*last_event_span.lock().unwrap(), None); - - let parent = tracing::info_span!("explicit"); - tracing::info!(parent: &parent, "explicit span"); - assert_eq!(*last_event_span.lock().unwrap(), Some("explicit")); - - let _guard = tracing::info_span!("contextual").entered(); - tracing::info!("contextual span"); - assert_eq!(*last_event_span.lock().unwrap(), Some("contextual")); - }, - ); - } -} diff --git a/tracing-subscriber/src/subscribe/context.rs b/tracing-subscriber/src/subscribe/context.rs new file mode 100644 index 0000000..dedc640 --- /dev/null +++ b/tracing-subscriber/src/subscribe/context.rs @@ -0,0 +1,499 @@ +use tracing_core::{collect::Collect, metadata::Metadata, span, Event}; + +use crate::registry::{self, LookupSpan, SpanRef}; +#[cfg(feature = "registry")] +use crate::{filter::FilterId, registry::Registry}; +/// Represents information about the current context provided to +/// [subscriber][`Subscribe`]s by the wrapped [collector][`Collect`]. +/// +/// To access [stored data] keyed by a span ID, implementors of the [`Subscribe`] +/// trait should ensure that the [`Collect`] type parameter is *also* bound by the +/// [`LookupSpan`]: +/// +/// ```rust +/// use tracing::Collect; +/// use tracing_subscriber::{Subscribe, registry::LookupSpan}; +/// +/// pub struct MySubscriber; +/// +/// impl Subscribe for MySubscriber +/// where +/// C: Collect + for<'a> LookupSpan<'a>, +/// { +/// // ... +/// } +/// ``` +/// +/// [`Subscribe`]: crate::subscribe::Subscribe +/// [`Collect`]: tracing_core::Collect +/// [stored data]: ../registry/struct.SpanRef.html +/// [`LookupSpan`]: "../registry/trait.LookupSpan.html +#[derive(Debug)] +pub struct Context<'a, S> { + subscriber: Option<&'a S>, + /// The bitmask of all [`Filtered`] subscribers that currently apply in this + /// context. If there is only a single [`Filtered`] wrapping the subscriber that + /// produced this context, then this is that filter's ID. Otherwise, if we + /// are in a nested tree with multiple filters, this is produced by + /// [`and`]-ing together the [`FilterId`]s of each of the filters that wrap + /// the current subscriber. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [`FilterId`]: crate::filter::FilterId + /// [`and`]: crate::filter::FilterId::and + #[cfg(feature = "registry")] + filter: FilterId, +} + +/// An iterator over the [stored data] for all the spans in the +/// current context, starting the root of the trace tree and ending with +/// the current span. +/// +/// This is returned by [`Context::scope`]. +/// +/// [stored data]: ../registry/struct.SpanRef.html +/// [`Context::scope`]: struct.Context.html#method.scope +#[deprecated(note = "renamed to crate::registry::ScopeFromRoot", since = "0.2.19")] +#[derive(Debug)] +pub struct Scope<'a, L>(std::iter::Flatten>>) +where + L: LookupSpan<'a>; + +#[allow(deprecated)] +impl<'a, L> Iterator for Scope<'a, L> +where + L: LookupSpan<'a>, +{ + type Item = SpanRef<'a, L>; + + fn next(&mut self) -> Option { + self.0.next() + } +} + +// === impl Context === + +impl<'a, C> Context<'a, C> +where + C: Collect, +{ + pub(super) fn new(subscriber: &'a C) -> Self { + Self { + subscriber: Some(subscriber), + + #[cfg(feature = "registry")] + filter: FilterId::none(), + } + } + + /// Returns the wrapped subscriber's view of the current span. + #[inline] + pub fn current_span(&self) -> span::Current { + self.subscriber + .map(Collect::current_span) + // TODO: this would be more correct as "unknown", so perhaps + // `tracing-core` should make `Current::unknown()` public? + .unwrap_or_else(span::Current::none) + } + + /// Returns whether the wrapped subscriber would enable the current span. + #[inline] + pub fn enabled(&self, metadata: &Metadata<'_>) -> bool { + self.subscriber + .map(|subscriber| subscriber.enabled(metadata)) + // If this context is `None`, we are registering a callsite, so + // return `true` so that the subscriber does not incorrectly assume that + // the inner subscriber has disabled this metadata. + // TODO(eliza): would it be more correct for this to return an `Option`? + .unwrap_or(true) + } + + /// Records the provided `event` with the wrapped subscriber. + /// + /// # Notes + /// + /// - The subscriber is free to expect that the event's callsite has been + /// [registered][register], and may panic or fail to observe the event if this is + /// not the case. The `tracing` crate's macros ensure that all events are + /// registered, but if the event is constructed through other means, the + /// user is responsible for ensuring that [`register_callsite`][register] + /// has been called prior to calling this method. + /// - This does _not_ call [`enabled`] on the inner subscriber. If the + /// caller wishes to apply the wrapped subscriber's filter before choosing + /// whether to record the event, it may first call [`Context::enabled`] to + /// check whether the event would be enabled. This allows `Layer`s to + /// elide constructing the event if it would not be recorded. + /// + /// [register]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html#method.register_callsite + /// [`enabled`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html#method.enabled + /// [`Context::enabled`]: #method.enabled + #[inline] + pub fn event(&self, event: &Event<'_>) { + if let Some(subscriber) = self.subscriber { + subscriber.event(event); + } + } + + /// Returns a [`SpanRef`] for the parent span of the given [`Event`], if + /// it has a parent. + /// + /// If the event has an explicitly overridden parent, this method returns + /// a reference to that span. If the event's parent is the current span, + /// this returns a reference to the current span, if there is one. If this + /// returns `None`, then either the event's parent was explicitly set to + /// `None`, or the event's parent was defined contextually, but no span + /// is currently entered. + /// + /// Compared to [`Context::current_span`] and [`Context::lookup_current`], + /// this respects overrides provided by the [`Event`]. + /// + /// Compared to [`Event::parent`], this automatically falls back to the contextual + /// span, if required. + /// + /// ```rust + /// use tracing::{Event, Collect}; + /// use tracing_subscriber::{ + /// subscribe::{Context, Subscribe}, + /// prelude::*, + /// registry::LookupSpan, + /// }; + /// + /// struct PrintingSubscriber; + /// impl Subscribe for PrintingSubscriber + /// where + /// C: Collect + for<'lookup> LookupSpan<'lookup>, + /// { + /// fn on_event(&self, event: &Event, ctx: Context) { + /// let span = ctx.event_span(event); + /// println!("Event in span: {:?}", span.map(|s| s.name())); + /// } + /// } + /// + /// tracing::collect::with_default(tracing_subscriber::registry().with(PrintingSubscriber), || { + /// tracing::info!("no span"); + /// // Prints: Event in span: None + /// + /// let span = tracing::info_span!("span"); + /// tracing::info!(parent: &span, "explicitly specified"); + /// // Prints: Event in span: Some("span") + /// + /// let _guard = span.enter(); + /// tracing::info!("contextual span"); + /// // Prints: Event in span: Some("span") + /// }); + /// ``` + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ #[inline] + pub fn event_span(&self, event: &Event<'_>) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + if event.is_root() { + None + } else if event.is_contextual() { + self.lookup_current() + } else { + // TODO(eliza): this should handle parent IDs + event.parent().and_then(|id| self.span(id)) + } + } + + /// Returns metadata for the span with the given `id`, if it exists. + /// + /// If this returns `None`, then no span exists for that ID (either it has + /// closed or the ID is invalid). + #[inline] + pub fn metadata(&self, id: &span::Id) -> Option<&'static Metadata<'static>> + where + C: for<'lookup> LookupSpan<'lookup>, + { + let span = self.span(id)?; + Some(span.metadata()) + } + + /// Returns [stored data] for the span with the given `id`, if it exists. + /// + /// If this returns `None`, then no span exists for that ID (either it has + /// closed or the ID is invalid). + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + #[inline] + pub fn span(&self, id: &span::Id) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + let span = self.subscriber.as_ref()?.span(id)?; + + #[cfg(feature = "registry")] + return span.try_with_filter(self.filter); + + #[cfg(not(feature = "registry"))] + Some(span) + } + + /// Returns `true` if an active span exists for the given `Id`. + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ #[inline] + pub fn exists(&self, id: &span::Id) -> bool + where + C: for<'lookup> LookupSpan<'lookup>, + { + self.subscriber.as_ref().and_then(|s| s.span(id)).is_some() + } + + /// Returns [stored data] for the span that the wrapped subscriber considers + /// to be the current. + /// + /// If this returns `None`, then we are not currently within a span. + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + #[inline] + pub fn lookup_current(&self) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + let subscriber = *self.subscriber.as_ref()?; + let current = subscriber.current_span(); + let id = current.id()?; + let span = subscriber.span(id); + debug_assert!( + span.is_some(), + "the subscriber should have data for the current span ({:?})!", + id, + ); + + // If we found a span, and our per-subscriber filter enables it, return that + // span! + #[cfg(feature = "registry")] + if let Some(span) = span?.try_with_filter(self.filter) { + Some(span) + } else { + // Otherwise, the span at the *top* of the stack is disabled by + // per-subscriber filtering, but there may be additional spans in the stack. + // + // Currently, `LookupSpan` doesn't have a nice way of exposing access to + // the whole span stack. However, if we can downcast the innermost + // subscriber to a a `Registry`, we can iterate over its current span + // stack. + // + // TODO(eliza): when https://github.com/tokio-rs/tracing/issues/1459 is + // implemented, change this to use that instead... + self.lookup_current_filtered(subscriber) + } + + #[cfg(not(feature = "registry"))] + span + } + + /// Slow path for when the current span is disabled by PLF and we have a + /// registry. + // This is called by `lookup_current` in the case that per-subscriber filtering + // is in use. `lookup_current` is allowed to be inlined, but this method is + // factored out to prevent the loop and (potentially-recursive) subscriber + // downcasting from being inlined if `lookup_current` is inlined. + #[inline(never)] + #[cfg(feature = "registry")] + fn lookup_current_filtered<'lookup>( + &self, + subscriber: &'lookup C, + ) -> Option> + where + C: LookupSpan<'lookup>, + { + let registry = (subscriber as &dyn Collect).downcast_ref::()?; + registry + .span_stack() + .iter() + .find_map(|id| subscriber.span(id)?.try_with_filter(self.filter)) + } + + /// Returns an iterator over the [stored data] for all the spans in the + /// current context, starting the root of the trace tree and ending with + /// the current span. + /// + /// If this iterator is empty, then there are no spans in the current context. + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + #[deprecated( + note = "equivalent to `self.current_span().id().and_then(|id| self.span_scope(id).from_root())` but consider passing an explicit ID instead of relying on the contextual span", + since = "0.2.19" + )] + #[allow(deprecated)] + pub fn scope(&self) -> Scope<'_, C> + where + C: for<'lookup> LookupSpan<'lookup>, + { + Scope( + self.lookup_current() + .as_ref() + .map(registry::SpanRef::scope) + .map(registry::Scope::from_root) + .into_iter() + .flatten(), + ) + } + + /// Returns an iterator over the [stored data] for all the spans in the + /// current context, starting with the specified span and ending with the + /// root of the trace tree and ending with the current span. + /// + ///
+ ///
ⓘNote
+ ///
+ ///
+ /// 
+    /// Note: Compared to scope this
+    /// returns the spans in reverse order (from leaf to root). Use
+    /// Scope::from_root
+    /// in case root-to-leaf ordering is desired.
+    ///
+ /// + ///
+ ///
ⓘNote
+ ///
+ ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + pub fn span_scope(&self, id: &span::Id) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + Some(self.span(id)?.scope()) + } + + /// Returns an iterator over the [stored data] for all the spans in the + /// current context, starting with the parent span of the specified event, + /// and ending with the root of the trace tree and ending with the current span. + /// + ///
+ /// 
+    /// Note: Compared to scope this
+    /// returns the spans in reverse order (from leaf to root). Use
+    /// Scope::from_root
+    /// in case root-to-leaf ordering is desired.
+    ///
+ /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + pub fn event_scope(&self, event: &Event<'_>) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + Some(self.event_span(event)?.scope()) + } + + #[cfg(feature = "registry")] + pub(crate) fn with_filter(self, filter: FilterId) -> Self { + // If we already have our own `FilterId`, combine it with the provided + // one. That way, the new `FilterId` will consider a span to be disabled + // if it was disabled by the given `FilterId` *or* any `FilterId`s for + // subscribers "above" us in the stack. + // + // See the doc comment for `FilterId::and` for details. + let filter = self.filter.and(filter); + Self { filter, ..self } + } + + #[cfg(feature = "registry")] + pub(crate) fn is_enabled_for(&self, span: &span::Id, filter: FilterId) -> bool + where + C: for<'lookup> LookupSpan<'lookup>, + { + self.is_enabled_inner(span, filter).unwrap_or(false) + } + + #[cfg(feature = "registry")] + pub(crate) fn if_enabled_for(self, span: &span::Id, filter: FilterId) -> Option + where + C: for<'lookup> LookupSpan<'lookup>, + { + if self.is_enabled_inner(span, filter)? { + Some(self.with_filter(filter)) + } else { + None + } + } + + #[cfg(feature = "registry")] + fn is_enabled_inner(&self, span: &span::Id, filter: FilterId) -> Option + where + C: for<'lookup> LookupSpan<'lookup>, + { + Some(self.span(span)?.is_enabled_for(filter)) + } +} + +impl<'a, S> Context<'a, S> { + pub(crate) fn none() -> Self { + Self { + subscriber: None, + + #[cfg(feature = "registry")] + filter: FilterId::none(), + } + } +} + +impl<'a, S> Clone for Context<'a, S> { + #[inline] + fn clone(&self) -> Self { + let subscriber = self.subscriber.as_ref().copied(); + Context { + subscriber, + + #[cfg(feature = "registry")] + filter: self.filter, + } + } +} diff --git a/tracing-subscriber/src/subscribe/layered.rs b/tracing-subscriber/src/subscribe/layered.rs new file mode 100644 index 0000000..6d32540 --- /dev/null +++ b/tracing-subscriber/src/subscribe/layered.rs @@ -0,0 +1,465 @@ +use tracing_core::{ + collect::{Collect, Interest}, + metadata::Metadata, + span, Event, LevelFilter, +}; + +use crate::{ + filter, + registry::LookupSpan, + subscribe::{Context, Subscribe}, +}; +#[cfg(feature = "registry")] +use crate::{filter::FilterId, registry::Registry}; +use std::{any::TypeId, fmt, marker::PhantomData, ptr::NonNull}; + +/// A [collector] composed of a [collector] wrapped by one or more +/// [subscriber]s. +/// +/// [subscriber]: crate::Subscribe +/// [collector]: tracing_core::Collect +#[derive(Clone)] +pub struct Layered { + /// The subscriber. + subscriber: S, + + /// The inner value that `self.subscriber` was layered onto. + /// + /// If this is also a `Subscribe`, then this `Layered` will implement `Subscribe`. + /// If this is a `Collect`, then this `Layered` will implement + /// `Collect` instead. + inner: I, + + // These booleans are used to determine how to combine `Interest`s and max + // level hints when per-subscriber filters are in use. + /// Is `self.inner` a `Registry`? + /// + /// If so, when combining `Interest`s, we want to "bubble up" its + /// `Interest`. + inner_is_registry: bool, + + /// Does `self.subscriber` have per-subscriber filters? + /// + /// This will be true if: + /// - `self.inner` is a `Filtered`. + /// - `self.inner` is a tree of `Layered`s where _all_ arms of those + /// `Layered`s have per-subscriber filters. + /// + /// Otherwise, if it's a `Layered` with one per-subscriber filter in one branch, + /// but a non-per-subscriber-filtered subscriber in the other branch, this will be + /// _false_, because the `Layered` is already handling the combining of + /// per-subscriber filter `Interest`s and max level hints with its non-filtered + /// `Subscribe`. + has_subscriber_filter: bool, + + /// Does `self.inner` have per-subscriber filters? + /// + /// This is determined according to the same rules as + /// `has_subscriber_filter` above. + inner_has_subscriber_filter: bool, + _s: PhantomData, +} + +// === impl Layered === + +impl Collect for Layered +where + S: Subscribe, + C: Collect, +{ + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.pick_interest(self.subscriber.register_callsite(metadata), || { + self.inner.register_callsite(metadata) + }) + } + + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + if self.subscriber.enabled(metadata, self.ctx()) { + // if the outer subscriber enables the callsite metadata, ask the collector. + self.inner.enabled(metadata) + } else { + // otherwise, the callsite is disabled by the collector + false + } + } + + fn max_level_hint(&self) -> Option { + self.pick_level_hint( + self.subscriber.max_level_hint(), + self.inner.max_level_hint(), + ) + } + + fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { + let id = self.inner.new_span(span); + self.subscriber.on_new_span(span, &id, self.ctx()); + id + } + + fn record(&self, span: &span::Id, values: &span::Record<'_>) { + self.inner.record(span, values); + self.subscriber.on_record(span, values, self.ctx()); + } + + fn record_follows_from(&self, span: &span::Id, follows: &span::Id) { + self.inner.record_follows_from(span, follows); + self.subscriber.on_follows_from(span, follows, self.ctx()); + } + + fn event(&self, event: &Event<'_>) { + self.inner.event(event); + self.subscriber.on_event(event, self.ctx()); + } + + fn enter(&self, span: &span::Id) { + self.inner.enter(span); + self.subscriber.on_enter(span, self.ctx()); + } + + fn exit(&self, span: &span::Id) { + self.inner.exit(span); + self.subscriber.on_exit(span, self.ctx()); + } + + fn clone_span(&self, old: &span::Id) -> span::Id { + let new = self.inner.clone_span(old); + if &new != old { + self.subscriber.on_id_change(old, &new, self.ctx()) + }; + new + } + + #[inline] + fn drop_span(&self, id: span::Id) { + self.try_close(id); + } + + fn try_close(&self, id: span::Id) -> bool { + #[cfg(feature = "registry")] + let subscriber = &self.inner as &dyn Collect; + #[cfg(feature = "registry")] + let mut guard = subscriber + .downcast_ref::() + .map(|registry| registry.start_close(id.clone())); + if self.inner.try_close(id.clone()) { + // If we have a registry's close guard, indicate that the span is + // closing. + #[cfg(feature = "registry")] + { + if let Some(g) = guard.as_mut() { + g.is_closing() + }; + } + + self.subscriber.on_close(id, self.ctx()); + true + } else { + false + } + } + + #[inline] + fn current_span(&self) -> span::Current { + self.inner.current_span() + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + // Unlike the implementation of `Subscribe` for `Layered`, we don't have to + // handle the "magic PSF downcast marker" here. If a `Layered` + // implements `Collect`, we already know that the `inner` branch is + // going to contain something that doesn't have per-subscriber filters (the + // actual root `Collect`). Thus, a `Layered` that implements + // `Collect` will always be propagating the root subscriber's + // `Interest`/level hint, even if it includes a `Subscribe` that has + // per-subscriber filters, because it will only ever contain subscribers where + // _one_ child has per-subscriber filters. + // + // The complex per-subscriber filter detection logic is only relevant to + // *trees* of subscribers, which involve the `Subscribe` implementation for + // `Layered`, not *lists* of subscribers, where every `Layered` implements + // `Collect`. Of course, a linked list can be thought of as a + // degenerate tree...but luckily, we are able to make a type-level + // distinction between individual `Layered`s that are definitely + // list-shaped (their inner child implements `Collect`), and + // `Layered`s that might be tree-shaped (the inner child is also a + // `Subscribe`). + + // If downcasting to `Self`, return a pointer to `self`. + if id == TypeId::of::() { + return Some(NonNull::from(self).cast()); + } + + self.subscriber + .downcast_raw(id) + .or_else(|| self.inner.downcast_raw(id)) + } +} + +impl Subscribe for Layered +where + A: Subscribe, + B: Subscribe, + C: Collect, +{ + fn on_subscribe(&mut self, collect: &mut C) { + self.subscriber.on_subscribe(collect); + self.inner.on_subscribe(collect); + } + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.pick_interest(self.subscriber.register_callsite(metadata), || { + self.inner.register_callsite(metadata) + }) + } + + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + if self.subscriber.enabled(metadata, ctx.clone()) { + // if the outer subscriber enables the callsite metadata, ask the inner subscriber. + self.inner.enabled(metadata, ctx) + } else { + // otherwise, the callsite is disabled by this subscriber + false + } + } + + fn max_level_hint(&self) -> Option { + self.pick_level_hint( + self.subscriber.max_level_hint(), + self.inner.max_level_hint(), + ) + } + + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + self.inner.on_new_span(attrs, id, ctx.clone()); + self.subscriber.on_new_span(attrs, id, ctx); + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { + self.inner.on_record(span, values, ctx.clone()); + self.subscriber.on_record(span, values, ctx); + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { + self.inner.on_follows_from(span, follows, ctx.clone()); + self.subscriber.on_follows_from(span, follows, ctx); + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + self.inner.on_event(event, ctx.clone()); + self.subscriber.on_event(event, ctx); + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { + self.inner.on_enter(id, ctx.clone()); + self.subscriber.on_enter(id, ctx); + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { + self.inner.on_exit(id, ctx.clone()); + self.subscriber.on_exit(id, ctx); + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { + self.inner.on_close(id.clone(), ctx.clone()); + self.subscriber.on_close(id, ctx); + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { + self.inner.on_id_change(old, new, ctx.clone()); + self.subscriber.on_id_change(old, new, ctx); + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + match id { + // If downcasting to `Self`, return a pointer to `self`. + id if id == TypeId::of::() => Some(NonNull::from(self).cast()), + + // Oh, we're looking for per-subscriber filters! + // + // This should only happen if we are inside of another `Layered`, + // and it's trying to determine how it should combine `Interest`s + // and max level hints. + // + // In that case, this `Layered` should be considered to be + // "per-subscriber filtered" if *both* the outer subscriber and the inner + // subscriber/subscriber have per-subscriber filters. Otherwise, this `Layered + // should *not* be considered per-subscriber filtered (even if one or the + // other has per subscriber filters). If only one `Subscribe` is per-subscriber + // filtered, *this* `Layered` will handle aggregating the `Interest` + // and level hints on behalf of its children, returning the + // aggregate (which is the value from the &non-per-subscriber-filtered* + // child). + // + // Yes, this rule *is* slightly counter-intuitive, but it's + // necessary due to a weird edge case that can occur when two + // `Layered`s where one side is per-subscriber filtered and the other + // isn't are `Layered` together to form a tree. If we didn't have + // this rule, we would actually end up *ignoring* `Interest`s from + // the non-per-subscriber-filtered subscribers, since both branches would + // claim to have PSF. + // + // If you don't understand this...that's fine, just don't mess with + // it. :) + id if filter::is_psf_downcast_marker(id) => self + .subscriber + .downcast_raw(id) + .and(self.inner.downcast_raw(id)), + + // Otherwise, try to downcast both branches normally... + _ => self + .subscriber + .downcast_raw(id) + .or_else(|| self.inner.downcast_raw(id)), + } + } +} + +impl<'a, S, C> LookupSpan<'a> for Layered +where + C: Collect + LookupSpan<'a>, +{ + type Data = C::Data; + + fn span_data(&'a self, id: &span::Id) -> Option { + self.inner.span_data(id) + } + + #[cfg(feature = "registry")] + fn register_filter(&mut self) -> FilterId { + self.inner.register_filter() + } +} + +impl Layered +where + C: Collect, +{ + fn ctx(&self) -> Context<'_, C> { + Context::new(&self.inner) + } +} + +impl Layered +where + A: Subscribe, + C: Collect, +{ + pub(super) fn new(subscriber: A, inner: B, inner_has_subscriber_filter: bool) -> Self { + #[cfg(feature = "registry")] + let inner_is_registry = TypeId::of::() == TypeId::of::(); + #[cfg(not(feature = "registry"))] + let inner_is_registry = false; + + let inner_has_subscriber_filter = inner_has_subscriber_filter || inner_is_registry; + let has_subscriber_filter = filter::subscriber_has_psf(&subscriber); + Self { + subscriber, + inner, + has_subscriber_filter, + inner_has_subscriber_filter, + inner_is_registry, + _s: PhantomData, + } + } + + fn pick_interest(&self, outer: Interest, inner: impl FnOnce() -> Interest) -> Interest { + if self.has_subscriber_filter { + return inner(); + } + + // If the outer subscriber has disabled the callsite, return now so that + // the inner subscriber/subscriber doesn't get its hopes up. + if outer.is_never() { + return outer; + } + + // The `inner` closure will call `inner.register_callsite()`. We do this + // before the `if` statement to ensure that the inner subscriber is + // informed that the callsite exists regardless of the outer subscriber's + // filtering decision. + let inner = inner(); + if outer.is_sometimes() { + // if this interest is "sometimes", return "sometimes" to ensure that + // filters are reevaluated. + return outer; + } + + // If there is a per-subscriber filter in the `inner` stack, and it returns + // `never`, change the interest to `sometimes`, because the `outer` + // subscriber didn't return `never`. This means that _some_ subscriber still wants + // to see that callsite, even though the inner stack's per-subscriber filter + // didn't want it. Therefore, returning `sometimes` will ensure + // `enabled` is called so that the per-subscriber filter can skip that + // span/event, while the `outer` subscriber still gets to see it. + if inner.is_never() && self.inner_has_subscriber_filter { + return Interest::sometimes(); + } + + // otherwise, allow the inner subscriber or collector to weigh in. + inner + } + + fn pick_level_hint( + &self, + outer_hint: Option, + inner_hint: Option, + ) -> Option { + use std::cmp::max; + + if self.inner_is_registry { + return outer_hint; + } + + if self.has_subscriber_filter && self.inner_has_subscriber_filter { + return Some(max(outer_hint?, inner_hint?)); + } + + if self.has_subscriber_filter && inner_hint.is_none() { + return None; + } + + if self.inner_has_subscriber_filter && outer_hint.is_none() { + return None; + } + + max(outer_hint, inner_hint) + } +} + +impl fmt::Debug for Layered +where + A: fmt::Debug, + B: fmt::Debug, +{ + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + #[cfg(feature = "registry")] + let alt = f.alternate(); + let mut s = f.debug_struct("Layered"); + // These additional fields are more verbose and usually only necessary + // for internal debugging purposes, so only print them if alternate mode + // is enabled. + #[cfg(feature = "registry")] + if alt { + s.field("inner_is_registry", &self.inner_is_registry) + .field("has_subscriber_filter", &self.has_subscriber_filter) + .field( + "inner_has_subscriber_filter", + &self.inner_has_subscriber_filter, + ); + } + + s.field("subscriber", &self.subscriber) + .field("inner", &self.inner) + .finish() + } +} diff --git a/tracing-subscriber/src/subscribe/mod.rs b/tracing-subscriber/src/subscribe/mod.rs new file mode 100644 index 0000000..8ebad1c --- /dev/null +++ b/tracing-subscriber/src/subscribe/mod.rs @@ -0,0 +1,1197 @@ +//! The [`Subscribe`] trait, a composable abstraction for building [collector]s. +//! +//! The [`Collect`] trait in `tracing-core` represents the _complete_ set of +//! functionality required to consume `tracing` instrumentation. This means that +//! a single `Collect` instance is a self-contained implementation of a +//! complete strategy for collecting traces; but it _also_ means that the +//! `Collect` trait cannot easily be composed with other collectors. +//! +//! In particular, [collector]s are responsible for generating [span IDs] and +//! assigning them to spans. Since these IDs must uniquely identify a span +//! within the context of the current trace, this means that there may only be +//! a single collector for a given thread at any point in time — +//! otherwise, there would be no authoritative source of span IDs. +//! +//! On the other hand, the majority of the [`Collect`] trait's functionality +//! is composable: any number of subscribers may _observe_ events, span entry +//! and exit, and so on, provided that there is a single authoritative source of +//! span IDs. The [`Subscribe`] trait represents this composable subset of the +//! [`Collect`] behavior; it can _observe_ events and spans, but does not +//! assign IDs. +//! +//! ## Composing Subscribers +//! +//! Since a [subscriber] does not implement a complete strategy for collecting +//! traces, it must be composed with a [collector] in order to be used. The +//! [`Subscribe`] trait is generic over a type parameter (called `C` in the trait +//! definition), representing the types of `Collect` they can be composed +//! with. Thus, a subscriber may be implemented that will only compose with a +//! particular `Collect` implementation, or additional trait bounds may be +//! added to constrain what types implementing `Collect` a subscriber can wrap. +//! +//! Subscribers may be added to a collector by using the [`CollectExt::with`] +//! method, which is provided by `tracing-subscriber`'s [prelude]. This method +//! returns a [`Layered`] struct that implements [`Collect`] by composing the +//! `Subscribe` with the collector. +//! +//! For example: +//! ```rust +//! use tracing_subscriber::Subscribe; +//! use tracing_subscriber::prelude::*; +//! use tracing::Collect; +//! +//! pub struct MySubscriber { +//! // ... +//! } +//! +//! impl Subscribe for MySubscriber { +//! // ... +//! } +//! +//! pub struct MyCollector { +//! // ... +//! } +//! +//! # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; +//! impl Collect for MyCollector { +//! // ... +//! # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } +//! # fn record(&self, _: &Id, _: &Record) {} +//! # fn event(&self, _: &Event) {} +//! # fn record_follows_from(&self, _: &Id, _: &Id) {} +//! # fn enabled(&self, _: &Metadata) -> bool { false } +//! # fn enter(&self, _: &Id) {} +//! # fn exit(&self, _: &Id) {} +//! # fn current_span(&self) -> tracing_core::span::Current { tracing_core::span::Current::none() } +//! } +//! # impl MySubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyCollector { +//! # fn new() -> Self { Self { }} +//! # } +//! +//! let collector = MyCollector::new() +//! .with(MySubscriber::new()); +//! +//! tracing::collect::set_global_default(collector); +//! ``` +//! +//! Multiple subscriber may be composed in the same manner: +//! ```rust +//! # use tracing_subscriber::{Subscribe, subscribe::CollectExt}; +//! # use tracing::Collect; +//! pub struct MyOtherSubscriber { +//! // ... +//! } +//! +//! impl Subscribe for MyOtherSubscriber { +//! // ... +//! } +//! +//! pub struct MyThirdSubscriber { +//! // ... +//! } +//! +//! impl Subscribe for MyThirdSubscriber { +//! // ... +//! } +//! # pub struct MySubscriber {} +//! # impl Subscribe for MySubscriber {} +//! # pub struct MyCollector { } +//! # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; +//! # impl Collect for MyCollector { +//! # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } +//! # fn record(&self, _: &Id, _: &Record) {} +//! # fn event(&self, _: &Event) {} +//! # fn record_follows_from(&self, _: &Id, _: &Id) {} +//! # fn enabled(&self, _: &Metadata) -> bool { false } +//! # fn current_span(&self) -> tracing_core::span::Current { tracing_core::span::Current::none() } +//! # fn enter(&self, _: &Id) {} +//! # fn exit(&self, _: &Id) {} +//! } +//! # impl MySubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyOtherSubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyThirdSubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyCollector { +//! # fn new() -> Self { Self { }} +//! # } +//! +//! let collect = MyCollector::new() +//! .with(MySubscriber::new()) +//! .with(MyOtherSubscriber::new()) +//! .with(MyThirdSubscriber::new()); +//! +//! tracing::collect::set_global_default(collect); +//! ``` +//! +//! The [`Subscribe::with_collector`] constructs the [`Layered`] type from a +//! [`Subscribe`] and [`Collect`], and is called by [`CollectExt::with`]. In +//! general, it is more idiomatic to use [`CollectExt::with`], and treat +//! [`Subscribe::with_collector`] as an implementation detail, as `with_collector` +//! calls must be nested, leading to less clear code for the reader. +//! +//! [prelude]: crate::prelude +//! +//! ## Recording Traces +//! +//! The [`Subscribe`] trait defines a set of methods for consuming notifications from +//! tracing instrumentation, which are generally equivalent to the similarly +//! named methods on [`Collect`]. Unlike [`Collect`], the methods on +//! `Subscribe` are additionally passed a [`Context`] type, which exposes additional +//! information provided by the wrapped subscriber (such as [the current span]) +//! to the subscriber. +//! +//! ## Filtering with `Subscribers`s +//! +//! As well as strategies for handling trace events, the `Subscribe` trait may also +//! be used to represent composable _filters_. This allows the determination of +//! what spans and events should be recorded to be decoupled from _how_ they are +//! recorded: a filtering subscriber can be applied to other subscribers or +//! subscribers. `Subscribe`s can be used to implement _global filtering_, where a +//! `Subscribe` provides a filtering strategy for the entire subscriber. +//! Additionally, individual recording `Subscribe`s or sets of `Subscribe`s may be +//! combined with _per-subscriber filters_ that control what spans and events are +//! recorded by those subscribers. +//! +//! ### Global Filtering +//! +//! A `Subscribe` that implements a filtering strategy should override the +//! [`register_callsite`] and/or [`enabled`] methods. It may also choose to implement +//! methods such as [`on_enter`], if it wishes to filter trace events based on +//! the current span context. +//! +//! Note that the [`Subscribe::register_callsite`] and [`Subscribe::enabled`] methods +//! determine whether a span or event is enabled *globally*. Thus, they should +//! **not** be used to indicate whether an individual subscriber wishes to record a +//! particular span or event. Instead, if a subscriber is only interested in a subset +//! of trace data, but does *not* wish to disable other spans and events for the +//! rest of the subscriber stack should ignore those spans and events in its +//! notification methods. +//! +//! The filtering methods on a stack of `Subscribe`s are evaluated in a top-down +//! order, starting with the outermost `Subscribe` and ending with the wrapped +//! [`Collect`]. If any subscriber returns `false` from its [`enabled`] method, or +//! [`Interest::never()`] from its [`register_callsite`] method, filter +//! evaluation will short-circuit and the span or event will be disabled. +//! +//! ### Per-Subscriber Filtering +//! +//! **Note**: per-subscriber filtering APIs currently require the [`"registry"` crate +//! feature flag][feat] to be enabled. +//! +//! Sometimes, it may be desirable for one `Subscribe` to record a particular subset +//! of spans and events, while a different subset of spans and events are +//! recorded by other `Subscribe`s. For example: +//! +//! - A subscriber that records metrics may wish to observe only events including +//! particular tracked values, while a logging subscriber ignores those events. +//! - If recording a distributed trace is expensive, it might be desirable to +//! only send spans with `INFO` and lower verbosity to the distributed tracing +//! system, while logging more verbose spans to a file. +//! - Spans and events with a particular target might be recorded differently +//! from others, such as by generating an HTTP access log from a span that +//! tracks the lifetime of an HTTP request. +//! +//! The [`Filter`] trait is used to control what spans and events are +//! observed by an individual `Subscribe`, while still allowing other `Subscribe`s to +//! potentially record them. The [`Subscribe::with_filter`] method combines a +//! `Subscribe` with a [`Filter`], returning a [`Filtered`] subscriber. +//! +//! This crate's [`filter`] module provides a number of types which implement +//! the [`Filter`] trait, such as [`LevelFilter`], [`Targets`], and +//! [`FilterFn`]. These [`Filter`]s provide ready-made implementations of +//! common forms of filtering. For custom filtering policies, the [`FilterFn`] +//! and [`DynFilterFn`] types allow implementing a [`Filter`] with a closure or +//! function pointer. In addition, when more control is required, the [`Filter`] +//! trait may also be implemented for user-defined types. +//! +//!
+//! 
+//!     Warning: Currently, the 
+//!     Registry type defined in this crate is the only root
+//!     Collect capable of supporting subscriberss with
+//!     per-subscriber filters. In the future, new APIs will be added to allow other
+//!     root Collects to support per-subscriber filters.
+//!
+//! +//! For example, to generate an HTTP access log based on spans with +//! the `http_access` target, while logging other spans and events to +//! standard out, a [`Filter`] can be added to the access log subscriber: +//! +//! ``` +//! use tracing_subscriber::{filter, prelude::*}; +//! +//! // Generates an HTTP access log. +//! let access_log = // ... +//! # filter::LevelFilter::INFO; +//! +//! // Add a filter to the access log subscriber so that it only observes +//! // spans and events with the `http_access` target. +//! let access_log = access_log.with_filter(filter::filter_fn(|metadata| { +//! // Returns `true` if and only if the span or event's target is +//! // "http_access". +//! metadata.target() == "http_access" +//! })); +//! +//! // A gteneral-purpose logging subscriber. +//! let fmt_subscriber = tracing_subscriber::fmt::subscriber(); +//! +//! // Build a subscriber that combines the access log and stdout log +//! // subscribers. +//! tracing_subscriber::registry() +//! .with(fmt_subscriber) +//! .with(access_log) +//! .init(); +//! ``` +//! +//! Multiple subscribers can have their own, separate per-subscriber filters. A span or +//! event will be recorded if it is enabled by _any_ per-subscriber filter, but it +//! will be skipped by the subscribers whose filters did not enable it. Building on +//! the previous example: +//! +//! ``` +//! use tracing_subscriber::{filter::{filter_fn, LevelFilter}, prelude::*}; +//! +//! let access_log = // ... +//! # LevelFilter::INFO; +//! let fmt_subscriber = tracing_subscriber::fmt::subscriber(); +//! +//! tracing_subscriber::registry() +//! // Add the filter for the "http_access" target to the access +//! // log subscriber, like before. +//! .with(access_log.with_filter(filter_fn(|metadata| { +//! metadata.target() == "http_access" +//! }))) +//! // Add a filter for spans and events with the INFO level +//! // and below to the logging subscriber. +//! .with(fmt_subscriber.with_filter(LevelFilter::INFO)) +//! .init(); +//! +//! // Neither subscriber will observe this event +//! tracing::debug!(does_anyone_care = false, "a tree fell in the forest"); +//! +//! // This event will be observed by the logging subscriber, but not +//! // by the access log subscriber. +//! tracing::warn!(dose_roentgen = %3.8, "not great, but not terrible"); +//! +//! // This event will be observed only by the access log subscriber. +//! tracing::trace!(target: "http_access", "HTTP request started"); +//! +//! // Both subscribers will observe this event. +//! tracing::error!(target: "http_access", "HTTP request failed with a very bad error!"); +//! ``` +//! +//! A per-subscriber filter can be applied to multiple [`Subscribe`]s at a time, by +//! combining them into a [`Layered`] subscriber using [`Subscribe::and_then`], and then +//! calling [`Subscribe::with_filter`] on the resulting [`Layered`] subscriber. +//! +//! Consider the following: +//! - `subscriber_a` and `subscriber_b`, which should only receive spans and events at +//! the [`INFO`] [level] and above. +//! - A third subscriber, `subscriber_c`, which should receive spans and events at +//! the [`DEBUG`] [level] as well. +//! The subscribers and filters would be composed thusly: +//! +//! ``` +//! use tracing_subscriber::{filter::LevelFilter, prelude::*}; +//! +//! let subscriber_a = // ... +//! # LevelFilter::INFO; +//! let subscriber_b = // ... +//! # LevelFilter::INFO; +//! let subscriber_c = // ... +//! # LevelFilter::INFO; +//! +//! let info_subscribers = subscriber_a +//! // Combine `subscriber_a` and `subscriber_b` into a `Layered` subscriber: +//! .and_then(subscriber_b) +//! // ...and then add an `INFO` `LevelFilter` to that subscriber: +//! .with_filter(LevelFilter::INFO); +//! +//! tracing_subscriber::registry() +//! // Add `subscriber_c` with a `DEBUG` filter. +//! .with(subscriber_c.with_filter(LevelFilter::DEBUG)) +//! .with(info_subscribers) +//! .init(); +//!``` +//! +//! If a [`Filtered`] [`Subscribe`] is combined with another [`Subscribe`] +//! [`Subscribe::and_then`], and a filter is added to the [`Layered`] subscriber, that +//! subscriber will be filtered by *both* the inner filter and the outer filter. +//! Only spans and events that are enabled by *both* filters will be +//! observed by that subscriber. This can be used to implement complex filtering +//! trees. +//! +//! As an example, consider the following constraints: +//! - Suppose that a particular [target] is used to indicate events that +//! should be counted as part of a metrics system, which should be only +//! observed by a subscriber that collects metrics. +//! - A log of high-priority events ([`INFO`] and above) should be logged +//! to stdout, while more verbose events should be logged to a debugging log file. +//! - Metrics-focused events should *not* be included in either log output. +//! +//! In that case, it is possible to apply a filter to both logging subscribers to +//! exclude the metrics events, while additionally adding a [`LevelFilter`] +//! to the stdout log: +//! +//! ``` +//! # // wrap this in a function so we don't actually create `debug.log` when +//! # // running the doctests.. +//! # fn docs() -> Result<(), Box> { +//! use tracing_subscriber::{filter, prelude::*}; +//! use std::{fs::File, sync::Arc}; +//! +//! // A subscriber that logs events to stdout using the human-readable "pretty" +//! // format. +//! let stdout_log = tracing_subscriber::fmt::subscriber() +//! .pretty(); +//! +//! // A subscriber that logs events to a file. +//! let file = File::create("debug.log")?; +//! let debug_log = tracing_subscriber::fmt::subscriber() +//! .with_writer(file); +//! +//! // A subscriber that collects metrics using specific events. +//! let metrics_subscriber = /* ... */ filter::LevelFilter::INFO; +//! +//! tracing_subscriber::registry() +//! .with( +//! stdout_log +//! // Add an `INFO` filter to the stdout logging subscriber +//! .with_filter(filter::LevelFilter::INFO) +//! // Combine the filtered `stdout_log` subscriber with the +//! // `debug_log` subscriber, producing a new `Layered` subscriber. +//! .and_then(debug_log) +//! // Add a filter to *both* subscribers that rejects spans and +//! // events whose targets start with `metrics`. +//! .with_filter(filter::filter_fn(|metadata| { +//! !metadata.target().starts_with("metrics") +//! })) +//! ) +//! .with( +//! // Add a filter to the metrics label that *only* enables +//! // events whose targets start with `metrics`. +//! metrics_subscriber.with_filter(filter::filter_fn(|metadata| { +//! metadata.target().starts_with("metrics") +//! })) +//! ) +//! .init(); +//! +//! // This event will *only* be recorded by the metrics subscriber. +//! tracing::info!(target: "metrics::cool_stuff_count", value = 42); +//! +//! // This event will only be seen by the debug log file subscriber: +//! tracing::debug!("this is a message, and part of a system of messages"); +//! +//! // This event will be seen by both the stdout log subscriber *and* +//! // the debug log file subscriber, but not by the metrics subscriber. +//! tracing::warn!("the message is a warning about danger!"); +//! # Ok(()) } +//! ``` +//! +//! [subscriber]: Subscribe +//! [`Collect`]:tracing_core::Collect +//! [collector]: tracing_core::Collect +//! [span IDs]: https://docs.rs/tracing-core/latest/tracing_core/span/struct.Id.html +//! [the current span]: Context::current_span +//! [`register_callsite`]: Subscribe::register_callsite +//! [`enabled`]: Subscribe::enabled +//! [`on_enter`]: Subscribe::on_enter +//! [`Subscribe::register_callsite`]: Subscribe::register_callsite +//! [`Subscribe::enabled`]: Subscribe::enabled +//! [`Interest::never()`]: tracing_core::collect::Interest::never +//! [`Filtered`]: crate::filter::Filtered +//! [`filter`]: crate::filter +//! [`Targets`]: crate::filter::Targets +//! [`FilterFn`]: crate::filter::FilterFn +//! [`DynFilterFn`]: crate::filter::DynFilterFn +//! [level]: tracing_core::Level +//! [`INFO`]: tracing_core::Level::INFO +//! [`DEBUG`]: tracing_core::Level::DEBUG +//! [target]: tracing_core::Metadata::target +//! [`LevelFilter`]: crate::filter::LevelFilter +//! [feat]: crate#feature-flags +use crate::filter; +use std::{any::TypeId, ops::Deref, ptr::NonNull, sync::Arc}; +use tracing_core::{ + collect::{Collect, Interest}, + metadata::Metadata, + span, Event, LevelFilter, +}; + +mod context; +mod layered; +pub use self::{context::*, layered::*}; + +// The `tests` module is `pub(crate)` because it contains test utilities used by +// other modules. +#[cfg(test)] +pub(crate) mod tests; + +/// A composable handler for `tracing` events. +/// +/// A type that implements `Subscribe` &mdash a "subscriber" — provides a +/// particular behavior for recording or collecting traces that can +/// be composed together with other subscribers to build a [collector]. See the +/// [module-level documentation](crate::subscribe) for details. +/// +/// [collector]: tracing_core::Collect +pub trait Subscribe +where + C: Collect, + Self: 'static, +{ + /// Performs late initialization when attaching a subscriber to a + /// [collector]. + /// + /// This is a callback that is called when the `Subscribe` is added to a + /// [`Collect`] (e.g. in [`Subscribe::with_collector`] and + /// [`CollectExt::with`]). Since this can only occur before the + /// [`Collect`] has been set as the default, both the subscriber and + /// [`Collect`] are passed to this method _mutably_. This gives the + /// subscribe the opportunity to set any of its own fields with values + /// recieved by method calls on the [`Collect`]. + /// + /// For example, [`Filtered`] subscribers implement `on_subscribe` to call the + /// [`Collect`]'s [`register_filter`] method, and store the returned + /// [`FilterId`] as a field. + /// + /// **Note** In most cases, subscriber implementations will not need to + /// implement this method. However, in cases where a type implementing + /// subscriber wraps one or more other types that implement `Subscribe`, like the + /// [`Layered`] and [`Filtered`] types in this crate, that type MUST ensure + /// that the inner `Subscribe` instance's' `on_subscribe` methods are + /// called. Otherwise, unctionality that relies on `on_subscribe`, such as + /// [per-subscriber filtering], may not work correctly. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [`register_filter`]: crate::registry::LookupSpan::register_filter + /// [per-subscribe filtering]: #per-subscriber-filtering + /// [`FilterId`]: crate::filter::FilterId + fn on_subscribe(&mut self, collector: &mut C) { + let _ = collector; + } + + /// Registers a new callsite with this subscriber, returning whether or not + /// the subscriber is interested in being notified about the callsite, similarly + /// to [`Collect::register_callsite`]. + /// + /// By default, this returns [`Interest::always()`] if [`self.enabled`] returns + /// true, or [`Interest::never()`] if it returns false. + /// + ///
+ /// 
+    ///
+    /// **Note**: This method (and [`Subscribe::enabled`]) determine whether a span or event is
+    /// globally enabled, *not* whether the individual subscriber will be notified about that
+    /// span or event.  This is intended to be used by subscribers that implement filtering for
+    /// the entire stack. Subscribers which do not wish to be notified about certain spans or
+    /// events but do not wish to globally disable them should ignore those spans or events in
+    /// their [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
+    /// and other notification methods.
+    ///
+    ///
+ /// + /// See [the trait-level documentation] for more information on filtering + /// with subscribers. + /// + /// Subscribers may also implement this method to perform any behaviour that + /// should be run once per callsite. If the subscriber wishes to use + /// `register_callsite` for per-callsite behaviour, but does not want to + /// globally enable or disable those callsites, it should always return + /// [`Interest::always()`]. + /// + /// [`Interest`]: tracing_core::collect::Interest + /// [`Collect::register_callsite`]: tracing_core::Collect::register_callsite() + /// [`self.enabled`]: Subscribe::enabled() + /// [the trait-level documentation]: #filtering-with-subscribers + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + if self.enabled(metadata, Context::none()) { + Interest::always() + } else { + Interest::never() + } + } + + /// Returns `true` if this subscriber is interested in a span or event with the + /// given `metadata` in the current [`Context`], similarly to + /// [`Collect::enabled`]. + /// + /// By default, this always returns `true`, allowing the wrapped collector + /// to choose to disable the span. + /// + ///
+ /// 
+    ///
+    /// **Note**: This method (and [`register_callsite`][Self::register_callsite])
+    /// determine whether a span or event is
+    /// globally enabled, *not* whether the individual subscriber will be
+    /// notified about that span or event. This is intended to be used
+    /// by subscribers that implement filtering for the entire stack. Layers which do
+    /// not wish to be notified about certain spans or events but do not wish to
+    /// globally disable them should ignore those spans or events in their
+    /// [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
+    /// and other notification methods.
+    ///
+    ///
+ /// + /// + /// See [the trait-level documentation] for more information on filtering + /// with subscribers. + /// + /// [`Interest`]: tracing_core::Interest + /// [the trait-level documentation]: #filtering-with-subscribers + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + let _ = (metadata, ctx); + true + } + + /// Notifies this subscriber that a new span was constructed with the given + /// `Attributes` and `Id`. + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + let _ = (attrs, id, ctx); + } + + // TODO(eliza): do we want this to be a public API? If we end up moving + // filtering subscribers to a separate trait, we may no longer want subscribers to + // be able to participate in max level hinting... + #[doc(hidden)] + fn max_level_hint(&self) -> Option { + None + } + + /// Notifies this subscriber that a span with the given `Id` recorded the given + /// `values`. + // Note: it's unclear to me why we'd need the current span in `record` (the + // only thing the `Context` type currently provides), but passing it in anyway + // seems like a good future-proofing measure as it may grow other methods later... + fn on_record(&self, _span: &span::Id, _values: &span::Record<'_>, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that a span with the ID `span` recorded that it + /// follows from the span with the ID `follows`. + // Note: it's unclear to me why we'd need the current span in `record` (the + // only thing the `Context` type currently provides), but passing it in anyway + // seems like a good future-proofing measure as it may grow other methods later... + fn on_follows_from(&self, _span: &span::Id, _follows: &span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that an event has occurred. + fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that a span with the given ID was entered. + fn on_enter(&self, _id: &span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that the span with the given ID was exited. + fn on_exit(&self, _id: &span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that the span with the given ID has been closed. + fn on_close(&self, _id: span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that a span ID has been cloned, and that the + /// subscriber returned a different ID. + fn on_id_change(&self, _old: &span::Id, _new: &span::Id, _ctx: Context<'_, C>) {} + + /// Composes this subscriber around the given collector, returning a `Layered` + /// struct implementing `Subscribe`. + /// + /// The returned subscriber will call the methods on this subscriber and then + /// those of the new subscriber, before calling the methods on the collector + /// it wraps. For example: + /// + /// ```rust + /// # use tracing_subscriber::subscribe::Subscribe; + /// # use tracing_core::Collect; + /// # use tracing_core::span::Current; + /// pub struct FooSubscriber { + /// // ... + /// } + /// + /// pub struct BarSubscriber { + /// // ... + /// } + /// + /// pub struct MyCollector { + /// // ... + /// } + /// + /// impl Subscribe for FooSubscriber { + /// // ... + /// } + /// + /// impl Subscribe for BarSubscriber { + /// // ... + /// } + /// + /// # impl FooSubscriber { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl BarSubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # impl MyCollector { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; + /// # impl tracing_core::Collect for MyCollector { + /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } + /// # fn record(&self, _: &Id, _: &Record) {} + /// # fn event(&self, _: &Event) {} + /// # fn record_follows_from(&self, _: &Id, _: &Id) {} + /// # fn enabled(&self, _: &Metadata) -> bool { false } + /// # fn enter(&self, _: &Id) {} + /// # fn exit(&self, _: &Id) {} + /// # fn current_span(&self) -> Current { Current::unknown() } + /// # } + /// let collector = FooSubscriber::new() + /// .and_then(BarSubscriber::new()) + /// .with_collector(MyCollector::new()); + /// ``` + /// + /// Multiple subscribers may be composed in this manner: + /// + /// ```rust + /// # use tracing_subscriber::subscribe::Subscribe; + /// # use tracing_core::{Collect, span::Current}; + /// # pub struct FooSubscriber {} + /// # pub struct BarSubscriber {} + /// # pub struct MyCollector {} + /// # impl Subscribe for FooSubscriber {} + /// # impl Subscribe for BarSubscriber {} + /// # impl FooSubscriber { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl BarSubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # impl MyCollector { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; + /// # impl tracing_core::Collect for MyCollector { + /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } + /// # fn record(&self, _: &Id, _: &Record) {} + /// # fn event(&self, _: &Event) {} + /// # fn record_follows_from(&self, _: &Id, _: &Id) {} + /// # fn enabled(&self, _: &Metadata) -> bool { false } + /// # fn enter(&self, _: &Id) {} + /// # fn exit(&self, _: &Id) {} + /// # fn current_span(&self) -> Current { Current::unknown() } + /// # } + /// pub struct BazSubscriber { + /// // ... + /// } + /// + /// impl Subscribe for BazSubscriber { + /// // ... + /// } + /// # impl BazSubscriber { fn new() -> Self { BazSubscriber {} } } + /// + /// let collector = FooSubscriber::new() + /// .and_then(BarSubscriber::new()) + /// .and_then(BazSubscriber::new()) + /// .with_collector(MyCollector::new()); + /// ``` + fn and_then(self, subscriber: S) -> Layered + where + S: Subscribe, + Self: Sized, + { + let inner_has_subscriber_filter = filter::subscriber_has_psf(&self); + Layered::new(subscriber, self, inner_has_subscriber_filter) + } + + /// Composes this subscriber with the given collector, returning a + /// `Layered` struct that implements [`Collect`]. + /// + /// The returned `Layered` subscriber will call the methods on this subscriber + /// and then those of the wrapped collector. + /// + /// For example: + /// ```rust + /// # use tracing_subscriber::subscribe::Subscribe; + /// # use tracing_core::Collect; + /// # use tracing_core::span::Current; + /// pub struct FooSubscriber { + /// // ... + /// } + /// + /// pub struct MyCollector { + /// // ... + /// } + /// + /// impl Subscribe for FooSubscriber { + /// // ... + /// } + /// + /// # impl FooSubscriber { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl MyCollector { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata}; + /// # impl tracing_core::Collect for MyCollector { + /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(0) } + /// # fn record(&self, _: &Id, _: &Record) {} + /// # fn event(&self, _: &tracing_core::Event) {} + /// # fn record_follows_from(&self, _: &Id, _: &Id) {} + /// # fn enabled(&self, _: &Metadata) -> bool { false } + /// # fn enter(&self, _: &Id) {} + /// # fn exit(&self, _: &Id) {} + /// # fn current_span(&self) -> Current { Current::unknown() } + /// # } + /// let collector = FooSubscriber::new() + /// .with_collector(MyCollector::new()); + ///``` + /// + /// [`Collect`]: tracing_core::Collect + fn with_collector(mut self, mut inner: C) -> Layered + where + Self: Sized, + { + let inner_has_subscriber_filter = filter::collector_has_psf(&inner); + self.on_subscribe(&mut inner); + Layered::new(self, inner, inner_has_subscriber_filter) + } + + /// Combines `self` with a [`Filter`], returning a [`Filtered`] subscriber. + /// + /// The [`Filter`] will control which spans and events are enabled for + /// this subscriber. See [the trait-level documentation][psf] for details on + /// per-subscriber filtering. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [psf]: #per-subscriber-filtering + #[cfg(all(feature = "registry", feature = "std"))] + #[cfg_attr(docsrs, doc(cfg(all(feature = "registry", feature = "std"))))] + fn with_filter(self, filter: F) -> filter::Filtered + where + Self: Sized, + F: Filter, + { + filter::Filtered::new(self, filter) + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + if id == TypeId::of::() { + Some(NonNull::from(self).cast()) + } else { + None + } + } +} + +/// A per-[`Subscribe`] filter that determines whether a span or event is enabled +/// for an individual subscriber. +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry"), notable_trait))] +pub trait Filter { + /// Returns `true` if this subscriber is interested in a span or event with the + /// given [`Metadata`] in the current [`Context`], similarly to + /// [`Collect::enabled`]. + /// + /// If this returns `false`, the span or event will be disabled _for the + /// wrapped [`Subscribe`]_. Unlike [`Subscribe::enabled`], the span or event will + /// still be recorded if any _other_ subscribers choose to enable it. However, + /// the subscriber [filtered] by this filter will skip recording that span or + /// event. + /// + /// If all subscribers indicate that they do not wish to see this span or event, + /// it will be disabled. + /// + /// [`metadata`]: tracing_core::Metadata + /// [`Collect::enabled`]: tracing_core::Collect::enabled + /// [filtered]: crate::filter::Filtered + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, S>) -> bool; + + /// Returns an [`Interest`] indicating whether this subscriber will [always], + /// [sometimes], or [never] be interested in the given [`Metadata`]. + /// + /// When a given callsite will [always] or [never] be enabled, the results + /// of evaluating the filter may be cached for improved performance. + /// Therefore, if a filter is capable of determining that it will always or + /// never enable a particular callsite, providing an implementation of this + /// function is recommended. + /// + ///
+ /// 
+    /// Note: If a Filter will perform
+    /// dynamic filtering that depends on the current context in which
+    /// a span or event was observered (e.g. only enabling an event when it
+    /// occurs within a particular span), it must return
+    /// Interest::sometimes() from this method. If it returns
+    /// Interest::always() or Interest::never(), the
+    /// enabled method may not be called when a particular instance
+    /// of that span or event is recorded.
+    ///
+ ///
+ /// + /// This method is broadly similar to [`Collect::register_callsite`]; + /// however, since the returned value represents only the interest of + /// *this* subscriber, the resulting behavior is somewhat different. + /// + /// If a [`Collect`] returns [`Interest::always()`][always] or + /// [`Interest::never()`][never] for a given [`Metadata`], its [`enabled`] + /// method is then *guaranteed* to never be called for that callsite. On the + /// other hand, when a `Filter` returns [`Interest::always()`][always] or + /// [`Interest::never()`][never] for a callsite, _other_ [`Subscribe`]s may have + /// differing interests in that callsite. If this is the case, the callsite + /// will recieve [`Interest::sometimes()`][sometimes], and the [`enabled`] + /// method will still be called for that callsite when it records a span or + /// event. + /// + /// Returning [`Interest::always()`][always] or [`Interest::never()`][never] from + /// `Filter::callsite_enabled` will permanently enable or disable a + /// callsite (without requiring subsequent calls to [`enabled`]) if and only + /// if the following is true: + /// + /// - all [`Subscribe`]s that comprise the subscriber include `Filter`s + /// (this includes a tree of [`Layered`] subscribers that share the same + /// `Filter`) + /// - all those `Filter`s return the same [`Interest`]. + /// + /// For example, if a [`Collect`] consists of two [`Filtered`] subscribers, + /// and both of those subscribers return [`Interest::never()`][never], that + /// callsite *will* never be enabled, and the [`enabled`] methods of those + /// [`Filter`]s will not be called. + /// + /// ## Default Implementation + /// + /// The default implementation of this method assumes that the + /// `Filter`'s [`enabled`] method _may_ perform dynamic filtering, and + /// returns [`Interest::sometimes()`][sometimes], to ensure that [`enabled`] + /// is called to determine whether a particular _instance_ of the callsite + /// is enabled in the current context. If this is *not* the case, and the + /// `Filter`'s [`enabled`] method will always return the same result + /// for a particular [`Metadata`], this method can be overridden as + /// follows: + /// + /// ``` + /// use tracing_subscriber::subscribe; + /// use tracing_core::{Metadata, collect::Interest}; + /// + /// struct MyFilter { + /// // ... + /// } + /// + /// impl MyFilter { + /// // The actual logic for determining whether a `Metadata` is enabled + /// // must be factored out from the `enabled` method, so that it can be + /// // called without a `Context` (which is not provided to the + /// // `callsite_enabled` method). + /// fn is_enabled(&self, metadata: &Metadata<'_>) -> bool { + /// // ... + /// # drop(metadata); true + /// } + /// } + /// + /// impl subscribe::Filter for MyFilter { + /// fn enabled(&self, metadata: &Metadata<'_>, _: &subscribe::Context<'_, C>) -> bool { + /// // Even though we are implementing `callsite_enabled`, we must still provide a + /// // working implementation of `enabled`, as returning `Interest::always()` or + /// // `Interest::never()` will *allow* caching, but will not *guarantee* it. + /// // Other filters may still return `Interest::sometimes()`, so we may be + /// // asked again in `enabled`. + /// self.is_enabled(metadata) + /// } + /// + /// fn callsite_enabled(&self, metadata: &'static Metadata<'static>) -> Interest { + /// // The result of `self.enabled(metadata, ...)` will always be + /// // the same for any given `Metadata`, so we can convert it into + /// // an `Interest`: + /// if self.is_enabled(metadata) { + /// Interest::always() + /// } else { + /// Interest::never() + /// } + /// } + /// } + /// ``` + /// + /// [`Metadata`]: tracing_core::Metadata + /// [`Interest`]: tracing_core::Interest + /// [always]: tracing_core::Interest::always + /// [sometimes]: tracing_core::Interest::sometimes + /// [never]: tracing_core::Interest::never + /// [`Collect::register_callsite`]: tracing_core::Collect::register_callsite + /// [`Collect`]: tracing_core::Collect + /// [`enabled`]: Filter::enabled + /// [`Filtered`]: crate::filter::Filtered + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + let _ = meta; + Interest::sometimes() + } + + /// Returns an optional hint of the highest [verbosity level][level] that + /// this `Filter` will enable. + /// + /// If this method returns a [`LevelFilter`], it will be used as a hint to + /// determine the most verbose level that will be enabled. This will allow + /// spans and events which are more verbose than that level to be skipped + /// more efficiently. An implementation of this method is optional, but + /// strongly encouraged. + /// + /// If the maximum level the `Filter` will enable can change over the + /// course of its lifetime, it is free to return a different value from + /// multiple invocations of this method. However, note that changes in the + /// maximum level will **only** be reflected after the callsite [`Interest`] + /// cache is rebuilt, by calling the + /// [`tracing_core::callsite::rebuild_interest_cache`][rebuild] function. + /// Therefore, if the `Filter will change the value returned by this + /// method, it is responsible for ensuring that + /// [`rebuild_interest_cache`][rebuild] is called after the value of the max + /// level changes. + /// + /// ## Default Implementation + /// + /// By default, this method returns `None`, indicating that the maximum + /// level is unknown. + /// + /// [level]: tracing_core::metadata::Level + /// [`LevelFilter`]: crate::filter::LevelFilter + /// [`Interest`]: tracing_core::collect::Interest + /// [rebuild]: tracing_core::callsite::rebuild_interest_cache + fn max_level_hint(&self) -> Option { + None + } +} + +/// Extension trait adding a `with(Subscribe)` combinator to types implementing +/// [`Collect`]. +pub trait CollectExt: Collect + crate::sealed::Sealed { + /// Wraps `self` with the provided `subscriber`. + fn with(self, subscriber: S) -> Layered + where + S: Subscribe, + Self: Sized, + { + subscriber.with_collector(self) + } +} +/// A subscriber that does nothing. +#[derive(Clone, Debug, Default)] +pub struct Identity { + _p: (), +} + +// === impl Subscribe === + +impl Subscribe for Option +where + S: Subscribe, + C: Collect, +{ + fn on_subscribe(&mut self, collector: &mut C) { + if let Some(ref mut subscriber) = self { + subscriber.on_subscribe(collector) + } + } + + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_new_span(attrs, id, ctx) + } + } + + #[inline] + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + match self { + Some(ref inner) => inner.register_callsite(metadata), + None => Interest::always(), + } + } + + #[inline] + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + match self { + Some(ref inner) => inner.enabled(metadata, ctx), + None => true, + } + } + + #[inline] + fn max_level_hint(&self) -> Option { + match self { + Some(ref inner) => inner.max_level_hint(), + None => None, + } + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_record(span, values, ctx); + } + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_follows_from(span, follows, ctx); + } + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_event(event, ctx); + } + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_enter(id, ctx); + } + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_exit(id, ctx); + } + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_close(id, ctx); + } + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_id_change(old, new, ctx) + } + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + if id == TypeId::of::() { + Some(NonNull::from(self).cast()) + } else { + self.as_ref().and_then(|inner| inner.downcast_raw(id)) + } + } +} + +macro_rules! subscriber_impl_body { + () => { + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + self.deref().on_new_span(attrs, id, ctx) + } + + #[inline] + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.deref().register_callsite(metadata) + } + + #[inline] + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + self.deref().enabled(metadata, ctx) + } + + #[inline] + fn max_level_hint(&self) -> Option { + self.deref().max_level_hint() + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { + self.deref().on_record(span, values, ctx) + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { + self.deref().on_follows_from(span, follows, ctx) + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + self.deref().on_event(event, ctx) + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { + self.deref().on_enter(id, ctx) + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { + self.deref().on_exit(id, ctx) + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { + self.deref().on_close(id, ctx) + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { + self.deref().on_id_change(old, new, ctx) + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + self.deref().downcast_raw(id) + } + }; +} + +impl Subscribe for Arc +where + S: Subscribe, + C: Collect, +{ + subscriber_impl_body! {} +} + +impl Subscribe for Arc> +where + C: Collect, +{ + subscriber_impl_body! {} +} + +impl Subscribe for Box +where + S: Subscribe, + C: Collect, +{ + subscriber_impl_body! {} +} + +impl Subscribe for Box> +where + C: Collect, +{ + subscriber_impl_body! {} +} + +// === impl CollectExt === + +impl crate::sealed::Sealed for C {} +impl CollectExt for C {} + +// === impl Identity === + +impl Subscribe for Identity {} + +impl Identity { + /// Returns a new `Identity` subscriber. + pub fn new() -> Self { + Self { _p: () } + } +} diff --git a/tracing-subscriber/src/subscribe/tests.rs b/tracing-subscriber/src/subscribe/tests.rs new file mode 100644 index 0000000..1d08811 --- /dev/null +++ b/tracing-subscriber/src/subscribe/tests.rs @@ -0,0 +1,328 @@ +use super::*; + +pub(crate) struct NopCollector; + +impl Collect for NopCollector { + fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + Interest::never() + } + + fn enabled(&self, _: &Metadata<'_>) -> bool { + false + } + + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, _: &Event<'_>) {} + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} + fn current_span(&self) -> span::Current { + span::Current::unknown() + } +} + +#[derive(Debug)] +pub(crate) struct NopSubscriber; +impl Subscribe for NopSubscriber {} + +#[allow(dead_code)] +struct NopSubscriber2; +impl Subscribe for NopSubscriber2 {} + +/// A subscriber that holds a string. +/// +/// Used to test that pointers returned by downcasting are actually valid. +struct StringSubscriber(String); +impl Subscribe for StringSubscriber {} +struct StringSubscriber2(String); +impl Subscribe for StringSubscriber2 {} + +struct StringSubscriber3(String); +impl Subscribe for StringSubscriber3 {} + +pub(crate) struct StringCollector(String); + +impl Collect for StringCollector { + fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + Interest::never() + } + + fn enabled(&self, _: &Metadata<'_>) -> bool { + false + } + + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, _: &Event<'_>) {} + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} + + fn current_span(&self) -> span::Current { + todo!() + } +} + +fn assert_collector(_s: impl Collect) {} + +#[test] +fn subscriber_is_collector() { + let s = NopSubscriber.with_collector(NopCollector); + assert_collector(s) +} + +#[test] +fn two_subscribers_are_collector() { + let s = NopSubscriber + .and_then(NopSubscriber) + .with_collector(NopCollector); + assert_collector(s) +} + +#[test] +fn three_subscribers_are_collector() { + let s = NopSubscriber + .and_then(NopSubscriber) + .and_then(NopSubscriber) + .with_collector(NopCollector); + assert_collector(s) +} + +#[test] +fn downcasts_to_collector() { + let s = NopSubscriber + .and_then(NopSubscriber) + .and_then(NopSubscriber) + .with_collector(StringCollector("collector".into())); + let collector = + ::downcast_ref::(&s).expect("collector should downcast"); + assert_eq!(&collector.0, "collector"); +} + +#[test] +fn downcasts_to_subscriber() { + let s = StringSubscriber("subscriber_1".into()) + .and_then(StringSubscriber2("subscriber_2".into())) + .and_then(StringSubscriber3("subscriber_3".into())) + .with_collector(NopCollector); + let subscriber = + ::downcast_ref::(&s).expect("subscriber 1 should downcast"); + assert_eq!(&subscriber.0, "subscriber_1"); + let subscriber = + ::downcast_ref::(&s).expect("subscriber 2 should downcast"); + assert_eq!(&subscriber.0, "subscriber_2"); + let subscriber = + ::downcast_ref::(&s).expect("subscriber 3 should downcast"); + assert_eq!(&subscriber.0, "subscriber_3"); +} + +#[cfg(feature = "registry")] +mod registry_tests { + use super::*; + use crate::registry::LookupSpan; + + #[test] + fn context_event_span() { + use std::sync::{Arc, Mutex}; + let last_event_span = Arc::new(Mutex::new(None)); + + struct RecordingSubscriber { + last_event_span: Arc>>, + } + + impl Subscribe for RecordingSubscriber + where + C: Collect + for<'lookup> LookupSpan<'lookup>, + { + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + let span = ctx.event_span(event); + *self.last_event_span.lock().unwrap() = span.map(|s| s.name()); + } + } + + tracing::collect::with_default( + crate::registry().with(RecordingSubscriber { + last_event_span: last_event_span.clone(), + }), + || { + tracing::info!("no span"); + assert_eq!(*last_event_span.lock().unwrap(), None); + + let parent = tracing::info_span!("explicit"); + tracing::info!(parent: &parent, "explicit span"); + assert_eq!(*last_event_span.lock().unwrap(), Some("explicit")); + + let _guard = tracing::info_span!("contextual").entered(); + tracing::info!("contextual span"); + assert_eq!(*last_event_span.lock().unwrap(), Some("contextual")); + }, + ); + } + + /// Tests for how max-level hints are calculated when combining subscribers + /// with and without per-subscriber filtering. + mod max_level_hints { + + use super::*; + use crate::filter::*; + + #[test] + fn mixed_with_unfiltered() { + let collector = crate::registry() + .with(NopSubscriber) + .with(NopSubscriber.with_filter(LevelFilter::INFO)); + assert_eq!(collector.max_level_hint(), None); + } + + #[test] + fn mixed_with_unfiltered_layered() { + let collector = crate::registry().with(NopSubscriber).with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber.with_filter(LevelFilter::TRACE)), + ); + assert_eq!(dbg!(collector).max_level_hint(), None); + } + + #[test] + fn mixed_interleaved() { + let collector = crate::registry() + .with(NopSubscriber) + .with(NopSubscriber.with_filter(LevelFilter::INFO)) + .with(NopSubscriber) + .with(NopSubscriber.with_filter(LevelFilter::INFO)); + assert_eq!(dbg!(collector).max_level_hint(), None); + } + + #[test] + fn mixed_layered() { + let collector = crate::registry() + .with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber), + ) + .with(NopSubscriber.and_then(NopSubscriber.with_filter(LevelFilter::INFO))); + assert_eq!(dbg!(collector).max_level_hint(), None); + } + + #[test] + fn psf_only_unhinted() { + let collector = crate::registry() + .with(NopSubscriber.with_filter(LevelFilter::INFO)) + .with(NopSubscriber.with_filter(filter_fn(|_| true))); + assert_eq!(dbg!(collector).max_level_hint(), None); + } + + #[test] + fn psf_only_unhinted_nested_outer() { + // if a nested tree of per-subscriber filters has an _outer_ filter with + // no max level hint, it should return `None`. + let collector = crate::registry() + .with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber.with_filter(LevelFilter::WARN)), + ) + .with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(LevelFilter::DEBUG)), + ); + assert_eq!(dbg!(collector).max_level_hint(), None); + } + + #[test] + fn psf_only_unhinted_nested_inner() { + // If a nested tree of per-subscriber filters has an _inner_ filter with + // no max-level hint, but the _outer_ filter has a max level hint, + // it should pick the outer hint. This is because the outer filter + // will disable the spans/events before they make it to the inner + // filter. + let collector = dbg!(crate::registry().with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::INFO), + )); + assert_eq!(dbg!(collector).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn unhinted_nested_inner() { + let collector = dbg!(crate::registry() + .with( + NopSubscriber + .and_then(NopSubscriber) + .with_filter(LevelFilter::INFO) + ) + .with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::WARN), + )); + assert_eq!(dbg!(collector).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn unhinted_nested_inner_mixed() { + let collector = dbg!(crate::registry() + .with( + NopSubscriber + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::INFO) + ) + .with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::WARN), + )); + assert_eq!(dbg!(collector).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn psf_only_picks_max() { + let collector = crate::registry() + .with(NopSubscriber.with_filter(LevelFilter::WARN)) + .with(NopSubscriber.with_filter(LevelFilter::DEBUG)); + assert_eq!(dbg!(collector).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn many_psf_only_picks_max() { + let collector = crate::registry() + .with(NopSubscriber.with_filter(LevelFilter::WARN)) + .with(NopSubscriber.with_filter(LevelFilter::DEBUG)) + .with(NopSubscriber.with_filter(LevelFilter::INFO)) + .with(NopSubscriber.with_filter(LevelFilter::ERROR)); + assert_eq!(dbg!(collector).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn nested_psf_only_picks_max() { + let collector = crate::registry() + .with( + NopSubscriber.with_filter(LevelFilter::INFO).and_then( + NopSubscriber + .with_filter(LevelFilter::WARN) + .and_then(NopSubscriber.with_filter(LevelFilter::DEBUG)), + ), + ) + .with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber.with_filter(LevelFilter::ERROR)), + ); + assert_eq!(dbg!(collector).max_level_hint(), Some(LevelFilter::DEBUG)); + } + } +} diff --git a/tracing-subscriber/tests/cached_subscriber_filters_dont_break_other_subscribers.rs b/tracing-subscriber/tests/cached_subscriber_filters_dont_break_other_subscribers.rs new file mode 100644 index 0000000..3c538fa --- /dev/null +++ b/tracing-subscriber/tests/cached_subscriber_filters_dont_break_other_subscribers.rs @@ -0,0 +1,123 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::Level; +use tracing_subscriber::{filter::LevelFilter, prelude::*}; + +#[test] +fn subscriber_filters() { + let (unfiltered, unfiltered_handle) = unfiltered("unfiltered"); + let (filtered, filtered_handle) = filtered("filtered"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered.with_filter(filter())) + .set_default(); + + events(); + + unfiltered_handle.assert_finished(); + filtered_handle.assert_finished(); +} + +#[test] +fn layered_subscriber_filters() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let unfiltered = unfiltered1.and_then(unfiltered2); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + let filtered = filtered1 + .with_filter(filter()) + .and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn out_of_order() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered1) + .with(filtered1.with_filter(filter())) + .with(unfiltered2) + .with(filtered2.with_filter(filter())) + .set_default(); + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn mixed_layered() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let layered1 = filtered1.with_filter(filter()).and_then(unfiltered1); + let layered2 = unfiltered2.and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(layered1) + .with(layered2) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); +} + +fn filter() -> LevelFilter { + LevelFilter::INFO +} + +fn unfiltered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle() +} + +fn filtered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle() +} diff --git a/tracing-subscriber/tests/hinted_subscriber_filters_dont_break_other_subscribers.rs b/tracing-subscriber/tests/hinted_subscriber_filters_dont_break_other_subscribers.rs new file mode 100644 index 0000000..e1c3c84 --- /dev/null +++ b/tracing-subscriber/tests/hinted_subscriber_filters_dont_break_other_subscribers.rs @@ -0,0 +1,131 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::{Collect, Level, Metadata}; +use tracing_subscriber::{filter::DynFilterFn, prelude::*, subscribe::Context}; + +#[test] +fn subscriber_filters() { + let (unfiltered, unfiltered_handle) = unfiltered("unfiltered"); + let (filtered, filtered_handle) = filtered("filtered"); + + let subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered.with_filter(filter())); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered_handle.assert_finished(); + filtered_handle.assert_finished(); +} + +#[test] +fn layered_subscriber_filters() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let unfiltered = unfiltered1.and_then(unfiltered2); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + let filtered = filtered1 + .with_filter(filter()) + .and_then(filtered2.with_filter(filter())); + + let subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn out_of_order() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let subscriber = tracing_subscriber::registry() + .with(unfiltered1) + .with(filtered1.with_filter(filter())) + .with(unfiltered2) + .with(filtered2.with_filter(filter())); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn mi() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let layered1 = filtered1.with_filter(filter()).and_then(unfiltered1); + let layered2 = unfiltered2.and_then(filtered2.with_filter(filter())); + + let subscriber = tracing_subscriber::registry().with(layered1).with(layered2); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); +} + +fn filter() -> DynFilterFn { + DynFilterFn::new( + (|metadata: &Metadata<'_>, _: &tracing_subscriber::subscribe::Context<'_, S>| { + metadata.level() <= &Level::INFO + }) as fn(&Metadata<'_>, &Context<'_, S>) -> bool, + ) + .with_max_level_hint(Level::INFO) +} + +fn unfiltered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle() +} + +fn filtered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle() +} diff --git a/tracing-subscriber/tests/multiple_subscriber_filter_interests_cached.rs b/tracing-subscriber/tests/multiple_subscriber_filter_interests_cached.rs new file mode 100644 index 0000000..8088fbb --- /dev/null +++ b/tracing-subscriber/tests/multiple_subscriber_filter_interests_cached.rs @@ -0,0 +1,131 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; + +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, +}; +use tracing::{Collect, Level}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn multiple_subscriber_filter_interests_are_cached() { + // This subscriber will return Interest::always for INFO and lower. + let seen_info = Arc::new(Mutex::new(HashMap::new())); + let seen_info2 = seen_info.clone(); + let filter = filter::filter_fn(move |meta| { + *seen_info + .lock() + .unwrap() + .entry(*meta.level()) + .or_insert(0usize) += 1; + meta.level() <= &Level::INFO + }); + let seen_info = seen_info2; + + let (info_subscriber, info_handle) = subscriber::named("info") + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + let info_subscriber = info_subscriber.with_filter(filter); + + // This subscriber will return Interest::always for WARN and lower. + let seen_warn = Arc::new(Mutex::new(HashMap::new())); + let seen_warn2 = seen_warn.clone(); + let filter = filter::filter_fn(move |meta| { + *seen_warn + .lock() + .unwrap() + .entry(*meta.level()) + .or_insert(0usize) += 1; + meta.level() <= &Level::WARN + }); + let seen_warn = seen_warn2; + + let (warn_subscriber, warn_handle) = subscriber::named("warn") + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + let warn_subscriber = warn_subscriber.with_filter(filter); + + let subscriber = tracing_subscriber::registry() + .with(warn_subscriber) + .with(info_subscriber); + assert!(subscriber.max_level_hint().is_none()); + + let _subscriber = subscriber.set_default(); + + fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + } + + events(); + { + let lock = seen_info.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the INFO subscriber (after first set of events)", + level + ); + } + + let lock = seen_warn.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the WARN subscriber (after first set of events)", + level + ); + } + } + + events(); + { + let lock = seen_info.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the INFO subscriber (after second set of events)", + level + ); + } + + let lock = seen_warn.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the WARN subscriber (after second set of events)", + level + ); + } + } + + info_handle.assert_finished(); + warn_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/subscriber_filter_interests_are_cached.rs b/tracing-subscriber/tests/subscriber_filter_interests_are_cached.rs new file mode 100644 index 0000000..647d170 --- /dev/null +++ b/tracing-subscriber/tests/subscriber_filter_interests_are_cached.rs @@ -0,0 +1,69 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; + +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, +}; +use tracing::{Collect, Level}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn subscriber_filter_interests_are_cached() { + let seen = Arc::new(Mutex::new(HashMap::new())); + let seen2 = seen.clone(); + let filter = filter::filter_fn(move |meta| { + *seen + .lock() + .unwrap() + .entry(meta.callsite()) + .or_insert(0usize) += 1; + meta.level() == &Level::INFO + }); + + let (expect, handle) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let subscriber = tracing_subscriber::registry().with(expect.with_filter(filter)); + assert!(subscriber.max_level_hint().is_none()); + + let _subscriber = subscriber.set_default(); + + fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + } + + events(); + { + let lock = seen2.lock().unwrap(); + for (callsite, &count) in lock.iter() { + assert_eq!( + count, 1, + "callsite {:?} should have been seen 1 time (after first set of events)", + callsite + ); + } + } + + events(); + { + let lock = seen2.lock().unwrap(); + for (callsite, &count) in lock.iter() { + assert_eq!( + count, 1, + "callsite {:?} should have been seen 1 time (after second set of events)", + callsite + ); + } + } + + handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/subscriber_filters/combinators.rs b/tracing-subscriber/tests/subscriber_filters/combinators.rs new file mode 100644 index 0000000..7cc84d8 --- /dev/null +++ b/tracing-subscriber/tests/subscriber_filters/combinators.rs @@ -0,0 +1,42 @@ +use super::*; +use tracing_subscriber::{ + filter::{filter_fn, FilterExt, LevelFilter}, + prelude::*, +}; + +#[test] +fn and() { + let (subscriber, handle) = subscriber::mock() + .event( + event::msg("a very interesting event") + .at_level(tracing::Level::INFO) + .with_target("interesting_target"), + ) + .done() + .run_with_handle(); + + // Enables spans and events with targets starting with `interesting_target`: + let target_filter = filter::filter_fn(|meta| meta.target().starts_with("interesting_target")); + + // Enables spans and events with levels `INFO` and below: + let level_filter = LevelFilter::INFO; + + // Combine the two filters together, returning a filter that only enables + // spans and events that *both* filters will enable: + let filter = target_filter.and(level_filter); + + let _subscriber = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + // This event will *not* be enabled: + tracing::info!("an event with an uninteresting target"); + + // This event *will* be enabled: + tracing::info!(target: "interesting_target", "a very interesting event"); + + // This event will *not* be enabled: + tracing::debug!(target: "interesting_target", "interesting debug event..."); + + handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/subscriber_filters/filter_scopes.rs b/tracing-subscriber/tests/subscriber_filters/filter_scopes.rs new file mode 100644 index 0000000..710d267 --- /dev/null +++ b/tracing-subscriber/tests/subscriber_filters/filter_scopes.rs @@ -0,0 +1,131 @@ +use super::*; + +#[test] +fn filters_span_scopes() { + let (debug_subscriber, debug_handle) = subscriber::named("debug") + .enter(span::mock().at_level(Level::DEBUG)) + .enter(span::mock().at_level(Level::INFO)) + .enter(span::mock().at_level(Level::WARN)) + .enter(span::mock().at_level(Level::ERROR)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().at_level(Level::ERROR), + span::mock().at_level(Level::WARN), + span::mock().at_level(Level::INFO), + span::mock().at_level(Level::DEBUG), + ])) + .exit(span::mock().at_level(Level::ERROR)) + .exit(span::mock().at_level(Level::WARN)) + .exit(span::mock().at_level(Level::INFO)) + .exit(span::mock().at_level(Level::DEBUG)) + .done() + .run_with_handle(); + let (info_subscriber, info_handle) = subscriber::named("info") + .enter(span::mock().at_level(Level::INFO)) + .enter(span::mock().at_level(Level::WARN)) + .enter(span::mock().at_level(Level::ERROR)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().at_level(Level::ERROR), + span::mock().at_level(Level::WARN), + span::mock().at_level(Level::INFO), + ])) + .exit(span::mock().at_level(Level::ERROR)) + .exit(span::mock().at_level(Level::WARN)) + .exit(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + let (warn_subscriber, warn_handle) = subscriber::named("warn") + .enter(span::mock().at_level(Level::WARN)) + .enter(span::mock().at_level(Level::ERROR)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().at_level(Level::ERROR), + span::mock().at_level(Level::WARN), + ])) + .exit(span::mock().at_level(Level::ERROR)) + .exit(span::mock().at_level(Level::WARN)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(debug_subscriber.with_filter(LevelFilter::DEBUG)) + .with(info_subscriber.with_filter(LevelFilter::INFO)) + .with(warn_subscriber.with_filter(LevelFilter::WARN)) + .set_default(); + + { + let _trace = tracing::trace_span!("my_span").entered(); + let _debug = tracing::debug_span!("my_span").entered(); + let _info = tracing::info_span!("my_span").entered(); + let _warn = tracing::warn_span!("my_span").entered(); + let _error = tracing::error_span!("my_span").entered(); + tracing::error!("hello world"); + } + + debug_handle.assert_finished(); + info_handle.assert_finished(); + warn_handle.assert_finished(); +} + +#[test] +fn filters_interleaved_span_scopes() { + fn target_subscriber(target: &'static str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(format!("target_{}", target)) + .enter(span::mock().with_target(target)) + .enter(span::mock().with_target(target)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().with_target(target), + span::mock().with_target(target), + ])) + .event( + event::msg("hello to my target") + .in_scope(vec![ + span::mock().with_target(target), + span::mock().with_target(target), + ]) + .with_target(target), + ) + .exit(span::mock().with_target(target)) + .exit(span::mock().with_target(target)) + .done() + .run_with_handle() + } + + let (a_subscriber, a_handle) = target_subscriber("a"); + let (b_subscriber, b_handle) = target_subscriber("b"); + let (all_subscriber, all_handle) = subscriber::named("all") + .enter(span::mock().with_target("b")) + .enter(span::mock().with_target("a")) + .event(event::msg("hello world").in_scope(vec![ + span::mock().with_target("a"), + span::mock().with_target("b"), + ])) + .exit(span::mock().with_target("a")) + .exit(span::mock().with_target("b")) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(all_subscriber.with_filter(LevelFilter::INFO)) + .with(a_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "a" || target == module_path!() + }))) + .with(b_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "b" || target == module_path!() + }))) + .set_default(); + + { + let _a1 = tracing::trace_span!(target: "a", "a/trace").entered(); + let _b1 = tracing::info_span!(target: "b", "b/info").entered(); + let _a2 = tracing::info_span!(target: "a", "a/info").entered(); + let _b2 = tracing::trace_span!(target: "b", "b/trace").entered(); + tracing::info!("hello world"); + tracing::debug!(target: "a", "hello to my target"); + tracing::debug!(target: "b", "hello to my target"); + } + + a_handle.assert_finished(); + b_handle.assert_finished(); + all_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/subscriber_filters/main.rs b/tracing-subscriber/tests/subscriber_filters/main.rs new file mode 100644 index 0000000..a61b8ff --- /dev/null +++ b/tracing-subscriber/tests/subscriber_filters/main.rs @@ -0,0 +1,185 @@ +#![cfg(feature = "registry")] +#[path = "../support.rs"] +mod support; +use self::support::*; +mod filter_scopes; +mod trees; + +use tracing::{level_filters::LevelFilter, Level}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn basic_subscriber_filters() { + let (trace_subscriber, trace_handle) = subscriber::named("trace") + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (debug_subscriber, debug_handle) = subscriber::named("debug") + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (info_subscriber, info_handle) = subscriber::named("info") + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(trace_subscriber.with_filter(LevelFilter::TRACE)) + .with(debug_subscriber.with_filter(LevelFilter::DEBUG)) + .with(info_subscriber.with_filter(LevelFilter::INFO)) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + + trace_handle.assert_finished(); + debug_handle.assert_finished(); + info_handle.assert_finished(); +} + +#[test] +fn basic_subscriber_filters_spans() { + let (trace_subscriber, trace_handle) = subscriber::named("trace") + .new_span(span::mock().at_level(Level::TRACE)) + .new_span(span::mock().at_level(Level::DEBUG)) + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (debug_subscriber, debug_handle) = subscriber::named("debug") + .new_span(span::mock().at_level(Level::DEBUG)) + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (info_subscriber, info_handle) = subscriber::named("info") + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(trace_subscriber.with_filter(LevelFilter::TRACE)) + .with(debug_subscriber.with_filter(LevelFilter::DEBUG)) + .with(info_subscriber.with_filter(LevelFilter::INFO)) + .set_default(); + + tracing::trace_span!("hello trace"); + tracing::debug_span!("hello debug"); + tracing::info_span!("hello info"); + + trace_handle.assert_finished(); + debug_handle.assert_finished(); + info_handle.assert_finished(); +} + +#[test] +fn global_filters_subscribers_still_work() { + let (expect, handle) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(expect) + .with(LevelFilter::INFO) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} + +#[test] +fn global_filter_interests_are_cached() { + let (expect, handle) = subscriber::mock() + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(expect.with_filter(filter::filter_fn(|meta| { + assert!( + meta.level() <= &Level::INFO, + "enabled should not be called for callsites disabled by the global filter" + ); + meta.level() <= &Level::WARN + }))) + .with(LevelFilter::INFO) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} + +#[test] +fn global_filters_affect_subscriber_filters() { + let (expect, handle) = subscriber::named("debug") + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(expect.with_filter(LevelFilter::DEBUG)) + .with(LevelFilter::INFO) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} + +#[test] +fn filter_fn() { + let (all, all_handle) = subscriber::named("all_targets") + .event(event::msg("hello foo")) + .event(event::msg("hello bar")) + .done() + .run_with_handle(); + + let (foo, foo_handle) = subscriber::named("foo_target") + .event(event::msg("hello foo")) + .done() + .run_with_handle(); + + let (bar, bar_handle) = subscriber::named("bar_target") + .event(event::msg("hello bar")) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(all) + .with(foo.with_filter(filter::filter_fn(|meta| meta.target().starts_with("foo")))) + .with(bar.with_filter(filter::filter_fn(|meta| meta.target().starts_with("bar")))) + .set_default(); + + tracing::trace!(target: "foo", "hello foo"); + tracing::trace!(target: "bar", "hello bar"); + + foo_handle.assert_finished(); + bar_handle.assert_finished(); + all_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/subscriber_filters/trees.rs b/tracing-subscriber/tests/subscriber_filters/trees.rs new file mode 100644 index 0000000..3332045 --- /dev/null +++ b/tracing-subscriber/tests/subscriber_filters/trees.rs @@ -0,0 +1,146 @@ +use super::*; + +#[test] +fn basic_trees() { + let (with_target, with_target_handle) = subscriber::named("info_with_target") + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .done() + .run_with_handle(); + + let (info, info_handle) = subscriber::named("info") + .event( + event::mock() + .at_level(Level::INFO) + .with_target(module_path!()), + ) + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .done() + .run_with_handle(); + + let (all, all_handle) = subscriber::named("all") + .event( + event::mock() + .at_level(Level::INFO) + .with_target(module_path!()), + ) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .event( + event::mock() + .at_level(Level::TRACE) + .with_target("my_target"), + ) + .done() + .run_with_handle(); + + let info_tree = info + .and_then( + with_target.with_filter(filter::filter_fn(|meta| dbg!(meta.target()) == "my_target")), + ) + .with_filter(LevelFilter::INFO); + + let subscriber = tracing_subscriber::registry().with(info_tree).with(all); + let _guard = dbg!(subscriber).set_default(); + + tracing::info!("hello world"); + tracing::trace!("hello trace"); + tracing::info!(target: "my_target", "hi to my target"); + tracing::trace!(target: "my_target", "hi to my target at trace"); + + all_handle.assert_finished(); + info_handle.assert_finished(); + with_target_handle.assert_finished(); +} + +#[test] +fn filter_span_scopes() { + fn target_subscriber(target: &'static str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(format!("target_{}", target)) + .enter(span::mock().with_target(target).at_level(Level::INFO)) + .event( + event::msg("hello world") + .in_scope(vec![span::mock().with_target(target).at_level(Level::INFO)]), + ) + .exit(span::mock().with_target(target).at_level(Level::INFO)) + .done() + .run_with_handle() + } + + let (a_subscriber, a_handle) = target_subscriber("a"); + let (b_subscriber, b_handle) = target_subscriber("b"); + let (info_subscriber, info_handle) = subscriber::named("info") + .enter(span::mock().with_target("b").at_level(Level::INFO)) + .enter(span::mock().with_target("a").at_level(Level::INFO)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().with_target("a").at_level(Level::INFO), + span::mock().with_target("b").at_level(Level::INFO), + ])) + .exit(span::mock().with_target("a").at_level(Level::INFO)) + .exit(span::mock().with_target("b").at_level(Level::INFO)) + .done() + .run_with_handle(); + + let full_scope = vec![ + span::mock().with_target("b").at_level(Level::TRACE), + span::mock().with_target("a").at_level(Level::INFO), + span::mock().with_target("b").at_level(Level::INFO), + span::mock().with_target("a").at_level(Level::TRACE), + ]; + let (all_subscriber, all_handle) = subscriber::named("all") + .enter(span::mock().with_target("a").at_level(Level::TRACE)) + .enter(span::mock().with_target("b").at_level(Level::INFO)) + .enter(span::mock().with_target("a").at_level(Level::INFO)) + .enter(span::mock().with_target("b").at_level(Level::TRACE)) + .event(event::msg("hello world").in_scope(full_scope.clone())) + .event( + event::msg("hello to my target") + .with_target("a") + .in_scope(full_scope.clone()), + ) + .event( + event::msg("hello to my target") + .with_target("b") + .in_scope(full_scope), + ) + .exit(span::mock().with_target("b").at_level(Level::TRACE)) + .exit(span::mock().with_target("a").at_level(Level::INFO)) + .exit(span::mock().with_target("b").at_level(Level::INFO)) + .exit(span::mock().with_target("a").at_level(Level::TRACE)) + .done() + .run_with_handle(); + + let a_subscriber = a_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "a" || target == module_path!() + })); + + let b_subscriber = b_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "b" || target == module_path!() + })); + + let info_tree = info_subscriber + .and_then(a_subscriber) + .and_then(b_subscriber) + .with_filter(LevelFilter::INFO); + + let subscriber = tracing_subscriber::registry() + .with(info_tree) + .with(all_subscriber); + let _guard = dbg!(subscriber).set_default(); + + { + let _a1 = tracing::trace_span!(target: "a", "a/trace").entered(); + let _b1 = tracing::info_span!(target: "b", "b/info").entered(); + let _a2 = tracing::info_span!(target: "a", "a/info").entered(); + let _b2 = tracing::trace_span!(target: "b", "b/trace").entered(); + tracing::info!("hello world"); + tracing::debug!(target: "a", "hello to my target"); + tracing::debug!(target: "b", "hello to my target"); + } + + all_handle.assert_finished(); + info_handle.assert_finished(); + a_handle.assert_finished(); + b_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/support.rs b/tracing-subscriber/tests/support.rs new file mode 100644 index 0000000..fab742b --- /dev/null +++ b/tracing-subscriber/tests/support.rs @@ -0,0 +1,407 @@ +#![allow(missing_docs, dead_code)] +pub use tracing_mock::{collector, event, field, span}; + +use self::{ + collector::{Expect, MockHandle}, + event::MockEvent, + span::{MockSpan, NewSpan}, +}; +use tracing_core::{ + span::{Attributes, Id, Record}, + Collect, Event, +}; +use tracing_subscriber::{ + registry::{LookupSpan, SpanRef}, + subscribe::{Context, Subscribe}, +}; + +use std::{ + collections::VecDeque, + fmt, + sync::{Arc, Mutex}, +}; + +pub mod subscriber { + use super::ExpectSubscriberBuilder; + + pub fn mock() -> ExpectSubscriberBuilder { + ExpectSubscriberBuilder { + expected: Default::default(), + name: std::thread::current() + .name() + .map(String::from) + .unwrap_or_default(), + } + } + + pub fn named(name: impl std::fmt::Display) -> ExpectSubscriberBuilder { + mock().named(name) + } +} + +pub struct ExpectSubscriberBuilder { + expected: VecDeque, + name: String, +} + +pub struct ExpectSubscriber { + expected: Arc>>, + current: Mutex>, + name: String, +} + +impl ExpectSubscriberBuilder { + /// Overrides the name printed by the mock subscriber's debugging output. + /// + /// The debugging output is displayed if the test panics, or if the test is + /// run with `--nocapture`. + /// + /// By default, the mock subscriber's name is the name of the test + /// (*technically*, the name of the thread where it was created, which is + /// the name of the test unless tests are run with `--test-threads=1`). + /// When a test has only one mock subscriber, this is sufficient. However, + /// some tests may include multiple subscribers, in order to test + /// interactions between multiple subscribers. In that case, it can be + /// helpful to give each subscriber a separate name to distinguish where the + /// debugging output comes from. + pub fn named(mut self, name: impl fmt::Display) -> Self { + use std::fmt::Write; + if !self.name.is_empty() { + write!(&mut self.name, "::{}", name).unwrap(); + } else { + self.name = name.to_string(); + } + self + } + + pub fn enter(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::Enter(span)); + self + } + + pub fn event(mut self, event: MockEvent) -> Self { + self.expected.push_back(Expect::Event(event)); + self + } + + pub fn exit(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::Exit(span)); + self + } + + pub fn done(mut self) -> Self { + self.expected.push_back(Expect::Nothing); + self + } + + pub fn record(mut self, span: MockSpan, fields: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::Visit(span, fields.into())); + self + } + + pub fn new_span(mut self, new_span: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::NewSpan(new_span.into())); + self + } + + pub fn run(self) -> ExpectSubscriber { + ExpectSubscriber { + expected: Arc::new(Mutex::new(self.expected)), + name: self.name, + current: Mutex::new(Vec::new()), + } + } + + pub fn run_with_handle(self) -> (ExpectSubscriber, MockHandle) { + let expected = Arc::new(Mutex::new(self.expected)); + let handle = MockHandle::new(expected.clone(), self.name.clone()); + let subscriber = ExpectSubscriber { + expected, + name: self.name, + current: Mutex::new(Vec::new()), + }; + (subscriber, handle) + } +} + +impl ExpectSubscriber { + fn check_span_ref<'spans, S>( + &self, + expected: &MockSpan, + actual: &SpanRef<'spans, S>, + what_happened: impl fmt::Display, + ) where + S: LookupSpan<'spans>, + { + if let Some(exp_name) = expected.name() { + assert_eq!( + actual.name(), + exp_name, + "\n[{}] expected {} a span named {:?}\n\ + [{}] but it was named {:?} instead (span {} {:?})", + self.name, + what_happened, + exp_name, + self.name, + actual.name(), + actual.name(), + actual.id() + ); + } + + if let Some(exp_level) = expected.level() { + let actual_level = actual.metadata().level(); + assert_eq!( + actual_level, + &exp_level, + "\n[{}] expected {} a span at {:?}\n\ + [{}] but it was at {:?} instead (span {} {:?})", + self.name, + what_happened, + exp_level, + self.name, + actual_level, + actual.name(), + actual.id(), + ); + } + + if let Some(exp_target) = expected.target() { + let actual_target = actual.metadata().target(); + assert_eq!( + actual_target, + exp_target, + "\n[{}] expected {} a span with target {:?}\n\ + [{}] but it had the target {:?} instead (span {} {:?})", + self.name, + what_happened, + exp_target, + self.name, + actual_target, + actual.name(), + actual.id(), + ); + } + } +} + +impl Subscribe for ExpectSubscriber +where + C: Collect + for<'a> LookupSpan<'a>, +{ + fn register_callsite( + &self, + metadata: &'static tracing::Metadata<'static>, + ) -> tracing_core::Interest { + println!("[{}] register_callsite {:#?}", self.name, metadata); + tracing_core::Interest::always() + } + + fn on_record(&self, _: &Id, _: &Record<'_>, _: Context<'_, C>) { + unimplemented!( + "so far, we don't have any tests that need an `on_record` \ + implementation.\nif you just wrote one that does, feel free to \ + implement it!" + ); + } + + fn on_event(&self, event: &Event<'_>, cx: Context<'_, C>) { + let name = event.metadata().name(); + println!( + "[{}] event: {}; level: {}; target: {}", + self.name, + name, + event.metadata().level(), + event.metadata().target(), + ); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Event(mut expected)) => { + let get_parent_name = || cx.event_span(event).map(|span| span.name().to_string()); + expected.check(event, get_parent_name, &self.name); + let mut current_scope = cx.event_scope(event).into_iter().flatten(); + let expected_scope = expected.scope_mut(); + let mut i = 0; + for (expected, actual) in expected_scope.iter_mut().zip(&mut current_scope) { + println!( + "[{}] event_scope[{}] actual={} ({:?}); expected={}", + self.name, + i, + actual.name(), + actual.id(), + expected + ); + self.check_span_ref( + expected, + &actual, + format_args!("the {}th span in the event's scope to be", i), + ); + i += 1; + } + let remaining_expected = &expected_scope[i..]; + assert!( + remaining_expected.is_empty(), + "\n[{}] did not observe all expected spans in event scope!\n[{}] missing: {:#?}", + self.name, + self.name, + remaining_expected, + ); + assert!( + current_scope.next().is_none(), + "\n[{}] did not expect all spans in the actual event scope!", + self.name, + ); + } + Some(ex) => ex.bad(&self.name, format_args!("observed event {:#?}", event)), + } + } + + fn on_follows_from(&self, _span: &Id, _follows: &Id, _: Context<'_, C>) { + // TODO: it should be possible to expect spans to follow from other spans + } + + fn on_new_span(&self, span: &Attributes<'_>, id: &Id, cx: Context<'_, C>) { + let meta = span.metadata(); + println!( + "[{}] new_span: name={:?}; target={:?}; id={:?};", + self.name, + meta.name(), + meta.target(), + id + ); + let mut expected = self.expected.lock().unwrap(); + let was_expected = matches!(expected.front(), Some(Expect::NewSpan(_))); + if was_expected { + if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { + let get_parent_name = || { + span.parent() + .and_then(|id| cx.span(id)) + .or_else(|| cx.lookup_current()) + .map(|span| span.name().to_string()) + }; + expected.check(span, get_parent_name, &self.name); + } + } + } + + fn on_enter(&self, id: &Id, cx: Context<'_, C>) { + let span = cx + .span(id) + .unwrap_or_else(|| panic!("[{}] no span for ID {:?}", self.name, id)); + println!("[{}] enter: {}; id={:?};", self.name, span.name(), id); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Enter(ref expected_span)) => { + self.check_span_ref(expected_span, &span, "to enter"); + } + Some(ex) => ex.bad(&self.name, format_args!("entered span {:?}", span.name())), + } + self.current.lock().unwrap().push(id.clone()); + } + + fn on_exit(&self, id: &Id, cx: Context<'_, C>) { + if std::thread::panicking() { + // `exit()` can be called in `drop` impls, so we must guard against + // double panics. + println!("[{}] exit {:?} while panicking", self.name, id); + return; + } + let span = cx + .span(id) + .unwrap_or_else(|| panic!("[{}] no span for ID {:?}", self.name, id)); + println!("[{}] exit: {}; id={:?};", self.name, span.name(), id); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Exit(ref expected_span)) => { + self.check_span_ref(expected_span, &span, "to exit"); + let curr = self.current.lock().unwrap().pop(); + assert_eq!( + Some(id), + curr.as_ref(), + "[{}] exited span {:?}, but the current span was {:?}", + self.name, + span.name(), + curr.as_ref().and_then(|id| cx.span(id)).map(|s| s.name()) + ); + } + Some(ex) => ex.bad(&self.name, format_args!("exited span {:?}", span.name())), + }; + } + + fn on_close(&self, id: Id, cx: Context<'_, C>) { + if std::thread::panicking() { + // `try_close` can be called in `drop` impls, so we must guard against + // double panics. + println!("[{}] close {:?} while panicking", self.name, id); + return; + } + let span = cx.span(&id); + let name = span.as_ref().map(|span| { + println!("[{}] close_span: {}; id={:?};", self.name, span.name(), id,); + span.name() + }); + if name.is_none() { + println!("[{}] drop_span: id={:?}", self.name, id); + } + if let Ok(mut expected) = self.expected.try_lock() { + let was_expected = match expected.front() { + Some(Expect::DropSpan(ref expected_span)) => { + // Don't assert if this function was called while panicking, + // as failing the assertion can cause a double panic. + if !::std::thread::panicking() { + if let Some(ref span) = span { + self.check_span_ref(expected_span, span, "to close"); + } + } + true + } + Some(Expect::Event(_)) => { + if !::std::thread::panicking() { + panic!( + "[{}] expected an event, but dropped span {} (id={:?}) instead", + self.name, + name.unwrap_or(""), + id + ); + } + true + } + _ => false, + }; + if was_expected { + expected.pop_front(); + } + } + } + + fn on_id_change(&self, _old: &Id, _new: &Id, _ctx: Context<'_, C>) { + panic!("well-behaved subscribers should never do this to us, lol"); + } +} + +impl fmt::Debug for ExpectSubscriber { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("ExpectSubscriber"); + s.field("name", &self.name); + + if let Ok(expected) = self.expected.try_lock() { + s.field("expected", &expected); + } else { + s.field("expected", &format_args!("")); + } + + if let Ok(current) = self.current.try_lock() { + s.field("current", &format_args!("{:?}", ¤t)); + } else { + s.field("current", &format_args!("")); + } + + s.finish() + } +} diff --git a/tracing-subscriber/tests/unhinted_subscriber_filters_dont_break_other_subscribers.rs b/tracing-subscriber/tests/unhinted_subscriber_filters_dont_break_other_subscribers.rs new file mode 100644 index 0000000..725bd4c --- /dev/null +++ b/tracing-subscriber/tests/unhinted_subscriber_filters_dont_break_other_subscribers.rs @@ -0,0 +1,123 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::Level; +use tracing_subscriber::{filter::DynFilterFn, prelude::*}; + +#[test] +fn subscriber_filters() { + let (unfiltered, unfiltered_handle) = unfiltered("unfiltered"); + let (filtered, filtered_handle) = filtered("filtered"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered.with_filter(filter())) + .set_default(); + + events(); + + unfiltered_handle.assert_finished(); + filtered_handle.assert_finished(); +} + +#[test] +fn layered_subscriber_filters() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let unfiltered = unfiltered1.and_then(unfiltered2); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + let filtered = filtered1 + .with_filter(filter()) + .and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn out_of_order() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered1) + .with(filtered1.with_filter(filter())) + .with(unfiltered2) + .with(filtered2.with_filter(filter())) + .set_default(); + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn mixed_layered() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let layered1 = filtered1.with_filter(filter()).and_then(unfiltered1); + let layered2 = unfiltered2.and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(layered1) + .with(layered2) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); +} + +fn filter() -> DynFilterFn { + DynFilterFn::new(|metadata, _| metadata.level() <= &Level::INFO) +} + +fn unfiltered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle() +} + +fn filtered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle() +} diff --git a/tracing/tests/event.rs b/tracing/tests/event.rs index eeba3a0..3db6c68 100644 --- a/tracing/tests/event.rs +++ b/tracing/tests/event.rs @@ -81,12 +81,10 @@ fn message_without_delims() { field::mock("answer") .with_value(&42) .and(field::mock("question").with_value(&"life, the universe, and everything")) - .and( - field::mock("message").with_value(&tracing::field::debug(format_args!( - "hello from my event! tricky? {:?}!", - true - ))), - ) + .and(field::msg(format_args!( + "hello from my event! tricky? {:?}!", + true + ))) .only(), ), ) @@ -110,11 +108,7 @@ fn string_message_without_delims() { field::mock("answer") .with_value(&42) .and(field::mock("question").with_value(&"life, the universe, and everything")) - .and( - field::mock("message").with_value(&tracing::field::debug(format_args!( - "hello from my event" - ))), - ) + .and(field::msg(format_args!("hello from my event"))) .only(), ), ) diff --git a/tracing/tests/support/mod.rs b/tracing/tests/support/mod.rs new file mode 100644 index 0000000..cdfbfa0 --- /dev/null +++ b/tracing/tests/support/mod.rs @@ -0,0 +1,84 @@ +#![allow(dead_code)] +pub mod collector; +pub mod event; +pub mod field; +mod metadata; +pub mod span; + +#[derive(Debug, Eq, PartialEq)] +pub(in crate::support) enum Parent { + ContextualRoot, + Contextual(String), + ExplicitRoot, + Explicit(String), +} + +impl Parent { + pub(in crate::support) fn check_parent_name( + &self, + parent_name: Option<&str>, + provided_parent: Option, + ctx: impl std::fmt::Display, + collector_name: &str, + ) { + match self { + Parent::ExplicitRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to be an explicit root, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + } + Parent::Explicit(expected_parent) => { + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have explicit parent {}, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + expected_parent, + provided_parent, + parent_name, + ); + } + Parent::ContextualRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to have a contextual parent, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert!( + parent_name.is_none(), + "[{}] expected {} to be contextual a root, but we were inside span {:?}", + collector_name, + ctx, + parent_name, + ); + } + Parent::Contextual(expected_parent) => { + assert!(provided_parent.is_none(), + "[{}] expected {} to have a contextual parent\nbut its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have contextual parent {:?}, but got {:?}", + collector_name, + ctx, + expected_parent, + parent_name, + ); + } + } + } +}