Skip to content

Commit 8c67359

Browse files
hawkwhawkw
committed
tracing: fix the "log" feature making async block futures !Send (#2073)
## 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 <[email protected]>
1 parent 438b013 commit 8c67359

File tree

9 files changed

+139
-126
lines changed

9 files changed

+139
-126
lines changed

‎tracing/src/lib.rs

Lines changed: 71 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -926,10 +926,6 @@
926926
#[cfg(not(feature = "std"))]
927927
extern crate alloc;
928928

929-
#[cfg(feature = "log")]
930-
#[doc(hidden)]
931-
pub use log;
932-
933929
// Somehow this `use` statement is necessary for us to re-export the `core`
934930
// macros on Rust 1.26.0. I'm not sure how this makes it work, but it does.
935931
#[allow(unused_imports)]
@@ -1069,6 +1065,31 @@ pub mod __macro_support {
10691065
pub fn disabled_span(&self) -> crate::Span {
10701066
crate::Span::none()
10711067
}
1068+
1069+
#[cfg(feature = "log")]
1070+
pub fn log(
1071+
&self,
1072+
logger: &'static dyn log::Log,
1073+
log_meta: log::Metadata<'_>,
1074+
values: &tracing_core::field::ValueSet<'_>,
1075+
) {
1076+
let meta = self.metadata();
1077+
logger.log(
1078+
&crate::log::Record::builder()
1079+
.file(meta.file())
1080+
.module_path(meta.module_path())
1081+
.line(meta.line())
1082+
.metadata(log_meta)
1083+
.args(format_args!(
1084+
"{}",
1085+
crate::log::LogValueSet {
1086+
values,
1087+
is_first: true
1088+
}
1089+
))
1090+
.build(),
1091+
);
1092+
}
10721093
}
10731094

10741095
impl Callsite for MacroCallsite {
@@ -1096,66 +1117,63 @@ pub mod __macro_support {
10961117
.finish()
10971118
}
10981119
}
1120+
}
10991121

1100-
#[cfg(feature = "log")]
1122+
#[cfg(feature = "log")]
1123+
#[doc(hidden)]
1124+
pub mod log {
1125+
use core::fmt;
1126+
pub use log::*;
11011127
use tracing_core::field::{Field, ValueSet, Visit};
11021128

1103-
/// Utility to format [`ValueSet`] for logging, used by macro-generated code.
1104-
///
1105-
/// /!\ WARNING: This is *not* a stable API! /!\
1106-
/// This type, and all code contained in the `__macro_support` module, is
1107-
/// a *private* API of `tracing`. It is exposed publicly because it is used
1108-
/// by the `tracing` macros, but it is not part of the stable versioned API.
1109-
/// Breaking changes to this module may occur in small-numbered versions
1110-
/// without warning.
1111-
#[cfg(feature = "log")]
1112-
#[allow(missing_debug_implementations)]
1113-
pub struct LogValueSet<'a>(pub &'a ValueSet<'a>);
1129+
/// Utility to format [`ValueSet`]s for logging.
1130+
pub(crate) struct LogValueSet<'a> {
1131+
pub(crate) values: &'a ValueSet<'a>,
1132+
pub(crate) is_first: bool,
1133+
}
11141134

1115-
#[cfg(feature = "log")]
11161135
impl<'a> fmt::Display for LogValueSet<'a> {
1136+
#[inline]
11171137
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
1118-
let mut visit = LogVisitor {
1119-
f,
1120-
is_first: true,
1121-
result: Ok(()),
1122-
};
1123-
self.0.record(&mut visit);
1124-
visit.result
1125-
}
1126-
}
1138+
struct LogVisitor<'a, 'b> {
1139+
f: &'a mut fmt::Formatter<'b>,
1140+
is_first: bool,
1141+
result: fmt::Result,
1142+
}
11271143

1128-
#[cfg(feature = "log")]
1129-
struct LogVisitor<'a, 'b> {
1130-
f: &'a mut fmt::Formatter<'b>,
1131-
is_first: bool,
1132-
result: fmt::Result,
1133-
}
1144+
impl Visit for LogVisitor<'_, '_> {
1145+
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
1146+
let res = if self.is_first {
1147+
self.is_first = false;
1148+
if field.name() == "message" {
1149+
write!(self.f, "{:?}", value)
1150+
} else {
1151+
write!(self.f, "{}={:?}", field.name(), value)
1152+
}
1153+
} else {
1154+
write!(self.f, " {}={:?}", field.name(), value)
1155+
};
1156+
if let Err(err) = res {
1157+
self.result = self.result.and(Err(err));
1158+
}
1159+
}
11341160

