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

@@ -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.

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)

tracing-subscriber/src/fmt/mod.rs

@@ -397,6 +397,11 @@ where
         self.inner.record_follows_from(span, follows)
     }
 
+    #[inline]
+    fn event_enabled(&self, event: &Event<'_>) -> bool {
+        self.inner.event_enabled(event)
+    }
+
     #[inline]
     fn event(&self, event: &Event<'_>) {
         self.inner.event(event);

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

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.
+    ///
+    /// <div class="example-wrap" style="display:inline-block">
+    /// <pre class="ignore" style="white-space:normal;font:inherit;">
+    ///
+    /// **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].
+    ///
+    /// </pre></div>
+    ///
+    /// 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());

tracing-subscriber/src/reload.rs

@@ -134,6 +134,11 @@ where
         try_lock!(self.inner.read()).on_follows_from(span, follows, ctx)
     }
 
+    #[inline]
+    fn event_enabled(&self, event: &Event<'_>, ctx: layer::Context<'_, S>) -> bool {
+        try_lock!(self.inner.read(), else return false).event_enabled(event, ctx)
+    }
+
     #[inline]
     fn on_event(&self, event: &Event<'_>, ctx: layer::Context<'_, S>) {
         try_lock!(self.inner.read()).on_event(event, ctx)

tracing-subscriber/tests/event_enabling.rs

@@ -0,0 +1,81 @@
+#![cfg(feature = "registry")]
+
+use std::sync::{Arc, Mutex};
+use tracing::{subscriber::with_default, Event, Metadata, Subscriber};
+use tracing_subscriber::{layer::Context, prelude::*, registry, Layer};
+
+struct TrackingLayer {
+    enabled: bool,
+    event_enabled_count: Arc<Mutex<usize>>,
+    event_enabled: bool,
+    on_event_count: Arc<Mutex<usize>>,
+}
+
+impl<C> Layer<C> for TrackingLayer
+where
+    C: Subscriber + Send + Sync + 'static,
+{
+    fn enabled(&self, _metadata: &Metadata<'_>, _ctx: Context<'_, C>) -> bool {
+        self.enabled
+    }
+
+    fn event_enabled(&self, _event: &Event<'_>, _ctx: Context<'_, C>) -> bool {
+        *self.event_enabled_count.lock().unwrap() += 1;
+        self.event_enabled
+    }
+
+    fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) {
+        *self.on_event_count.lock().unwrap() += 1;
+    }
+}
+
+#[test]
+fn event_enabled_is_only_called_once() {
+    let event_enabled_count = Arc::new(Mutex::default());
+    let count = event_enabled_count.clone();
+    let subscriber = registry().with(TrackingLayer {
+        enabled: true,
+        event_enabled_count,
+        event_enabled: true,
+        on_event_count: Arc::new(Mutex::default()),
+    });
+    with_default(subscriber, || {
+        tracing::error!("hiya!");
+    });
+
+    assert_eq!(1, *count.lock().unwrap());
+}
+
+#[test]
+fn event_enabled_not_called_when_not_enabled() {
+    let event_enabled_count = Arc::new(Mutex::default());
+    let count = event_enabled_count.clone();
+    let subscriber = registry().with(TrackingLayer {
+        enabled: false,
+        event_enabled_count,
+        event_enabled: true,
+        on_event_count: Arc::new(Mutex::default()),
+    });
+    with_default(subscriber, || {
+        tracing::error!("hiya!");
+    });
+
+    assert_eq!(0, *count.lock().unwrap());
+}
+
+#[test]
+fn event_disabled_does_disable_event() {
+    let on_event_count = Arc::new(Mutex::default());
+    let count = on_event_count.clone();
+    let subscriber = registry().with(TrackingLayer {
+        enabled: true,
+        event_enabled_count: Arc::new(Mutex::default()),
+        event_enabled: false,
+        on_event_count,
+    });
+    with_default(subscriber, || {
+        tracing::error!("hiya!");
+    });
+
+    assert_eq!(0, *count.lock().unwrap());
+}