Skip to content

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

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

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 4 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
50 changes: 49 additions & 1 deletion tracing/src/lib.rs
View file
Open in desktop
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)]
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...


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
}
}

struct LogVisitor<'a, 'b> {
f: &'a mut fmt::Formatter<'b>,
is_first: bool,
result: fmt::Result,
}

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)
};
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
183 changes: 83 additions & 100 deletions tracing/src/macros.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,22 +32,24 @@ macro_rules! span {
fields: $($fields)*
};
let mut interest = $crate::collect::Interest::never();
(|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)*))
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
}
}
};
(target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => {
Expand All @@ -62,22 +64,23 @@ macro_rules! span {
};

let mut interest = $crate::collect::Interest::never();
(|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)*))
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
}
}
};
(target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr) => {
Expand Down Expand Up @@ -594,25 +597,33 @@ macro_rules! event {
level: $lvl,
fields: $($fields)*
};
(|value_set: $crate::field::ValueSet| {

let enabled = $crate::level_enabled!($lvl) && {
let interest = CALLSITE.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,
&value_set
);
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
Copy link
Member

Choose a reason for hiding this comment

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

is there a reason we still need the closure in the event! macros, but we don't in the span! macros? I haven't actually tried it yet, but it seems like we should be able to just write this and get exactly the same behavior:

Suggested change
(|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,
&value_set
);
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
let value_set = ($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*);
$crate::__tracing_log!(
target: $target,
$lvl,
&value_set
);
let meta = CALLSITE.metadata();
// event with explicit parent
$crate::Event::child_of(
$parent,
meta,
&value_set
);

Copy link
Contributor Author

Choose a reason for hiding this comment

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

This doesn't work for the reasons mentioned elsewhere, however I can replace the closures with function calls which may be preferable (it also appears to improve perf, see benchmarking comment). However, those functions do look a bit weird:

#[inline]
pub fn log_and_dispatcht(target: &str, callsite: &MacroCallsite, value_set: ValueSet) {
        let meta = callsite.metadata();
        // event with contextual parent
        $crate::Event::dispatch(
            meta,
            &value_set
        );
        $crate::__tracing_log!(
            target: target,
            $lvl,
            &value_set
        );
}

and similarly a log_and_event, I imagine both would go in the __macro_support module.

} else {
$crate::__tracing_log!(
target: $target,
$lvl,
value_set
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
);
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)+ ) => (
Expand Down Expand Up @@ -643,25 +654,31 @@ macro_rules! event {
level: $lvl,
fields: $($fields)*
};
(|value_set: $crate::field::ValueSet| {
let enabled = $crate::level_enabled!($lvl) && {
let interest = CALLSITE.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,
&value_set
);
$crate::__tracing_log!(
target: $target,
$lvl,
&value_set
);
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
Copy link
Member

Choose a reason for hiding this comment

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

similarly, it seems like the closure should be able to be replaced by a let-binding?

} else {
$crate::__tracing_log!(
target: $target,
$lvl,
value_set
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
);
if $crate::level_enabled!($lvl) {
let interest = CALLSITE.interest();
if !interest.is_never() && CALLSITE.is_enabled(interest) {
let meta = CALLSITE.metadata();
//let value_set = $crate::valueset!(meta.fields(), $($fields)*);
// 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 @@ -2160,50 +2177,16 @@ macro_rules! __tracing_stringify {
#[doc(hidden)]
#[macro_export]
macro_rules! __tracing_log {
(target: $target:expr, $level:expr, $($field:tt)+ ) => {};
(target: $target:expr, $level:expr, $value_set:expr ) => {};
}

#[cfg(feature = "log")]
#[doc(hidden)]
#[macro_export]
macro_rules! __tracing_log {
(target: $target:expr, $level:expr, $value_set:ident ) => {
(target: $target:expr, $level:expr, $value_set:expr ) => {
$crate::if_log_enabled! { $level, {
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) {
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));
}
}
}
use $crate::log;
let level = $crate::level_to_log!($level);
if level <= log::max_level() {
let log_meta = log::Metadata::builder()
Expand All @@ -2217,7 +2200,7 @@ macro_rules! __tracing_log {
.module_path(Some(module_path!()))
.line(Some(line!()))
.metadata(log_meta)
.args(format_args!("{}", LogValueSet(&$value_set)))
.args(format_args!("{}", $crate::__macro_support::LogValueSet($value_set)))
.build());
}
}
Expand Down