1135-
#[cfg(feature = "log")]
1136-
impl Visit for LogVisitor<'_, '_> {
1137-
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
1138-
let res = if self.is_first {
1139-
self.is_first = false;
1140-
if field.name() == "message" {
1141-
write!(self.f, "{:?}", value)
1142-
} else {
1143-
write!(self.f, "{}={:?}", field.name(), value)
1161+
fn record_str(&mut self, field: &Field, value: &str) {
1162+
if field.name() == "message" {
1163+
self.record_debug(field, &format_args!("{}", value))
1164+
} else {
1165+
self.record_debug(field, &value)
1166+
}
11441167
}
1145-
} else {
1146-
write!(self.f, " {}={:?}", field.name(), value)
1147-
};
1148-
if let Err(err) = res {
1149-
self.result = self.result.and(Err(err));
11501168
}
1151-
}
11521169

1153-
fn record_str(&mut self, field: &Field, value: &str) {
1154-
if field.name() == "message" {
1155-
self.record_debug(field, &format_args!("{}", value))
1156-
} else {
1157-
self.record_debug(field, &value)
1158-
}
1170+
let mut visit = LogVisitor {
1171+
f,
1172+
is_first: self.is_first,
1173+
result: Ok(()),
1174+
};
1175+
self.values.record(&mut visit);
1176+
visit.result
11591177
}
11601178
}
11611179
}

‎tracing/src/macros.rs

Lines changed: 8 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -604,8 +604,8 @@ macro_rules! event {
604604
if enabled {
605605
(|value_set: $crate::field::ValueSet| {
606606
$crate::__tracing_log!(
607-
target: $target,
608607
$lvl,
608+
CALLSITE,
609609
&value_set
610610
);
611611
let meta = CALLSITE.metadata();
@@ -618,8 +618,8 @@ macro_rules! event {
618618
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
619619
} else {
620620
$crate::__tracing_log!(
621-
target: $target,
622621
$lvl,
622+
CALLSITE,
623623
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
624624
);
625625
}
@@ -666,15 +666,15 @@ macro_rules! event {
666666
&value_set
667667
);
668668
$crate::__tracing_log!(
669-
target: $target,
670669
$lvl,
670+
CALLSITE,
671671
&value_set
672672
);
673673
})($crate::valueset!(CALLSITE.metadata().fields(), $($fields)*));
674674
} else {
675675
$crate::__tracing_log!(
676-
target: $target,
677676
$lvl,
677+
CALLSITE,
678678
&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)
679679
);
680680
}
@@ -2416,31 +2416,25 @@ macro_rules! __tracing_stringify {
24162416
#[doc(hidden)]
24172417
#[macro_export]
24182418
macro_rules! __tracing_log {
2419-
(target: $target:expr, $level:expr, $value_set:expr ) => {};
2419+
($level:expr, $callsite:expr, $value_set:expr) => {};
24202420
}
24212421

24222422
#[cfg(feature = "log")]
24232423
#[doc(hidden)]
24242424
#[macro_export]
24252425
macro_rules! __tracing_log {
2426-
(target: $target:expr, $level:expr, $value_set:expr ) => {
2426+
($level:expr, $callsite:expr, $value_set:expr) => {
24272427
$crate::if_log_enabled! { $level, {
24282428
use $crate::log;
24292429
let level = $crate::level_to_log!($level);
24302430
if level <= log::max_level() {
24312431
let log_meta = log::Metadata::builder()
24322432
.level(level)
2433-
.target($target)
2433+
.target(CALLSITE.metadata().target())
24342434
.build();
24352435
let logger = log::logger();
24362436
if logger.enabled(&log_meta) {
2437-
logger.log(&log::Record::builder()
2438-
.file(Some(file!()))
2439-
.module_path(Some(module_path!()))
2440-
.line(Some(line!()))
2441-
.metadata(log_meta)
2442-
.args(format_args!("{}", $crate::__macro_support::LogValueSet($value_set)))
2443-
.build());
2437+
$callsite.log(logger, log_meta, $value_set)
24442438
}
24452439
}
24462440
}}

‎tracing/src/span.rs

Lines changed: 15 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -580,7 +580,12 @@ impl Span {
580580
} else {
581581
meta.target()
582582
};
583-
span.log(target, level_to_log!(*meta.level()), format_args!("++ {}{}", meta.name(), FmtAttrs(attrs)));
583+
let values = attrs.values();
584+
span.log(
585+
target,
586+
level_to_log!(*meta.level()),
587+
format_args!("++ {};{}", meta.name(), crate::log::LogValueSet { values, is_first: false }),
588+
);
584589
}}
585590

586591
span
@@ -1034,7 +1039,7 @@ impl Span {
10341039

10351040
if_log_enabled! { crate::Level::TRACE, {
10361041
if let Some(_meta) = self.meta {
1037-
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", _meta.name()));
1042+
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {};", _meta.name()));
10381043
}
10391044
}}
10401045
}
@@ -1051,7 +1056,7 @@ impl Span {
10511056

10521057
if_log_enabled! { crate::Level::TRACE, {
10531058
if let Some(_meta) = self.meta {
1054-
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", _meta.name()));
1059+
self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {};", _meta.name()));
10551060
}
10561061
}}
10571062
}
@@ -1218,7 +1223,11 @@ impl Span {
12181223
} else {
12191224
_meta.target()
12201225
};
1221-
self.log(target, level_to_log!(*_meta.level()), format_args!("{}{}", _meta.name(), FmtValues(&record)));
1226+
self.log(
1227+
target,
1228+
level_to_log!(*_meta.level()),
1229+
format_args!("{};{}", _meta.name(), crate::log::LogValueSet { values, is_first: false }),
1230+
);
12221231
}}
12231232
}
12241233

