diff --git a/tracing-subscriber/CHANGELOG.md b/tracing-subscriber/CHANGELOG.md index f40420f105..00dc4aa65b 100644 --- a/tracing-subscriber/CHANGELOG.md +++ b/tracing-subscriber/CHANGELOG.md @@ -1,3 +1,12 @@ +# Unreleased + +### Deprecated + +- **registry**: `SpanRef::parent_id`, which cannot properly support per-layer + filtering. Use `.parent().map(SpanRef::id)` instead. ([#1523]) + +[#1523]: https://github.com/tokio-rs/tracing/pull/1523 + # 0.2.20 (August 17, 2021) ### Fixed diff --git a/tracing-subscriber/debug.log b/tracing-subscriber/debug.log new file mode 100644 index 0000000000..c30729483a --- /dev/null +++ b/tracing-subscriber/debug.log @@ -0,0 +1,2 @@ +Sep 09 10:44:41.182 DEBUG rust_out: this is a message, and part of a system of messages +Sep 09 10:44:41.182  WARN rust_out: the message is a warning about danger! diff --git a/tracing-subscriber/src/filter/layer_filters.rs b/tracing-subscriber/src/filter/layer_filters.rs index c42b36bbc5..b39bdea575 100644 --- a/tracing-subscriber/src/filter/layer_filters.rs +++ b/tracing-subscriber/src/filter/layer_filters.rs @@ -1,39 +1,81 @@ -use super::LevelFilter; +//! ## Per-Layer Filtering +//! +//! Per-layer filters permit individual `Layer`s to have their own filter +//! configurations without interfering with other `Layer`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 `Layer` trait documentation's [per-layer filtering +//! section]][1]. +//! +//! ## How does per-layer filtering work? +//! +//! As described in the API documentation, the [`Filter`] trait defines a +//! filtering strategy for a per-layer 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 +//! [`Layer`] by the [`Filtered`] struct defined in this module. [`Filtered`] +//! implements [`Layer`] by calling into the wrapped [`Layer`], or not, based on +//! the filtering strategy. While there will be a variety of types that implement +//! [`Filter`], all actual *uses* of per-layer filtering will occur through the +//! [`Filtered`] struct. Therefore, most of the implementation details live +//! there. +//! +//! [1]: crate::layer#per-layer-filtering +//! [`Filter`]: crate::layer::Filter use crate::{ - layer::{Context, Layer}, + filter::LevelFilter, + layer::{self, Context, Layer}, registry, }; -use std::{any::type_name, cell::Cell, fmt, marker::PhantomData, thread_local}; +use std::{ + any::{type_name, TypeId}, + cell::{Cell, RefCell}, + fmt, + marker::PhantomData, + sync::Arc, + thread_local, +}; use tracing_core::{ span, subscriber::{Interest, Subscriber}, Event, Metadata, }; -/// A filter that determines whether a span or event is enabled. -pub trait Filter { - fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, S>) -> bool; - - fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { - let _ = meta; - Interest::sometimes() - } - - fn max_level_hint(&self) -> Option { - None - } -} - -#[derive(Debug, Clone)] +/// A [`Layer`] that wraps an inner [`Layer`] and adds a [`Filter`] which +/// controls what spans and events are enabled for that layer. +/// +/// This is returned by the [`Layer::with_filter`] method. See the +/// [documentation on per-layer filtering][plf] for details. +/// +/// [`Filter`]: crate::layer::Filter +/// [plf]: crate::layer#per-layer-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Clone)] pub struct Filtered { filter: F, layer: L, - id: FilterId, + id: MagicPlfDowncastMarker, _s: PhantomData, } -pub struct FilterFn< +/// A per-layer [`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-layer filtering][plf] for details. +/// +/// [span context]: crate::layer::Context +/// [`Filter`]: crate::layer::Filter +/// [plf]: crate::layer#per-layer-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub struct DynFilterFn< S, + // TODO(eliza): should these just be boxed functions? F = fn(&Metadata<'_>, &Context<'_, S>) -> bool, R = fn(&'static Metadata<'static>) -> Interest, > { @@ -43,49 +85,121 @@ pub struct FilterFn< _s: PhantomData, } -#[derive(Copy, Clone, Debug)] -pub struct FilterId(u8); +/// A per-layer [`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-layer filtering][plf] for details. +/// +/// [`Metadata`]: tracing_core::Metadata +/// [`Filter`]: crate::layer::Filter +/// [plf]: crate::layer#per-layer-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Clone)] +pub struct FilterFn) -> bool> { + enabled: F, + max_level_hint: Option, +} -#[derive(Default, Copy, Clone)] +/// Uniquely identifies an individual [`Filter`] instance in the context of +/// a [`Subscriber`]. +/// +/// When adding a [`Filtered`] [`Layer`] to a [`Subscriber`], the [`Subscriber`] +/// generates a `FilterId` for that [`Filtered`] layer. The [`Filtered`] layer +/// will then use the generated ID to query whether a particular span was +/// previously enabled by that layer's [`Filter`]. +/// +/// **Note**: Currently, the [`Registry`] type provided by this crate is the +/// **only** [`Subscriber`] implementation capable of participating in per-layer +/// 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 [`Subscriber`]s to also participate in per-layer +/// filtering. When those APIs are added, subscribers will be responsible +/// for generating and assigning `FilterId`s. +/// +/// [`Filter`]: crate::layer::Filter +/// [`Subscriber`]: tracing_core::Subscriber +/// [`Layer`]: crate::layer::Layer +/// [`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::layer::Filter +#[derive(Default, Copy, Clone, Eq, PartialEq)] pub(crate) struct FilterMap { bits: u64, } +/// The current state of `enabled` calls to per-layer 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-layer filter will +/// check its bit to determine if it disabled that event or span, and skip +/// forwarding the event or span to the inner layer if the bit is set. Once +/// a span or event has been skipped by a per-layer 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` layers to determine +/// whether they had previously disabled a given span, and avoid showing it +/// to the wrapped layer if it was disabled. +/// +/// This allows `Filtered` layers 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-layer 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-layer filters have participated in the current `enabled` + /// call? + in_filter_pass: Cell, + + /// How many per-layer filters have participated in the current `register_callsite` + /// call? + in_interest_pass: Cell, +} + thread_local! { - /// The current state of `enabled` calls to per-layer filters on this - /// thread. - /// - /// When `Filtered::enabled` is called, the filter will set the bit - /// corresponding to its ID if it will disable the event/span being - /// filtered. When the event or span is recorded, the per-layer filter will - /// check its bit to determine if it disabled that event or span, and skip - /// forwarding the event or span to the inner layer if the bit is set. Once - /// a span or event has been skipped by a per-layer filter, it unsets its - /// bit, so that the `FilterMap` has been cleared for the next set of - /// `enabled` calls. - /// - /// This 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` layers to determine - /// whether they previously disabled a given span, and avoid showing it - /// to the wrapped layer if it was disabled. - /// - /// This is the mechanism that allows `Filtered` layers 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-layer 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 we can - /// skip recording it entirely. - pub(crate) static FILTERING: Cell = Cell::new(FilterMap::default()); - pub(crate) static INTERESTING: Cell = Cell::new(Interest::never()); + pub(crate) static FILTERING: FilterState = FilterState::new(); } // === impl Filter === - -impl Filter for LevelFilter { +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +impl layer::Filter for LevelFilter { fn enabled(&self, meta: &Metadata<'_>, _: &Context<'_, S>) -> bool { meta.level() <= self } @@ -103,38 +217,80 @@ impl Filter for LevelFilter { } } +impl layer::Filter for Arc + Send + Sync + 'static> { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, S>) -> 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 layer::Filter for Box + Send + Sync + 'static> { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, S>) -> 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 [`Layer`] so that it is filtered by the given + /// [`Filter`]. + /// + /// This is equivalent to calling the [`Layer::with_filter`] method. + /// + /// See the [documentation on per-layer filtering][plf] for details. + /// + /// [`Filter`]: crate::layer::Filter + /// [plf]: crate::layer#per-layer-filtering pub fn new(layer: L, filter: F) -> Self { Self { layer, filter, - id: FilterId(255), + id: MagicPlfDowncastMarker(FilterId::disabled()), _s: PhantomData, } } - fn did_enable(&self, f: impl FnOnce()) { - FILTERING.with(|filtering| { - if filtering.get().is_enabled(self.id) { - f(); + #[inline(always)] + fn id(&self) -> FilterId { + self.id.0 + } - filtering.set(filtering.get().set(self.id, true)); - } - }) + fn did_enable(&self, f: impl FnOnce()) { + FILTERING.with(|filtering| filtering.did_enable(self.id(), f)) } } impl Layer for Filtered where S: Subscriber + for<'span> registry::LookupSpan<'span> + 'static, - F: Filter + 'static, + F: layer::Filter + 'static, L: Layer, { - fn on_register(&mut self, subscriber: &mut S) { - self.id = subscriber.register_filter(); - self.layer.on_register(subscriber); + fn on_layer(&mut self, subscriber: &mut S) { + self.id = MagicPlfDowncastMarker(subscriber.register_filter()); + self.layer.on_layer(subscriber); } // TODO(eliza): can we figure out a nice way to make the `Filtered` layer @@ -146,19 +302,60 @@ where // almsot certainly impossible...right? fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - // self.filter.callsite_enabled(metadata) - Interest::sometimes() + let interest = self.filter.callsite_enabled(metadata); + + // If the filter didn't disable the callsite, allow the inner layer to + // register it — since `register_callsite` is also used for purposes + // such as reserving/caching per-callsite data, we want the inner layer + // to be able to perform any other registration steps. However, we'll + // ignore its `Interest`. + if !interest.is_never() { + self.layer.register_callsite(metadata); + } + + // Add our `Interest` to the current sum of per-layer filter `Interest`s + // for this callsite. + FILTERING.with(|filtering| filtering.add_interest(interest)); + + // don't short circuit! if the stack consists entirely of `Layer`s with + // per-layer filters, the `Registry` will return the actual `Interest` + // value that's the sum of all the `register_callsite` calls to those + // per-layer filters. if we returned an actual `never` interest here, a + // `Layered` layer would short-circuit and not allow any `Filtered` + // layers below us if _they_ are interested in the callsite. + Interest::always() } fn enabled(&self, metadata: &Metadata<'_>, cx: Context<'_, S>) -> bool { - let enabled = self.filter.enabled(metadata, &cx.with_filter(self.id)); - FILTERING.with(|filtering| filtering.set(filtering.get().set(self.id, enabled))); - true // keep filtering + 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 layer if + // _it_ wants it --- it might have a global filter. + self.layer.enabled(metadata, cx) + } else { + // Otherwise, return `true`. The _per-layer_ filter disabled this + // metadata, but returning `false` in `Layer::enabled` will + // short-circuit and globally disable the span or event. This is + // *not* what we want for per-layer filters, as other layers may + // still want this event. Returning `true` here means we'll continue + // asking the next layer in the stack. + // + // Once all per-layer filters have been evaluated, the `Registry` + // at the root of the stack will return `false` from its `enabled` + // method if *every* per-layer filter disabled this metadata. + // Otherwise, the individual per-layer filters will skip the next + // `new_span` or `on_event` call for their layer if *they* disabled + // the span or event, but it was not globally disabled. + true + } } fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, cx: Context<'_, S>) { self.did_enable(|| { - self.layer.new_span(attrs, id, cx.with_filter(self.id)); + self.layer.new_span(attrs, id, cx.with_filter(self.id())); }) } @@ -168,64 +365,421 @@ where } fn on_record(&self, span: &span::Id, values: &span::Record<'_>, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(span, self.id) { + if let Some(cx) = cx.if_enabled_for(span, self.id()) { self.layer.on_record(span, values, cx) } } fn on_follows_from(&self, span: &span::Id, follows: &span::Id, cx: Context<'_, S>) { // 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) { + if cx.is_enabled_for(span, self.id()) && cx.is_enabled_for(follows, self.id()) { self.layer - .on_follows_from(span, follows, cx.with_filter(self.id)) + .on_follows_from(span, follows, cx.with_filter(self.id())) } } fn on_event(&self, event: &Event<'_>, cx: Context<'_, S>) { self.did_enable(|| { - self.layer.on_event(event, cx.with_filter(self.id)); + self.layer.on_event(event, cx.with_filter(self.id())); }) } fn on_enter(&self, id: &span::Id, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(id, self.id) { + if let Some(cx) = cx.if_enabled_for(id, self.id()) { self.layer.on_enter(id, cx) } } fn on_exit(&self, id: &span::Id, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(id, self.id) { + if let Some(cx) = cx.if_enabled_for(id, self.id()) { self.layer.on_exit(id, cx) } } fn on_close(&self, id: span::Id, cx: Context<'_, S>) { - if let Some(cx) = cx.if_enabled_for(&id, self.id) { + if let Some(cx) = cx.if_enabled_for(&id, self.id()) { self.layer.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<'_, S>) { - if let Some(cx) = cx.if_enabled_for(old, self.id) { + if let Some(cx) = cx.if_enabled_for(old, self.id()) { self.layer.on_id_change(old, new, cx) } } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { + match id { + id if id == TypeId::of::() => Some(self as *const _ as *const ()), + id if id == TypeId::of::() => Some(&self.layer as *const _ as *const ()), + id if id == TypeId::of::() => Some(&self.filter as *const _ as *const ()), + id if id == TypeId::of::() => { + Some(&self.id as *const _ as *const ()) + } + _ => 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("layer", &self.layer) + .field("id", &self.id) + .finish() + } } // === impl FilterFn === -pub fn filter_fn(f: F) -> 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-layer filtering][plf] for details on using +/// [`Filter`]s. +/// +/// [`Filter`]: crate::layer::Filter +/// [plf]: crate::layer#per-layer-filtering +/// +/// # Examples +/// +/// ``` +/// use tracing_subscriber::{ +/// layer::{Layer, SubscriberExt}, +/// 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_layer = tracing_subscriber::fmt::layer(); +/// +/// tracing_subscriber::registry() +/// .with(my_layer.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<'_>, &Context<'_, S>) -> bool, + F: Fn(&Metadata<'_>) -> bool, { FilterFn::new(f) } -impl FilterFn +/// 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-layer filtering][plf] for details on using +/// [`Filter`]s. +/// +/// # Examples +/// +/// ``` +/// use tracing_subscriber::{ +/// layer::{Layer, SubscriberExt}, +/// 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_layer = tracing_subscriber::fmt::layer(); +/// +/// tracing_subscriber::registry() +/// .with(my_layer.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::layer::Filter +/// [plf]: crate::layer#per-layer-filtering +/// [`Context`]: crate::layer::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-layer filtering][plf] for details on using + /// [`Filter`]s. + /// + /// [`Filter`]: crate::layer::Filter + /// [plf]: crate::layer#per-layer-filtering + /// [`Metadata`]: tracing_core::Metadata + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// layer::{Layer, SubscriberExt}, + /// 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_layer = tracing_subscriber::fmt::layer(); + /// + /// tracing_subscriber::registry() + /// .with(my_layer.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::{ + /// layer::{Layer, SubscriberExt}, + /// 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_layer = tracing_subscriber::fmt::layer(); + /// + /// tracing_subscriber::registry() + /// .with(my_layer.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [`Level`]: tracing_core::Level + /// [`Filter::max_level_hint`]: crate::layer::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 layer::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-layer filtering][plf] for details on using + /// [`Filter`]s. + /// + /// [`Filter`]: crate::layer::Filter + /// [plf]: crate::layer#per-layer-filtering + /// [`Context`]: crate::layer::Context + /// [`Metadata`]: tracing_core::Metadata + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// layer::{Layer, SubscriberExt}, + /// 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_layer = tracing_subscriber::fmt::layer(); + /// + /// tracing_subscriber::registry() + /// .with(my_layer.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, @@ -236,29 +790,142 @@ where } } -impl FilterFn +impl DynFilterFn where F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, { - pub fn with_max_level_hint(self, max_level_hint: LevelFilter) -> Self { + /// 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::{ + /// layer::{Layer, SubscriberExt}, + /// 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_layer = tracing_subscriber::fmt::layer(); + /// + /// tracing_subscriber::registry() + /// .with(my_layer.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [`Level`]: tracing_core::Level + /// [`Filter::max_level_hint`]: crate::layer::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), + max_level_hint: Some(max_level_hint.into()), ..self } } - pub fn with_callsite_filter(self, callsite_enabled: R2) -> FilterFn + /// 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::{ + /// layer::{Layer, SubscriberExt}, + /// filter::DynFilterFn, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::subscriber::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_layer = tracing_subscriber::fmt::layer(); + /// + /// tracing_subscriber::registry() + /// .with(my_layer.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [cse]: crate::layer::Filter::callsite_enabled + /// [`enabled`]: crate::layer::Filter::enabled + /// [`Metadata`]: tracing_core::Metadata + /// [span context]: crate::layer::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 FilterFn { + let DynFilterFn { enabled, max_level_hint, _s, .. } = self; - FilterFn { + DynFilterFn { enabled, register_callsite, max_level_hint, @@ -266,23 +933,30 @@ where } } - fn is_below_max_level(&self, metadata: &Metadata<'_>) -> bool { - self.max_level_hint - .as_ref() - .map(|hint| metadata.level() <= hint) - .unwrap_or(true) - } - fn default_callsite_enabled(&self, metadata: &Metadata<'_>) -> Interest { - if (self.enabled)(metadata, &Context::none()) { - Interest::always() - } else { - Interest::never() + // 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 Filter for FilterFn +impl layer::Filter for DynFilterFn where F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, R: Fn(&'static Metadata<'static>) -> Interest, @@ -290,8 +964,8 @@ where fn enabled(&self, metadata: &Metadata<'_>, cx: &Context<'_, S>) -> bool { let enabled = (self.enabled)(metadata, cx); debug_assert!( - !enabled || self.is_below_max_level(metadata), - "FilterFn<{}> claimed it would only enable {:?} and below, \ + !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(), @@ -309,8 +983,8 @@ where .map(|callsite_enabled| callsite_enabled(metadata)) .unwrap_or_else(|| self.default_callsite_enabled(metadata)); debug_assert!( - interest.is_never() || self.is_below_max_level(metadata), - "FilterFn<{}, {}> claimed it was only interested in {:?} and below, \ + 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::(), @@ -327,9 +1001,9 @@ where } } -impl fmt::Debug for FilterFn { +impl fmt::Debug for DynFilterFn { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let mut s = f.debug_struct("FilterFn"); + let mut s = f.debug_struct("DynFilterFn"); s.field("enabled", &format_args!("{}", type_name::())); if self.register_callsite.is_some() { s.field( @@ -340,13 +1014,11 @@ impl fmt::Debug for FilterFn { s.field("register_callsite", &format_args!("None")); } - s.field("max_level_hint", &self.max_level_hint) - .field("subscriber_type", &format_args!("{}", type_name::())) - .finish() + s.field("max_level_hint", &self.max_level_hint).finish() } } -impl Clone for FilterFn +impl Clone for DynFilterFn where F: Clone, R: Clone, @@ -361,7 +1033,7 @@ where } } -impl From for FilterFn +impl From for DynFilterFn where F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, { @@ -373,50 +1045,407 @@ where // === 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(id) + 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`] layer to the context. + /// + /// This is necessary for cases where we have a tree of nested [`Filtered`] + /// layers, like this: + /// + /// ```text + /// Filtered { + /// filter1, + /// Layered { + /// layer1, + /// Filtered { + /// filter2, + /// layer2, + /// }, + /// } + /// ``` + /// + /// We want `layer2` 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` layer (`filter1`) + /// won't call the inner layer'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 `layer2` + /// 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`] layer adds its ID to a [`Context`], it _combines_ it + /// with any previous filter ID that the context had, rather than replacing + /// it. That way, `layer2`'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 `layer2`'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::layer::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(idx): FilterId, enabled: bool) -> Self { - debug_assert!(idx < 64 || idx == 255); - if idx >= 64 { + pub(crate) fn set(self, FilterId(mask): FilterId, enabled: bool) -> Self { + if mask == u64::MAX { return self; } if enabled { Self { - bits: self.bits & !(1 << idx), + bits: self.bits & (!mask), } } else { Self { - bits: self.bits | (1 << idx), + bits: self.bits | mask, } } } - pub(crate) fn is_enabled(self, FilterId(idx): FilterId) -> bool { - debug_assert!(idx < 64 || idx == 255); - if idx >= 64 { - return false; - } - - self.bits & (1 << idx) == 0 + #[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)) + .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 layer has per-layer filtering, within +/// `tracing-subscriber`, without exposing a public API for it. +/// +/// If a `Layer` has per-layer filtering, it will downcast to a +/// `MagicPlfDowncastMarker`. Since layers which contain other layers permit +/// downcasting to recurse to their children, this will do the Right Thing with +/// layers 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 MagicPlfDowncastMarker(FilterId); +impl fmt::Debug for MagicPlfDowncastMarker { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + // Just pretend that `MagicPlfDowncastMarker` 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_plf_downcast_marker(type_id: TypeId) -> bool { + type_id == TypeId::of::() +} + +/// Does a type implementing `Subscriber` contain any per-layer filters? +pub(crate) fn subscriber_has_plf(subscriber: &S) -> bool +where + S: Subscriber, +{ + (subscriber as &dyn Subscriber).is::() +} + +/// Does a type implementing `Layer` contain any per-layer filters? +pub(crate) fn layer_has_plf(layer: &L) -> bool +where + L: Layer, + S: Subscriber, +{ + 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 layer decides to be evil and give us some kind of invalid + // pointer, we don't ever dereference it, so this is always safe. + layer.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/filter/mod.rs b/tracing-subscriber/src/filter/mod.rs index 5bffe8b893..6a66dc7d26 100644 --- a/tracing-subscriber/src/filter/mod.rs +++ b/tracing-subscriber/src/filter/mod.rs @@ -1,13 +1,51 @@ //! [`Layer`]s that control which spans and events are enabled by the wrapped //! subscriber. //! -//! [`Layer`]: ../layer/trait.Layer.html +//! For details on filtering spans and events using [`Layer`]s, see the [`layer` +//! module documentation]. +//! +//! [`layer` module documentation]: crate::layer#filtering-with-layers +//! [`Layer`]: crate::layer #[cfg(feature = "env-filter")] mod env; +#[cfg(feature = "registry")] +mod layer_filters; mod level; +#[cfg(not(feature = "registry"))] +pub(crate) use self::has_plf_stubs::*; +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub use self::layer_filters::*; + pub use self::level::{LevelFilter, ParseError as LevelParseError}; #[cfg(feature = "env-filter")] #[cfg_attr(docsrs, doc(cfg(feature = "env-filter")))] pub use self::env::*; + +/// Stub implementations of the per-layer-fitler detection functions for when the +/// `registry` feature is disabled. +#[cfg(not(feature = "registry"))] +mod has_plf_stubs { + pub(crate) fn is_plf_downcast_marker(_: std::any::TypeId) -> bool { + false + } + + /// Does a type implementing `Subscriber` contain any per-layer filters? + pub(crate) fn subscriber_has_plf(_: &S) -> bool + where + S: tracing_core::Subscriber, + { + false + } + + /// Does a type implementing `Layer` contain any per-layer filters? + pub(crate) fn layer_has_plf(_: &L) -> bool + where + L: crate::Layer, + S: tracing_core::Subscriber, + { + false + } +} diff --git a/tracing-subscriber/src/layer.rs b/tracing-subscriber/src/layer.rs deleted file mode 100644 index cbddb9dd70..0000000000 --- a/tracing-subscriber/src/layer.rs +++ /dev/null @@ -1,1555 +0,0 @@ -//! A composable abstraction for building `Subscriber`s. -use tracing_core::{ - metadata::Metadata, - span, - subscriber::{Interest, Subscriber}, - Event, LevelFilter, -}; - -#[cfg(feature = "registry")] -use crate::registry::Registry; -use crate::registry::{self, LookupSpan, SpanRef}; -use std::{ - any::{type_name, TypeId}, - fmt, - marker::PhantomData, - ops::Deref, - sync::Arc, -}; - -/// A composable handler for `tracing` events. -/// -/// The [`Subscriber`] trait in `tracing-core` represents the _complete_ set of -/// functionality required to consume `tracing` instrumentation. This means that -/// a single `Subscriber` instance is a self-contained implementation of a -/// complete strategy for collecting traces; but it _also_ means that the -/// `Subscriber` trait cannot easily be composed with other `Subscriber`s. -/// -/// In particular, [`Subscriber`]'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 `Subscriber` 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 [`Subscriber`] 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 `Layer` trait represents this composable subset of the -/// [`Subscriber`] behavior; it can _observe_ events and spans, but does not -/// assign IDs. -/// -/// ## Composing Layers -/// -/// Since a `Layer` does not implement a complete strategy for collecting -/// traces, it must be composed with a `Subscriber` in order to be used. The -/// `Layer` trait is generic over a type parameter (called `S` in the trait -/// definition), representing the types of `Subscriber` they can be composed -/// with. Thus, a `Layer` may be implemented that will only compose with a -/// particular `Subscriber` implementation, or additional trait bounds may be -/// added to constrain what types implementing `Subscriber` a `Layer` can wrap. -/// -/// `Layer`s may be added to a `Subscriber` by using the [`SubscriberExt::with`] -/// method, which is provided by `tracing-subscriber`'s [prelude]. This method -/// returns a [`Layered`] struct that implements `Subscriber` by composing the -/// `Layer` with the `Subscriber`. -/// -/// For example: -/// ```rust -/// use tracing_subscriber::Layer; -/// use tracing_subscriber::prelude::*; -/// use tracing::Subscriber; -/// -/// pub struct MyLayer { -/// // ... -/// } -/// -/// impl Layer for MyLayer { -/// // ... -/// } -/// -/// pub struct MySubscriber { -/// // ... -/// } -/// -/// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; -/// impl Subscriber for MySubscriber { -/// // ... -/// # 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) {} -/// } -/// # impl MyLayer { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MySubscriber { -/// # fn new() -> Self { Self { }} -/// # } -/// -/// let subscriber = MySubscriber::new() -/// .with(MyLayer::new()); -/// -/// tracing::subscriber::set_global_default(subscriber); -/// ``` -/// -/// Multiple `Layer`s may be composed in the same manner: -/// ```rust -/// # use tracing_subscriber::{Layer, layer::SubscriberExt}; -/// # use tracing::Subscriber; -/// pub struct MyOtherLayer { -/// // ... -/// } -/// -/// impl Layer for MyOtherLayer { -/// // ... -/// } -/// -/// pub struct MyThirdLayer { -/// // ... -/// } -/// -/// impl Layer for MyThirdLayer { -/// // ... -/// } -/// # pub struct MyLayer {} -/// # impl Layer for MyLayer {} -/// # pub struct MySubscriber { } -/// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; -/// # impl Subscriber for MySubscriber { -/// # 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) {} -/// } -/// # impl MyLayer { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyOtherLayer { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyThirdLayer { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MySubscriber { -/// # fn new() -> Self { Self { }} -/// # } -/// -/// let subscriber = MySubscriber::new() -/// .with(MyLayer::new()) -/// .with(MyOtherLayer::new()) -/// .with(MyThirdLayer::new()); -/// -/// tracing::subscriber::set_global_default(subscriber); -/// ``` -/// -/// The [`Layer::with_subscriber` method][with-sub] constructs the `Layered` -/// type from a `Layer` and `Subscriber`, and is called by -/// [`SubscriberExt::with`]. In general, it is more idiomatic to use -/// `SubscriberExt::with`, and treat `Layer::with_subscriber` as an -/// implementation detail, as `with_subscriber` calls must be nested, leading to -/// less clear code for the reader. However, `Layer`s which wish to perform -/// additional behavior when composed with a subscriber may provide their own -/// implementations of `SubscriberExt::with`. -/// -/// [`SubscriberExt::with`]: trait.SubscriberExt.html#method.with -/// [`Layered`]: struct.Layered.html -/// [prelude]: ../prelude/index.html -/// [with-sub]: #method.with_subscriber -/// -/// ## Recording Traces -/// -/// The `Layer` trait defines a set of methods for consuming notifications from -/// tracing instrumentation, which are generally equivalent to the similarly -/// named methods on [`Subscriber`]. Unlike [`Subscriber`], the methods on -/// `Layer` are additionally passed a [`Context`] type, which exposes additional -/// information provided by the wrapped subscriber (such as [the current span]) -/// to the layer. -/// -/// ## Filtering with `Layer`s -/// -/// As well as strategies for handling trace events, the `Layer` 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 layer can be applied to other layers or -/// subscribers. A `Layer` 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 [`Layer::register_callsite`] and [`Layer::enabled`] methods -/// determine whether a span or event is enabled *globally*. Thus, they should -/// **not** be used to indicate whether an individual layer wishes to record a -/// particular span or event. Instead, if a layer is only interested in a subset -/// of trace data, but does *not* wish to disable other spans and events for the -/// rest of the layer stack should ignore those spans and events in its -/// notification methods. -/// -/// The filtering methods on a stack of `Layer`s are evaluated in a top-down -/// order, starting with the outermost `Layer` and ending with the wrapped -/// [`Subscriber`]. If any layer 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. -/// -/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html -/// [span IDs]: https://docs.rs/tracing-core/latest/tracing_core/span/struct.Id.html -/// [`Context`]: struct.Context.html -/// [the current span]: struct.Context.html#method.current_span -/// [`register_callsite`]: #method.register_callsite -/// [`enabled`]: #method.enabled -/// [`on_enter`]: #method.on_enter -/// [`Layer::register_callsite`]: #method.register_callsite -/// [`Layer::enabled`]: #method.enabled -/// [`Interest::never()`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/struct.Interest.html#method.never -pub trait Layer -where - S: Subscriber, - Self: 'static, -{ - /// Registers a new callsite with this layer, returning whether or not - /// the layer is interested in being notified about the callsite, similarly - /// to [`Subscriber::register_callsite`]. - /// - /// By default, this returns [`Interest::always()`] if [`self.enabled`] returns - /// true, or [`Interest::never()`] if it returns false. - /// - ///
- /// 
-    /// Note: This method (and 
-    /// Layer::enabled) determine whether a span or event is
-    /// globally enabled, not whether the individual layer 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,
-    /// on_enter,
-    /// on_exit, and other notification
-    /// methods.
-    ///
- /// - /// See [the trait-level documentation] for more information on filtering - /// with `Layer`s. - /// - /// Layers may also implement this method to perform any behaviour that - /// should be run once per callsite. If the layer 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`]: https://docs.rs/tracing-core/latest/tracing_core/struct.Interest.html - /// [`Subscriber::register_callsite`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html#method.register_callsite - /// [`Interest::never()`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/struct.Interest.html#method.never - /// [`Interest::always()`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/struct.Interest.html#method.always - /// [`self.enabled`]: #method.enabled - /// [`Layer::enabled`]: #method.enabled - /// [`on_event`]: #method.on_event - /// [`on_enter`]: #method.on_enter - /// [`on_exit`]: #method.on_exit - /// [the trait-level documentation]: #filtering-with-layers - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - if self.enabled(metadata, Context::none()) { - Interest::always() - } else { - Interest::never() - } - } - - /// Returns `true` if this layer is interested in a span or event with the - /// given `metadata` in the current [`Context`], similarly to - /// [`Subscriber::enabled`]. - /// - /// By default, this always returns `true`, allowing the wrapped subscriber - /// to choose to disable the span. - /// - ///
- /// 
-    /// Note: This method (and 
-    /// Layer::register_callsite) determine whether a span or event is
-    /// globally enabled, not whether the individual layer 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,
-    /// on_enter,
-    /// on_exit, and other notification
-    /// methods.
-    ///
- /// - /// - /// See [the trait-level documentation] for more information on filtering - /// with `Layer`s. - /// - /// [`Interest`]: https://docs.rs/tracing-core/latest/tracing_core/struct.Interest.html - /// [`Context`]: ../struct.Context.html - /// [`Subscriber::enabled`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html#method.enabled - /// [`Layer::register_callsite`]: #method.register_callsite - /// [`on_event`]: #method.on_event - /// [`on_enter`]: #method.on_enter - /// [`on_exit`]: #method.on_exit - /// [the trait-level documentation]: #filtering-with-layers - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool { - let _ = (metadata, ctx); - true - } - - /// Notifies this layer that a new span was constructed with the given - /// `Attributes` and `Id`. - fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { - let _ = (attrs, id, ctx); - } - - // TODO(eliza): do we want this to be a public API? If we end up moving - // filtering layers to a separate trait, we may no longer want `Layer`s to - // be able to participate in max level hinting... - #[doc(hidden)] - fn max_level_hint(&self) -> Option { - None - } - - /// Notifies this layer 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<'_, S>) {} - - /// Notifies this layer 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<'_, S>) {} - - /// Notifies this layer that an event has occurred. - fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, S>) {} - - /// Notifies this layer that a span with the given ID was entered. - fn on_enter(&self, _id: &span::Id, _ctx: Context<'_, S>) {} - - /// Notifies this layer that the span with the given ID was exited. - fn on_exit(&self, _id: &span::Id, _ctx: Context<'_, S>) {} - - /// Notifies this layer that the span with the given ID has been closed. - fn on_close(&self, _id: span::Id, _ctx: Context<'_, S>) {} - - /// Notifies this layer 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<'_, S>) {} - - /// Composes this layer around the given `Layer`, returning a `Layered` - /// struct implementing `Layer`. - /// - /// The returned `Layer` will call the methods on this `Layer` and then - /// those of the new `Layer`, before calling the methods on the subscriber - /// it wraps. For example: - /// - /// ```rust - /// # use tracing_subscriber::layer::Layer; - /// # use tracing_core::Subscriber; - /// pub struct FooLayer { - /// // ... - /// } - /// - /// pub struct BarLayer { - /// // ... - /// } - /// - /// pub struct MySubscriber { - /// // ... - /// } - /// - /// impl Layer for FooLayer { - /// // ... - /// } - /// - /// impl Layer for BarLayer { - /// // ... - /// } - /// - /// # impl FooLayer { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl BarLayer { - /// # fn new() -> Self { Self { }} - /// # } - /// # impl MySubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; - /// # impl tracing_core::Subscriber for MySubscriber { - /// # 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) {} - /// # } - /// let subscriber = FooLayer::new() - /// .and_then(BarLayer::new()) - /// .with_subscriber(MySubscriber::new()); - /// ``` - /// - /// Multiple layers may be composed in this manner: - /// - /// ```rust - /// # use tracing_subscriber::layer::Layer; - /// # use tracing_core::Subscriber; - /// # pub struct FooLayer {} - /// # pub struct BarLayer {} - /// # pub struct MySubscriber {} - /// # impl Layer for FooLayer {} - /// # impl Layer for BarLayer {} - /// # impl FooLayer { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl BarLayer { - /// # fn new() -> Self { Self { }} - /// # } - /// # impl MySubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; - /// # impl tracing_core::Subscriber for MySubscriber { - /// # 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) {} - /// # } - /// pub struct BazLayer { - /// // ... - /// } - /// - /// impl Layer for BazLayer { - /// // ... - /// } - /// # impl BazLayer { fn new() -> Self { BazLayer {} } } - /// - /// let subscriber = FooLayer::new() - /// .and_then(BarLayer::new()) - /// .and_then(BazLayer::new()) - /// .with_subscriber(MySubscriber::new()); - /// ``` - fn and_then(self, layer: L) -> Layered - where - L: Layer, - Self: Sized, - { - Layered { - layer, - inner: self, - _s: PhantomData, - } - } - - /// Composes this `Layer` with the given [`Subscriber`], returning a - /// `Layered` struct that implements [`Subscriber`]. - /// - /// The returned `Layered` subscriber will call the methods on this `Layer` - /// and then those of the wrapped subscriber. - /// - /// For example: - /// ```rust - /// # use tracing_subscriber::layer::Layer; - /// # use tracing_core::Subscriber; - /// pub struct FooLayer { - /// // ... - /// } - /// - /// pub struct MySubscriber { - /// // ... - /// } - /// - /// impl Layer for FooLayer { - /// // ... - /// } - /// - /// # impl FooLayer { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl MySubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata}; - /// # impl tracing_core::Subscriber for MySubscriber { - /// # 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) {} - /// # } - /// let subscriber = FooLayer::new() - /// .with_subscriber(MySubscriber::new()); - ///``` - /// - /// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html - fn with_subscriber(self, inner: S) -> Layered - where - Self: Sized, - { - Layered { - layer: self, - inner, - _s: PhantomData, - } - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { - if id == TypeId::of::() { - Some(self as *const _ as *const ()) - } else { - None - } - } -} - -/// Extension trait adding a `with(Layer)` combinator to `Subscriber`s. -pub trait SubscriberExt: Subscriber + crate::sealed::Sealed { - /// Wraps `self` with the provided `layer`. - fn with(self, layer: L) -> Layered - where - L: Layer, - Self: Sized, - { - layer.with_subscriber(self) - } -} - -/// Represents information about the current context provided to [`Layer`]s by the -/// wrapped [`Subscriber`]. -/// -/// To access [stored data] keyed by a span ID, implementors of the `Layer` -/// trait should ensure that the `Subscriber` type parameter is *also* bound by the -/// [`LookupSpan`]: -/// -/// ```rust -/// use tracing::Subscriber; -/// use tracing_subscriber::{Layer, registry::LookupSpan}; -/// -/// pub struct MyLayer; -/// -/// impl Layer for MyLayer -/// where -/// S: Subscriber + for<'a> LookupSpan<'a>, -/// { -/// // ... -/// } -/// ``` -/// -/// [`Layer`]: ../layer/trait.Layer.html -/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html -/// [stored data]: ../registry/struct.SpanRef.html -/// [`LookupSpan`]: "../registry/trait.LookupSpan.html -#[derive(Debug)] -pub struct Context<'a, S> { - subscriber: Option<&'a S>, -} - -/// A [`Subscriber`] composed of a `Subscriber` wrapped by one or more -/// [`Layer`]s. -/// -/// [`Layer`]: ../layer/trait.Layer.html -/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html -#[derive(Clone)] -pub struct Layered { - layer: L, - inner: I, - _s: PhantomData, -} - -/// A layer that does nothing. -#[derive(Clone, Debug, Default)] -pub struct Identity { - _p: (), -} - -/// 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 Layered === - -impl Subscriber for Layered -where - L: Layer, - S: Subscriber, -{ - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - let outer = self.layer.register_callsite(metadata); - if outer.is_never() { - // if the outer layer has disabled the callsite, return now so that - // the subscriber doesn't get its hopes up. - return outer; - } - - 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 to weigh in. - inner - } - } - - fn enabled(&self, metadata: &Metadata<'_>) -> bool { - if self.layer.enabled(metadata, self.ctx()) { - // if the outer layer enables the callsite metadata, ask the subscriber. - self.inner.enabled(metadata) - } else { - // otherwise, the callsite is disabled by the layer - false - } - } - - fn max_level_hint(&self) -> Option { - std::cmp::max(self.layer.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.layer.new_span(span, &id, self.ctx()); - id - } - - fn record(&self, span: &span::Id, values: &span::Record<'_>) { - self.inner.record(span, values); - self.layer.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.layer.on_follows_from(span, follows, self.ctx()); - } - - fn event(&self, event: &Event<'_>) { - self.inner.event(event); - self.layer.on_event(event, self.ctx()); - } - - fn enter(&self, span: &span::Id) { - self.inner.enter(span); - self.layer.on_enter(span, self.ctx()); - } - - fn exit(&self, span: &span::Id) { - self.inner.exit(span); - self.layer.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.layer.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 Subscriber; - #[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.layer.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<*const ()> { - if id == TypeId::of::() { - return Some(self as *const _ as *const ()); - } - self.layer - .downcast_raw(id) - .or_else(|| self.inner.downcast_raw(id)) - } -} - -impl Layer for Layered -where - A: Layer, - B: Layer, - S: Subscriber, -{ - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - let outer = self.layer.register_callsite(metadata); - if outer.is_never() { - // if the outer layer has disabled the callsite, return now so that - // inner layers 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 layer to weigh in. - inner - } - } - - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool { - if self.layer.enabled(metadata, ctx.clone()) { - // if the outer layer enables the callsite metadata, ask the inner layer. - self.inner.enabled(metadata, ctx) - } else { - // otherwise, the callsite is disabled by this layer - false - } - } - - #[inline] - fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { - self.inner.new_span(attrs, id, ctx.clone()); - self.layer.new_span(attrs, id, ctx); - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { - self.inner.on_record(span, values, ctx.clone()); - self.layer.on_record(span, values, ctx); - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, S>) { - self.inner.on_follows_from(span, follows, ctx.clone()); - self.layer.on_follows_from(span, follows, ctx); - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { - self.inner.on_event(event, ctx.clone()); - self.layer.on_event(event, ctx); - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - self.inner.on_enter(id, ctx.clone()); - self.layer.on_enter(id, ctx); - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - self.inner.on_exit(id, ctx.clone()); - self.layer.on_exit(id, ctx); - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { - self.inner.on_close(id.clone(), ctx.clone()); - self.layer.on_close(id, ctx); - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, S>) { - self.inner.on_id_change(old, new, ctx.clone()); - self.layer.on_id_change(old, new, ctx); - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { - if id == TypeId::of::() { - return Some(self as *const _ as *const ()); - } - self.layer - .downcast_raw(id) - .or_else(|| self.inner.downcast_raw(id)) - } -} - -impl Layer for Option -where - L: Layer, - S: Subscriber, -{ - #[inline] - fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { - if let Some(ref inner) = self { - inner.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<'_, S>) -> 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<'_, S>) { - 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<'_, S>) { - if let Some(ref inner) = self { - inner.on_follows_from(span, follows, ctx); - } - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { - if let Some(ref inner) = self { - inner.on_event(event, ctx); - } - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - if let Some(ref inner) = self { - inner.on_enter(id, ctx); - } - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - if let Some(ref inner) = self { - inner.on_exit(id, ctx); - } - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { - 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<'_, S>) { - if let Some(ref inner) = self { - inner.on_id_change(old, new, ctx) - } - } - - #[doc(hidden)] - #[inline] - unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { - if id == TypeId::of::() { - Some(self as *const _ as *const ()) - } else { - self.as_ref().and_then(|inner| inner.downcast_raw(id)) - } - } -} - -macro_rules! layer_impl_body { - () => { - #[inline] - fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { - self.deref().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<'_, S>) -> 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<'_, S>) { - self.deref().on_record(span, values, ctx) - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, S>) { - self.deref().on_follows_from(span, follows, ctx) - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { - self.deref().on_event(event, ctx) - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - self.deref().on_enter(id, ctx) - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - self.deref().on_exit(id, ctx) - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { - self.deref().on_close(id, ctx) - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, S>) { - self.deref().on_id_change(old, new, ctx) - } - - #[doc(hidden)] - #[inline] - unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { - self.deref().downcast_raw(id) - } - }; -} - -impl Layer for Arc -where - L: Layer, - S: Subscriber, -{ - layer_impl_body! {} -} - -impl Layer for Arc> -where - S: Subscriber, -{ - layer_impl_body! {} -} - -impl Layer for Box -where - L: Layer, - S: Subscriber, -{ - layer_impl_body! {} -} - -impl Layer for Box> -where - S: Subscriber, -{ - layer_impl_body! {} -} - -impl<'a, L, S> LookupSpan<'a> for Layered -where - S: Subscriber + LookupSpan<'a>, -{ - type Data = S::Data; - - fn span_data(&'a self, id: &span::Id) -> Option { - self.inner.span_data(id) - } -} - -impl Layered -where - S: Subscriber, -{ - fn ctx(&self) -> Context<'_, S> { - Context { - subscriber: 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 fmt::Debug for Layered -where - A: fmt::Debug, - B: fmt::Debug, -{ - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let alt = f.alternate(); - let mut s = f.debug_struct("Layered"); - s.field("layer", &self.layer).field("inner", &self.inner); - if alt { - s.field( - "subscriber", - &format_args!("PhantomData<{}>", type_name::()), - ); - }; - s.finish() - } -} - -// === impl SubscriberExt === - -impl crate::sealed::Sealed for S {} -impl SubscriberExt for S {} - -// === impl Context === - -impl<'a, S> Context<'a, S> -where - S: Subscriber, -{ - /// Returns the wrapped subscriber's view of the current span. - #[inline] - pub fn current_span(&self) -> span::Current { - self.subscriber - .map(Subscriber::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 layer 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, Subscriber}; - /// use tracing_subscriber::{ - /// layer::{Context, Layer}, - /// prelude::*, - /// registry::LookupSpan, - /// }; - /// - /// struct PrintingLayer; - /// impl Layer for PrintingLayer - /// where - /// S: Subscriber + 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::subscriber::with_default(tracing_subscriber::registry().with(PrintingLayer), || { - /// 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 - S: 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 - S: for<'lookup> LookupSpan<'lookup>, - { - let span = self.subscriber.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 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 - S: for<'lookup> LookupSpan<'lookup>, - { - self.subscriber.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 - S: 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 - S: 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, - ); - span - } - - /// 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<'_, S> - where - S: 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 - S: 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 - S: for<'lookup> LookupSpan<'lookup>, - { - Some(self.event_span(event)?.scope()) - } -} - -impl<'a, S> Context<'a, S> { - pub(crate) fn none() -> Self { - Self { subscriber: None } - } -} - -impl<'a, S> Clone for Context<'a, S> { - #[inline] - fn clone(&self) -> Self { - let subscriber = self.subscriber.as_ref().copied(); - Context { subscriber } - } -} - -// === impl Identity === -// -impl Layer for Identity {} - -impl Identity { - /// Returns a new `Identity` layer. - pub fn new() -> Self { - Self { _p: () } - } -} - -#[cfg(test)] -pub(crate) mod tests { - - use super::*; - - pub(crate) struct NopSubscriber; - - impl Subscriber for NopSubscriber { - 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) {} - } - - struct NopLayer; - impl Layer for NopLayer {} - - #[allow(dead_code)] - struct NopLayer2; - impl Layer for NopLayer2 {} - - /// A layer that holds a string. - /// - /// Used to test that pointers returned by downcasting are actually valid. - struct StringLayer(String); - impl Layer for StringLayer {} - struct StringLayer2(String); - impl Layer for StringLayer2 {} - - struct StringLayer3(String); - impl Layer for StringLayer3 {} - - pub(crate) struct StringSubscriber(String); - - impl Subscriber for StringSubscriber { - 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 assert_subscriber(_s: impl Subscriber) {} - - #[test] - fn layer_is_subscriber() { - let s = NopLayer.with_subscriber(NopSubscriber); - assert_subscriber(s) - } - - #[test] - fn two_layers_are_subscriber() { - let s = NopLayer.and_then(NopLayer).with_subscriber(NopSubscriber); - assert_subscriber(s) - } - - #[test] - fn three_layers_are_subscriber() { - let s = NopLayer - .and_then(NopLayer) - .and_then(NopLayer) - .with_subscriber(NopSubscriber); - assert_subscriber(s) - } - - #[test] - fn downcasts_to_subscriber() { - let s = NopLayer - .and_then(NopLayer) - .and_then(NopLayer) - .with_subscriber(StringSubscriber("subscriber".into())); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber should downcast"); - assert_eq!(&subscriber.0, "subscriber"); - } - - #[test] - fn downcasts_to_layer() { - let s = StringLayer("layer_1".into()) - .and_then(StringLayer2("layer_2".into())) - .and_then(StringLayer3("layer_3".into())) - .with_subscriber(NopSubscriber); - let layer = - ::downcast_ref::(&s).expect("layer 1 should downcast"); - assert_eq!(&layer.0, "layer_1"); - let layer = - ::downcast_ref::(&s).expect("layer 2 should downcast"); - assert_eq!(&layer.0, "layer_2"); - let layer = - ::downcast_ref::(&s).expect("layer 3 should downcast"); - assert_eq!(&layer.0, "layer_3"); - } - - #[test] - #[cfg(feature = "registry")] - fn context_event_span() { - use std::sync::{Arc, Mutex}; - let last_event_span = Arc::new(Mutex::new(None)); - - struct RecordingLayer { - last_event_span: Arc>>, - } - - impl Layer for RecordingLayer - where - S: Subscriber + 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::subscriber::with_default( - crate::registry().with(RecordingLayer { - 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/layer/context.rs b/tracing-subscriber/src/layer/context.rs new file mode 100644 index 0000000000..a59e5faef3 --- /dev/null +++ b/tracing-subscriber/src/layer/context.rs @@ -0,0 +1,499 @@ +use tracing_core::{metadata::Metadata, span, subscriber::Subscriber, Event}; + +use crate::registry::{self, LookupSpan, SpanRef}; +#[cfg(feature = "registry")] +use crate::{filter::FilterId, registry::Registry}; +/// Represents information about the current context provided to [`Layer`]s by the +/// wrapped [`Subscriber`]. +/// +/// To access [stored data] keyed by a span ID, implementors of the `Layer` +/// trait should ensure that the `Subscriber` type parameter is *also* bound by the +/// [`LookupSpan`]: +/// +/// ```rust +/// use tracing::Subscriber; +/// use tracing_subscriber::{Layer, registry::LookupSpan}; +/// +/// pub struct MyLayer; +/// +/// impl Layer for MyLayer +/// where +/// S: Subscriber + for<'a> LookupSpan<'a>, +/// { +/// // ... +/// } +/// ``` +/// +/// [`Layer`]: ../layer/trait.Layer.html +/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html +/// [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`] layers that currently apply in this + /// context. If there is only a single [`Filtered`] wrapping the layer 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 layer. + /// + /// [`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, S> Context<'a, S> +where + S: Subscriber, +{ + pub(super) fn new(subscriber: &'a S) -> 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(Subscriber::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 layer 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, Subscriber}; + /// use tracing_subscriber::{ + /// layer::{Context, Layer}, + /// prelude::*, + /// registry::LookupSpan, + /// }; + /// + /// struct PrintingLayer; + /// impl Layer for PrintingLayer + /// where + /// S: Subscriber + 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::subscriber::with_default(tracing_subscriber::registry().with(PrintingLayer), || { + /// 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 + S: 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 + S: 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 + S: 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 + S: 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 + S: 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-layer 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-layer 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-layer 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 S, + ) -> Option> + where + S: LookupSpan<'lookup>, + { + let registry = (subscriber as &dyn Subscriber).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<'_, S> + where + S: 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 + S: 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 + S: 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 + // layers "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 + S: 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 + S: 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 + S: 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/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs new file mode 100644 index 0000000000..ee9d61ad5b --- /dev/null +++ b/tracing-subscriber/src/layer/layered.rs @@ -0,0 +1,456 @@ +use tracing_core::{ + metadata::Metadata, + span, + subscriber::{Interest, Subscriber}, + Event, LevelFilter, +}; + +use crate::{ + filter, + layer::{Context, Layer}, + registry::LookupSpan, +}; +#[cfg(feature = "registry")] +use crate::{filter::FilterId, registry::Registry}; +use std::{any::TypeId, fmt, marker::PhantomData}; + +/// A [`Subscriber`] composed of a `Subscriber` wrapped by one or more +/// [`Layer`]s. +/// +/// [`Layer`]: crate::Layer +/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html +#[derive(Clone)] +pub struct Layered { + /// The layer. + layer: L, + + /// The inner value that `self.layer` was layered onto. + /// + /// If this is also a `Layer`, then this `Layered` will implement `Layer`. + /// If this is a `Subscriber`, then this `Layered` will implement + /// `Subscriber` instead. + inner: I, + + // These booleans are used to determine how to combine `Interest`s and max + // level hints when per-layer 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.layer` have per-layer 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-layer filters. + /// + /// Otherwise, if it's a `Layered` with one per-layer filter in one branch, + /// but a non-per-layer-filtered layer in the other branch, this will be + /// _false_, because the `Layered` is already handling the combining of + /// per-layer filter `Interest`s and max level hints with its non-filtered + /// `Layer`. + has_layer_filter: bool, + + /// Does `self.inner` have per-layer filters? + /// + /// This is determined according to the same rules as + /// `has_layer_filter` above. + inner_has_layer_filter: bool, + _s: PhantomData, +} + +// === impl Layered === + +impl Subscriber for Layered +where + L: Layer, + S: Subscriber, +{ + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.pick_interest(self.layer.register_callsite(metadata), || { + self.inner.register_callsite(metadata) + }) + } + + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + if self.layer.enabled(metadata, self.ctx()) { + // if the outer layer enables the callsite metadata, ask the subscriber. + self.inner.enabled(metadata) + } else { + // otherwise, the callsite is disabled by the layer + false + } + } + + fn max_level_hint(&self) -> Option { + self.pick_level_hint(self.layer.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.layer.new_span(span, &id, self.ctx()); + id + } + + fn record(&self, span: &span::Id, values: &span::Record<'_>) { + self.inner.record(span, values); + self.layer.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.layer.on_follows_from(span, follows, self.ctx()); + } + + fn event(&self, event: &Event<'_>) { + self.inner.event(event); + self.layer.on_event(event, self.ctx()); + } + + fn enter(&self, span: &span::Id) { + self.inner.enter(span); + self.layer.on_enter(span, self.ctx()); + } + + fn exit(&self, span: &span::Id) { + self.inner.exit(span); + self.layer.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.layer.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 Subscriber; + #[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.layer.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<*const ()> { + // Unlike the implementation of `Layer` for `Layered`, we don't have to + // handle the "magic PLF downcast marker" here. If a `Layered` + // implements `Subscriber`, we already know that the `inner` branch is + // going to contain something that doesn't have per-layer filters (the + // actual root `Subscriber`). Thus, a `Layered` that implements + // `Subscriber` will always be propagating the root subscriber's + // `Interest`/level hint, even if it includes a `Layer` that has + // per-layer filters, because it will only ever contain layers where + // _one_ child has per-layer filters. + // + // The complex per-layer filter detection logic is only relevant to + // *trees* of layers, which involve the `Layer` implementation for + // `Layered`, not *lists* of layers, where every `Layered` implements + // `Subscriber`. 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 `Subscriber`), and + // `Layered`s that might be tree-shaped (the inner child is also a + // `Layer`). + + // If downcasting to `Self`, return a pointer to `self`. + if id == TypeId::of::() { + return Some(self as *const _ as *const ()); + } + + self.layer + .downcast_raw(id) + .or_else(|| self.inner.downcast_raw(id)) + } +} + +impl Layer for Layered +where + A: Layer, + B: Layer, + S: Subscriber, +{ + fn on_layer(&mut self, subscriber: &mut S) { + self.layer.on_layer(subscriber); + self.inner.on_layer(subscriber); + } + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.pick_interest(self.layer.register_callsite(metadata), || { + self.inner.register_callsite(metadata) + }) + } + + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool { + if self.layer.enabled(metadata, ctx.clone()) { + // if the outer subscriber enables the callsite metadata, ask the inner layer. + self.inner.enabled(metadata, ctx) + } else { + // otherwise, the callsite is disabled by this layer + false + } + } + + fn max_level_hint(&self) -> Option { + self.pick_level_hint(self.layer.max_level_hint(), self.inner.max_level_hint()) + } + + #[inline] + fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + self.inner.new_span(attrs, id, ctx.clone()); + self.layer.new_span(attrs, id, ctx); + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + self.inner.on_record(span, values, ctx.clone()); + self.layer.on_record(span, values, ctx); + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, S>) { + self.inner.on_follows_from(span, follows, ctx.clone()); + self.layer.on_follows_from(span, follows, ctx); + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + self.inner.on_event(event, ctx.clone()); + self.layer.on_event(event, ctx); + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + self.inner.on_enter(id, ctx.clone()); + self.layer.on_enter(id, ctx); + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + self.inner.on_exit(id, ctx.clone()); + self.layer.on_exit(id, ctx); + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + self.inner.on_close(id.clone(), ctx.clone()); + self.layer.on_close(id, ctx); + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, S>) { + self.inner.on_id_change(old, new, ctx.clone()); + self.layer.on_id_change(old, new, ctx); + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { + match id { + // If downcasting to `Self`, return a pointer to `self`. + id if id == TypeId::of::() => Some(self as *const _ as *const ()), + + // Oh, we're looking for per-layer 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-layer filtered" if *both* the outer layer and the inner + // layer/subscriber have per-layer filters. Otherwise, this `Layered + // should *not* be considered per-layer filtered (even if one or the + // other has per layer filters). If only one `Layer` is per-layer + // 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-layer-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-layer 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-layer-filtered layers, since both branches would + // claim to have PLF. + // + // If you don't understand this...that's fine, just don't mess with + // it. :) + id if filter::is_plf_downcast_marker(id) => { + self.layer.downcast_raw(id).and(self.inner.downcast_raw(id)) + } + + // Otherwise, try to downcast both branches normally... + _ => self + .layer + .downcast_raw(id) + .or_else(|| self.inner.downcast_raw(id)), + } + } +} + +impl<'a, L, S> LookupSpan<'a> for Layered +where + S: Subscriber + LookupSpan<'a>, +{ + type Data = S::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 + S: Subscriber, +{ + fn ctx(&self) -> Context<'_, S> { + Context::new(&self.inner) + } +} + +impl Layered +where + A: Layer, + S: Subscriber, +{ + pub(super) fn new(layer: A, inner: B, inner_has_layer_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_layer_filter = inner_has_layer_filter || inner_is_registry; + let has_layer_filter = filter::layer_has_plf(&layer); + Self { + layer, + inner, + has_layer_filter, + inner_has_layer_filter, + inner_is_registry, + _s: PhantomData, + } + } + + fn pick_interest(&self, outer: Interest, inner: impl FnOnce() -> Interest) -> Interest { + if self.has_layer_filter { + return inner(); + } + + // If the outer layer has disabled the callsite, return now so that + // the inner layer/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 layer'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-layer filter in the `inner` stack, and it returns + // `never`, change the interest to `sometimes`, because the `outer` + // layer didn't return `never`. This means that _some_ layer still wants + // to see that callsite, even though the inner stack's per-layer filter + // didn't want it. Therefore, returning `sometimes` will ensure + // `enabled` is called so that the per-layer filter can skip that + // span/event, while the `outer` layer still gets to see it. + if inner.is_never() && self.inner_has_layer_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_layer_filter && self.inner_has_layer_filter { + return Some(max(outer_hint?, inner_hint?)); + } + + if self.has_layer_filter && inner_hint.is_none() { + return None; + } + + if self.inner_has_layer_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_layer_filter", &self.has_layer_filter) + .field("inner_has_layer_filter", &self.inner_has_layer_filter); + } + + s.field("layer", &self.layer) + .field("inner", &self.inner) + .finish() + } +} diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs new file mode 100644 index 0000000000..9a98fc5f43 --- /dev/null +++ b/tracing-subscriber/src/layer/mod.rs @@ -0,0 +1,1189 @@ +//! The [`Layer`] trait, a composable abstraction for building [`Subscriber`]s. +//! +//! The [`Subscriber`] trait in `tracing-core` represents the _complete_ set of +//! functionality required to consume `tracing` instrumentation. This means that +//! a single `Subscriber` instance is a self-contained implementation of a +//! complete strategy for collecting traces; but it _also_ means that the +//! `Subscriber` trait cannot easily be composed with other `Subscriber`s. +//! +//! In particular, [`Subscriber`]'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 `Subscriber` 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 [`Subscriber`] 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 [`Layer`] trait represents this composable subset of the +//! [`Subscriber`] behavior; it can _observe_ events and spans, but does not +//! assign IDs. +//! +//! ## Composing Layers +//! +//! Since a [`Layer`] does not implement a complete strategy for collecting +//! traces, it must be composed with a `Subscriber` in order to be used. The +//! [`Layer`] trait is generic over a type parameter (called `S` in the trait +//! definition), representing the types of `Subscriber` they can be composed +//! with. Thus, a [`Layer`] may be implemented that will only compose with a +//! particular `Subscriber` implementation, or additional trait bounds may be +//! added to constrain what types implementing `Subscriber` a `Layer` can wrap. +//! +//! `Layer`s may be added to a `Subscriber` by using the [`SubscriberExt::with`] +//! method, which is provided by `tracing-subscriber`'s [prelude]. This method +//! returns a [`Layered`] struct that implements `Subscriber` by composing the +//! `Layer` with the `Subscriber`. +//! +//! For example: +//! ```rust +//! use tracing_subscriber::Layer; +//! use tracing_subscriber::prelude::*; +//! use tracing::Subscriber; +//! +//! pub struct MyLayer { +//! // ... +//! } +//! +//! impl Layer for MyLayer { +//! // ... +//! } +//! +//! pub struct MySubscriber { +//! // ... +//! } +//! +//! # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; +//! impl Subscriber for MySubscriber { +//! // ... +//! # 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) {} +//! } +//! # impl MyLayer { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MySubscriber { +//! # fn new() -> Self { Self { }} +//! # } +//! +//! let subscriber = MySubscriber::new() +//! .with(MyLayer::new()); +//! +//! tracing::subscriber::set_global_default(subscriber); +//! ``` +//! +//! Multiple `Layer`s may be composed in the same manner: +//! ```rust +//! # use tracing_subscriber::{Layer, layer::SubscriberExt}; +//! # use tracing::Subscriber; +//! pub struct MyOtherLayer { +//! // ... +//! } +//! +//! impl Layer for MyOtherLayer { +//! // ... +//! } +//! +//! pub struct MyThirdLayer { +//! // ... +//! } +//! +//! impl Layer for MyThirdLayer { +//! // ... +//! } +//! # pub struct MyLayer {} +//! # impl Layer for MyLayer {} +//! # pub struct MySubscriber { } +//! # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; +//! # impl Subscriber for MySubscriber { +//! # 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) {} +//! } +//! # impl MyLayer { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyOtherLayer { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyThirdLayer { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MySubscriber { +//! # fn new() -> Self { Self { }} +//! # } +//! +//! let subscriber = MySubscriber::new() +//! .with(MyLayer::new()) +//! .with(MyOtherLayer::new()) +//! .with(MyThirdLayer::new()); +//! +//! tracing::subscriber::set_global_default(subscriber); +//! ``` +//! +//! The [`Layer::with_subscriber`] constructs the [`Layered`] type from a +//! [`Layer`] and [`Subscriber`], and is called by [`SubscriberExt::with`]. In +//! general, it is more idiomatic to use [`SubscriberExt::with`], and treat +//! [`Layer::with_subscriber`] as an implementation detail, as `with_subscriber` +//! calls must be nested, leading to less clear code for the reader. +//! +//! [prelude]: crate::prelude +//! +//! ## Recording Traces +//! +//! The [`Layer`] trait defines a set of methods for consuming notifications from +//! tracing instrumentation, which are generally equivalent to the similarly +//! named methods on [`Subscriber`]. Unlike [`Subscriber`], the methods on +//! `Layer` are additionally passed a [`Context`] type, which exposes additional +//! information provided by the wrapped subscriber (such as [the current span]) +//! to the layer. +//! +//! ## Filtering with `Layer`s +//! +//! As well as strategies for handling trace events, the `Layer` 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 layer can be applied to other layers or +//! subscribers. `Layer`s can be used to implement _global filtering_, where a +//! `Layer` provides a filtering strategy for the entire subscriber. +//! Additionally, individual recording `Layer`s or sets of `Layer`s may be +//! combined with _per-layer filters_ that control what spans and events are +//! recorded by those layers. +//! +//! ### Global Filtering +//! +//! A `Layer` 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 [`Layer::register_callsite`] and [`Layer::enabled`] methods +//! determine whether a span or event is enabled *globally*. Thus, they should +//! **not** be used to indicate whether an individual layer wishes to record a +//! particular span or event. Instead, if a layer is only interested in a subset +//! of trace data, but does *not* wish to disable other spans and events for the +//! rest of the layer stack should ignore those spans and events in its +//! notification methods. +//! +//! The filtering methods on a stack of `Layer`s are evaluated in a top-down +//! order, starting with the outermost `Layer` and ending with the wrapped +//! [`Subscriber`]. If any layer 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-Layer Filtering +//! +//! **Note**: per-layer filtering APIs currently require the [`"registry"` crate +//! feature flag][feat] to be enabled. +//! +//! Sometimes, it may be desirable for one `Layer` to record a particular subset +//! of spans and events, while a different subset of spans and events are +//! recorded by other `Layer`s. For example: +//! +//! - A layer that records metrics may wish to observe only events including +//! particular tracked values, while a logging layer 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 `Layer`, while still allowing other `Layer`s to +//! potentially record them. The [`Layer::with_filter`] method combines a +//! `Layer` with a [`Filter`], returning a [`Filtered`] layer. +//! +//!
+//! 
+//!     Warning: Currently, the 
+//!     Registry type defined in this crate is the only root
+//!     Subscriber capable of supporting Layers with
+//!     per-layer filters. In the future, new APIs will be added to allow other
+//!     root Subscribers to support per-layer 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 layer: +//! +//! ``` +//! use tracing_subscriber::{filter, prelude::*}; +//! +//! // Generates an HTTP access log. +//! let access_log = // ... +//! # filter::LevelFilter::INFO; +//! +//! // Add a filter to the access log layer 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 general-purpose logging layer. +//! let fmt_layer = tracing_subscriber::fmt::layer(); +//! +//! // Build a subscriber that combines the access log and stdout log +//! // layers. +//! tracing_subscriber::registry() +//! .with(fmt_layer) +//! .with(access_log) +//! .init(); +//! ``` +//! +//! Multiple layers can have their own, separate per-layer filters. A span or +//! event will be recorded if it is enabled by _any_ per-layer filter, but it +//! will be skipped by the layers 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_layer = tracing_subscriber::fmt::layer(); +//! +//! tracing_subscriber::registry() +//! // Add the filter for the "http_access" target to the access +//! // log layer, 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 layer. +//! .with(fmt_layer.with_filter(LevelFilter::INFO)) +//! .init(); +//! +//! // Neither layer will observe this event +//! tracing::debug!(does_anyone_care = false, "a tree fell in the forest"); +//! +//! // This event will be observed by the logging layer, but not +//! // by the access log layer. +//! tracing::warn!(dose_roentgen = %3.8, "not great, but not terrible"); +//! +//! // This event will be observed only by the access log layer. +//! tracing::trace!(target: "http_access", "HTTP request started"); +//! +//! // Both layers will observe this event. +//! tracing::error!(target: "http_access", "HTTP request failed with a very bad error!"); +//! ``` +//! +//! A per-layer filter can be applied to multiple [`Layer`]s at a time, by +//! combining them into a [`Layered`] layer using [`Layer::and_then`], and then +//! calling [`Layer::with_filter`] on the resulting [`Layered`] layer. +//! +//! Consider the following: +//! - `layer_a` and `layer_b`, which should only receive spans and events at +//! the [`INFO`] [level] and above. +//! - A third layer, `layer_c`, which should receive spans and events at +//! the [`DEBUG`] [level] as well. +//! The layers and filters would be composed thusly: +//! +//! ``` +//! use tracing_subscriber::{filter::LevelFilter, prelude::*}; +//! +//! let layer_a = // ... +//! # LevelFilter::INFO; +//! let layer_b = // ... +//! # LevelFilter::INFO; +//! let layer_c = // ... +//! # LevelFilter::INFO; +//! +//! let info_layers = layer_a +//! // Combine `layer_a` and `layer_b` into a `Layered` layer: +//! .and_then(layer_b) +//! // ...and then add an `INFO` `LevelFilter` to that layer: +//! .with_filter(LevelFilter::INFO); +//! +//! tracing_subscriber::registry() +//! // Add `layer_c` with a `DEBUG` filter. +//! .with(layer_c.with_filter(LevelFilter::DEBUG)) +//! .with(info_layers) +//! .init(); +//!``` +//! +//! If a [`Filtered`] [`Layer`] is combined with another [`Layer`] +//! [`Layer::and_then`], and a filter is added to the [`Layered`] layer, that +//! layer 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 layer. 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 layer 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 layers 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 layer that logs events to stdout using the human-readable "pretty" +//! // format. +//! let stdout_log = tracing_subscriber::fmt::layer() +//! .pretty(); +//! +//! // A layer that logs events to a file. +//! let file = File::create("debug.log")?; +//! let debug_log = tracing_subscriber::fmt::layer() +//! .with_writer(Arc::new(file)); +//! +//! // A layer that collects metrics using specific events. +//! let metrics_layer = /* ... */ filter::LevelFilter::INFO; +//! +//! tracing_subscriber::registry() +//! .with( +//! stdout_log +//! // Add an `INFO` filter to the stdout logging layer +//! .with_filter(filter::LevelFilter::INFO) +//! // Combine the filtered `stdout_log` layer with the +//! // `debug_log` layer, producing a new `Layered` layer. +//! .and_then(debug_log) +//! // Add a filter to *both* layers 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_layer.with_filter(filter::filter_fn(|metadata| { +//! metadata.target().starts_with("metrics") +//! })) +//! ) +//! .init(); +//! +//! // This event will *only* be recorded by the metrics layer. +//! tracing::info!(target: "metrics::cool_stuff_count", value = 42); +//! +//! // This event will only be seen by the debug log file layer: +//! tracing::debug!("this is a message, and part of a system of messages"); +//! +//! // This event will be seen by both the stdout log layer *and* +//! // the debug log file layer, but not by the metrics layer. +//! tracing::warn!("the message is a warning about danger!"); +//! # Ok(()) } +//! ``` +//! +//! [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html +//! [span IDs]: https://docs.rs/tracing-core/latest/tracing_core/span/struct.Id.html +//! [the current span]: Context::current_span +//! [`register_callsite`]: Layer::register_callsite +//! [`enabled`]: Layer::enabled +//! [`on_enter`]: Layer::on_enter +//! [`Layer::register_callsite`]: Layer::register_callsite +//! [`Layer::enabled`]: Layer::enabled +//! [`Interest::never()`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/struct.Interest.html#method.never +//! [`Filtered`]: crate::filter::Filtered +//! [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, sync::Arc}; +use tracing_core::{ + metadata::Metadata, + span, + subscriber::{Interest, Subscriber}, + 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 `Layer` implements a behavior for recording or collecting traces that can +/// be composed together with other `Layer`s to build a [`Subscriber`]. See the +/// [module-level documentation](crate::layer) for details. +/// +/// [`Subscriber`]: tracing_core::Subscriber +pub trait Layer +where + S: Subscriber, + Self: 'static, +{ + /// Performs late initialization when attaching a `Layer` to a + /// [`Subscriber`]. + /// + /// This is a callback that is called when the `Layer` is added to a + /// [`Subscriber`] (e.g. in [`Layer::with_subscriber`] and + /// [`SubscriberExt::with`]). Since this can only occur before the + /// [`Subscriber`] has been set as the default, both the `Layer` and + /// [`Subscriber`] are passed to this method _mutably_. This gives the + /// `Layer` the opportunity to set any of its own fields with values + /// recieved by method calls on the [`Subscriber`]. + /// + /// For example, [`Filtered`] layers implement `on_layer` to call the + /// [`Subscriber`]'s [`register_filter`] method, and store the returned + /// [`FilterId`] as a field. + /// + /// **Note** In most cases, `Layer` implementations will not need to + /// implement this method. However, in cases where a type implementing + /// `Layer` wraps one or more other types that implement `Layer`, like the + /// [`Layered`] and [`Filtered`] types in this crate, that type MUST ensure + /// that the inner `Layer`s' `on_layer` methods are called. Otherwise, + /// functionality that relies on `on_layer`, such as [per-layer filtering], + /// may not work correctly. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [`register_filter`]: crate::registry::LookupSpan::register_filter + /// [per-layer filtering]: #per-layer-filtering + /// [`FilterId`]: crate::filter::FilterId + fn on_layer(&mut self, subscriber: &mut S) { + let _ = subscriber; + } + + /// Registers a new callsite with this layer, returning whether or not + /// the layer is interested in being notified about the callsite, similarly + /// to [`Subscriber::register_callsite`]. + /// + /// By default, this returns [`Interest::always()`] if [`self.enabled`] returns + /// true, or [`Interest::never()`] if it returns false. + /// + ///
+ /// 
+    /// Note: This method (and 
+    /// Layer::enabled) determine whether a span or event is
+    /// globally enabled, not whether the individual layer 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,
+    /// on_enter,
+    /// on_exit, and other notification
+    /// methods.
+    ///
+ /// + /// See [the trait-level documentation] for more information on filtering + /// with `Layer`s. + /// + /// Layers may also implement this method to perform any behaviour that + /// should be run once per callsite. If the layer 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`]: https://docs.rs/tracing-core/latest/tracing_core/struct.Interest.html + /// [`Subscriber::register_callsite`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html#method.register_callsite + /// [`Interest::never()`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/struct.Interest.html#method.never + /// [`Interest::always()`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/struct.Interest.html#method.always + /// [`self.enabled`]: #method.enabled + /// [`Layer::enabled`]: #method.enabled + /// [`on_event`]: #method.on_event + /// [`on_enter`]: #method.on_enter + /// [`on_exit`]: #method.on_exit + /// [the trait-level documentation]: #filtering-with-layers + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + if self.enabled(metadata, Context::none()) { + Interest::always() + } else { + Interest::never() + } + } + + /// Returns `true` if this layer is interested in a span or event with the + /// given `metadata` in the current [`Context`], similarly to + /// [`Subscriber::enabled`]. + /// + /// By default, this always returns `true`, allowing the wrapped subscriber + /// to choose to disable the span. + /// + ///
+ /// 
+    /// Note: This method (and 
+    /// Layer::register_callsite) determine whether a span or event is
+    /// globally enabled, not whether the individual layer 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,
+    /// on_enter,
+    /// on_exit, and other notification
+    /// methods.
+    ///
+ /// + /// + /// See [the trait-level documentation] for more information on filtering + /// with `Layer`s. + /// + /// [`Interest`]: https://docs.rs/tracing-core/latest/tracing_core/struct.Interest.html + /// [`Context`]: ../struct.Context.html + /// [`Subscriber::enabled`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html#method.enabled + /// [`Layer::register_callsite`]: #method.register_callsite + /// [`on_event`]: #method.on_event + /// [`on_enter`]: #method.on_enter + /// [`on_exit`]: #method.on_exit + /// [the trait-level documentation]: #filtering-with-layers + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool { + let _ = (metadata, ctx); + true + } + + /// Notifies this layer that a new span was constructed with the given + /// `Attributes` and `Id`. + fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + let _ = (attrs, id, ctx); + } + + // TODO(eliza): do we want this to be a public API? If we end up moving + // filtering layers to a separate trait, we may no longer want `Layer`s to + // be able to participate in max level hinting... + #[doc(hidden)] + fn max_level_hint(&self) -> Option { + None + } + + /// Notifies this layer 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<'_, S>) {} + + /// Notifies this layer 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<'_, S>) {} + + /// Notifies this layer that an event has occurred. + fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, S>) {} + + /// Notifies this layer that a span with the given ID was entered. + fn on_enter(&self, _id: &span::Id, _ctx: Context<'_, S>) {} + + /// Notifies this layer that the span with the given ID was exited. + fn on_exit(&self, _id: &span::Id, _ctx: Context<'_, S>) {} + + /// Notifies this layer that the span with the given ID has been closed. + fn on_close(&self, _id: span::Id, _ctx: Context<'_, S>) {} + + /// Notifies this layer 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<'_, S>) {} + + /// Composes this layer around the given `Layer`, returning a `Layered` + /// struct implementing `Layer`. + /// + /// The returned `Layer` will call the methods on this `Layer` and then + /// those of the new `Layer`, before calling the methods on the subscriber + /// it wraps. For example: + /// + /// ```rust + /// # use tracing_subscriber::layer::Layer; + /// # use tracing_core::Subscriber; + /// pub struct FooLayer { + /// // ... + /// } + /// + /// pub struct BarLayer { + /// // ... + /// } + /// + /// pub struct MySubscriber { + /// // ... + /// } + /// + /// impl Layer for FooLayer { + /// // ... + /// } + /// + /// impl Layer for BarLayer { + /// // ... + /// } + /// + /// # impl FooLayer { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl BarLayer { + /// # fn new() -> Self { Self { }} + /// # } + /// # impl MySubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; + /// # impl tracing_core::Subscriber for MySubscriber { + /// # 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) {} + /// # } + /// let subscriber = FooLayer::new() + /// .and_then(BarLayer::new()) + /// .with_subscriber(MySubscriber::new()); + /// ``` + /// + /// Multiple layers may be composed in this manner: + /// + /// ```rust + /// # use tracing_subscriber::layer::Layer; + /// # use tracing_core::Subscriber; + /// # pub struct FooLayer {} + /// # pub struct BarLayer {} + /// # pub struct MySubscriber {} + /// # impl Layer for FooLayer {} + /// # impl Layer for BarLayer {} + /// # impl FooLayer { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl BarLayer { + /// # fn new() -> Self { Self { }} + /// # } + /// # impl MySubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; + /// # impl tracing_core::Subscriber for MySubscriber { + /// # 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) {} + /// # } + /// pub struct BazLayer { + /// // ... + /// } + /// + /// impl Layer for BazLayer { + /// // ... + /// } + /// # impl BazLayer { fn new() -> Self { BazLayer {} } } + /// + /// let subscriber = FooLayer::new() + /// .and_then(BarLayer::new()) + /// .and_then(BazLayer::new()) + /// .with_subscriber(MySubscriber::new()); + /// ``` + fn and_then(self, layer: L) -> Layered + where + L: Layer, + Self: Sized, + { + let inner_has_layer_filter = filter::layer_has_plf(&self); + Layered::new(layer, self, inner_has_layer_filter) + } + + /// Composes this `Layer` with the given [`Subscriber`], returning a + /// `Layered` struct that implements [`Subscriber`]. + /// + /// The returned `Layered` subscriber will call the methods on this `Layer` + /// and then those of the wrapped subscriber. + /// + /// For example: + /// ```rust + /// # use tracing_subscriber::layer::Layer; + /// # use tracing_core::Subscriber; + /// pub struct FooLayer { + /// // ... + /// } + /// + /// pub struct MySubscriber { + /// // ... + /// } + /// + /// impl Layer for FooLayer { + /// // ... + /// } + /// + /// # impl FooLayer { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl MySubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata}; + /// # impl tracing_core::Subscriber for MySubscriber { + /// # 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) {} + /// # } + /// let subscriber = FooLayer::new() + /// .with_subscriber(MySubscriber::new()); + ///``` + /// + /// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html + fn with_subscriber(mut self, mut inner: S) -> Layered + where + Self: Sized, + { + let inner_has_layer_filter = filter::subscriber_has_plf(&inner); + self.on_layer(&mut inner); + Layered::new(self, inner, inner_has_layer_filter) + } + + /// Combines `self` with a [`Filter`], returning a [`Filtered`] layer. + /// + /// The [`Filter`] will control which spans and events are enabled for + /// this layer. See [the trait-level documentation][plf] for details on + /// per-layer filtering. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [plf]: #per-layer-filtering + #[cfg(feature = "registry")] + #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] + 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<*const ()> { + if id == TypeId::of::() { + Some(self as *const _ as *const ()) + } else { + None + } + } +} + +/// A per-[`Layer`] filter that determines whether a span or event is enabled +/// for an individual layer. +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry"), notable_trait))] +pub trait Filter { + /// Returns `true` if this layer is interested in a span or event with the + /// given [`Metadata`] in the current [`Context`], similarly to + /// [`Subscriber::enabled`]. + /// + /// If this returns `false`, the span or event will be disabled _for the + /// wrapped [`Layer`]_. Unlike [`Layer::enabled`], the span or event will + /// still be recorded if any _other_ layers choose to enable it. However, + /// the layer [filtered] by this filter will skip recording that span or + /// event. + /// + /// If all layers indicate that they do not wish to see this span or event, + /// it will be disabled. + /// + /// [`metadata`]: tracing_core::Metadata + /// [`Subscriber::enabled`]: tracing_core::Subscriber::enabled + /// [filtered]: crate::filter::Filtered + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, S>) -> bool; + + /// Returns an [`Interest`] indicating whether this layer 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 [`Subscriber::register_callsite`]; + /// however, since the returned value represents only the interest of + /// *this* layer, the resulting behavior is somewhat different. + /// + /// If a [`Subscriber`] 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_ [`Layer`]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 [`Layer`]s that comprise the subscriber include `Filter`s + /// (this includes a tree of [`Layered`] layers that share the same + /// `Filter`) + /// - all those `Filter`s return the same [`Interest`]. + /// + /// For example, if a [`Subscriber`] consists of two [`Filtered`] layers, + /// and both of those layers 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::layer; + /// use tracing_core::{Metadata, subscriber::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 layer::Filter for MyFilter { + /// fn enabled(&self, metadata: &Metadata<'_>, _: &layer::Context<'_, S>) -> 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 + /// [`Subscriber::register_callsite`]: tracing_core::Subscriber::register_callsite + /// [`Subscriber`]: tracing_core::Subscriber + /// [`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::subscriber::Interest + /// [rebuild]: tracing_core::callsite::rebuild_interest_cache + fn max_level_hint(&self) -> Option { + None + } +} + +/// Extension trait adding a `with(Layer)` combinator to `Subscriber`s. +pub trait SubscriberExt: Subscriber + crate::sealed::Sealed { + /// Wraps `self` with the provided `layer`. + fn with(self, layer: L) -> Layered + where + L: Layer, + Self: Sized, + { + layer.with_subscriber(self) + } +} +/// A layer that does nothing. +#[derive(Clone, Debug, Default)] +pub struct Identity { + _p: (), +} + +// === impl Layer === + +impl Layer for Option +where + L: Layer, + S: Subscriber, +{ + fn on_layer(&mut self, subscriber: &mut S) { + if let Some(ref mut layer) = self { + layer.on_layer(subscriber) + } + } + + #[inline] + fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + if let Some(ref inner) = self { + inner.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<'_, S>) -> 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<'_, S>) { + 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<'_, S>) { + if let Some(ref inner) = self { + inner.on_follows_from(span, follows, ctx); + } + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + if let Some(ref inner) = self { + inner.on_event(event, ctx); + } + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + if let Some(ref inner) = self { + inner.on_enter(id, ctx); + } + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + if let Some(ref inner) = self { + inner.on_exit(id, ctx); + } + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + 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<'_, S>) { + if let Some(ref inner) = self { + inner.on_id_change(old, new, ctx) + } + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { + if id == TypeId::of::() { + Some(self as *const _ as *const ()) + } else { + self.as_ref().and_then(|inner| inner.downcast_raw(id)) + } + } +} + +macro_rules! layer_impl_body { + () => { + #[inline] + fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + self.deref().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<'_, S>) -> 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<'_, S>) { + self.deref().on_record(span, values, ctx) + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, S>) { + self.deref().on_follows_from(span, follows, ctx) + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + self.deref().on_event(event, ctx) + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + self.deref().on_enter(id, ctx) + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + self.deref().on_exit(id, ctx) + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + self.deref().on_close(id, ctx) + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, S>) { + self.deref().on_id_change(old, new, ctx) + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { + self.deref().downcast_raw(id) + } + }; +} + +impl Layer for Arc +where + L: Layer, + S: Subscriber, +{ + layer_impl_body! {} +} + +impl Layer for Arc> +where + S: Subscriber, +{ + layer_impl_body! {} +} + +impl Layer for Box +where + L: Layer, + S: Subscriber, +{ + layer_impl_body! {} +} + +impl Layer for Box> +where + S: Subscriber, +{ + layer_impl_body! {} +} + +// === impl SubscriberExt === + +impl crate::sealed::Sealed for S {} +impl SubscriberExt for S {} + +// === impl Identity === + +impl Layer for Identity {} + +impl Identity { + /// Returns a new `Identity` layer. + pub fn new() -> Self { + Self { _p: () } + } +} diff --git a/tracing-subscriber/src/layer/tests.rs b/tracing-subscriber/src/layer/tests.rs new file mode 100644 index 0000000000..68ac956a37 --- /dev/null +++ b/tracing-subscriber/src/layer/tests.rs @@ -0,0 +1,310 @@ +use super::*; + +pub(crate) struct NopSubscriber; + +impl Subscriber for NopSubscriber { + 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) {} +} + +#[derive(Debug)] +pub(crate) struct NopLayer; +impl Layer for NopLayer {} + +#[allow(dead_code)] +struct NopLayer2; +impl Layer for NopLayer2 {} + +/// A layer that holds a string. +/// +/// Used to test that pointers returned by downcasting are actually valid. +struct StringLayer(String); +impl Layer for StringLayer {} +struct StringLayer2(String); +impl Layer for StringLayer2 {} + +struct StringLayer3(String); +impl Layer for StringLayer3 {} + +pub(crate) struct StringSubscriber(String); + +impl Subscriber for StringSubscriber { + 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 assert_subscriber(_s: impl Subscriber) {} + +#[test] +fn layer_is_subscriber() { + let s = NopLayer.with_subscriber(NopSubscriber); + assert_subscriber(s) +} + +#[test] +fn two_layers_are_subscriber() { + let s = NopLayer.and_then(NopLayer).with_subscriber(NopSubscriber); + assert_subscriber(s) +} + +#[test] +fn three_layers_are_subscriber() { + let s = NopLayer + .and_then(NopLayer) + .and_then(NopLayer) + .with_subscriber(NopSubscriber); + assert_subscriber(s) +} + +#[test] +fn downcasts_to_subscriber() { + let s = NopLayer + .and_then(NopLayer) + .and_then(NopLayer) + .with_subscriber(StringSubscriber("subscriber".into())); + let subscriber = + ::downcast_ref::(&s).expect("subscriber should downcast"); + assert_eq!(&subscriber.0, "subscriber"); +} + +#[test] +fn downcasts_to_layer() { + let s = StringLayer("layer_1".into()) + .and_then(StringLayer2("layer_2".into())) + .and_then(StringLayer3("layer_3".into())) + .with_subscriber(NopSubscriber); + let layer = ::downcast_ref::(&s).expect("layer 1 should downcast"); + assert_eq!(&layer.0, "layer_1"); + let layer = + ::downcast_ref::(&s).expect("layer 2 should downcast"); + assert_eq!(&layer.0, "layer_2"); + let layer = + ::downcast_ref::(&s).expect("layer 3 should downcast"); + assert_eq!(&layer.0, "layer_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 RecordingLayer { + last_event_span: Arc>>, + } + + impl Layer for RecordingLayer + where + S: Subscriber + 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::subscriber::with_default( + crate::registry().with(RecordingLayer { + 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 layers + /// with and without per-layer filtering. + mod max_level_hints { + + use super::*; + use crate::filter::*; + + #[test] + fn mixed_with_unfiltered() { + let subscriber = crate::registry() + .with(NopLayer) + .with(NopLayer.with_filter(LevelFilter::INFO)); + assert_eq!(subscriber.max_level_hint(), None); + } + + #[test] + fn mixed_with_unfiltered_layered() { + let subscriber = crate::registry().with(NopLayer).with( + NopLayer + .with_filter(LevelFilter::INFO) + .and_then(NopLayer.with_filter(LevelFilter::TRACE)), + ); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn mixed_interleaved() { + let subscriber = crate::registry() + .with(NopLayer) + .with(NopLayer.with_filter(LevelFilter::INFO)) + .with(NopLayer) + .with(NopLayer.with_filter(LevelFilter::INFO)); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn mixed_layered() { + let subscriber = crate::registry() + .with(NopLayer.with_filter(LevelFilter::INFO).and_then(NopLayer)) + .with(NopLayer.and_then(NopLayer.with_filter(LevelFilter::INFO))); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn plf_only_unhinted() { + let subscriber = crate::registry() + .with(NopLayer.with_filter(LevelFilter::INFO)) + .with(NopLayer.with_filter(filter_fn(|_| true))); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn plf_only_unhinted_nested_outer() { + // if a nested tree of per-layer filters has an _outer_ filter with + // no max level hint, it should return `None`. + let subscriber = crate::registry() + .with( + NopLayer + .with_filter(LevelFilter::INFO) + .and_then(NopLayer.with_filter(LevelFilter::WARN)), + ) + .with( + NopLayer + .with_filter(filter_fn(|_| true)) + .and_then(NopLayer.with_filter(LevelFilter::DEBUG)), + ); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn plf_only_unhinted_nested_inner() { + // If a nested tree of per-layer 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 subscriber = dbg!(crate::registry().with( + NopLayer + .with_filter(filter_fn(|_| true)) + .and_then(NopLayer.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::INFO), + )); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn unhinted_nested_inner() { + let subscriber = dbg!(crate::registry() + .with(NopLayer.and_then(NopLayer).with_filter(LevelFilter::INFO)) + .with( + NopLayer + .with_filter(filter_fn(|_| true)) + .and_then(NopLayer.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::WARN), + )); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn unhinted_nested_inner_mixed() { + let subscriber = dbg!(crate::registry() + .with( + NopLayer + .and_then(NopLayer.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::INFO) + ) + .with( + NopLayer + .with_filter(filter_fn(|_| true)) + .and_then(NopLayer.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::WARN), + )); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn plf_only_picks_max() { + let subscriber = crate::registry() + .with(NopLayer.with_filter(LevelFilter::WARN)) + .with(NopLayer.with_filter(LevelFilter::DEBUG)); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn many_plf_only_picks_max() { + let subscriber = crate::registry() + .with(NopLayer.with_filter(LevelFilter::WARN)) + .with(NopLayer.with_filter(LevelFilter::DEBUG)) + .with(NopLayer.with_filter(LevelFilter::INFO)) + .with(NopLayer.with_filter(LevelFilter::ERROR)); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn nested_plf_only_picks_max() { + let subscriber = crate::registry() + .with( + NopLayer.with_filter(LevelFilter::INFO).and_then( + NopLayer + .with_filter(LevelFilter::WARN) + .and_then(NopLayer.with_filter(LevelFilter::DEBUG)), + ), + ) + .with( + NopLayer + .with_filter(LevelFilter::INFO) + .and_then(NopLayer.with_filter(LevelFilter::ERROR)), + ); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::DEBUG)); + } + } +} diff --git a/tracing-subscriber/src/lib.rs b/tracing-subscriber/src/lib.rs index 6cc877bddb..67fa24b0fa 100644 --- a/tracing-subscriber/src/lib.rs +++ b/tracing-subscriber/src/lib.rs @@ -72,7 +72,15 @@ html_logo_url = "https://raw.githubusercontent.com/tokio-rs/tracing/master/assets/logo-type.png", issue_tracker_base_url = "https://github.com/tokio-rs/tracing/issues/" )] -#![cfg_attr(docsrs, feature(doc_cfg), deny(rustdoc::broken_intra_doc_links))] +#![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/extensions.rs b/tracing-subscriber/src/registry/extensions.rs index 5db1911d81..35f2781c57 100644 --- a/tracing-subscriber/src/registry/extensions.rs +++ b/tracing-subscriber/src/registry/extensions.rs @@ -108,8 +108,8 @@ impl<'a> ExtensionsMut<'a> { /// A type map of span extensions. /// -/// [ExtensionsInner] is used by [Data] to store and -/// span-specific data. A given [Layer] can read and write +/// [ExtensionsInner] is used by `SpanData` to store and +/// span-specific data. A given `Layer` can read and write /// data that it is interested in recording and emitting. #[derive(Default)] pub(crate) struct ExtensionsInner { diff --git a/tracing-subscriber/src/registry/mod.rs b/tracing-subscriber/src/registry/mod.rs index 5db41e35d3..9951c50d30 100644 --- a/tracing-subscriber/src/registry/mod.rs +++ b/tracing-subscriber/src/registry/mod.rs @@ -64,6 +64,8 @@ //! [`SpanData`]: trait.SpanData.html use std::fmt::Debug; +#[cfg(feature = "registry")] +use crate::filter::FilterId; use tracing_core::{field::FieldSet, span::Id, Metadata}; /// A module containing a type map of span extensions. @@ -128,8 +130,34 @@ pub trait LookupSpan<'a> { Some(SpanRef { registry: self, data, + #[cfg(feature = "registry")] + filter: FilterId::none(), }) } + + /// Registers a [`Filter`] for [per-layer filtering] with this + /// [`Subscriber`]. + /// + /// The [`Filter`] can then use the returned [`FilterId`] to + /// [check if it previously enabled a span][check]. + /// + /// # Panics + /// + /// If this `Subscriber` does not support [per-layer filtering]. + /// + /// [`Filter`]: crate::layer::Filter + /// [per-layer filtering]: crate::layer::Layer#per-layer-filtering + /// [`Subscriber`]: tracing_core::Subscriber + /// [`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. @@ -154,6 +182,23 @@ pub trait SpanData<'a> { /// The extensions may be used by `Layer`s to store additional data /// describing the span. fn extensions_mut(&self) -> ExtensionsMut<'_>; + + /// Returns `true` if this span is enabled for the [per-layer filter][plf] + /// corresponding to the provided [`FilterId`]. + /// + /// ## Default Implementation + /// + /// By default, this method assumes that the [`LookupSpan`] implementation + /// does not support [per-layer filtering][plf], and always returns `true`. + /// + /// [plf]: crate::layer::Layer#per-layer-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]. @@ -168,6 +213,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. @@ -177,6 +225,9 @@ pub struct SpanRef<'a, R: LookupSpan<'a>> { pub struct Scope<'a, R> { registry: &'a R, next: Option, + + #[cfg(feature = "registry")] + filter: FilterId, } impl<'a, R> Scope<'a, R> @@ -212,9 +263,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); + } } } @@ -333,15 +400,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-layer filtering, and may \ + return the `Id` of a disabled span if per-layer 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 PLF 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 PLF. which is not great. + // + // i think if we want this to play nice with PLF, 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 + // PLF in its current form (which is what we would want to do if we want + // to release PLF 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, @@ -419,6 +540,9 @@ where Scope { registry: self.registry, next: Some(self.id()), + + #[cfg(feature = "registry")] + filter: self.filter, } } @@ -436,6 +560,9 @@ where Parents(Scope { registry: self.registry, next: self.parent_id().cloned(), + + #[cfg(feature = "registry")] + filter: self.filter, }) } @@ -472,6 +599,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"))] diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index 1c77c0a823..0619aadd0d 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::{ @@ -91,6 +92,7 @@ use tracing_core::{ pub struct Registry { spans: Pool, current_spans: ThreadLocal>, + next_filter_id: u8, } /// Span data stored in a [`Registry`]. @@ -119,6 +121,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, @@ -134,6 +137,7 @@ impl Default for Registry { Self { spans: Pool::new(), current_spans: ThreadLocal::new(), + next_filter_id: 0, } } } @@ -197,6 +201,14 @@ impl Registry { is_closing: false, } } + + pub(crate) fn has_per_layer_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! { @@ -210,10 +222,17 @@ thread_local! { impl Subscriber for Registry { fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + if self.has_per_layer_filters() { + return FilterState::take_interest().unwrap_or_else(Interest::always); + } + Interest::always() } fn enabled(&self, _: &Metadata<'_>) -> bool { + if self.has_per_layer_filters() { + return FilterState::event_enabled(); + } true } @@ -236,6 +255,14 @@ impl Subscriber 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_layer_filters()); + } + } + let refs = data.ref_count.get_mut(); debug_assert_eq!(*refs, 0); *refs = 1; @@ -342,6 +369,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 === @@ -399,6 +432,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 === @@ -439,6 +477,7 @@ impl Default for DataInner { }; Self { + filter_map: FilterMap::default(), metadata: &NULL_METADATA, parent: None, ref_count: AtomicUsize::new(0), @@ -482,12 +521,14 @@ impl Clear for DataInner { l.into_inner() }) .clear(); + + self.filter_map = FilterMap::default(); } } #[cfg(test)] mod tests { - use super::Registry; + use super::*; use crate::{layer::Context, registry::LookupSpan, Layer}; use std::{ collections::HashMap, @@ -500,6 +541,10 @@ mod tests { Subscriber, }; + #[derive(Debug)] + struct DoesNothing; + impl Layer for DoesNothing {} + struct AssertionLayer; impl Layer for AssertionLayer where diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index b0b372c13f..4a3f7e59d8 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 14a069dae0..6dacf9db87 100644 --- a/tracing-subscriber/src/reload.rs +++ b/tracing-subscriber/src/reload.rs @@ -62,6 +62,10 @@ where L: crate::Layer + 'static, S: Subscriber, { + fn on_layer(&mut self, subscriber: &mut S) { + try_lock!(self.inner.write(), else return).on_layer(subscriber); + } + #[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/tests/cached_layer_filters_dont_break_other_layers.rs b/tracing-subscriber/tests/cached_layer_filters_dont_break_other_layers.rs new file mode 100644 index 0000000000..00e98a994c --- /dev/null +++ b/tracing-subscriber/tests/cached_layer_filters_dont_break_other_layers.rs @@ -0,0 +1,123 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::Level; +use tracing_subscriber::{filter::LevelFilter, prelude::*}; + +#[test] +fn layer_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_layer_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) -> (ExpectLayer, subscriber::MockHandle) { + layer::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) -> (ExpectLayer, subscriber::MockHandle) { + layer::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_layer_filters_dont_break_other_layers.rs b/tracing-subscriber/tests/hinted_layer_filters_dont_break_other_layers.rs new file mode 100644 index 0000000000..897dae2822 --- /dev/null +++ b/tracing-subscriber/tests/hinted_layer_filters_dont_break_other_layers.rs @@ -0,0 +1,131 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::{Level, Metadata, Subscriber}; +use tracing_subscriber::{filter::DynFilterFn, layer::Context, prelude::*}; + +#[test] +fn layer_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_layer_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 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); + 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::layer::Context<'_, S>| { + metadata.level() <= &Level::INFO + }) as fn(&Metadata<'_>, &Context<'_, S>) -> bool, + ) + .with_max_level_hint(Level::INFO) +} + +fn unfiltered(name: &str) -> (ExpectLayer, subscriber::MockHandle) { + layer::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) -> (ExpectLayer, subscriber::MockHandle) { + layer::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/layer_filter_interests_are_cached.rs b/tracing-subscriber/tests/layer_filter_interests_are_cached.rs new file mode 100644 index 0000000000..d89d3bf174 --- /dev/null +++ b/tracing-subscriber/tests/layer_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::{Level, Subscriber}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn layer_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) = layer::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/layer_filters/filter_scopes.rs b/tracing-subscriber/tests/layer_filters/filter_scopes.rs new file mode 100644 index 0000000000..7fd7d843b4 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/filter_scopes.rs @@ -0,0 +1,131 @@ +use super::*; + +#[test] +fn filters_span_scopes() { + let (debug_layer, debug_handle) = layer::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_layer, info_handle) = layer::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_layer, warn_handle) = layer::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_layer.with_filter(LevelFilter::DEBUG)) + .with(info_layer.with_filter(LevelFilter::INFO)) + .with(warn_layer.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_layer(target: &'static str) -> (ExpectLayer, subscriber::MockHandle) { + layer::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_layer, a_handle) = target_layer("a"); + let (b_layer, b_handle) = target_layer("b"); + let (all_layer, all_handle) = layer::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_layer.with_filter(LevelFilter::INFO)) + .with(a_layer.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "a" || target == module_path!() + }))) + .with(b_layer.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/layer_filters/main.rs b/tracing-subscriber/tests/layer_filters/main.rs new file mode 100644 index 0000000000..445b029cf6 --- /dev/null +++ b/tracing-subscriber/tests/layer_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_layer_filters() { + let (trace_layer, trace_handle) = layer::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_layer, debug_handle) = layer::named("debug") + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (info_layer, info_handle) = layer::named("info") + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(trace_layer.with_filter(LevelFilter::TRACE)) + .with(debug_layer.with_filter(LevelFilter::DEBUG)) + .with(info_layer.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_layer_filters_spans() { + let (trace_layer, trace_handle) = layer::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_layer, debug_handle) = layer::named("debug") + .new_span(span::mock().at_level(Level::DEBUG)) + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (info_layer, info_handle) = layer::named("info") + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(trace_layer.with_filter(LevelFilter::TRACE)) + .with(debug_layer.with_filter(LevelFilter::DEBUG)) + .with(info_layer.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_layers_still_work() { + let (expect, handle) = layer::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) = layer::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_layer_filters() { + let (expect, handle) = layer::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) = layer::named("all_targets") + .event(event::msg("hello foo")) + .event(event::msg("hello bar")) + .done() + .run_with_handle(); + + let (foo, foo_handle) = layer::named("foo_target") + .event(event::msg("hello foo")) + .done() + .run_with_handle(); + + let (bar, bar_handle) = layer::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/layer_filters/trees.rs b/tracing-subscriber/tests/layer_filters/trees.rs new file mode 100644 index 0000000000..18cdd8ccc8 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/trees.rs @@ -0,0 +1,146 @@ +use super::*; + +#[test] +fn basic_trees() { + let (with_target, with_target_handle) = layer::named("info_with_target") + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .done() + .run_with_handle(); + + let (info, info_handle) = layer::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) = layer::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_layer(target: &'static str) -> (ExpectLayer, subscriber::MockHandle) { + layer::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_layer, a_handle) = target_layer("a"); + let (b_layer, b_handle) = target_layer("b"); + let (info_layer, info_handle) = layer::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_layer, all_handle) = layer::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_layer = a_layer.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "a" || target == module_path!() + })); + + let b_layer = b_layer.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "b" || target == module_path!() + })); + + let info_tree = info_layer + .and_then(a_layer) + .and_then(b_layer) + .with_filter(LevelFilter::INFO); + + let subscriber = tracing_subscriber::registry() + .with(info_tree) + .with(all_layer); + 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/multiple_layer_filter_interests_cached.rs b/tracing-subscriber/tests/multiple_layer_filter_interests_cached.rs new file mode 100644 index 0000000000..5c25e7f03c --- /dev/null +++ b/tracing-subscriber/tests/multiple_layer_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::{Level, Subscriber}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn multiple_layer_filter_interests_are_cached() { + // This layer 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_layer, info_handle) = layer::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_layer = info_layer.with_filter(filter); + + // This layer 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_layer, warn_handle) = layer::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_layer = warn_layer.with_filter(filter); + + let subscriber = tracing_subscriber::registry() + .with(warn_layer) + .with(info_layer); + 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 layer (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 layer (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 layer (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 layer (after second set of events)", + level + ); + } + } + + info_handle.assert_finished(); + warn_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/support.rs b/tracing-subscriber/tests/support.rs index a69d95e84d..af96cea9f5 100644 --- a/tracing-subscriber/tests/support.rs +++ b/tracing-subscriber/tests/support.rs @@ -1,8 +1,412 @@ -#[cfg(test)] -pub use self::support::*; +#![allow(missing_docs, dead_code)] +pub use self::support::{event, field, span, subscriber}; // This has to have the same name as the module in `tracing`. -#[path = "../../tracing/tests/support/mod.rs"] -#[cfg(test)] // path attribute requires referenced module to have same name so allow module inception here #[allow(clippy::module_inception)] +#[path = "../../tracing/tests/support/mod.rs"] mod support; + +use self::{ + event::MockEvent, + span::{MockSpan, NewSpan}, + subscriber::{Expect, MockHandle}, +}; +use tracing_core::{ + span::{Attributes, Id, Record}, + Event, Subscriber, +}; +use tracing_subscriber::{ + layer::{Context, Layer}, + registry::{LookupSpan, SpanRef}, +}; + +use std::{ + collections::VecDeque, + fmt, + sync::{Arc, Mutex}, +}; + +pub mod layer { + use super::ExpectLayerBuilder; + + pub fn mock() -> ExpectLayerBuilder { + ExpectLayerBuilder { + expected: Default::default(), + name: std::thread::current() + .name() + .map(String::from) + .unwrap_or_default(), + } + } + + pub fn named(name: impl std::fmt::Display) -> ExpectLayerBuilder { + mock().named(name) + } +} + +pub struct ExpectLayerBuilder { + expected: VecDeque, + name: String, +} + +pub struct ExpectLayer { + expected: Arc>>, + current: Mutex>, + name: String, +} + +impl ExpectLayerBuilder { + /// 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) -> ExpectLayer { + ExpectLayer { + expected: Arc::new(Mutex::new(self.expected)), + name: self.name, + current: Mutex::new(Vec::new()), + } + } + + pub fn run_with_handle(self) -> (ExpectLayer, MockHandle) { + let expected = Arc::new(Mutex::new(self.expected)); + let handle = MockHandle::new(expected.clone(), self.name.clone()); + let layer = ExpectLayer { + expected, + name: self.name, + current: Mutex::new(Vec::new()), + }; + (layer, handle) + } +} + +impl ExpectLayer { + 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 Layer for ExpectLayer +where + S: Subscriber + 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<'_, S>) { + 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<'_, S>) { + 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<'_, S>) { + // TODO: it should be possible to expect spans to follow from other spans + } + + fn new_span(&self, span: &Attributes<'_>, id: &Id, cx: Context<'_, S>) { + 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<'_, S>) { + 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<'_, S>) { + 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<'_, S>) { + 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<'_, S>) { + panic!("well-behaved subscribers should never do this to us, lol"); + } +} + +impl fmt::Debug for ExpectLayer { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("ExpectLayer"); + 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_layer_filters_dont_break_other_layers.rs b/tracing-subscriber/tests/unhinted_layer_filters_dont_break_other_layers.rs new file mode 100644 index 0000000000..9fa5c6bd41 --- /dev/null +++ b/tracing-subscriber/tests/unhinted_layer_filters_dont_break_other_layers.rs @@ -0,0 +1,123 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::Level; +use tracing_subscriber::{filter::DynFilterFn, prelude::*}; + +#[test] +fn layer_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_layer_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) -> (ExpectLayer, subscriber::MockHandle) { + layer::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) -> (ExpectLayer, subscriber::MockHandle) { + layer::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 5d757d821a..b29d622330 100644 --- a/tracing/tests/event.rs +++ b/tracing/tests/event.rs @@ -60,8 +60,9 @@ event_without_message! {nonzeroi32_event_without_message: std::num::NonZeroI32:: #[test] fn event_with_message() { let (subscriber, handle) = subscriber::mock() - .event(event::mock().with_fields(field::mock("message").with_value( - &tracing::field::debug(format_args!("hello from my event! yak shaved = {:?}", true)), + .event(event::msg(format_args!( + "hello from my event! yak shaved = {:?}", + true ))) .done() .run_with_handle(); @@ -82,12 +83,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(), ), ) @@ -111,11 +110,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/event.rs b/tracing/tests/support/event.rs index 7033d8a134..332ff09d7c 100644 --- a/tracing/tests/support/event.rs +++ b/tracing/tests/support/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(in crate::support) 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(in crate::support) fn check(&mut self, event: &tracing::Event<'_>) { + pub fn check( + &mut self, + event: &tracing::Event<'_>, + get_parent_name: impl FnOnce() -> Option, + subscriber_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), subscriber_name); + assert!( + meta.is_event(), + "[{}] expected {}, but got {:?}", + subscriber_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, subscriber_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(), + subscriber_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/tests/support/field.rs b/tracing/tests/support/field.rs index 0e7799fa26..bdf22aba1d 100644 --- a/tracing/tests/support/field.rs +++ b/tracing/tests/support/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,20 @@ 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, + subscriber_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`{}{}`", + subscriber_name, ctx, name, expected, @@ -127,15 +141,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`{}{}`", + subscriber_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, subscriber_name: &'a str) -> CheckVisitor<'a> { + CheckVisitor { + expect: self, + ctx, + subscriber_name, + } } pub fn is_empty(&self) -> bool { @@ -159,38 +177,43 @@ impl fmt::Display for MockValue { pub struct CheckVisitor<'a> { expect: &'a mut Expect, - ctx: String, + ctx: &'a str, + subscriber_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.subscriber_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.subscriber_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.subscriber_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.subscriber_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.subscriber_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.subscriber_name, + ) } } @@ -198,7 +221,8 @@ impl<'a> CheckVisitor<'a> { pub fn finish(self) { assert!( self.expect.fields.is_empty(), - "{}missing {}", + "[{}] {}missing {}", + self.subscriber_name, self.expect, self.ctx ); diff --git a/tracing/tests/support/metadata.rs b/tracing/tests/support/metadata.rs index 2c3606b05e..d10395da46 100644 --- a/tracing/tests/support/metadata.rs +++ b/tracing/tests/support/metadata.rs @@ -9,12 +9,18 @@ pub struct Expect { } impl Expect { - pub(in crate::support) fn check(&self, actual: &Metadata<'_>, ctx: fmt::Arguments<'_>) { + pub(in crate::support) fn check( + &self, + actual: &Metadata<'_>, + ctx: fmt::Arguments<'_>, + subscriber_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 `{}`", + subscriber_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", + subscriber_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", + subscriber_name, ctx, expected_target, target, diff --git a/tracing/tests/support/mod.rs b/tracing/tests/support/mod.rs index 7900f38c76..c65f45b570 100644 --- a/tracing/tests/support/mod.rs +++ b/tracing/tests/support/mod.rs @@ -12,3 +12,73 @@ pub(in crate::support) enum Parent { 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, + subscriber_name: &str, + ) { + match self { + Parent::ExplicitRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to be an explicit root, but its parent was actually {:?} (name: {:?})", + subscriber_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: {:?})", + subscriber_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: {:?})", + subscriber_name, + ctx, + provided_parent, + parent_name, + ); + assert!( + parent_name.is_none(), + "[{}] expected {} to be contextual a root, but we were inside span {:?}", + subscriber_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: {:?})", + subscriber_name, + ctx, + provided_parent, + parent_name, + ); + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have contextual parent {:?}, but got {:?}", + subscriber_name, + ctx, + expected_parent, + parent_name, + ); + } + } + } +} diff --git a/tracing/tests/support/span.rs b/tracing/tests/support/span.rs index 21112a8818..e35e7ed0f1 100644 --- a/tracing/tests/support/span.rs +++ b/tracing/tests/support/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(in crate::support) metadata: metadata::Expect, } -#[derive(Debug, Default, Eq, PartialEq)] +#[derive(Default, Eq, PartialEq)] pub struct NewSpan { pub(in crate::support) span: MockSpan, pub(in crate::support) 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, @@ -96,10 +104,25 @@ impl MockSpan { ..Default::default() } } +} + +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); + } - pub(in crate::support) fn check_metadata(&self, actual: &tracing::Metadata<'_>) { - self.metadata.check(actual, format_args!("span {}", self)); - assert!(actual.is_span(), "expected a span but got {:?}", actual); + s.finish() } } @@ -154,6 +177,32 @@ impl NewSpan { ..self } } + + pub fn check( + &mut self, + span: &tracing_core::span::Attributes<'_>, + get_parent_name: impl FnOnce() -> Option, + subscriber_name: &str, + ) { + let meta = span.metadata(); + let name = meta.name(); + self.span + .metadata + .check(meta, format_args!("span `{}`", name), subscriber_name); + let mut checker = self.fields.checker(name, subscriber_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), + subscriber_name, + ) + } + } } impl fmt::Display for NewSpan { @@ -165,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/tests/support/subscriber.rs b/tracing/tests/support/subscriber.rs index 1163aab0c5..8fbffbb396 100644 --- a/tracing/tests/support/subscriber.rs +++ b/tracing/tests/support/subscriber.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), @@ -220,7 +219,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(); } @@ -233,69 +233,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)), } } @@ -319,70 +268,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( @@ -523,11 +416,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 ); @@ -536,26 +433,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, ), } }