Skip to content

Commit

Permalink
tracing: fix the "log" feature making async block futures !Send (#2073
Browse files Browse the repository at this point in the history 
)

## Motivation

Currently, enabling the `log` feature can cause a compilation error when
using `tracing` macros in async functions or blocks. This is because,
when the `log` feature is enabled, the `tracing` macros will construct a
`log::Record`, which is not `Send`, causing the async fn/block future to
become `!Send`. This can break compilation when the future is `Send`
without the `log` feature enabled. This is really not great, as it makes
the feature no longer purely additive.

## Solution

This branch fixes the issue by moving the `log::Record` construction
behind a function call. Because the `log::Record` is now only
constructed inside of a function, the `log::Record` is now never a local
variable within the async block, so it no longer affects the future's
auto traits.

It's kind of a shame that the compiler can't otherwise determine that
the `log::Record` can never be held across an await point, but sticking
it in a separate function makes this obvious to the compiler. Also, as a
side benefit, this may reduce the size of macro-generated code when the
`log` feature is enabled a bit, which could improve performance
marginally in some cases.

I added two tests ensuring that `async fn` and `async` block futures are
`Send` when containing `tracing` macro calls. Previously, on `master`,
these failed when the `log` feature is enabled. After this change, the
tests now pass. Thanks to @Noah-Kennedy for the original MCRE these
tests were based on!

Finally, while I was here, I took advantage of the opportunity to clean
up the log integration code a bit. Now that the `log::Record`
construction is behind a function call in `__macro_support`, the
`LogValueSet` type, which is used to wrap a `ValueSet` and implement
`fmt::Display` to add it to the textual message of `log::Record`, no
longer needs to be exposed to the macros, so it can be made properly
private, rather than `#[doc(hidden)] pub`. Also, I noticed that the
`span` module implemented its own versions of `LogValueSet` (`FmtAttrs`
and `FmtValues`), which were essentially duplicating the same behavior
for logging span fields. I removed these and changed this code to use
the `LogValueSet` type instead (which will format string `message`
fields slightly nicer as well).

Fixes #1793
Fixes #1487

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
@hawkw
hawkw committed Apr 14, 2022
1 parent 438b013 commit 8c67359
Show file tree
Hide file tree
Showing 9 changed files with 139 additions and 126 deletions.
124 changes: 71 additions & 53 deletions tracing/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -926,10 +926,6 @@
#[cfg(not(feature = "std"))]
extern crate alloc;

#[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 @@ -1069,6 +1065,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 @@ -1096,66 +1117,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
Original file line number Diff line number Diff line change
Expand Up @@ -604,8 +604,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 @@ -618,8 +618,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 @@ -666,15 +666,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 @@ -2416,31 +2416,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
Original file line number Diff line number Diff line change
Expand Up @@ -580,7 +580,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 @@ -1034,7 +1039,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 @@ -1051,7 +1056,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 @@ -1218,7 +1223,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 @@ -1332,7 +1341,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 @@ -1459,7 +1468,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 @@ -1594,38 +1603,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
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
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
Original file line number Diff line number Diff line change
Expand Up @@ -59,7 +59,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

0 comments on commit 8c67359

Please sign in to comment.