From 8e207deed96e5762eeaf0c26654bc02842378b03 Mon Sep 17 00:00:00 2001 From: Christopher Durham Date: Tue, 21 Jun 2022 14:02:21 -0400 Subject: [PATCH] core, subscriber: add `event_enabled` to filter events on fields (#2008) ## Motivation Allow filter layers to filter on the contents of events (see #2007). ## Solution This branch adds a new `Subscriber::event_enabled` method, taking an `Event` and returning `bool`. This is called before the `Subscriber::event` method, and if it returns `false`, `Subscriber::event` is not called. For simple subscriber (e.g. not using `Layer`s), the `event_enabled` method is not particulary necessary, as the subscriber can just skip the `event` call. However, this branch also adds a new `Layer::event_enabled` method, with the signature: ```rust fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool; ``` This is called before `Layer::on_event`, and if `event_enabled` returns `false`, `on_event` is not called (nor is `Subscriber::event`). This allows filter `Layer`s to filter out an `Event` based on its fields. Closes #2007 --- tracing-core/src/dispatcher.rs | 4 +- tracing-core/src/subscriber.rs | 26 ++++++++++ tracing-subscriber/src/layer/layered.rs | 21 ++++++++ tracing-subscriber/src/layer/mod.rs | 65 +++++++++++++++++++++++++ 4 files changed, 115 insertions(+), 1 deletion(-) diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 741744437c..041722c366 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -511,7 +511,9 @@ impl Dispatch { /// [`event`]: super::subscriber::Subscriber::event #[inline] pub fn event(&self, event: &Event<'_>) { - self.subscriber.event(event) + if self.subscriber.event_enabled(event) { + self.subscriber.event(event); + } } /// Records that a span has been can_enter. diff --git a/tracing-core/src/subscriber.rs b/tracing-core/src/subscriber.rs index 9c7e210b06..a6f0834e2c 100644 --- a/tracing-core/src/subscriber.rs +++ b/tracing-core/src/subscriber.rs @@ -60,6 +60,9 @@ use crate::stdlib::{ /// See also the [documentation on the callsite registry][cs-reg] for details /// on [`register_callsite`]. /// +/// - [`event_enabled`] is called once before every call to the [`event`] +/// method. This can be used to implement filtering on events once their field +/// values are known, but before any processing is done in the `event` method. /// - [`clone_span`] is called every time a span ID is cloned, and [`try_close`] /// is called when a span ID is dropped. By default, these functions do /// nothing. However, they can be used to implement reference counting for @@ -75,6 +78,8 @@ use crate::stdlib::{ /// [`clone_span`]: Subscriber::clone_span /// [`try_close`]: Subscriber::try_close /// [cs-reg]: crate::callsite#registering-callsites +/// [`event`]: Subscriber::event +/// [`event_enabled`]: Subscriber::event_enabled pub trait Subscriber: 'static { // === Span registry methods ============================================== @@ -291,6 +296,17 @@ pub trait Subscriber: 'static { /// follow from _b_), it may silently do nothing. fn record_follows_from(&self, span: &span::Id, follows: &span::Id); + /// Determine if an [`Event`] should be recorded. + /// + /// By default, this returns `true` and `Subscriber`s can filter events in + /// [`event`][Self::event] without any penalty. However, when `event` is + /// more complicated, this can be used to determine if `event` should be + /// called at all, separating out the decision from the processing. + fn event_enabled(&self, event: &Event<'_>) -> bool { + let _ = event; + true + } + /// Records that an [`Event`] has occurred. /// /// This method will be invoked when an Event is constructed by @@ -696,6 +712,11 @@ where self.as_ref().record_follows_from(span, follows) } + #[inline] + fn event_enabled(&self, event: &Event<'_>) -> bool { + self.as_ref().event_enabled(event) + } + #[inline] fn event(&self, event: &Event<'_>) { self.as_ref().event(event) @@ -776,6 +797,11 @@ where self.as_ref().record_follows_from(span, follows) } + #[inline] + fn event_enabled(&self, event: &Event<'_>) -> bool { + self.as_ref().event_enabled(event) + } + #[inline] fn event(&self, event: &Event<'_>) { self.as_ref().event(event) diff --git a/tracing-subscriber/src/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs index 5c9b934e35..0160f99c1d 100644 --- a/tracing-subscriber/src/layer/layered.rs +++ b/tracing-subscriber/src/layer/layered.rs @@ -139,6 +139,16 @@ where self.layer.on_follows_from(span, follows, self.ctx()); } + fn event_enabled(&self, event: &Event<'_>) -> bool { + if self.layer.event_enabled(event, self.ctx()) { + // if the outer layer enables the event, ask the inner subscriber. + self.inner.event_enabled(event) + } else { + // otherwise, the event is disabled by this layer + false + } + } + fn event(&self, event: &Event<'_>) { self.inner.event(event); self.layer.on_event(event, self.ctx()); @@ -278,6 +288,17 @@ where self.layer.on_follows_from(span, follows, ctx); } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + if self.layer.event_enabled(event, ctx.clone()) { + // if the outer layer enables the event, ask the inner subscriber. + self.inner.event_enabled(event, ctx) + } else { + // otherwise, the event is disabled by this layer + false + } + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { self.inner.on_event(event, ctx.clone()); diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index d94742f0f2..a15870e691 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/tracing-subscriber/src/layer/mod.rs @@ -415,6 +415,28 @@ //! [`Interest::never()`] from its [`register_callsite`] method, filter //! evaluation will short-circuit and the span or event will be disabled. //! +//! ### Enabling Interest +//! +//! Whenever an tracing event (or span) is emitted, it goes through a number of +//! steps to determine how and how much it should be processed. The earlier an +//! event is disabled, the less work has to be done to process the event, so +//! `Layer`s that implement filtering should attempt to disable unwanted +//! events as early as possible. In order, each event checks: +//! +//! - [`register_callsite`], once per callsite (roughly: once per time that +//! `event!` or `span!` is written in the source code; this is cached at the +//! callsite). See [`Subscriber::register_callsite`] and +//! [`tracing_core::callsite`] for a summary of how this behaves. +//! - [`enabled`], once per emitted event (roughly: once per time that `event!` +//! or `span!` is *executed*), and only if `register_callsite` regesters an +//! [`Interest::sometimes`]. This is the main customization point to globally +//! filter events based on their [`Metadata`]. If an event can be disabled +//! based only on [`Metadata`], it should be, as this allows the construction +//! of the actual `Event`/`Span` to be skipped. +//! - For events only (and not spans), [`event_enabled`] is called just before +//! processing the event. This gives layers one last chance to say that +//! an event should be filtered out, now that the event's fields are known. +//! //! ## Per-Layer Filtering //! //! **Note**: per-layer filtering APIs currently require the [`"registry"` crate @@ -634,6 +656,7 @@ //! [the current span]: Context::current_span //! [`register_callsite`]: Layer::register_callsite //! [`enabled`]: Layer::enabled +//! [`event_enabled`]: Layer::event_enabled //! [`on_enter`]: Layer::on_enter //! [`Layer::register_callsite`]: Layer::register_callsite //! [`Layer::enabled`]: Layer::enabled @@ -832,6 +855,31 @@ where // 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>) {} + /// Called before [`on_event`], to determine if `on_event` should be called. + /// + ///
+ /// 
+    ///
+    /// **Note**: This method determines whether an event is globally enabled,
+    /// *not* whether the individual `Layer` will be notified about the
+    /// event. This is intended to be used by `Layer`s that implement
+    /// filtering for the entire stack. `Layer`s which do not wish to be
+    /// notified about certain events but do not wish to globally disable them
+    /// should ignore those events in their [on_event][Self::on_event].
+    ///
+    ///
+ /// + /// See [the trait-level documentation] for more information on filtering + /// with `Layer`s. + /// + /// [`on_event`]: Self::on_event + /// [`Interest`]: tracing_core::Interest + /// [the trait-level documentation]: #filtering-with-layers + #[inline] // collapse this to a constant please mrs optimizer + fn event_enabled(&self, _event: &Event<'_>, _ctx: Context<'_, S>) -> bool { + true + } + /// Notifies this layer that an event has occurred. fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, S>) {} @@ -1460,6 +1508,14 @@ where } } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + match self { + Some(ref inner) => inner.event_enabled(event, ctx), + None => false, + } + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { if let Some(ref inner) = self { @@ -1548,6 +1604,11 @@ feature! { self.deref().on_follows_from(span, follows, ctx) } + #[inline] + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + self.deref().event_enabled(event, ctx) + } + #[inline] fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { self.deref().on_event(event, ctx) @@ -1629,6 +1690,10 @@ feature! { self.iter().all(|l| l.enabled(metadata, ctx.clone())) } + fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, S>) -> bool { + self.iter().all(|l| l.event_enabled(event, ctx.clone())) + } + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { for l in self { l.on_new_span(attrs, id, ctx.clone());