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 the "log" feature making async block futures !Send #2073

Merged
merged 7 commits into from
Apr 14, 2022
Merged

tracing: fix the "log" feature making async block futures !Send #2073

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
6c394a7
add tests reproducing #1793
hawkw Apr 14, 2022
0dca979
fix send + sync issues with `log`
hawkw Apr 14, 2022
95190ae
LogValueSet need no longer be `pub`
hawkw Apr 14, 2022
2f21008
de-duplicate log support code
hawkw Apr 14, 2022
9feecfa
minor test cleanup
hawkw Apr 14, 2022
d0afec4
disembreak span lifecycle log formatting
hawkw Apr 14, 2022
4ec8349
rustfmt
hawkw Apr 14, 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
124 changes: 71 additions & 53 deletions tracing/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -941,10 +941,6 @@
while_true
)]

#[cfg(feature = "log")]
#[doc(hidden)]
pub use log;

// Somehow this `use` statement is necessary for us to re-export the `core`
// macros on Rust 1.26.0. I'm not sure how this makes it work, but it does.
#[allow(unused_imports)]
Expand Down Expand Up @@ -1090,6 +1086,31 @@ pub mod __macro_support {
pub fn disabled_span(&self) -> crate::Span {
crate::Span::none()
}

#[cfg(feature = "log")]
pub fn log(
&self,
logger: &'static dyn log::Log,
log_meta: log::Metadata<'_>,
values: &tracing_core::field::ValueSet<'_>,
) {
let meta = self.metadata();
logger.log(
&crate::log::Record::builder()
.file(meta.file())
.module_path(meta.module_path())
.line(meta.line())
.metadata(log_meta)
.args(format_args!(
"{}",
crate::log::LogValueSet {
values,
is_first: true
}
))
.build(),
);
}
}

impl Callsite for MacroCallsite {
Expand Down Expand Up @@ -1118,66 +1139,63 @@ pub mod __macro_support {
.finish()
}
}
}

#[cfg(feature = "log")]
#[cfg(feature = "log")]
#[doc(hidden)]
pub mod log {
use core::fmt;
pub use 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>);
/// Utility to format [`ValueSet`]s for logging.
pub(crate) struct LogValueSet<'a> {
pub(crate) values: &'a ValueSet<'a>,
pub(crate) is_first: bool,
}

#[cfg(feature = "log")]
impl<'a> fmt::Display for LogValueSet<'a> {
#[inline]
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,
}

#[cfg(feature = "log")]
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)
};
if let Err(err) = res {
self.result = self.result.and(Err(err));
}
}

#[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)
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)
}
}
} 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)
}
let mut visit = LogVisitor {
f,
is_first: self.is_first,
result: Ok(()),
};
self.values.record(&mut visit);
visit.result
}
}
}
Expand Down
22 changes: 8 additions & 14 deletions tracing/src/macros.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -605,8 +605,8 @@ macro_rules! event {
if enabled {
(|value_set: $crate::field::ValueSet| {
$crate::__tracing_log!(
target: $target,
$lvl,
CALLSITE,
&value_set
);
let meta = CALLSITE.metadata();
Expand All @@ -619,8 +619,8 @@ macro_rules! event {
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
} else {
$crate::__tracing_log!(
target: $target,
$lvl,
CALLSITE,
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
);
}
Expand Down Expand Up @@ -667,15 +667,15 @@ macro_rules! event {
&value_set
);
$crate::__tracing_log!(
target: $target,
$lvl,
CALLSITE,
&value_set
);
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
} else {
$crate::__tracing_log!(
target: $target,
$lvl,
CALLSITE,
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
);
}
Expand Down Expand Up @@ -2413,31 +2413,25 @@ macro_rules! __tracing_stringify {
#[doc(hidden)]
#[macro_export]
macro_rules! __tracing_log {
(target: $target:expr, $level:expr, $value_set:expr ) => {};
($level:expr, $callsite:expr, $value_set:expr) => {};
}

#[cfg(feature = "log")]
#[doc(hidden)]
#[macro_export]
macro_rules! __tracing_log {
(target: $target:expr, $level:expr, $value_set:expr ) => {
($level:expr, $callsite:expr, $value_set:expr) => {
$crate::if_log_enabled! { $level, {
use $crate::log;
let level = $crate::level_to_log!($level);
if level <= log::max_level() {
let log_meta = log::Metadata::builder()
.level(level)
.target($target)
.target(CALLSITE.metadata().target())
.build();
let logger = log::logger();
if logger.enabled(&log_meta) {
logger.log(&log::Record::builder()
.file(Some(file!()))
.module_path(Some(module_path!()))
.line(Some(line!()))
.metadata(log_meta)
.args(format_args!("{}", $crate::__macro_support::LogValueSet($value_set)))
.build());
$callsite.log(logger, log_meta, $value_set)
}
}
}}
Expand Down
53 changes: 15 additions & 38 deletions tracing/src/span.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -570,7 +570,12 @@ impl Span {
} else {
meta.target()
};
span.log(target, level_to_log!(*meta.level()), format_args!("++ {}{}", meta.name(), FmtAttrs(attrs)));
let values = attrs.values();
span.log(
target,
level_to_log!(*meta.level()),
format_args!("++ {};{}", meta.name(), crate::log::LogValueSet { values, is_first: false }),
);
}}

span
Expand Down Expand Up @@ -1035,7 +1040,7 @@ impl Span {

if_log_enabled! { crate::Level::TRACE, {
if let Some(_meta) = self.meta {
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", _meta.name()));
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {};", _meta.name()));
}
}}
}
Expand All @@ -1052,7 +1057,7 @@ impl Span {

if_log_enabled! { crate::Level::TRACE, {
if let Some(_meta) = self.meta {
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {};", _meta.name()));
}
}}
}
Expand Down Expand Up @@ -1220,7 +1225,11 @@ impl Span {
} else {
_meta.target()
};
self.log(target, level_to_log!(*_meta.level()), format_args!("{}{}", _meta.name(), FmtValues(&record)));
self.log(
target,
level_to_log!(*_meta.level()),
format_args!("{};{}", _meta.name(), crate::log::LogValueSet { values, is_first: false }),
);
}}
}

Expand Down Expand Up @@ -1325,7 +1334,7 @@ impl Span {
.module_path(meta.module_path())
.file(meta.file())
.line(meta.line())
.args(format_args!("{}; span={}", message, inner.id.into_u64()))
.args(format_args!("{} span={}", message, inner.id.into_u64()))
.build(),
);
} else {
Expand Down Expand Up @@ -1446,7 +1455,7 @@ impl Drop for Span {
self.log(
LIFECYCLE_LOG_TARGET,
log::Level::Trace,
format_args!("-- {}", meta.name()),
format_args!("-- {};", meta.name()),
);
}
}}
Expand Down Expand Up @@ -1581,38 +1590,6 @@ const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData };
/// Trivially safe, as `PhantomNotSend` doesn't have any API.
unsafe impl Sync for PhantomNotSend {}

