Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

tracing: fix macros "use of moved value" with log #1823

Merged
merged 12 commits into from
Jan 29, 2022
2 changes: 1 addition & 1 deletion tracing-core/src/field.rs
Original file line number Diff line number Diff line change
Expand Up @@ -748,7 +748,7 @@ impl<'a> ValueSet<'a> {
/// Visits all the fields in this `ValueSet` with the provided [visitor].
///
/// [visitor]: super::Visit
hawkw marked this conversation as resolved.
Show resolved Hide resolved
pub(crate) fn record(&self, visitor: &mut dyn Visit) {
pub fn record(&self, visitor: &mut dyn Visit) {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
let my_callsite = self.callsite();
for (field, value) in self.values {
if field.callsite() != my_callsite {
Expand Down
50 changes: 49 additions & 1 deletion tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -980,7 +980,8 @@ pub mod __macro_support {
use crate::{collect::Interest, Metadata};
use core::fmt;
use core::sync::atomic::{AtomicUsize, Ordering};
use tracing_core::Once;
use tracing_core::field::{ValueSet, Visit};
use tracing_core::{Field, Once};

/// Callsite implementation used by macro-generated code.
///
Expand Down Expand Up @@ -1109,6 +1110,53 @@ pub mod __macro_support {
.finish()
}
}

/// 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.
#[derive(Debug)]
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
pub struct LogValueSet<'a>(pub &'a ValueSet<'a>);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i have a slight preference for giving this a new constructor, rather than a pub field, so that we can add new fields to it while still supporting earlier versions of the macros. however, i doubt this is an issue in practice, so it may not really matter...

Skepfyr marked this conversation as resolved.
Show resolved Hide resolved

impl<'a> fmt::Display for LogValueSet<'a> {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
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
}
}

struct LogVisitor<'a, 'b> {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
f: &'a mut fmt::Formatter<'b>,
is_first: bool,
result: fmt::Result,
}

impl Visit for LogVisitor<'_, '_> {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
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)
};
Comment on lines +1154 to +1163
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit, take it or leave it: this might look slightly nicer as a match?

Suggested change
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)
};
let res = match field.name() {
"message" if self.is_first() => write!(self.f, "{:?}", value),
"message" => write!(self.f, " {:?}", value),
name if self.is_first => write!(self.f, "{}={:?}", name, value),
name => write!(self.f, " {}={:?}", name, value,
};
self.is_first = false;

though, up to you

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I prefer the explicit something is only weird about the first one of the if. However, your snippet does produce a different output to mine, in the case of message not being the first field. Mine would produce:

foo=bar message=Hi! baz=quux

whereas yours would produce:

foo=bar Hi! baz=quux

Is that behaviour ok, or should I change it to be in line with yours?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

in practice, the valueset! macro will always re-order the message field to come first, so it doesn't really matter whether we handle it differently if it isn't the first field. i don't have a strong opinion about this code, so it's fine to leave it the way you had it if you prefer.

if let Err(err) = res {
self.result = self.result.and(Err(err));
}
}
}
}

mod sealed {
Expand Down
227 changes: 65 additions & 162 deletions tracing/src/macros.rs
Original file line number Diff line number Diff line change
Expand Up @@ -583,39 +583,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::Callsite as _;
static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! {
name: 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 {
Comment on lines -598 to +605
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i wonder if we could improve the benchmark performance for disabled spans by going back to having a separate if statement for level_enabled! and checking if the callsite is enabled? it might be worth trying that and re-running the benchmarks?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I had a go at this, but it didn't make any difference, and the way it is now is more readable to me.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

interesting, thanks for trying it anyway!

(|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!(
Expand All @@ -632,34 +641,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::Callsite as _;
static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! {
name: 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)+ ) => (
Expand Down Expand Up @@ -2159,129 +2177,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),* $(,)* } $(,)*) => {
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);
Expand All @@ -2297,7 +2200,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());
}
}
Expand Down