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.

Sign up for GitHub

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
Merged

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

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
874a462
tracing: fix macros "use of moved value" with log
Skepfyr Jan 9, 2022
bc81ef5
tracing: fix span macros with log feature
Skepfyr Jan 9, 2022
0ad95a9
tracing: revert fix span macros with log feature
Skepfyr Jan 11, 2022
68b56d0
tracing: Move LogValueSet into __macro_support
Skepfyr Jan 11, 2022
c20567a
tracing: Replace std with core in LogVisitor
Skepfyr Jan 11, 2022
50fd7f2
tracing: generate valueset only when needed
Skepfyr Jan 11, 2022
b4c6208
tracing: move some macro support behind log feature
Skepfyr Jan 17, 2022
ce02eda
tracing: add log_move_arg tests and fix log format
Skepfyr Jan 18, 2022
a691c5b
Merge branch 'master' into macros-with-log
hawkw Jan 19, 2022
a4e8d26
tracing: Add nop logger to global subcriber bench
Skepfyr Jan 23, 2022
0c1ab2b
Update tracing-core/src/field.rs
hawkw Jan 28, 2022
794040e
Merge branch 'master' into macros-with-log
hawkw Jan 29, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion tracing-core/src/field.rs
View file
Open in desktop
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
338 changes: 129 additions & 209 deletions tracing/src/macros.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,24 +32,22 @@ macro_rules! span {
fields: $($fields)*
};
let mut interest = $crate::collect::Interest::never();
if $crate::level_enabled!($lvl)
&& { interest = CALLSITE.interest(); !interest.is_never() }
&& CALLSITE.is_enabled(interest)
{
let meta = CALLSITE.metadata();
// span with explicit parent
$crate::Span::child_of(
$parent,
meta,
&$crate::valueset!(meta.fields(), $($fields)*),
)
} else {
let span = CALLSITE.disabled_span();
$crate::if_log_enabled! { $lvl, {
span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
}};
span
}
(|value_set| {
if $crate::level_enabled!($lvl)
&& { interest = CALLSITE.interest(); !interest.is_never() }
&& CALLSITE.is_enabled(interest)
{
let meta = CALLSITE.metadata();
// span with explicit parent
$crate::Span::child_of($parent, meta, &value_set)
} else {
let span = CALLSITE.disabled_span();
$crate::if_log_enabled! { $lvl, {
span.record_all(&value_set);
}};
span
}
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*))
}
};
(target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => {
Expand All @@ -64,23 +62,22 @@ macro_rules! span {
};

let mut interest = $crate::collect::Interest::never();
if $crate::level_enabled!($lvl)
&& { interest = CALLSITE.interest(); !interest.is_never() }
&& CALLSITE.is_enabled(interest)
{
let meta = CALLSITE.metadata();
// span with contextual parent
$crate::Span::new(
meta,
&$crate::valueset!(meta.fields(), $($fields)*),
)
} else {
let span = CALLSITE.disabled_span();
$crate::if_log_enabled! { $lvl, {
span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
}};
span
}
(|value_set| {
if $crate::level_enabled!($lvl)
&& { interest = CALLSITE.interest(); !interest.is_never() }
&& CALLSITE.is_enabled(interest)
{
let meta = CALLSITE.metadata();
// span with contextual parent
$crate::Span::new(meta, &value_set)
} else {
let span = CALLSITE.disabled_span();
$crate::if_log_enabled! { $lvl, {
span.record_all(&value_set);
}};
span
}
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*))
}
};
(target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr) => {
Expand Down Expand Up @@ -583,39 +580,40 @@ 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)*
);

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,
level: $lvl,
fields: $($fields)*
};
(|value_set: $crate::field::ValueSet| {
$crate::__tracing_log!(
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(
$parent,
meta,
&$crate::valueset!(meta.fields(), $($fields)*)
);
$lvl,
value_set
);
if $crate::level_enabled!($lvl) {
let interest = CALLSITE.interest();
if !interest.is_never() && CALLSITE.is_enabled(interest) {
let meta = CALLSITE.metadata();
// event with explicit parent
$crate::Event::child_of(
$parent,
meta,
&value_set
);
}
}
}
);
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
});

