From 71da8a5dbb1451c6afe0d0f392402d8af8efe734 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Fri, 28 Jan 2022 11:18:40 -0800 Subject: [PATCH] tracing: add `enabled!` macro (#1821) ## Motivation Closes: #1668 My usecase is different than the referenced "avoid doing something expensive to log": I want to guard turning on `debug` mode for an ffi'd library, based on some `target` that represents the "module" we care about. ## Solution The macro is very similar to `event!`, but adds a few simplistic cases, and generates ever so slightly different code (to return the correct value always. It also skips anything to do with `tracing-log`. I considered (and tried), to share the impl between `event!` and `enabled!`, but must confess I am not good at macros and got stuck. I think they are sufficiently different, where copied impls, is easier to read. We already manage Also, my project is on the crates.io version, so this would need to be backported to 0.1, I can help with that with guidance. Co-authored-by: Eliza Weisman Co-authored-by: David Barsky --- tracing-core/src/metadata.rs | 11 +++ tracing/src/macros.rs | 132 +++++++++++++++++++++++++++++++++++ tracing/tests/enabled.rs | 30 ++++++++ tracing/tests/macros.rs | 16 ++++- 4 files changed, 188 insertions(+), 1 deletion(-) create mode 100644 tracing/tests/enabled.rs diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 89c0e94e22..08689e75c1 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -373,6 +373,7 @@ impl<'a> fmt::Debug for Metadata<'a> { enum KindInner { Event, Span, + Hint, } impl Kind { @@ -382,6 +383,11 @@ impl Kind { /// `Span` callsite pub const SPAN: Kind = Kind(KindInner::Span); + /// `enabled!` callsite. [`Collect`][`crate::collect::Collect`]s can assume + /// this `Kind` means they will never recieve a + /// full event with this [`Metadata`]. + pub const HINT: Kind = Kind(KindInner::Hint); + /// Return true if the callsite kind is `Span` pub fn is_span(&self) -> bool { matches!(self, Kind(KindInner::Span)) @@ -391,6 +397,11 @@ impl Kind { pub fn is_event(&self) -> bool { matches!(self, Kind(KindInner::Event)) } + + /// Return true if the callsite kind is `Hint` + pub fn is_hint(&self) -> bool { + matches!(self, Kind(KindInner::Hint)) + } } // ===== impl Level ===== diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index cc82bab23d..ed0210761f 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -783,6 +783,138 @@ macro_rules! event { ); } +/// Checks whether a span or event is [enabled] based on the provided [metadata]. +/// +/// [enabled]: crate::Collect::enabled +/// [metadata]: crate::Metadata +/// +/// This macro is a specialized tool: it is intended to be used prior +/// to an expensive computation required *just* for that event, but +/// *cannot* be done as part of an argument to that event, such as +/// when multiple events are emitted (e.g., iterating over a collection +/// and emitting an event for each item). +/// +/// # Usage +/// +/// [Collectors] can make filtering decisions based all the data included in a +/// span or event's [`Metadata`]. This means that it is possible for `enabled!` +/// to return a _false positive_ (indicating that something would be enabled +/// when it actually would not be) or a _false negative_ (indicating that +/// something would be disabled when it would actually be enabled). +/// +/// [Collectors]: crate::collect::Collect +/// [`Metadata`]: crate::metadata::Metadata +/// +/// This occurs when a subscriber is using a _more specific_ filter than the +/// metadata provided to the `enabled!` macro. Some situations that can result +/// in false positives or false negatives include: +/// +/// - If a collector is using a filter which may enable a span or event based +/// on field names, but `enabled!` is invoked without listing field names, +/// `enabled!` may return a false negative if a specific field name would +/// cause the collector to enable something that would otherwise be disabled. +/// - If a collector is using a filter which enables or disables specific events by +/// file path and line number, a particular event may be enabled/disabled +/// even if an `enabled!` invocation with the same level, target, and fields +/// indicated otherwise. +/// - The collector can choose to enable _only_ spans or _only_ events, which `enabled` +/// will not reflect. +/// +/// `enabled!()` requires a [level](crate::Level) argument, an optional `target:` +/// argument, and an optional set of field names. If the fields are not provided, +/// they are considered to be unknown. `enabled!` attempts to match the +/// syntax of `event!()` as closely as possible, which can be seen in the +/// examples below. +/// +/// # Examples +/// +/// If the current collector is interested in recording `DEBUG`-level spans and +/// events in the current file and module path, this will evaluate to true: +/// ```rust +/// use tracing::{enabled, Level}; +/// +/// if enabled!(Level::DEBUG) { +/// // some expensive work... +/// } +/// ``` +/// +/// If the current collector is interested in recording spans and events +/// in the current file and module path, with the target "my_crate", and at the +/// level `DEBUG`, this will evaluate to true: +/// ```rust +/// # use tracing::{enabled, Level}; +/// if enabled!(target: "my_crate", Level::DEBUG) { +/// // some expensive work... +/// } +/// ``` +/// +/// If the current collector is interested in recording spans and events +/// in the current file and module path, with the target "my_crate", at +/// the level `DEBUG`, and with a field named "hello", this will evaluate +/// to true: +/// +/// ```rust +/// # use tracing::{enabled, Level}; +/// if enabled!(target: "my_crate", Level::DEBUG, hello) { +/// // some expensive work... +/// } +/// ``` +/// +#[macro_export] +macro_rules! enabled { + (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ + if $crate::level_enabled!($lvl) { + use $crate::__macro_support::Callsite as _; + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + name: concat!( + "enabled ", + file!(), + ":", + line!() + ), + kind: $crate::metadata::Kind::HINT, + target: $target, + level: $lvl, + fields: $($fields)* + }; + let interest = CALLSITE.interest(); + if !interest.is_never() && CALLSITE.is_enabled(interest) { + let meta = CALLSITE.metadata(); + $crate::dispatch::get_default(|current| current.enabled(meta)) + } else { + false + } + } else { + false + } + }); + // Just target and level + (target: $target:expr, $lvl:expr ) => ( + $crate::enabled!(target: $target, $lvl, { }) + ); + + // These two cases handle fields with no values + (target: $target:expr, $lvl:expr, $($field:tt)*) => ( + $crate::enabled!( + target: $target, + $lvl, + { $($field)*} + ) + ); + ($lvl:expr, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + $lvl, + { $($field)*} + ) + ); + + // Simplest `enabled!` case + ( $lvl:expr ) => ( + $crate::enabled!(target: module_path!(), $lvl, { }) + ); +} + /// Constructs an event at the trace level. /// /// This functions similarly to the [`event!`] macro. See [the top-level diff --git a/tracing/tests/enabled.rs b/tracing/tests/enabled.rs new file mode 100644 index 0000000000..59c9c1106e --- /dev/null +++ b/tracing/tests/enabled.rs @@ -0,0 +1,30 @@ +// liballoc is required because the test subscriber cannot be constructed +// statically +#![cfg(feature = "alloc")] + +mod support; + +use self::support::*; +use tracing::Level; + +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn level_and_target() { + let (collector, handle) = collector::mock() + .with_filter(|meta| { + if meta.target() == "debug_module" { + meta.level() <= &Level::DEBUG + } else { + meta.level() <= &Level::INFO + } + }) + .done() + .run_with_handle(); + + tracing::collect::set_global_default(collector).unwrap(); + + assert!(tracing::enabled!(target: "debug_module", Level::DEBUG)); + assert!(tracing::enabled!(Level::ERROR)); + assert!(!tracing::enabled!(Level::DEBUG)); + handle.assert_finished(); +} diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index 420319d373..0a32ebfc3f 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -1,6 +1,6 @@ #![deny(warnings)] use tracing::{ - callsite, debug, debug_span, error, error_span, event, info, info_span, span, trace, + callsite, debug, debug_span, enabled, error, error_span, event, info, info_span, span, trace, trace_span, warn, warn_span, Level, }; @@ -334,6 +334,20 @@ fn event() { event!(Level::DEBUG, foo); } +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn enabled() { + enabled!(Level::DEBUG, foo, bar.baz, quux,); + enabled!(Level::DEBUG, message); + enabled!(Level::INFO, foo, bar.baz, quux, message,); + enabled!(Level::INFO, foo, bar., message,); + enabled!(Level::DEBUG, foo); + + enabled!(Level::DEBUG); + enabled!(target: "rando", Level::DEBUG); + enabled!(target: "rando", Level::DEBUG, field); +} + #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] fn locals_with_message() {