@@ -1332,7 +1341,7 @@ impl Span {
13321341
.module_path(meta.module_path())
13331342
.file(meta.file())
13341343
.line(meta.line())
1335-
.args(format_args!("{}; span={}", message, inner.id.into_u64()))
1344+
.args(format_args!("{} span={}", message, inner.id.into_u64()))
13361345
.build(),
13371346
);
13381347
} else {
@@ -1459,7 +1468,7 @@ impl Drop for Span {
14591468
self.log(
14601469
LIFECYCLE_LOG_TARGET,
14611470
log::Level::Trace,
1462-
format_args!("-- {}", meta.name()),
1471+
format_args!("-- {};", meta.name()),
14631472
);
14641473
}
14651474
}}
@@ -1594,38 +1603,6 @@ const PhantomNotSend: PhantomNotSend = PhantomNotSend { ghost: PhantomData };
15941603
/// Trivially safe, as `PhantomNotSend` doesn't have any API.
15951604
unsafe impl Sync for PhantomNotSend {}
15961605

1597-
#[cfg(feature = "log")]
1598-
struct FmtValues<'a>(&'a Record<'a>);
1599-
1600-
#[cfg(feature = "log")]
1601-
impl<'a> fmt::Display for FmtValues<'a> {
1602-
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
1603-
let mut res = Ok(());
1604-
let mut is_first = true;
1605-
self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| {
1606-
res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v);
1607-
is_first = false;
1608-
});
1609-
res
1610-
}
1611-
}
1612-
1613-
#[cfg(feature = "log")]
1614-
struct FmtAttrs<'a>(&'a Attributes<'a>);
1615-
1616-
#[cfg(feature = "log")]
1617-
impl<'a> fmt::Display for FmtAttrs<'a> {
1618-
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
1619-
let mut res = Ok(());
1620-
let mut is_first = true;
1621-
self.0.record(&mut |k: &field::Field, v: &dyn fmt::Debug| {
1622-
res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v);
1623-
is_first = false;
1624-
});
1625-
res
1626-
}
1627-
}
1628-
16291606
#[cfg(test)]
16301607
mod test {
16311608
use super::*;

‎tracing/test-log-support/src/lib.rs

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -63,6 +63,7 @@ impl Test {
6363
Test { state }
6464
}
6565

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

79+
#[track_caller]
7880
pub fn assert_not_logged(&self) {
7981
if let Some(last) = self.state.last_log.lock().unwrap().take() {
8082
panic!(

‎tracing/test-log-support/tests/log_no_trace.rs

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -20,18 +20,18 @@ fn test_always_log() {
2020
test.assert_logged("hello world; thingy=42 other_thingy=666");
2121

2222
let foo = span!(Level::TRACE, "foo");
23-
test.assert_logged("foo");
23+
test.assert_logged("foo;");
2424

2525
foo.in_scope(|| {
26-
test.assert_logged("-> foo");
26+
test.assert_logged("-> foo;");
2727

2828
trace!({foo = 3, bar = 4}, "hello {};", "san francisco");
2929
test.assert_logged("hello san francisco; foo=3 bar=4");
3030
});
31-
test.assert_logged("<- foo");
31+
test.assert_logged("<- foo;");
3232

3333
drop(foo);
34-
test.assert_logged("-- foo");
34+
test.assert_logged("-- foo;");
3535

3636
trace!(foo = 1, bar = 2, "hello world");
3737
test.assert_logged("hello world foo=1 bar=2");

‎tracing/test-log-support/tests/log_with_trace.rs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,7 @@ fn log_with_trace() {
5959
test.assert_logged("-- foo; span=1");
6060

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

6464
drop(foo);
6565
test.assert_logged("-- foo; span=2");

0 commit comments

Comments
 (0)