(target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => (
$crate::event!(
Expand All @@ -632,35 +630,38 @@ 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,
level: $lvl,
fields: $($fields)*
};
(|value_set: $crate::field::ValueSet| {
Copy link
Member

Choose a reason for hiding this comment

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

hmm...previous attempts to move ValueSet construction into a closure has caused some severe breakage in crates using tracing, because the closure borrows entire structs or tuples when their fields are referenced in the value set (see #987). So, I'm a bit concerned about this. However, we did add some tests to prevent regressions with this issue in the future (

tracing/tracing/tests/macros.rs

Lines 870 to 896 in 84bbbea

#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn borrow_val_events() {
// Reproduces https://github.com/tokio-rs/tracing/issues/954
let mut foo = (String::new(), String::new());
let zero = &mut foo.0;
trace!(one = ?foo.1);
debug!(one = ?foo.1);
info!(one = ?foo.1);
warn!(one = ?foo.1);
error!(one = ?foo.1);
zero.push_str("hello world");
}
#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)]
#[test]
fn borrow_val_spans() {
// Reproduces https://github.com/tokio-rs/tracing/issues/954
let mut foo = (String::new(), String::new());
let zero = &mut foo.0;
let _span = trace_span!("span", one = ?foo.1);
let _span = debug_span!("span", one = ?foo.1);
let _span = info_span!("span", one = ?foo.1);
let _span = warn_span!("span", one = ?foo.1);
let _span = error_span!("span", one = ?foo.1);
zero.push_str("hello world");
}
), so if they pass, this is probably okay.

I'm not entirely sure if I get why the closure is necessary here, though. Is there a reason we can't just place the valueset in a let binding, instead?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It appears to be passing, which slightly surprises me because I can't see what's changed, I'll dig into this more to work out why, just in case the test is missing something. (oooh, it might be because value_set is constructed outside the closure)
I need to add some comments about this but the reason for the immediately invoked closures is to extend the lifetime of the temporaries created by valueset.
This doesn't compile because the string's are dropped before we get to baz.

let x = &[&String::from("foo"), &String::from("bar")];
baz(x);

This however does compile:

(|x| {
    baz(x);
})(&[&String::from("foo"), &String::from("bar")]);

$crate::__tracing_log!(
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::dispatch(
meta,
&$crate::valueset!(meta.fields(), $($fields)*)
);
$lvl,
value_set
);
if $crate::level_enabled!($lvl) {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
let interest = CALLSITE.interest();
if !interest.is_never() && CALLSITE.is_enabled(interest) {
let meta = CALLSITE.metadata();
//let value_set = $crate::valueset!(meta.fields(), $($fields)*);
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
// event with contextual parent
$crate::Event::dispatch(
meta,
&value_set
);
}
}
}
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
});
(target: $target:expr, $lvl:expr, { $($fields:tt)* }, $($arg:tt)+ ) => (
$crate::event!(
Expand Down Expand Up @@ -2162,128 +2163,47 @@ 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)*)
}
};
}

#[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:ident ) => {
$crate::if_log_enabled! { $level, {
use $crate::log;
use $crate::{log, field};
struct LogValueSet<'a>(&'a field::ValueSet<'a>);
impl<'a> std::fmt::Display for LogValueSet<'a> {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
let mut visit = Visit {
f,
is_first: true,
result: Ok(()),
};
self.0.record(&mut visit);
visit.result
}
}
struct Visit<'a, 'b> {
f: &'a mut std::fmt::Formatter<'b>,
is_first: bool,
result: std::fmt::Result,
}
impl field::Visit for Visit<'_, '_> {
fn record_debug(&mut self, field: &field::Field, value: &dyn std::fmt::Debug) {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
let res = if self.is_first {
self.is_first = false;
if field.name() == "message" {
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
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));
}
}
}
Skepfyr marked this conversation as resolved.
Show resolved Hide resolved
let level = $crate::level_to_log!($level);
if level <= log::max_level() {
let log_meta = log::Metadata::builder()
Expand All @@ -2297,7 +2217,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!("{}", LogValueSet(&$value_set)))
.build());
}
}
Expand Down