From f82d63ea0c9ffe0aef95b2daa0691b195a409bc1 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Fri, 7 Jan 2022 08:59:43 -0800 Subject: [PATCH] implement `enabled!` `enabled!` is similar to `event!`, but never dispatches an event. It also allows a simplistic version of calling it, filling in a fake message in the metadata. --- tracing-core/src/event.rs | 18 +++ tracing-core/src/metadata.rs | 13 ++ tracing/src/macros.rs | 236 +++++++++++++++++++++++++++++++++++ tracing/tests/enabled.rs | 37 ++++++ tracing/tests/macros.rs | 41 +++++- 5 files changed, 344 insertions(+), 1 deletion(-) create mode 100644 tracing/tests/enabled.rs diff --git a/tracing-core/src/event.rs b/tracing-core/src/event.rs index 70bd6658ca..675ab76d73 100644 --- a/tracing-core/src/event.rs +++ b/tracing-core/src/event.rs @@ -79,6 +79,24 @@ impl<'a> Event<'a> { }); } + /// Constructs a new `Event` with the specified metadata and set of values, + /// and returns whether such an event would be enabled by the current collector. + pub fn child_of_enabled( + parent: impl Into>, + metadata: &'static Metadata<'static>, + fields: &'a field::ValueSet<'_>, + ) -> bool { + let event = Self::new_child_of(parent, metadata, fields); + crate::dispatch::get_default(|current| current.enabled(event.metadata())) + } + + /// Constructs a new `Event` with the specified metadata and set of values, + /// and returns whether such an event would be enabled by the current collector. + pub fn enabled(metadata: &'static Metadata<'static>, fields: &'a field::ValueSet<'_>) -> bool { + let event = Event::new(metadata, fields); + crate::dispatch::get_default(|current| current.enabled(event.metadata())) + } + /// Visits all the fields on this `Event` with the specified [visitor]. /// /// [visitor]: super::field::Visit diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 89c0e94e22..88cfce1516 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,13 @@ impl Kind { /// `Span` callsite pub const SPAN: Kind = Kind(KindInner::Span); + /// `enabled!` callsite. [collectors] can assume + /// this `Kind` means they will never recieve a + /// full event with this [`Metadata`]. + /// [collectors]: crate::collect::Collect + /// [`Metadata`]: crate::metadata::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 +399,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..137995b515 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -783,6 +783,242 @@ macro_rules! event { ); } +/// Check's whether an equivalent `event!` invocation would result in an enabled +/// event. +/// +/// If you are using this macro to guard a log line that requires expensive computation, it can +/// result in false-negative's, if the default collector has filters based on line numbers or field +/// names. +/// +/// This macro operates similarly to [`event!`], with some extensions: +/// - Allows passing just a level. +/// - Allows passing just a level and a target. +/// +/// See [the top-level documentation][lib] for details on the syntax accepted by +/// this macro. +/// +/// [lib]: crate#using-the-macros +/// [`event!`]: event! +/// +/// # Examples +/// +/// ```rust +/// use tracing::{enabled, Level}; +/// +/// # fn main() { +/// # if enabled!(Level::DEBUG, "Debug loggin") { +/// # // Do something expensive +/// # } +/// # } +/// ``` +/// +#[macro_export] +macro_rules! enabled { + (target: $target:expr, parent: $parent: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(); + // event with explicit parent + $crate::Event::child_of_enabled( + $parent, + meta, + &$crate::valueset!(meta.fields(), $($fields)*) + ) + } else { + false + } + } else { + false + } + ); + + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::enabled!( + target: $target, + parent: $parent, + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( + $crate::enabled!(target: $target, parent: $parent, $lvl, { $($k).+ = $($fields)* }) + ); + (target: $target:expr, parent: $parent:expr, $lvl:expr, $($arg:tt)+) => ( + $crate::enabled!(target: $target, parent: $parent, $lvl, { $($arg)+ }) + ); + (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::EVENT, + target: $target, + level: $lvl, + fields: $($fields)* + }; + let interest = CALLSITE.interest(); + if !interest.is_never() && CALLSITE.is_enabled(interest) { + let meta = CALLSITE.metadata(); + // event with contextual parent + $crate::Event::enabled( + meta, + &$crate::valueset!(meta.fields(), $($fields)*) + ) + } else { + false + } + } else { + false + } + }); + (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::enabled!( + target: $target, + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + (target: $target:expr, $lvl:expr, $($k:ident).+ = $($fields:tt)* ) => ( + $crate::enabled!(target: $target, $lvl, { $($k).+ = $($fields)* }) + ); + (target: $target:expr, $lvl:expr, $($arg:tt)+ ) => ( + $crate::enabled!(target: $target, $lvl, { $($arg)+ }) + ); + // This cases is added on top of how `event` works + (target: $target:expr, $lvl:expr ) => ( + $crate::enabled!(target: $target, $lvl, { "hint_message" }) + ); + (parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + (parent: $parent:expr, $lvl:expr, $($k:ident).+ = $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { $($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+ = $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { ?$($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { %$($k).+ = $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { $($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, %$($k:ident).+, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { %$($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + parent: $parent, + $lvl, + { ?$($k).+, $($field)*} + ) + ); + (parent: $parent:expr, $lvl:expr, $($arg:tt)+ ) => ( + $crate::enabled!(target: module_path!(), parent: $parent, $lvl, { $($arg)+ }) + ); + ( $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( + $crate::enabled!( + target: module_path!(), + $lvl, + { message = format_args!($($arg)+), $($fields)* } + ) + ); + ($lvl:expr, $($k:ident).+ = $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + $lvl, + { $($k).+ = $($field)*} + ) + ); + ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + $lvl, + { $($k).+, $($field)*} + ) + ); + ($lvl:expr, ?$($k:ident).+, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + $lvl, + { ?$($k).+, $($field)*} + ) + ); + ($lvl:expr, %$($k:ident).+, $($field:tt)*) => ( + $crate::enabled!( + target: module_path!(), + $lvl, + { %$($k).+, $($field)*} + ) + ); + ($lvl:expr, ?$($k:ident).+) => ( + $crate::enabled!($lvl, ?$($k).+,) + ); + ($lvl:expr, %$($k:ident).+) => ( + $crate::enabled!($lvl, %$($k).+,) + ); + ($lvl:expr, $($k:ident).+) => ( + $crate::enabled!($lvl, $($k).+,) + ); + ( $lvl:expr, $($arg:tt)+ ) => ( + $crate::enabled!(target: module_path!(), $lvl, { $($arg)+ }) + ); + // This cases is added on top of how `event` works + ( $lvl:expr ) => ( + $crate::enabled!(target: module_path!(), $lvl, { "hint_message" }) + ); +} + /// 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..67768b026c --- /dev/null +++ b/tracing/tests/enabled.rs @@ -0,0 +1,37 @@ +// 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() { + // This test asserts that when a subscriber provides us with the global + // maximum level that it will enable (by implementing the + // `Collector::max_level_hint` method), we will never call + // `Collector::enabled` for events above that maximum level. + // + // In this case, we test that by making the `enabled` method assert that no + // `Metadata` for spans or events at the `TRACE` or `DEBUG` levels. + 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..77c7f1583f 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,45 @@ fn event() { event!(Level::DEBUG, foo); } +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn enabled() { + enabled!(Level::DEBUG, foo = ?3, bar.baz = %2, quux = false); + enabled!(Level::DEBUG, foo = 3, bar.baz = 2, quux = false); + enabled!(Level::DEBUG, foo = 3, bar.baz = 3,); + enabled!(Level::DEBUG, "foo"); + enabled!(Level::DEBUG, "foo: {}", 3); + enabled!(Level::INFO, foo = ?3, bar.baz = %2, quux = false, "hello world {:?}", 42); + enabled!( + Level::INFO, + foo = 3, + bar.baz = 2, + quux = false, + "hello world {:?}", + 42 + ); + enabled!(Level::INFO, foo = 3, bar.baz = 3, "hello world {:?}", 42,); + enabled!(Level::DEBUG, { foo = 3, bar.baz = 80 }, "quux"); + enabled!(Level::DEBUG, { foo = 2, bar.baz = 79 }, "quux {:?}", true); + enabled!(Level::DEBUG, { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false); + enabled!(Level::DEBUG, { foo = ?2, bar.baz = %78 }, "quux"); + enabled!(target: "foo_events", Level::DEBUG, foo = 3, bar.baz = 2, quux = false); + enabled!(target: "foo_events", Level::DEBUG, foo = 3, bar.baz = 3,); + enabled!(target: "foo_events", Level::DEBUG, "foo"); + enabled!(target: "foo_events", Level::DEBUG, "foo: {}", 3); + enabled!(target: "foo_events", Level::DEBUG, { foo = 3, bar.baz = 80 }, "quux"); + enabled!(target: "foo_events", Level::DEBUG, { foo = 2, bar.baz = 79 }, "quux {:?}", true); + enabled!(target: "foo_events", Level::DEBUG, { foo = 2, bar.baz = 79 }, "quux {:?}, {quux}", true, quux = false); + enabled!(target: "foo_events", Level::DEBUG, { foo = 2, bar.baz = 78, }, "quux"); + let foo = 1; + enabled!(Level::DEBUG, ?foo); + enabled!(Level::DEBUG, %foo); + enabled!(Level::DEBUG, foo); + + enabled!(Level::DEBUG); + enabled!(target: "rando", Level::DEBUG); +} + #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] fn locals_with_message() {