Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add Subscribe::event_enabled to conditionally dis/enable events based on fields #2008

Merged
merged 12 commits into from
Jun 21, 2022
26 changes: 26 additions & 0 deletions tracing-core/src/collect.rs
Original file line number Diff line number Diff line change
Expand Up @@ -57,6 +57,9 @@ use core::ptr::NonNull;
/// 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
Expand All @@ -72,6 +75,8 @@ use core::ptr::NonNull;
/// [`clone_span`]: Collect::clone_span
/// [`try_close`]: Collect::try_close
/// [cs-reg]: crate::callsite#registering-callsites
/// [`event`]: Collect::event
/// [`event_enabled`]: Collect::event_enabled
pub trait Collect: 'static {
// === Span registry methods ==============================================

Expand Down Expand Up @@ -288,6 +293,17 @@ pub trait Collect: '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 collectors 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
}
hawkw marked this conversation as resolved.
Show resolved Hide resolved

/// Records that an [`Event`] has occurred.
///
/// This method will be invoked when an Event is constructed by
Expand Down Expand Up @@ -688,6 +704,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)
Expand Down Expand Up @@ -762,6 +783,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)
Expand Down
5 changes: 4 additions & 1 deletion tracing-core/src/dispatch.rs
Original file line number Diff line number Diff line change
Expand Up @@ -682,7 +682,10 @@ impl Dispatch {
/// [`event`]: super::collect::Collect::event
#[inline]
pub fn event(&self, event: &Event<'_>) {
self.collector().event(event)
let collector = self.collector();
if collector.event_enabled(event) {
CAD97 marked this conversation as resolved.
Show resolved Hide resolved
collector.event(event);
}
}

/// Records that a span has been can_enter.
Expand Down
5 changes: 5 additions & 0 deletions tracing-subscriber/src/fmt/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -393,6 +393,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);
Expand Down
5 changes: 5 additions & 0 deletions tracing-subscriber/src/reload.rs
Original file line number Diff line number Diff line change
Expand Up @@ -106,6 +106,11 @@ where
try_lock!(self.inner.read()).on_follows_from(span, follows, ctx)
}

#[inline]
fn event_enabled(&self, event: &Event<'_>, ctx: subscribe::Context<'_, C>) -> bool {
try_lock!(self.inner.read(), else return false).event_enabled(event, ctx)
}

#[inline]
fn on_event(&self, event: &Event<'_>, ctx: subscribe::Context<'_, C>) {
try_lock!(self.inner.read()).on_event(event, ctx)
Expand Down
21 changes: 21 additions & 0 deletions tracing-subscriber/src/subscribe/layered.rs
Original file line number Diff line number Diff line change
Expand Up @@ -138,6 +138,16 @@ where
self.subscriber.on_follows_from(span, follows, self.ctx());
}

fn event_enabled(&self, event: &Event<'_>) -> bool {
if self.subscriber.event_enabled(event, self.ctx()) {
// if the outer subscriber enables the event, ask the inner collector.
self.inner.event_enabled(event)
} else {
// otherwise, the event is disabled by this subscriber
false
}
}

fn event(&self, event: &Event<'_>) {
self.inner.event(event);
self.subscriber.on_event(event, self.ctx());
Expand Down Expand Up @@ -280,6 +290,17 @@ where
self.subscriber.on_follows_from(span, follows, ctx);
}

#[inline]
fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, C>) -> bool {
if self.subscriber.event_enabled(event, ctx.clone()) {
// if the outer subscriber enables the event, ask the inner collector.
self.inner.event_enabled(event, ctx)
} else {
// otherwise, the event is disabled by this subscriber
false
}
}

#[inline]
fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) {
self.inner.on_event(event, ctx.clone());
Expand Down
61 changes: 61 additions & 0 deletions tracing-subscriber/src/subscribe/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -417,6 +417,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
//! subscribers 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 [`Collect::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 subscribers one last chance to say that
//! an event should be filtered out, now that the event's fields are known.
//!
//! ## Per-Subscriber Filtering
//!
//! **Note**: per-subscriber filtering APIs currently require the [`"registry"` crate
Expand Down Expand Up @@ -639,6 +661,7 @@
//! [the current span]: Context::current_span
//! [`register_callsite`]: Subscribe::register_callsite
//! [`enabled`]: Subscribe::enabled
//! [`event_enabled`]: Subscribe::event_enabled
//! [`on_enter`]: Subscribe::on_enter
//! [`Subscribe::register_callsite`]: Subscribe::register_callsite
//! [`Subscribe::enabled`]: Subscribe::enabled
Expand Down Expand Up @@ -827,6 +850,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<'_, C>) {}

/// Called before [`on_event`], to determine if `on_event` should be called.
///
CAD97 marked this conversation as resolved.
Show resolved Hide resolved
/// <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 subscriber will be notified about the
/// event. This is intended to be used by subscibers that implement
/// filtering for the entire stack. Subscribers 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 `Subscriber`s.
///
/// [`on_event`]: Self::on_event
/// [`Interest`]: tracing_core::Interest
/// [the trait-level documentation]: #filtering-with-subscribers
#[inline] // collapse this to a constant please mrs optimizer
fn event_enabled(&self, _event: &Event<'_>, _ctx: Context<'_, C>) -> bool {
true
}

/// Notifies this subscriber that an event has occurred.
fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) {}

Expand Down Expand Up @@ -1455,6 +1503,14 @@ where
}
}

#[inline]
fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, C>) -> bool {
match self {
Some(ref inner) => inner.event_enabled(event, ctx),
None => false,
}
}

#[inline]
fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) {
if let Some(ref inner) = self {
Expand Down Expand Up @@ -1534,6 +1590,11 @@ macro_rules! subscriber_impl_body {
self.deref().on_follows_from(span, follows, ctx)
}

#[inline]
fn event_enabled(&self, event: &Event<'_>, ctx: Context<'_, C>) -> bool {
self.deref().event_enabled(event, ctx)
}

#[inline]
fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) {
self.deref().on_event(event, ctx)
Expand Down
81 changes: 81 additions & 0 deletions tracing-subscriber/tests/event_enabling.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,81 @@
#![cfg(feature = "registry")]

CAD97 marked this conversation as resolved.
Show resolved Hide resolved
use std::sync::{Arc, Mutex};
use tracing::{collect::with_default, Collect, Event, Metadata};
use tracing_subscriber::{prelude::*, registry, subscribe::Context, Subscribe};

struct TrackingLayer {
enabled: bool,
event_enabled_count: Arc<Mutex<usize>>,
event_enabled: bool,
on_event_count: Arc<Mutex<usize>>,
}

impl<C> Subscribe<C> for TrackingLayer
where
C: Collect + 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 collector = registry().with(TrackingLayer {
enabled: true,
event_enabled_count,
event_enabled: true,
on_event_count: Arc::new(Mutex::default()),
});
with_default(collector, || {
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 collector = registry().with(TrackingLayer {
enabled: false,
event_enabled_count,
event_enabled: true,
on_event_count: Arc::new(Mutex::default()),
});
with_default(collector, || {
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 collector = registry().with(TrackingLayer {
enabled: true,
event_enabled_count: Arc::new(Mutex::default()),
event_enabled: false,
on_event_count,
});
with_default(collector, || {
tracing::error!("hiya!");
});

assert_eq!(0, *count.lock().unwrap());
}