From 0b4c3ac14455ac50de445cf680fc1588625fe0fa Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Fri, 7 Jan 2022 08:59:43 -0800 Subject: [PATCH 01/32] 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 | 11 ++ tracing/src/macros.rs | 236 +++++++++++++++++++++++++++++++++++ tracing/tests/enabled.rs | 30 +++++ tracing/tests/macros.rs | 41 +++++- 5 files changed, 335 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..42eb9ae41e 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..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..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..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() { From 12474e17cee4ac644c8d0bbaf0e7e1560ba4a52a Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Mon, 10 Jan 2022 16:34:56 -0800 Subject: [PATCH 02/32] simplify the macro --- tracing/src/macros.rs | 171 +++------------------------------------- tracing/tests/macros.rs | 34 +------- 2 files changed, 17 insertions(+), 188 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 137995b515..8e6cd795f0 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -814,52 +814,6 @@ macro_rules! event { /// #[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 _; @@ -878,11 +832,7 @@ macro_rules! enabled { 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)*) - ) + $crate::dispatch::get_default(|current| current.enabled(meta)) } else { false } @@ -890,96 +840,23 @@ macro_rules! enabled { 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 + // Just target and level (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)*} - ) + $crate::enabled!(target: $target, $lvl, { }) ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( - $crate::enabled!( - target: module_path!(), - parent: $parent, - $lvl, - { %$($k).+ = $($field)*} - ) + + // These two cases handle fields with no values + (target: $target:expr, $lvl:expr, $($k:ident).+) => ( + $crate::enabled!(target: $target, $lvl, $($k).+,) ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( $crate::enabled!( - target: module_path!(), - parent: $parent, + target: $target, $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!(), @@ -987,35 +864,13 @@ macro_rules! enabled { { $($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 + + // Simplest `enabled!` case ( $lvl:expr ) => ( - $crate::enabled!(target: module_path!(), $lvl, { "hint_message" }) + $crate::enabled!(target: module_path!(), $lvl, { }) ); } diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index 77c7f1583f..d010a804dc 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -337,40 +337,14 @@ fn event() { #[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, bar.baz, quux,); + enabled!(Level::DEBUG, message); + enabled!(Level::INFO, foo, bar.baz, quux, messaged,); 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)] From 5ccc947b0ad82146c3b564bc25f6887fa5fd2e0f Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Mon, 10 Jan 2022 16:45:24 -0800 Subject: [PATCH 03/32] remove new event methods --- tracing-core/src/event.rs | 18 ------------------ 1 file changed, 18 deletions(-) diff --git a/tracing-core/src/event.rs b/tracing-core/src/event.rs index 675ab76d73..70bd6658ca 100644 --- a/tracing-core/src/event.rs +++ b/tracing-core/src/event.rs @@ -79,24 +79,6 @@ 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 From 289bfed2ece1ec598ef99d836dfdeadc9f26fbcc Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Tue, 11 Jan 2022 08:40:33 -0800 Subject: [PATCH 04/32] fix Kind::HINT's doc's --- tracing-core/src/metadata.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 42eb9ae41e..08689e75c1 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -383,7 +383,7 @@ impl Kind { /// `Span` callsite pub const SPAN: Kind = Kind(KindInner::Span); - /// `enabled!` callsite. [`Collect`][`crate::collect::Collect`]'s can assume + /// `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); From 7d5831d654ba036f9008ad1dee1d1f5b2439caa4 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Fri, 7 Jan 2022 08:59:43 -0800 Subject: [PATCH 05/32] 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 | 11 ++ tracing/src/macros.rs | 236 +++++++++++++++++++++++++++++++++++ tracing/tests/enabled.rs | 30 +++++ tracing/tests/macros.rs | 41 +++++- 5 files changed, 335 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..42eb9ae41e 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..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..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..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() { From b3d042da3fc13c7520e2ed9f28696210ff8d632f Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Mon, 10 Jan 2022 16:34:56 -0800 Subject: [PATCH 06/32] simplify the macro --- tracing/src/macros.rs | 171 +++------------------------------------- tracing/tests/macros.rs | 34 +------- 2 files changed, 17 insertions(+), 188 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 137995b515..8e6cd795f0 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -814,52 +814,6 @@ macro_rules! event { /// #[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 _; @@ -878,11 +832,7 @@ macro_rules! enabled { 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)*) - ) + $crate::dispatch::get_default(|current| current.enabled(meta)) } else { false } @@ -890,96 +840,23 @@ macro_rules! enabled { 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 + // Just target and level (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)*} - ) + $crate::enabled!(target: $target, $lvl, { }) ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( - $crate::enabled!( - target: module_path!(), - parent: $parent, - $lvl, - { %$($k).+ = $($field)*} - ) + + // These two cases handle fields with no values + (target: $target:expr, $lvl:expr, $($k:ident).+) => ( + $crate::enabled!(target: $target, $lvl, $($k).+,) ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( $crate::enabled!( - target: module_path!(), - parent: $parent, + target: $target, $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!(), @@ -987,35 +864,13 @@ macro_rules! enabled { { $($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 + + // Simplest `enabled!` case ( $lvl:expr ) => ( - $crate::enabled!(target: module_path!(), $lvl, { "hint_message" }) + $crate::enabled!(target: module_path!(), $lvl, { }) ); } diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index 77c7f1583f..d010a804dc 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -337,40 +337,14 @@ fn event() { #[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, bar.baz, quux,); + enabled!(Level::DEBUG, message); + enabled!(Level::INFO, foo, bar.baz, quux, messaged,); 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)] From ac87e4257f40abf2c68b4fc428556bf7e5faa535 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Mon, 10 Jan 2022 16:45:24 -0800 Subject: [PATCH 07/32] remove new event methods --- tracing-core/src/event.rs | 18 ------------------ 1 file changed, 18 deletions(-) diff --git a/tracing-core/src/event.rs b/tracing-core/src/event.rs index 675ab76d73..70bd6658ca 100644 --- a/tracing-core/src/event.rs +++ b/tracing-core/src/event.rs @@ -79,24 +79,6 @@ 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 From 9b09230bcafef4029b68f24ca2d35467e66a458f Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Tue, 11 Jan 2022 08:40:33 -0800 Subject: [PATCH 08/32] fix Kind::HINT's doc's --- tracing-core/src/metadata.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 42eb9ae41e..08689e75c1 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -383,7 +383,7 @@ impl Kind { /// `Span` callsite pub const SPAN: Kind = Kind(KindInner::Span); - /// `enabled!` callsite. [`Collect`][`crate::collect::Collect`]'s can assume + /// `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); From 7f9aee9c80ed2bddff382d99f838318d283c9c28 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Thu, 13 Jan 2022 08:09:15 -0800 Subject: [PATCH 09/32] simplify dot cases --- tracing/src/macros.rs | 15 ++++----------- tracing/tests/macros.rs | 3 ++- 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 8e6cd795f0..f9fac13afa 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -846,27 +846,20 @@ macro_rules! enabled { ); // These two cases handle fields with no values - (target: $target:expr, $lvl:expr, $($k:ident).+) => ( - $crate::enabled!(target: $target, $lvl, $($k).+,) - ); - (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($field:tt)*) => ( $crate::enabled!( target: $target, $lvl, - { $($k).+, $($field)*} + { $($field)*} ) ); - - ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( + ($lvl:expr, $($field:tt)*) => ( $crate::enabled!( target: module_path!(), $lvl, - { $($k).+, $($field)*} + { $($field)*} ) ); - ($lvl:expr, $($k:ident).+) => ( - $crate::enabled!($lvl, $($k).+,) - ); // Simplest `enabled!` case ( $lvl:expr ) => ( diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index d010a804dc..0a32ebfc3f 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -339,7 +339,8 @@ fn event() { fn enabled() { enabled!(Level::DEBUG, foo, bar.baz, quux,); enabled!(Level::DEBUG, message); - enabled!(Level::INFO, foo, bar.baz, quux, messaged,); + enabled!(Level::INFO, foo, bar.baz, quux, message,); + enabled!(Level::INFO, foo, bar., message,); enabled!(Level::DEBUG, foo); enabled!(Level::DEBUG); From 14d8137b154d5150d7265cc174f769b5e491bcbb Mon Sep 17 00:00:00 2001 From: lunaryorn Date: Tue, 11 Jan 2022 22:04:12 +0100 Subject: [PATCH 10/32] journald: Set syslog identifier (#1822) Set the `SYSLOG_IDENTIFIER` field on all events. I noticed that the subscriber didn't do this so far. ## Motivation The identifier is used with `journalctl -t`, and while it's normally better to filter by unit with `journalctl -u` the identifier is still nice for processes that are not started through systemd units. Upstream does this as well, see [here]: ![grafik](https://user-images.githubusercontent.com/224922/148660479-9525b21e-547f-4787-9bb7-db933963041a.png) `program_invocation_short_name` is a glibc variable which holds the file name of the current executable; I tried to replicate this behaviour in Rust. ## Solution Add a syslog identifier field to the subscriber, defaulting to the filename of the current executable, and write this value as `SYSLOG_IDENTIFIER` with every event. It's not written for spans, because it's a global value and inevitably the same for each span. [here]: https://github.com/systemd/systemd/blob/81218ac1e14b4b50b4337938bcf55cacc76f0728/src/libsystemd/sd-journal/journal-send.c#L270 --- tracing-journald/src/lib.rs | 38 +++++++++++++++++++++++++++++++++++++ 1 file changed, 38 insertions(+) diff --git a/tracing-journald/src/lib.rs b/tracing-journald/src/lib.rs index 47121be4e4..8683143b02 100644 --- a/tracing-journald/src/lib.rs +++ b/tracing-journald/src/lib.rs @@ -84,6 +84,7 @@ pub struct Subscriber { #[cfg(unix)] socket: UnixDatagram, field_prefix: Option, + syslog_identifier: String, } #[cfg(unix)] @@ -101,6 +102,13 @@ impl Subscriber { let sub = Self { socket, field_prefix: Some("F".into()), + syslog_identifier: std::env::current_exe() + .ok() + .as_ref() + .and_then(|p| p.file_name()) + .map(|n| n.to_string_lossy().into_owned()) + // If we fail to get the name of the current executable fall back to an empty string. + .unwrap_or_else(String::new), }; // Check that we can talk to journald, by sending empty payload which journald discards. // However if the socket didn't exist or if none listened we'd get an error here. @@ -121,6 +129,32 @@ impl Subscriber { self } + /// Sets the syslog identifier for this logger. + /// + /// The syslog identifier comes from the classic syslog interface (`openlog()` + /// and `syslog()`) and tags log entries with a given identifier. + /// Systemd exposes it in the `SYSLOG_IDENTIFIER` journal field, and allows + /// filtering log messages by syslog identifier with `journalctl -t`. + /// Unlike the unit (`journalctl -u`) this field is not trusted, i.e. applications + /// can set it freely, and use it e.g. to further categorize log entries emitted under + /// the same systemd unit or in the same process. It also allows to filter for log + /// entries of processes not started in their own unit. + /// + /// See [Journal Fields](https://www.freedesktop.org/software/systemd/man/systemd.journal-fields.html) + /// and [journalctl](https://www.freedesktop.org/software/systemd/man/journalctl.html) + /// for more information. + /// + /// Defaults to the file name of the executable of the current process, if any. + pub fn with_syslog_identifier(mut self, identifier: String) -> Self { + self.syslog_identifier = identifier; + self + } + + /// Returns the syslog identifier in use. + pub fn syslog_identifier(&self) -> &str { + &self.syslog_identifier + } + #[cfg(not(unix))] fn send_payload(&self, _opayload: &[u8]) -> io::Result<()> { Err(io::Error::new( @@ -224,6 +258,10 @@ where // Record event fields put_metadata(&mut buf, event.metadata(), None); + put_field_length_encoded(&mut buf, "SYSLOG_IDENTIFIER", |buf| { + write!(buf, "{}", self.syslog_identifier).unwrap() + }); + event.record(&mut EventVisitor::new( &mut buf, self.field_prefix.as_ref().map(|x| &x[..]), From 9a1942f46a564ac75fdf2f1813ada64d9523d061 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 11 Jan 2022 13:48:39 -0800 Subject: [PATCH 11/32] docs: don't state that `tracing-futures` is required (#1827) Currently, the documentation states in a few places that the `tracing-futures` crate is required for asynchronous code to use `tracing`. This is no longer the case, as `tracing` provides the `Instrument` combinator for futures; `tracing-futures` is only needed for things defined in the `futures` crate, such as `Stream` and `Sink`. This branch updates the documentation so that it doesn't incorrectly state that `tracing-futures` is required. --- README.md | 6 +----- tracing/README.md | 5 ++--- 2 files changed, 3 insertions(+), 8 deletions(-) diff --git a/README.md b/README.md index f66008b174..0fa3dc92aa 100644 --- a/README.md +++ b/README.md @@ -209,9 +209,6 @@ async fn write(stream: &mut TcpStream) -> io::Result { } ``` -The [`tracing-futures`] crate must be specified as a dependency to enable -`async` support. - Special handling is needed for the general case of code using [`std::future::Future`][std-future] or blocks with `async`/`await`, as the following example _will not_ work: @@ -250,10 +247,9 @@ Under the hood, the [`#[instrument]`][instrument] macro performs same the explic attachment that `Future::instrument` does. [std-future]: https://doc.rust-lang.org/stable/std/future/trait.Future.html -[`tracing-futures`]: https://docs.rs/tracing-futures [closing]: https://docs.rs/tracing/latest/tracing/span/index.html#closing-spans [`Future::instrument`]: https://docs.rs/tracing/latest/tracing/trait.Instrument.html#method.instrument -[instrument]: https://docs.rs/tracing/0.1.11/tracing/attr.instrument.html +[instrument]: https://docs.rs/tracing/latest/tracing/attr.instrument.html ## Supported Rust Versions diff --git a/tracing/README.md b/tracing/README.md index 12dfdace49..69e542edde 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -210,9 +210,8 @@ conflicts when executables try to set the default later. If you are instrumenting code that make use of [`std::future::Future`](https://doc.rust-lang.org/stable/std/future/trait.Future.html) -or async/await, be sure to use the -[`tracing-futures`](https://docs.rs/tracing-futures) crate. This is needed -because the following example _will not_ work: +or async/await, avoid using the `Span::enter` method. The following example +_will not_ work: ```rust async { From 147d79363449398705f2d0ce5bd00c8f3145b769 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Thu, 13 Jan 2022 08:09:15 -0800 Subject: [PATCH 12/32] simplify dot cases --- tracing/src/macros.rs | 15 ++++----------- tracing/tests/macros.rs | 3 ++- 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 8e6cd795f0..f9fac13afa 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -846,27 +846,20 @@ macro_rules! enabled { ); // These two cases handle fields with no values - (target: $target:expr, $lvl:expr, $($k:ident).+) => ( - $crate::enabled!(target: $target, $lvl, $($k).+,) - ); - (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($field:tt)*) => ( $crate::enabled!( target: $target, $lvl, - { $($k).+, $($field)*} + { $($field)*} ) ); - - ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( + ($lvl:expr, $($field:tt)*) => ( $crate::enabled!( target: module_path!(), $lvl, - { $($k).+, $($field)*} + { $($field)*} ) ); - ($lvl:expr, $($k:ident).+) => ( - $crate::enabled!($lvl, $($k).+,) - ); // Simplest `enabled!` case ( $lvl:expr ) => ( diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index d010a804dc..0a32ebfc3f 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -339,7 +339,8 @@ fn event() { fn enabled() { enabled!(Level::DEBUG, foo, bar.baz, quux,); enabled!(Level::DEBUG, message); - enabled!(Level::INFO, foo, bar.baz, quux, messaged,); + enabled!(Level::INFO, foo, bar.baz, quux, message,); + enabled!(Level::INFO, foo, bar., message,); enabled!(Level::DEBUG, foo); enabled!(Level::DEBUG); From 48240a14a498c130c76277a426dea57e2cc5619a Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 13 Jan 2022 09:29:59 -0800 Subject: [PATCH 13/32] subscriber: fix leading comma with `Pretty` formatter (#1833) ## Motivation PR #1661 introduced a regression with the `Pretty` formatter: the `PrettyVisitor` type was [accidentally changed][1] from being constructed with `is_empty: true` to being constructed with `is_empty: false` This means that when visiting a set of span fields, we emit a leading `, ` _before_ the first field, which looks quite bad. ## Solution This branch changes it back, and now the output looks nice again. :) ### Before ``` 2022-01-13T17:09:04.772411Z TRACE fmt_pretty::yak_shave: hello! I'm gonna shave a yak, excitement: "yay!" at examples/examples/fmt/yak_shave.rs:16 on main in fmt_pretty::yak_shave::shave with , yak: 2 in fmt_pretty::yak_shave::shaving_yaks with , yaks: 3 ``` ### After ``` 2022-01-13T17:10:28.472525Z TRACE fmt_pretty::yak_shave: hello! I'm gonna shave a yak, excitement: "yay!" at examples/examples/fmt/yak_shave.rs:16 on main in fmt_pretty::yak_shave::shave with yak: 1 in fmt_pretty::yak_shave::shaving_yaks with yaks: 3, ``` Fixes: #1832 [1]: https://github.com/tokio-rs/tracing/commit/937c5d7cf08f5829651e3e9f99227c92e159fa82#diff-a27a4c3564a0c2f1b7af32be0f9eec25ddfbe8b4c2be8d74e84d874b919b393bR227 --- tracing-subscriber/src/fmt/format/pretty.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-subscriber/src/fmt/format/pretty.rs b/tracing-subscriber/src/fmt/format/pretty.rs index f67864d6db..37a9f63be3 100644 --- a/tracing-subscriber/src/fmt/format/pretty.rs +++ b/tracing-subscriber/src/fmt/format/pretty.rs @@ -227,7 +227,7 @@ where impl<'writer> FormatFields<'writer> for Pretty { fn format_fields(&self, writer: Writer<'writer>, fields: R) -> fmt::Result { - let mut v = PrettyVisitor::new(writer, false); + let mut v = PrettyVisitor::new(writer, true); fields.record(&mut v); v.finish() } From 133154b7baa9c97a6cb12d4a317d2e54d6277f2a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ren=C3=AA=20Couto=20e=20Silva?= <31329678+renecouto@users.noreply.github.com> Date: Fri, 14 Jan 2022 14:30:28 -0300 Subject: [PATCH 14/32] subscriber: add `Format::with_file` and `with_line_number` (#1773) ## Motivation Logging line numbers and file names can be useful for debugging. This feature was suggested by #1326 ## Solution As per @hawkw's suggestions, fields were added on `Format`, along with builder methods. Filename and line number information was gathered from the `meta` variable. The `Pretty` formatter already supports printing source locations, but this is configured separately on the `Pretty` formatter rather than on the `Format` type. This branch also changes `Pretty` to honor the `Format`-level configurations and deprecates the `Pretty`-specific method. Fixes #1326 Closes #1804 Co-authored-by: David Barsky Co-authored-by: Eliza Weisman --- examples/README.md | 2 + examples/examples/fmt-source-locations.rs | 29 +++ tracing-subscriber/src/fmt/fmt_subscriber.rs | 24 +++ tracing-subscriber/src/fmt/format/json.rs | 87 +++++++++ tracing-subscriber/src/fmt/format/mod.rs | 188 ++++++++++++++++++- tracing-subscriber/src/fmt/format/pretty.rs | 67 ++++--- tracing-subscriber/src/fmt/mod.rs | 28 +++ 7 files changed, 392 insertions(+), 33 deletions(-) create mode 100644 examples/examples/fmt-source-locations.rs diff --git a/examples/README.md b/examples/README.md index a1355d3dda..30f2ac7f87 100644 --- a/examples/README.md +++ b/examples/README.md @@ -26,6 +26,8 @@ This directory contains a collection of examples that demonstrate the use of the events. + `fmt-multiple-writers.rs`: demonstrates how `fmt::Subcriber` can write to multiple destinations (in this instance, stdout and a file) simultaneously. + + `fmt-source-locations.rs`: demonstrates displaying source code locations + with `fmt::Subscriber`. + `subscriber-filter`: Demonstrates the `tracing-subscriber::filter` module, which provides a subscriber which adds configurable filtering to a collector implementation. diff --git a/examples/examples/fmt-source-locations.rs b/examples/examples/fmt-source-locations.rs new file mode 100644 index 0000000000..799ebb17d5 --- /dev/null +++ b/examples/examples/fmt-source-locations.rs @@ -0,0 +1,29 @@ +//! Demonstrates displaying events' source code locations with the `fmt` +//! subscriber. +#![deny(rust_2018_idioms)] +#[path = "fmt/yak_shave.rs"] +mod yak_shave; + +fn main() { + tracing_subscriber::fmt() + // enable everything + .with_max_level(tracing::Level::TRACE) + // display source code file paths + .with_file(true) + // display source code line numbers + .with_line_number(true) + // disable targets + .with_target(false) + // sets this to be the default, global collector for this application. + .init(); + + let number_of_yaks = 3; + // this creates a new event, outside of any spans. + tracing::info!(number_of_yaks, "preparing to shave yaks"); + + let number_shaved = yak_shave::shave_all(number_of_yaks); + tracing::info!( + all_yaks_shaved = number_shaved == number_of_yaks, + "yak shaving completed." + ); +} diff --git a/tracing-subscriber/src/fmt/fmt_subscriber.rs b/tracing-subscriber/src/fmt/fmt_subscriber.rs index a3498d9d1c..a9fc30b465 100644 --- a/tracing-subscriber/src/fmt/fmt_subscriber.rs +++ b/tracing-subscriber/src/fmt/fmt_subscriber.rs @@ -297,6 +297,30 @@ where ..self } } + /// Sets whether or not an event's [source code file path][file] is + /// displayed. + /// + /// [file]: tracing_core::Metadata::file + pub fn with_file(self, display_filename: bool) -> Subscriber, W> { + Subscriber { + fmt_event: self.fmt_event.with_file(display_filename), + ..self + } + } + + /// Sets whether or not an event's [source code line number][line] is + /// displayed. + /// + /// [line]: tracing_core::Metadata::line + pub fn with_line_number( + self, + display_line_number: bool, + ) -> Subscriber, W> { + Subscriber { + fmt_event: self.fmt_event.with_line_number(display_line_number), + ..self + } + } /// Sets whether or not an event's level is displayed. pub fn with_level(self, display_level: bool) -> Subscriber, W> { diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index 3c085855fc..425634fe80 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -240,6 +240,18 @@ where serializer.serialize_entry("target", meta.target())?; } + if self.display_filename { + if let Some(filename) = meta.file() { + serializer.serialize_entry("filename", filename)?; + } + } + + if self.display_line_number { + if let Some(line_number) = meta.line() { + serializer.serialize_entry("line_number", &line_number)?; + } + } + if self.format.display_current_span { if let Some(ref span) = current_span { serializer @@ -483,6 +495,7 @@ mod test { use tracing::{self, collect::with_default}; use std::fmt; + use std::path::Path; struct MockTime; impl FormatTime for MockTime { @@ -510,6 +523,50 @@ mod test { }); } + #[test] + fn json_filename() { + let current_path = Path::new("tracing-subscriber") + .join("src") + .join("fmt") + .join("format") + .join("json.rs") + .to_str() + .expect("path must be valid unicode") + // escape windows backslashes + .replace('\\', "\\\\"); + let expected = + &format!("{}{}{}", + "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"filename\":\"", + current_path, + "\",\"fields\":{\"message\":\"some json test\"}}\n"); + let collector = collector() + .flatten_event(false) + .with_current_span(true) + .with_file(true) + .with_span_list(true); + test_json(expected, collector, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + + #[test] + fn json_line_number() { + let expected = + "{\"timestamp\":\"fake time\",\"level\":\"INFO\",\"span\":{\"answer\":42,\"name\":\"json_span\",\"number\":3},\"spans\":[{\"answer\":42,\"name\":\"json_span\",\"number\":3}],\"target\":\"tracing_subscriber::fmt::format::json::test\",\"line_number\":42,\"fields\":{\"message\":\"some json test\"}}\n"; + let collector = collector() + .flatten_event(false) + .with_current_span(true) + .with_line_number(true) + .with_span_list(true); + test_json_with_line_number(expected, collector, || { + let span = tracing::span!(tracing::Level::INFO, "json_span", answer = 42, number = 3); + let _guard = span.enter(); + tracing::info!("some json test"); + }); + } + #[test] fn json_flattened_event() { let expected = @@ -740,4 +797,34 @@ mod test { serde_json::from_str(actual).unwrap() ); } + + fn test_json_with_line_number( + expected: &str, + builder: crate::fmt::CollectorBuilder>, + producer: impl FnOnce() -> T, + ) { + let make_writer = MockMakeWriter::default(); + let collector = builder + .with_writer(make_writer.clone()) + .with_timer(MockTime) + .finish(); + + with_default(collector, producer); + + let buf = make_writer.buf(); + let actual = std::str::from_utf8(&buf[..]).unwrap(); + let mut expected = + serde_json::from_str::>(expected) + .unwrap(); + let expect_line_number = expected.remove("line_number").is_some(); + let mut actual: std::collections::HashMap<&str, serde_json::Value> = + serde_json::from_str(actual).unwrap(); + let line_number = actual.remove("line_number"); + if expect_line_number { + assert_eq!(line_number.map(|x| x.is_number()), Some(true)); + } else { + assert!(line_number.is_none()); + } + assert_eq!(actual, expected); + } } diff --git a/tracing-subscriber/src/fmt/format/mod.rs b/tracing-subscriber/src/fmt/format/mod.rs index 1374b675a6..204df05fab 100644 --- a/tracing-subscriber/src/fmt/format/mod.rs +++ b/tracing-subscriber/src/fmt/format/mod.rs @@ -328,6 +328,8 @@ pub struct Format { pub(crate) display_level: bool, pub(crate) display_thread_id: bool, pub(crate) display_thread_name: bool, + pub(crate) display_filename: bool, + pub(crate) display_line_number: bool, } // === impl Writer === @@ -504,6 +506,8 @@ impl Default for Format { display_level: true, display_thread_id: false, display_thread_name: false, + display_filename: false, + display_line_number: false, } } } @@ -522,6 +526,8 @@ impl Format { display_level: self.display_level, display_thread_id: self.display_thread_id, display_thread_name: self.display_thread_name, + display_filename: self.display_filename, + display_line_number: self.display_line_number, } } @@ -559,6 +565,8 @@ impl Format { display_level: self.display_level, display_thread_id: self.display_thread_id, display_thread_name: self.display_thread_name, + display_filename: true, + display_line_number: true, } } @@ -589,6 +597,8 @@ impl Format { display_level: self.display_level, display_thread_id: self.display_thread_id, display_thread_name: self.display_thread_name, + display_filename: self.display_filename, + display_line_number: self.display_line_number, } } @@ -616,6 +626,8 @@ impl Format { display_level: self.display_level, display_thread_id: self.display_thread_id, display_thread_name: self.display_thread_name, + display_filename: self.display_filename, + display_line_number: self.display_line_number, } } @@ -630,6 +642,8 @@ impl Format { display_level: self.display_level, display_thread_id: self.display_thread_id, display_thread_name: self.display_thread_name, + display_filename: self.display_filename, + display_line_number: self.display_line_number, } } @@ -679,6 +693,38 @@ impl Format { } } + /// Sets whether or not an event's [source code file path][file] is + /// displayed. + /// + /// [file]: tracing_core::Metadata::file + pub fn with_file(self, display_filename: bool) -> Format { + Format { + display_filename, + ..self + } + } + + /// Sets whether or not an event's [source code line number][line] is + /// displayed. + /// + /// [line]: tracing_core::Metadata::line + pub fn with_line_number(self, display_line_number: bool) -> Format { + Format { + display_line_number, + ..self + } + } + + /// Sets whether or not the source code location from which an event + /// originated is displayed. + /// + /// This is equivalent to calling [`Format::with_file`] and + /// [`Format::with_line_number`] with the same value. + pub fn with_source_location(self, display_location: bool) -> Self { + self.with_line_number(display_location) + .with_file(display_location) + } + fn format_level(&self, level: Level, writer: &mut Writer<'_>) -> fmt::Result where F: LevelNames, @@ -862,6 +908,34 @@ where )?; } + let line_number = if self.display_line_number { + meta.line() + } else { + None + }; + + if self.display_filename { + if let Some(filename) = meta.file() { + write!( + writer, + "{}{}{}", + dimmed.paint(filename), + dimmed.paint(":"), + if line_number.is_some() { "" } else { " " } + )?; + } + } + + if let Some(line_number) = line_number { + write!( + writer, + "{}{}:{} ", + dimmed.prefix(), + line_number, + dimmed.suffix() + )?; + } + ctx.format_fields(writer.by_ref(), event)?; writeln!(writer) } @@ -907,18 +981,33 @@ where write!(writer, "{:0>2?} ", std::thread::current().id())?; } + let bold = writer.bold(); + let dimmed = writer.dimmed(); if self.display_target { - write!( - writer, - "{}{}", - writer.bold().paint(meta.target()), - writer.dimmed().paint(":") - )?; + write!(writer, "{}{}", bold.paint(meta.target()), dimmed.paint(":"))?; + } + + if self.display_filename { + if let Some(filename) = meta.file() { + write!(writer, "{}{}", bold.paint(filename), dimmed.paint(":"))?; + } + } + + if self.display_line_number { + if let Some(line_number) = meta.line() { + write!( + writer, + "{}{}{}{}", + bold.prefix(), + line_number, + bold.suffix(), + dimmed.paint(":") + )?; + } } ctx.format_fields(writer.by_ref(), event)?; - let dimmed = writer.dimmed(); for span in ctx .event_scope() .into_iter() @@ -1115,9 +1204,18 @@ impl Style { fn new() -> Self { Style } + fn paint(&self, d: impl fmt::Display) -> impl fmt::Display { d } + + fn prefix(&self) -> impl fmt::Display { + "" + } + + fn suffix(&self) -> impl fmt::Display { + "" + } } struct FmtThreadName<'a> { @@ -1466,9 +1564,9 @@ pub(super) mod test { }; use super::{FmtSpan, TimingDisplay, Writer}; - use std::fmt; - use regex::Regex; + use std::fmt; + use std::path::Path; pub(crate) struct MockTime; impl FormatTime for MockTime { @@ -1541,6 +1639,66 @@ pub(super) mod test { assert_info_hello(subscriber, make_writer, expected); } + #[test] + fn with_line_number_and_file_name() { + let make_writer = MockMakeWriter::default(); + let subscriber = crate::fmt::Collector::builder() + .with_writer(make_writer.clone()) + .with_file(true) + .with_line_number(true) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime); + + let expected = Regex::new(&format!( + "^fake time tracing_subscriber::fmt::format::test: {}:[0-9]+: hello\n$", + current_path() + // if we're on Windows, the path might contain backslashes, which + // have to be escpaed before compiling the regex. + .replace('\\', "\\\\") + )) + .unwrap(); + let _default = set_default(&subscriber.into()); + tracing::info!("hello"); + let res = make_writer.get_string(); + assert!(expected.is_match(&res)); + } + + #[test] + fn with_line_number() { + let make_writer = MockMakeWriter::default(); + let subscriber = crate::fmt::Collector::builder() + .with_writer(make_writer.clone()) + .with_line_number(true) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime); + + let expected = + Regex::new("^fake time tracing_subscriber::fmt::format::test: [0-9]+: hello\n$") + .unwrap(); + let _default = set_default(&subscriber.into()); + tracing::info!("hello"); + let res = make_writer.get_string(); + assert!(expected.is_match(&res)); + } + + #[test] + fn with_filename() { + let make_writer = MockMakeWriter::default(); + let subscriber = crate::fmt::Collector::builder() + .with_writer(make_writer.clone()) + .with_file(true) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime); + let expected = &format!( + "fake time tracing_subscriber::fmt::format::test: {}: hello\n", + current_path(), + ); + assert_info_hello(subscriber, make_writer, expected); + } + #[test] fn with_thread_ids() { let make_writer = MockMakeWriter::default(); @@ -1697,4 +1855,16 @@ pub(super) mod test { assert!(!f.contains(FmtSpan::EXIT)); assert!(f.contains(FmtSpan::CLOSE)); } + + /// Returns the test's module path. + fn current_path() -> String { + Path::new("tracing-subscriber") + .join("src") + .join("fmt") + .join("format") + .join("mod.rs") + .to_str() + .expect("path must not contain invalid unicode") + .to_owned() + } } diff --git a/tracing-subscriber/src/fmt/format/pretty.rs b/tracing-subscriber/src/fmt/format/pretty.rs index 37a9f63be3..22e4258673 100644 --- a/tracing-subscriber/src/fmt/format/pretty.rs +++ b/tracing-subscriber/src/fmt/format/pretty.rs @@ -76,6 +76,10 @@ impl Pretty { /// Sets whether the event's source code location is displayed. /// /// This defaults to `true`. + #[deprecated( + since = "0.3.6", + note = "all formatters now support configurable source locations. Use `Format::with_source_location` instead." + )] pub fn with_source_location(self, display_location: bool) -> Self { Self { display_location, @@ -84,17 +88,6 @@ impl Pretty { } } -impl Format { - /// Sets whether or not the source code location from which an event - /// originated is displayed. - /// - /// This defaults to `true`. - pub fn with_source_location(mut self, display_location: bool) -> Self { - self.format = self.format.with_source_location(display_location); - self - } -} - impl FormatEvent for Format where C: Collect + for<'a> LookupSpan<'a>, @@ -135,12 +128,37 @@ where }; write!( writer, - "{}{}{}: ", + "{}{}{}:", target_style.prefix(), meta.target(), target_style.infix(style) )?; } + let line_number = if self.display_line_number { + meta.line() + } else { + None + }; + + // If the file name is disabled, format the line number right after the + // target. Otherwise, if we also display the file, it'll go on a + // separate line. + if let (Some(line_number), false, true) = ( + line_number, + self.display_filename, + self.format.display_location, + ) { + write!( + writer, + "{}{}{}:", + style.prefix(), + line_number, + style.infix(style) + )?; + } + + writer.write_char(' ')?; + let mut v = PrettyVisitor::new(writer.by_ref(), true).with_style(style); event.record(&mut v); v.finish()?; @@ -152,20 +170,21 @@ where Style::new() }; let thread = self.display_thread_name || self.display_thread_id; - if let (true, Some(file), Some(line)) = - (self.format.display_location, meta.file(), meta.line()) - { - write!( - writer, - " {} {}:{}{}", - dimmed.paint("at"), - file, - line, - dimmed.paint(if thread { " " } else { "\n" }) - )?; + + if let (Some(file), true, true) = ( + meta.file(), + self.format.display_location, + self.display_filename, + ) { + write!(writer, " {} {}", dimmed.paint("at"), file,)?; + + if let Some(line) = line_number { + write!(writer, ":{}", line)?; + } + writer.write_char(if thread { ' ' } else { '\n' })?; } else if thread { write!(writer, " ")?; - } + }; if thread { write!(writer, "{} ", dimmed.paint("on"))?; diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index ebda9e0865..e6c8345461 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -755,6 +755,34 @@ where } } + /// Sets whether or not an event's [source code file path][file] is + /// displayed. + /// + /// [file]: tracing_core::Metadata::file + pub fn with_file( + self, + display_filename: bool, + ) -> CollectorBuilder, F, W> { + CollectorBuilder { + inner: self.inner.with_file(display_filename), + ..self + } + } + + /// Sets whether or not an event's [source code line number][line] is + /// displayed. + /// + /// [line]: tracing_core::Metadata::line + pub fn with_line_number( + self, + display_line_number: bool, + ) -> CollectorBuilder, F, W> { + CollectorBuilder { + inner: self.inner.with_line_number(display_line_number), + ..self + } + } + /// Sets whether or not an event's level is displayed. pub fn with_level( self, From 27c3633183f12396970456187a61493b88aef048 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 21 Jan 2022 12:46:16 -0800 Subject: [PATCH 15/32] appender: bump MSRV to 1.53.0 (#1851) The `time` crate bumped its MSRV to 1.53.0 in v0.3.6: https://github.com/time-rs/time/commit/2d37c01aff74bdccb8c537afa6bc7ce4f028048d Since `tracing-appender` has a non-optional dependency on `time`, it's necessary to increase its MSRV to track this. --- .github/workflows/check_msrv.yml | 2 +- tracing-appender/Cargo.toml | 2 +- tracing-appender/README.md | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/.github/workflows/check_msrv.yml b/.github/workflows/check_msrv.yml index 0af6c29675..c94e60b170 100644 --- a/.github/workflows/check_msrv.yml +++ b/.github/workflows/check_msrv.yml @@ -53,7 +53,7 @@ jobs: - uses: actions/checkout@main - uses: actions-rs/toolchain@v1 with: - toolchain: 1.51.0 + toolchain: 1.53.0 profile: minimal override: true - name: Check diff --git a/tracing-appender/Cargo.toml b/tracing-appender/Cargo.toml index 77da71da4b..7020cdc39d 100644 --- a/tracing-appender/Cargo.toml +++ b/tracing-appender/Cargo.toml @@ -18,7 +18,7 @@ categories = [ ] keywords = ["logging", "tracing", "file-appender", "non-blocking-writer"] edition = "2018" -rust-version = "1.51.0" +rust-version = "1.53.0" [dependencies] crossbeam-channel = "0.5.0" diff --git a/tracing-appender/README.md b/tracing-appender/README.md index b04a13db4b..7245193bfc 100644 --- a/tracing-appender/README.md +++ b/tracing-appender/README.md @@ -36,7 +36,7 @@ allows events and spans to be recorded in a non-blocking manner through a dedicated logging thread. It also provides a [`RollingFileAppender`][file_appender] that can be used with _or_ without the non-blocking writer. -*Compiler support: [requires `rustc` 1.51+][msrv]* +*Compiler support: [requires `rustc` 1.53+][msrv]* [msrv]: #supported-rust-versions @@ -146,7 +146,7 @@ fn main() { ## Supported Rust Versions `tracing-appender` is built against the latest stable release. The minimum supported -version is 1.51. The current `tracing-appender` version is not guaranteed to build on +version is 1.53. The current `tracing-appender` version is not guaranteed to build on Rust versions earlier than the minimum supported version. Tracing follows the same compiler support policies as the rest of the Tokio From d88df7c8225f39c35bb362c62f997179e4e4510e Mon Sep 17 00:00:00 2001 From: Matthias Vogelgesang Date: Mon, 24 Jan 2022 19:18:28 +0100 Subject: [PATCH 16/32] subscriber: update thread_local to 1.1.4 (#1858) Fixes https://rustsec.org/advisories/RUSTSEC-2022-0006. ## Motivation `cargo audit` prevents us using `tracing-subscriber` at the moment. Upgrading `thread_local` to 1.1.4 would fix that. ## Solution Upgrade `thread_local`. --- tracing-subscriber/Cargo.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 59f06ba5f6..76e7619c18 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -61,7 +61,7 @@ parking_lot = { version = ">= 0.7, <= 0.12", optional = true } # registry sharded-slab = { version = "0.1.0", optional = true } -thread_local = { version = "1.0.1", optional = true } +thread_local = { version = "1.1.4", optional = true } [dev-dependencies] tracing = { path = "../tracing", version = "0.2" } From a0c69eb0111f6273b7f8969ddd61c5c0fc8f706d Mon Sep 17 00:00:00 2001 From: David Barsky Date: Wed, 12 Jan 2022 16:14:19 -0500 Subject: [PATCH 17/32] WIP docs --- tracing/src/macros.rs | 27 ++++++++++++++------------- 1 file changed, 14 insertions(+), 13 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index f9fac13afa..438a8faffc 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -783,22 +783,20 @@ macro_rules! event { ); } -/// Check's whether an equivalent `event!` invocation would result in an enabled -/// event. +/// Checks whether a span or event is enabled depending on the provided metadata. /// -/// 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 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). /// -/// This macro operates similarly to [`event!`], with some extensions: -/// - Allows passing just a level. -/// - Allows passing just a level and a target. +/// While `enabled!` can be used as a migration aid from [`log::log_enabled`], +/// it is recommended that it be used sparingly. In most cases, a centralized +/// filtering approach such as [`Targets`] or [`filter_fn`] will provide +/// similar performance and greater ease-of-use. /// -/// See [the top-level documentation][lib] for details on the syntax accepted by -/// this macro. /// -/// [lib]: crate#using-the-macros -/// [`event!`]: event! /// /// # Examples /// @@ -810,8 +808,11 @@ macro_rules! event { /// # // Do something expensive /// # } /// # } -/// ``` /// +/// [`log::log_enabled`]: https://docs.rs/log/0.4.14/log/macro.log_enabled.html +/// [`Targets`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/targets/struct.Targets.html +/// [`filter_fn`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/fn.filter_fn.html +/// ``` #[macro_export] macro_rules! enabled { (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ From 55ee5c2ce41d682b838c2d8eda414a60a1122042 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Wed, 12 Jan 2022 17:52:04 -0500 Subject: [PATCH 18/32] add examples --- tracing/src/macros.rs | 36 ++++++++++++++++++++++++++---------- 1 file changed, 26 insertions(+), 10 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 438a8faffc..31995f4798 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -793,10 +793,10 @@ macro_rules! event { /// /// While `enabled!` can be used as a migration aid from [`log::log_enabled`], /// it is recommended that it be used sparingly. In most cases, a centralized -/// filtering approach such as [`Targets`] or [`filter_fn`] will provide -/// similar performance and greater ease-of-use. -/// -/// +/// filtering approach such as [`Targets`], [`filter_fn`], or [`EnvFilter`] will provide +/// similar performance and greater ease-of-use. Similarly, while `enabled!` supports +/// spans-derived, idiomatic usage of spans means that using `enabled!` with spans +/// is unnecessary. /// /// # Examples /// @@ -804,15 +804,31 @@ macro_rules! event { /// use tracing::{enabled, Level}; /// /// # fn main() { -/// # if enabled!(Level::DEBUG, "Debug loggin") { -/// # // Do something expensive -/// # } +/// // If the underlying collector is interested in recording +/// // DEBUG-level spans and events, this will evaluate to true. +/// if enabled!(Level::DEBUG) { +/// // some expensive work... +/// } +/// +/// // If the underlying collector is interested in recording spans and events +/// // with the target "my_crate" at the level DEBUG, this will evaluate to true. +/// if enabled!(target: "my_crate", Level::DEBUG) { +/// // some expensive work... +/// } +/// +/// // If the underlying collector is interested in recording spans and events +/// // with the target "my_crate", at the level DEBUG, and the field name "hello", +/// // this will evaluate to true. +/// if enabled!(target: "my_crate", Level::DEBUG, {"hello"}) { +/// // some expensive work... +/// } /// # } +/// ``` /// /// [`log::log_enabled`]: https://docs.rs/log/0.4.14/log/macro.log_enabled.html -/// [`Targets`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/targets/struct.Targets.html -/// [`filter_fn`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/fn.filter_fn.html -/// ``` +/// [`Targets`]: https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/filter/targets/struct.Targets.html +/// [`filter_fn`]: https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/filter/fn.filter_fn.html +/// [`EnvFilter`]: https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/struct.EnvFilter.html #[macro_export] macro_rules! enabled { (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ From dd563c3b70cf3e633179441da5bd575e602203ea Mon Sep 17 00:00:00 2001 From: David Barsky Date: Fri, 21 Jan 2022 15:30:23 -0500 Subject: [PATCH 19/32] wip, sorry --- tracing/src/macros.rs | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 31995f4798..7660b0b9a8 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -791,12 +791,11 @@ macro_rules! event { /// when multiple events are emitted (e.g., iterating over a collection /// and emitting an event for each item). /// -/// While `enabled!` can be used as a migration aid from [`log::log_enabled`], -/// it is recommended that it be used sparingly. In most cases, a centralized -/// filtering approach such as [`Targets`], [`filter_fn`], or [`EnvFilter`] will provide -/// similar performance and greater ease-of-use. Similarly, while `enabled!` supports -/// spans-derived, idiomatic usage of spans means that using `enabled!` with spans -/// is unnecessary. +/// `enabled!()` requires a level argument, an optional `target:` +/// argument, and an optional set of fields. 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 /// @@ -819,7 +818,7 @@ macro_rules! event { /// // If the underlying collector is interested in recording spans and events /// // with the target "my_crate", at the level DEBUG, and the field name "hello", /// // this will evaluate to true. -/// if enabled!(target: "my_crate", Level::DEBUG, {"hello"}) { +/// if enabled!(target: "my_crate", Level::DEBUG, hello) { /// // some expensive work... /// } /// # } From 61dbf07452750a625d3c28edaba7b7419eb61c64 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Mon, 24 Jan 2022 18:15:58 -0500 Subject: [PATCH 20/32] okay, it covers stuff now --- tracing/src/macros.rs | 23 ++++++++++++++++++++--- 1 file changed, 20 insertions(+), 3 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 7660b0b9a8..7a476e510d 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -791,14 +791,31 @@ macro_rules! event { /// when multiple events are emitted (e.g., iterating over a collection /// and emitting an event for each item). /// -/// `enabled!()` requires a level argument, an optional `target:` +/// ## Usage +/// +/// It is possible for `enabled!` to return a false positive or negative. This might +/// occur when a subscriber is using a _more specific_ filter than what was (or could be) +/// provided to `enabled!`. Below are +/// +/// - If a subscriber 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 subscriber to enable something that would otherwise be disabled. +/// - If a subscriber 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 subscriber can choose to enable _only_ spans or _only_ events, which `enabled` +/// will not reflect. +/// +/// ## Examples +/// +/// /// `enabled!()` requires a level argument, an optional `target:` /// argument, and an optional set of fields. 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 -/// /// ```rust /// use tracing::{enabled, Level}; /// From ad24e273e0fc9ee21407b30e44de47da2afd4f90 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Mon, 24 Jan 2022 18:41:24 -0500 Subject: [PATCH 21/32] whoops, typo. --- tracing/src/macros.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 7a476e510d..d279058e2d 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -810,7 +810,7 @@ macro_rules! event { /// /// ## Examples /// -/// /// `enabled!()` requires a level argument, an optional `target:` +/// `enabled!()` requires a level argument, an optional `target:` /// argument, and an optional set of fields. 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 From 0b265857e9d7a66a59543288c85f5a959da99d72 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Mon, 24 Jan 2022 18:48:26 -0500 Subject: [PATCH 22/32] rebase, i think? --- tracing/src/macros.rs | 15 +++++++++++---- 1 file changed, 11 insertions(+), 4 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index d279058e2d..df919f37e2 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -879,20 +879,27 @@ macro_rules! enabled { ); // These two cases handle fields with no values - (target: $target:expr, $lvl:expr, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($k:ident).+) => ( + $crate::enabled!(target: $target, $lvl, $($k).+,) + ); + (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( $crate::enabled!( target: $target, $lvl, - { $($field)*} + { $($k).+, $($field)*} ) ); - ($lvl:expr, $($field:tt)*) => ( + + ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( $crate::enabled!( target: module_path!(), $lvl, - { $($field)*} + { $($k).+, $($field)*} ) ); + ($lvl:expr, $($k:ident).+) => ( + $crate::enabled!($lvl, $($k).+,) + ); // Simplest `enabled!` case ( $lvl:expr ) => ( From 18ae036f028c3b028d46be347d510604218e06e4 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Mon, 24 Jan 2022 18:49:48 -0500 Subject: [PATCH 23/32] fix phrasing fuckups --- tracing/src/macros.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index df919f37e2..87df7fe73f 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -793,9 +793,9 @@ macro_rules! event { /// /// ## Usage /// -/// It is possible for `enabled!` to return a false positive or negative. This might +/// It is possible for `enabled!` to return a false positive or false negative. This might /// occur when a subscriber is using a _more specific_ filter than what was (or could be) -/// provided to `enabled!`. Below are +/// provided to `enabled!`. Below are several examples where this might occur: /// /// - If a subscriber is using a filter which may enable a span or event based /// on field names, but `enabled!` is invoked without listing field names, From 8e68af02817d1a858f1bd62836e1eeb334c4096c Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Fri, 7 Jan 2022 08:59:43 -0800 Subject: [PATCH 24/32] 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 | 11 ++ tracing/src/macros.rs | 236 +++++++++++++++++++++++++++++++++++ tracing/tests/enabled.rs | 30 +++++ tracing/tests/macros.rs | 41 +++++- 5 files changed, 335 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..42eb9ae41e 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..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..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..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() { From 0bee395ed0b94b6d4646649dd21d2d378a394609 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Mon, 10 Jan 2022 16:34:56 -0800 Subject: [PATCH 25/32] simplify the macro --- tracing/src/macros.rs | 171 +++------------------------------------- tracing/tests/macros.rs | 34 +------- 2 files changed, 17 insertions(+), 188 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 137995b515..8e6cd795f0 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -814,52 +814,6 @@ macro_rules! event { /// #[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 _; @@ -878,11 +832,7 @@ macro_rules! enabled { 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)*) - ) + $crate::dispatch::get_default(|current| current.enabled(meta)) } else { false } @@ -890,96 +840,23 @@ macro_rules! enabled { 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 + // Just target and level (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)*} - ) + $crate::enabled!(target: $target, $lvl, { }) ); - (parent: $parent:expr, $lvl:expr, %$($k:ident).+ = $($field:tt)*) => ( - $crate::enabled!( - target: module_path!(), - parent: $parent, - $lvl, - { %$($k).+ = $($field)*} - ) + + // These two cases handle fields with no values + (target: $target:expr, $lvl:expr, $($k:ident).+) => ( + $crate::enabled!(target: $target, $lvl, $($k).+,) ); - (parent: $parent:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( $crate::enabled!( - target: module_path!(), - parent: $parent, + target: $target, $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!(), @@ -987,35 +864,13 @@ macro_rules! enabled { { $($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 + + // Simplest `enabled!` case ( $lvl:expr ) => ( - $crate::enabled!(target: module_path!(), $lvl, { "hint_message" }) + $crate::enabled!(target: module_path!(), $lvl, { }) ); } diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index 77c7f1583f..d010a804dc 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -337,40 +337,14 @@ fn event() { #[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, bar.baz, quux,); + enabled!(Level::DEBUG, message); + enabled!(Level::INFO, foo, bar.baz, quux, messaged,); 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)] From f68cc1f40e07b62665ab9f7403b1773aabe365ee Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Mon, 10 Jan 2022 16:45:24 -0800 Subject: [PATCH 26/32] remove new event methods --- tracing-core/src/event.rs | 18 ------------------ 1 file changed, 18 deletions(-) diff --git a/tracing-core/src/event.rs b/tracing-core/src/event.rs index 675ab76d73..70bd6658ca 100644 --- a/tracing-core/src/event.rs +++ b/tracing-core/src/event.rs @@ -79,24 +79,6 @@ 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 From 93657b735752b1cddba7550cae49edba7ea9b002 Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Tue, 11 Jan 2022 08:40:33 -0800 Subject: [PATCH 27/32] fix Kind::HINT's doc's --- tracing-core/src/metadata.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing-core/src/metadata.rs b/tracing-core/src/metadata.rs index 42eb9ae41e..08689e75c1 100644 --- a/tracing-core/src/metadata.rs +++ b/tracing-core/src/metadata.rs @@ -383,7 +383,7 @@ impl Kind { /// `Span` callsite pub const SPAN: Kind = Kind(KindInner::Span); - /// `enabled!` callsite. [`Collect`][`crate::collect::Collect`]'s can assume + /// `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); From 405e61c3c836c093d5b95db4d61fb56c96e05ceb Mon Sep 17 00:00:00 2001 From: Gus Wynn Date: Thu, 13 Jan 2022 08:09:15 -0800 Subject: [PATCH 28/32] simplify dot cases --- tracing/src/macros.rs | 15 ++++----------- tracing/tests/macros.rs | 3 ++- 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 8e6cd795f0..f9fac13afa 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -846,27 +846,20 @@ macro_rules! enabled { ); // These two cases handle fields with no values - (target: $target:expr, $lvl:expr, $($k:ident).+) => ( - $crate::enabled!(target: $target, $lvl, $($k).+,) - ); - (target: $target:expr, $lvl:expr, $($k:ident).+, $($field:tt)*) => ( + (target: $target:expr, $lvl:expr, $($field:tt)*) => ( $crate::enabled!( target: $target, $lvl, - { $($k).+, $($field)*} + { $($field)*} ) ); - - ($lvl:expr, $($k:ident).+, $($field:tt)*) => ( + ($lvl:expr, $($field:tt)*) => ( $crate::enabled!( target: module_path!(), $lvl, - { $($k).+, $($field)*} + { $($field)*} ) ); - ($lvl:expr, $($k:ident).+) => ( - $crate::enabled!($lvl, $($k).+,) - ); // Simplest `enabled!` case ( $lvl:expr ) => ( diff --git a/tracing/tests/macros.rs b/tracing/tests/macros.rs index d010a804dc..0a32ebfc3f 100644 --- a/tracing/tests/macros.rs +++ b/tracing/tests/macros.rs @@ -339,7 +339,8 @@ fn event() { fn enabled() { enabled!(Level::DEBUG, foo, bar.baz, quux,); enabled!(Level::DEBUG, message); - enabled!(Level::INFO, foo, bar.baz, quux, messaged,); + enabled!(Level::INFO, foo, bar.baz, quux, message,); + enabled!(Level::INFO, foo, bar., message,); enabled!(Level::DEBUG, foo); enabled!(Level::DEBUG); From 50a2c8728b67975efed4f56d3c01b9b1b14b8830 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 28 Jan 2022 10:48:34 -0800 Subject: [PATCH 29/32] Apply docs suggestions from code review --- tracing/src/macros.rs | 66 +++++++++++++++++++++++++++---------------- 1 file changed, 41 insertions(+), 25 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 491e661be5..87527e222a 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -783,7 +783,10 @@ macro_rules! event { ); } -/// Checks whether a span or event is enabled depending on the provided metadata. +/// 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 @@ -791,60 +794,73 @@ macro_rules! event { /// when multiple events are emitted (e.g., iterating over a collection /// and emitting an event for each item). /// -/// ## Usage +/// # 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 /// -/// It is possible for `enabled!` to return a false positive or false negative. This might -/// occur when a subscriber is using a _more specific_ filter than what was (or could be) -/// provided to `enabled!`. Below are several examples where this might occur: +/// 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 subscriber is using a filter which may enable a span or event based +/// - 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 subscriber to enable something that would otherwise be disabled. -/// - If a subscriber is using a filter which enables or disables specific events by +/// 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 subscriber can choose to enable _only_ spans or _only_ events, which `enabled` +/// - The collector can choose to enable _only_ spans or _only_ events, which `enabled` /// will not reflect. /// -/// ## Examples -/// -/// `enabled!()` requires a level argument, an optional `target:` -/// argument, and an optional set of fields. If the fields are not provided, +/// `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}; /// -/// # fn main() { -/// // If the underlying collector is interested in recording -/// // DEBUG-level spans and events, this will evaluate to true. /// if enabled!(Level::DEBUG) { /// // some expensive work... /// } +/// ``` /// -/// // If the underlying collector is interested in recording spans and events -/// // with the target "my_crate" at the level DEBUG, this will evaluate to true. +/// 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: /// -/// // If the underlying collector is interested in recording spans and events -/// // with the target "my_crate", at the level DEBUG, and the field name "hello", -/// // this will evaluate to true. +/// ```rust +/// # use tracing::{enabled, Level}; /// if enabled!(target: "my_crate", Level::DEBUG, hello) { /// // some expensive work... /// } /// # } /// ``` /// -/// [`log::log_enabled`]: https://docs.rs/log/0.4.14/log/macro.log_enabled.html -/// [`Targets`]: https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/filter/targets/struct.Targets.html -/// [`filter_fn`]: https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/filter/fn.filter_fn.html -/// [`EnvFilter`]: https://docs.rs/tracing-subscriber/0.3.5/tracing_subscriber/struct.EnvFilter.html #[macro_export] macro_rules! enabled { (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ From 9cb95d55fbfe881e9a059b9f31e74873a538ab18 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 28 Jan 2022 10:48:58 -0800 Subject: [PATCH 30/32] fix wrong callsite kind for `enabled!` --- tracing/src/macros.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 87527e222a..9bb853d7a1 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -873,7 +873,7 @@ macro_rules! enabled { ":", line!() ), - kind: $crate::metadata::Kind::EVENT, + kind: $crate::metadata::Kind::HINT, target: $target, level: $lvl, fields: $($fields)* From fbe5f842065d66d4d1213f04f0e4a921ba22dc21 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 28 Jan 2022 10:59:12 -0800 Subject: [PATCH 31/32] Update tracing/src/macros.rs --- tracing/src/macros.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 9bb853d7a1..887a494a86 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -858,7 +858,6 @@ macro_rules! event { /// if enabled!(target: "my_crate", Level::DEBUG, hello) { /// // some expensive work... /// } -/// # } /// ``` /// #[macro_export] From 3cf628afc452147a3e26e8a339a42a1daa3aa726 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 28 Jan 2022 11:07:56 -0800 Subject: [PATCH 32/32] bleh rustfmt --- tracing/src/macros.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 887a494a86..ed0210761f 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -849,9 +849,9 @@ macro_rules! event { /// ``` /// /// 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: +/// 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};