#[cfg(feature = "log")]
struct FmtValues<'a>(&'a Record<'a>);

#[cfg(feature = "log")]
impl<'a> fmt::Display for FmtValues<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
let mut res = Ok(());
let mut is_first = true;
self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| {
res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v);
is_first = false;
});
res
}
}

#[cfg(feature = "log")]
struct FmtAttrs<'a>(&'a Attributes<'a>);

#[cfg(feature = "log")]
impl<'a> fmt::Display for FmtAttrs<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
let mut res = Ok(());
let mut is_first = true;
self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| {
res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v);
is_first = false;
});
res
}
}

#[cfg(test)]
mod test {
use super::*;
Expand Down
2 changes: 2 additions & 0 deletions tracing/test-log-support/src/lib.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,6 +63,7 @@ impl Test {
Test { state }
}

#[track_caller]
pub fn assert_logged(&self, expected: &str) {
let last = match self.state.last_log.lock().unwrap().take() {
Some(last) => last,
Expand All @@ -75,6 +76,7 @@ impl Test {
assert_eq!(last.as_str().trim(), expected);
}

#[track_caller]
pub fn assert_not_logged(&self) {
if let Some(last) = self.state.last_log.lock().unwrap().take() {
panic!(
Expand Down
8 changes: 4 additions & 4 deletions tracing/test-log-support/tests/log_no_trace.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,18 +20,18 @@ fn test_always_log() {
test.assert_logged("hello world; thingy=42 other_thingy=666");

let foo = span!(Level::TRACE, "foo");
test.assert_logged("foo");
test.assert_logged("foo;");

foo.in_scope(|| {
test.assert_logged("-> foo");
test.assert_logged("-> foo;");

trace!({foo = 3, bar = 4}, "hello {};", "san francisco");
test.assert_logged("hello san francisco; foo=3 bar=4");
});
test.assert_logged("<- foo");
test.assert_logged("<- foo;");

drop(foo);
test.assert_logged("-- foo");
test.assert_logged("-- foo;");

trace!(foo = 1, bar = 2, "hello world");
test.assert_logged("hello world foo=1 bar=2");
Expand Down
2 changes: 1 addition & 1 deletion tracing/test-log-support/tests/log_with_trace.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,7 +63,7 @@ fn log_with_trace() {
test.assert_logged("-- foo; span=1");

let foo = span!(Level::TRACE, "foo", bar = 3, baz = false);
test.assert_logged("++ foo; bar=3 baz=false; span=2");
test.assert_logged("++ foo; bar=3 baz=false span=2");

drop(foo);
test.assert_logged("-- foo; span=2");
Expand Down
Loading