From 51613a6dfb7c1882a3622b2781f5bb718834d5b0 Mon Sep 17 00:00:00 2001 From: Jack Rickard Date: Sat, 29 Jan 2022 19:44:51 +0000 Subject: [PATCH] tracing: fix macros "use of moved value" with log (#1823) ## Motivation Fixes: #196, #1739 Previously, the `field` token trees would be substituted into the log macro invocation and the `ValueSet`, potentially meaning they are executed more than once. ## Solution This changes the `event!` macro (and all the upstream macros like `info!`), so that it only uses each field once when the log feature is enabled. It does this by generating the log using the `ValueSet` meaning the token trees are only substituted once. --- tracing-core/src/field.rs | 4 +- tracing/benches/global_subscriber.rs | 136 +++++++++++ tracing/src/lib.rs | 62 +++++ tracing/src/macros.rs | 227 +++++------------- .../test-log-support/tests/log_move_arg.rs | 22 ++ 5 files changed, 287 insertions(+), 164 deletions(-) create mode 100644 tracing/benches/global_subscriber.rs create mode 100644 tracing/test-log-support/tests/log_move_arg.rs diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs index e5c4cc7523..b62e91e235 100644 --- a/tracing-core/src/field.rs +++ b/tracing-core/src/field.rs @@ -881,8 +881,8 @@ impl<'a> ValueSet<'a> { /// Visits all the fields in this `ValueSet` with the provided [visitor]. /// - /// [visitor]: ../trait.Visit.html - pub(crate) fn record(&self, visitor: &mut dyn Visit) { + /// [visitor]: Visit + pub fn record(&self, visitor: &mut dyn Visit) { let my_callsite = self.callsite(); for (field, value) in self.values { if field.callsite() != my_callsite { diff --git a/tracing/benches/global_subscriber.rs b/tracing/benches/global_subscriber.rs new file mode 100644 index 0000000000..83519610a8 --- /dev/null +++ b/tracing/benches/global_subscriber.rs @@ -0,0 +1,136 @@ +use std::fmt::Write; + +use criterion::{black_box, criterion_group, criterion_main, Criterion}; +use tracing::Level; + +use tracing::{span, Event, Id, Metadata}; + +/// A subscriber that is enabled but otherwise does nothing. +struct EnabledSubscriber; + +impl tracing::Subscriber for EnabledSubscriber { + fn new_span(&self, span: &span::Attributes<'_>) -> Id { + let _ = span; + Id::from_u64(0xDEAD_FACE) + } + + fn event(&self, event: &Event<'_>) { + let _ = event; + } + + fn record(&self, span: &Id, values: &span::Record<'_>) { + let _ = (span, values); + } + + fn record_follows_from(&self, span: &Id, follows: &Id) { + let _ = (span, follows); + } + + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + let _ = metadata; + true + } + + fn enter(&self, span: &Id) { + let _ = span; + } + + fn exit(&self, span: &Id) { + let _ = span; + } +} + +const NOP_LOGGER: NopLogger = NopLogger; + +struct NopLogger; + +impl log::Log for NopLogger { + fn enabled(&self, _metadata: &log::Metadata) -> bool { + true + } + + fn log(&self, record: &log::Record) { + if self.enabled(record.metadata()) { + let mut this = self; + let _ = write!(this, "{}", record.args()); + } + } + + fn flush(&self) {} +} + +impl Write for &NopLogger { + fn write_str(&mut self, s: &str) -> std::fmt::Result { + black_box(s); + Ok(()) + } +} + +const N_SPANS: usize = 100; + +fn criterion_benchmark(c: &mut Criterion) { + let mut c = c.benchmark_group("global/subscriber"); + let _ = tracing::subscriber::set_global_default(EnabledSubscriber); + let _ = log::set_logger(&NOP_LOGGER); + log::set_max_level(log::LevelFilter::Trace); + c.bench_function("span_no_fields", |b| b.iter(|| span!(Level::TRACE, "span"))); + + c.bench_function("event", |b| { + b.iter(|| { + tracing::event!(Level::TRACE, "hello"); + }) + }); + + c.bench_function("enter_span", |b| { + let span = span!(Level::TRACE, "span"); + #[allow(clippy::unit_arg)] + b.iter(|| black_box(span.in_scope(|| {}))) + }); + + c.bench_function("span_repeatedly", |b| { + #[inline] + fn mk_span(i: u64) -> tracing::Span { + span!(Level::TRACE, "span", i = i) + } + + let n = black_box(N_SPANS); + b.iter(|| (0..n).fold(mk_span(0), |_, i| mk_span(i as u64))) + }); + + c.bench_function("span_with_fields", |b| { + b.iter(|| { + span!( + Level::TRACE, + "span", + foo = "foo", + bar = "bar", + baz = 3, + quuux = tracing::field::debug(0.99) + ) + }); + }); +} + +fn bench_dispatch(c: &mut Criterion) { + let mut group = c.benchmark_group("global/dispatch"); + let _ = tracing::subscriber::set_global_default(EnabledSubscriber); + let _ = log::set_logger(&NOP_LOGGER); + log::set_max_level(log::LevelFilter::Trace); + group.bench_function("get_ref", |b| { + b.iter(|| { + tracing::dispatcher::get_default(|current| { + black_box(¤t); + }) + }) + }); + group.bench_function("get_clone", |b| { + b.iter(|| { + let current = tracing::dispatcher::get_default(|current| current.clone()); + black_box(current); + }) + }); + group.finish(); +} + +criterion_group!(benches, criterion_benchmark, bench_dispatch); +criterion_main!(benches); diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index d583d6ce8b..f13fd0fd5e 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -1089,6 +1089,68 @@ pub mod __macro_support { .finish() } } + + #[cfg(feature = "log")] + use tracing_core::field::{Field, ValueSet, Visit}; + + /// Utility to format [`ValueSet`] for logging, used by macro-generated code. + /// + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This type, and all code contained in the `__macro_support` module, is + /// a *private* API of `tracing`. It is exposed publicly because it is used + /// by the `tracing` macros, but it is not part of the stable versioned API. + /// Breaking changes to this module may occur in small-numbered versions + /// without warning. + #[cfg(feature = "log")] + #[allow(missing_debug_implementations)] + pub struct LogValueSet<'a>(pub &'a ValueSet<'a>); + + #[cfg(feature = "log")] + impl<'a> fmt::Display for LogValueSet<'a> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut visit = LogVisitor { + f, + is_first: true, + result: Ok(()), + }; + self.0.record(&mut visit); + visit.result + } + } + + #[cfg(feature = "log")] + struct LogVisitor<'a, 'b> { + f: &'a mut fmt::Formatter<'b>, + is_first: bool, + result: fmt::Result, + } + + #[cfg(feature = "log")] + impl Visit for LogVisitor<'_, '_> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + let res = if self.is_first { + self.is_first = false; + if field.name() == "message" { + write!(self.f, "{:?}", value) + } else { + write!(self.f, "{}={:?}", field.name(), value) + } + } else { + write!(self.f, " {}={:?}", field.name(), value) + }; + if let Err(err) = res { + self.result = self.result.and(Err(err)); + } + } + + fn record_str(&mut self, field: &Field, value: &str) { + if field.name() == "message" { + self.record_debug(field, &format_args!("{}", value)) + } else { + self.record_debug(field, &value) + } + } + } } mod sealed { diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 55fc881e8b..ec680f43ba 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -582,39 +582,48 @@ macro_rules! error_span { // /// ``` #[macro_export] macro_rules! event { - (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ( - $crate::__tracing_log!( + (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ + use $crate::__macro_support::Callsite as _; + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + name: concat!( + "event ", + file!(), + ":", + line!() + ), + kind: $crate::metadata::Kind::EVENT, target: $target, - $lvl, - $($fields)* - ); + level: $lvl, + fields: $($fields)* + }; - if $crate::level_enabled!($lvl) { - use $crate::__macro_support::*; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { - name: $crate::__macro_support::concat!( - "event ", - file!(), - ":", - line!() - ), - kind: $crate::metadata::Kind::EVENT, - target: $target, - level: $lvl, - fields: $($fields)* - }; + let enabled = $crate::level_enabled!($lvl) && { let interest = CALLSITE.interest(); - if !interest.is_never() && CALLSITE.is_enabled(interest) { + !interest.is_never() && CALLSITE.is_enabled(interest) + }; + if enabled { + (|value_set: $crate::field::ValueSet| { + $crate::__tracing_log!( + target: $target, + $lvl, + &value_set + ); let meta = CALLSITE.metadata(); // event with explicit parent $crate::Event::child_of( $parent, meta, - &$crate::valueset!(meta.fields(), $($fields)*) + &value_set ); - } + })($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); + } else { + $crate::__tracing_log!( + target: $target, + $lvl, + &$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*) + ); } - ); + }); (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( $crate::event!( @@ -631,34 +640,43 @@ macro_rules! event { $crate::event!(target: $target, parent: $parent, $lvl, { $($arg)+ }) ); (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ - $crate::__tracing_log!( + use $crate::__macro_support::Callsite as _; + static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + name: concat!( + "event ", + file!(), + ":", + line!() + ), + kind: $crate::metadata::Kind::EVENT, target: $target, - $lvl, - $($fields)* - ); - if $crate::level_enabled!($lvl) { - use $crate::__macro_support::*; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { - name: $crate::__macro_support::concat!( - "event ", - file!(), - ":", - line!() - ), - kind: $crate::metadata::Kind::EVENT, - target: $target, - level: $lvl, - fields: $($fields)* - }; + level: $lvl, + fields: $($fields)* + }; + let enabled = $crate::level_enabled!($lvl) && { let interest = CALLSITE.interest(); - if !interest.is_never() && CALLSITE.is_enabled(interest) { + !interest.is_never() && CALLSITE.is_enabled(interest) + }; + if enabled { + (|value_set: $crate::field::ValueSet| { let meta = CALLSITE.metadata(); // event with contextual parent $crate::Event::dispatch( meta, - &$crate::valueset!(meta.fields(), $($fields)*) + &value_set ); - } + $crate::__tracing_log!( + target: $target, + $lvl, + &value_set + ); + })($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); + } else { + $crate::__tracing_log!( + target: $target, + $lvl, + &$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*) + ); } }); (target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => ( @@ -2294,129 +2312,14 @@ macro_rules! __tracing_stringify { #[doc(hidden)] #[macro_export] macro_rules! __tracing_log { - (target: $target:expr, $level:expr, $($field:tt)+ ) => {}; -} - -#[cfg(feature = "log")] -#[doc(hidden)] -#[macro_export] -macro_rules! __mk_format_string { - // === base case === - (@ { $(,)* $($out:expr),* $(,)* } $(,)*) => { - $crate::__macro_support::concat!( $($out),*) - }; - - // === recursive case (more tts), === - // ====== shorthand field syntax === - (@ { $(,)* $($out:expr),* }, ?$($k:ident).+, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, $crate::__tracing_stringify!($($k).+), "={:?} " }, $($rest)*) - }; - (@ { $(,)* $($out:expr),* }, %$($k:ident).+, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, $crate::__tracing_stringify!($($k).+), "={} " }, $($rest)*) - }; - (@ { $(,)* $($out:expr),* }, $($k:ident).+, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, $crate::__tracing_stringify!($($k).+), "={:?} " }, $($rest)*) - }; - // ====== kv field syntax === - (@ { $(,)* $($out:expr),* }, message = $val:expr, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, "{} " }, $($rest)*) - }; - (@ { $(,)* $($out:expr),* }, $($k:ident).+ = ?$val:expr, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, $crate::__tracing_stringify!($($k).+), "={:?} " }, $($rest)*) - }; - (@ { $(,)* $($out:expr),* }, $($k:ident).+ = %$val:expr, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, $crate::__tracing_stringify!($($k).+), "={} " }, $($rest)*) - }; - (@ { $(,)* $($out:expr),* }, $($k:ident).+ = $val:expr, $($rest:tt)*) => { - $crate::__mk_format_string!(@ { $($out),*, $crate::__tracing_stringify!($($k).+), "={:?} " }, $($rest)*) - }; - - // === rest is unparseable --- must be fmt args === - (@ { $(,)* $($out:expr),* }, $($rest:tt)+) => { - $crate::__mk_format_string!(@ { "{} ", $($out),* }, ) - }; - - // === entry === - ($($kvs:tt)+) => { - $crate::__mk_format_string!(@ { }, $($kvs)+,) - }; - () => { - "" - } -} - -#[cfg(feature = "log")] -#[doc(hidden)] -#[macro_export] -macro_rules! __mk_format_args { - // === finished --- called into by base cases === - (@ { $(,)* $($out:expr),* $(,)* }, $fmt:expr, fields: $(,)*) => { - format_args!($fmt, $($out),*) - }; - - // === base case (no more tts) === - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ = ?$val:expr $(,)*) => { - $crate::__mk_format_args!(@ { $($out),*, $val }, $fmt, fields: ) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ = %$val:expr $(,)*) => { - $crate::__mk_format_args!(@ { $($out),*, $val }, $fmt, fields: ) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ = $val:expr $(,)*) => { - $crate::__mk_format_args!(@ { $($out),*, $val }, $fmt, fields: ) - }; - // ====== shorthand field syntax === - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: ?$($k:ident).+ $(,)*) => { - $crate::__mk_format_args!(@ { $($out),*, &$($k).+ }, $fmt, fields:) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: %$($k:ident).+ $(,)*) => { - $crate::__mk_format_args!(@ { $($out),*, &$($k).+ }, $fmt, fields: ) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ $(,)*) => { - $crate::__mk_format_args!(@ { $($out),*, &$($k).+ }, $fmt, fields: ) - }; - - // === recursive case (more tts) === - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ = ?$val:expr, $($rest:tt)+) => { - $crate::__mk_format_args!(@ { $($out),*, $val }, $fmt, fields: $($rest)+) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ = %$val:expr, $($rest:tt)+) => { - $crate::__mk_format_args!(@ { $($out),*, $val }, $fmt, fields: $($rest)+) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+ = $val:expr, $($rest:tt)+) => { - $crate::__mk_format_args!(@ { $($out),*, $val }, $fmt, fields: $($rest)+) - }; - // ====== shorthand field syntax === - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: ?$($k:ident).+, $($rest:tt)+) => { - $crate::__mk_format_args!(@ { $($out),*, &$($k).+ }, $fmt, fields: $($rest)+) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: %$($k:ident).+, $($rest:tt)+) => { - $crate::__mk_format_args!(@ { $($out),*, &$($k).+ }, $fmt, fields: $($rest)+) - }; - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($k:ident).+, $($rest:tt)+) => { - $crate::__mk_format_args!(@ { $($out),*, &$($k).+ }, $fmt, fields: $($rest)+) - }; - - // === rest is unparseable --- must be fmt args === - (@ { $(,)* $($out:expr),* }, $fmt:expr, fields: $($rest:tt)+) => { - $crate::__mk_format_args!(@ { format_args!($($rest)+), $($out),* }, $fmt, fields: ) - }; - - // === entry === - ($($kv:tt)*) => { - { - #[allow(unused_imports)] - use $crate::field::{debug, display}; - // use $crate::__mk_format_string; - $crate::__mk_format_args!(@ { }, $crate::__mk_format_string!($($kv)*), fields: $($kv)*) - } - }; + (target: $target:expr, $level:expr, $value_set:expr ) => {}; } #[cfg(feature = "log")] #[doc(hidden)] #[macro_export] macro_rules! __tracing_log { - (target: $target:expr, $level:expr, $($field:tt)+ ) => { + (target: $target:expr, $level:expr, $value_set:expr ) => { $crate::if_log_enabled! { $level, { use $crate::log; let level = $crate::level_to_log!($level); @@ -2432,7 +2335,7 @@ macro_rules! __tracing_log { .module_path(Some(module_path!())) .line(Some(line!())) .metadata(log_meta) - .args($crate::__mk_format_args!($($field)+)) + .args(format_args!("{}", $crate::__macro_support::LogValueSet($value_set))) .build()); } } diff --git a/tracing/test-log-support/tests/log_move_arg.rs b/tracing/test-log-support/tests/log_move_arg.rs new file mode 100644 index 0000000000..f0d87193eb --- /dev/null +++ b/tracing/test-log-support/tests/log_move_arg.rs @@ -0,0 +1,22 @@ +use tracing::{event, span, Level}; + +/// Test that spans and events only use their argument once. See #196 and #1739. +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn test_move_arg() { + let foo = Foo; + let parent_span = span!(Level::INFO, "Span 1", bar = ?Bar(foo)); + let foo = Foo; + span!(parent: &parent_span, Level::INFO, "Span 2", bar = ?Bar(foo)); + + let foo = Foo; + event!(Level::INFO, bar = ?Bar(foo), "Event 1"); + let foo = Foo; + event!(parent: &parent_span, Level::INFO, bar = ?Bar(foo), "Event 2"); +} + +#[derive(Debug)] +struct Foo; + +#[derive(Debug)] +struct Bar(Foo);