diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 880ac4923c..cd574bc794 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -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)] @@ -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 { @@ -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 } } } diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index bf7cf54860..825c0d8689 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -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(); @@ -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)*) ); } @@ -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)*) ); } @@ -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) } } }} diff --git a/tracing/src/span.rs b/tracing/src/span.rs index 8379977fbd..7278e6d17c 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -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 @@ -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())); } }} } @@ -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())); } }} } @@ -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 }), + ); }} } @@ -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 { @@ -1459,7 +1468,7 @@ impl Drop for Span { self.log( LIFECYCLE_LOG_TARGET, log::Level::Trace, - format_args!("-- {}", meta.name()), + format_args!("-- {};", meta.name()), ); } }} @@ -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::*; diff --git a/tracing/test-log-support/src/lib.rs b/tracing/test-log-support/src/lib.rs index e63257445f..de2cc9457c 100644 --- a/tracing/test-log-support/src/lib.rs +++ b/tracing/test-log-support/src/lib.rs @@ -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, @@ -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!( diff --git a/tracing/test-log-support/tests/log_no_trace.rs b/tracing/test-log-support/tests/log_no_trace.rs index 206e9b577c..4a5edbb3d3 100644 --- a/tracing/test-log-support/tests/log_no_trace.rs +++ b/tracing/test-log-support/tests/log_no_trace.rs @@ -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"); diff --git a/tracing/test-log-support/tests/log_with_trace.rs b/tracing/test-log-support/tests/log_with_trace.rs index c32cb79e93..b1c92107c3 100644 --- a/tracing/test-log-support/tests/log_with_trace.rs +++ b/tracing/test-log-support/tests/log_with_trace.rs @@ -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"); diff --git a/tracing/test-log-support/tests/span_activity_filtered_separately.rs b/tracing/test-log-support/tests/span_activity_filtered_separately.rs index 32bc00d96a..2086f97a7e 100644 --- a/tracing/test-log-support/tests/span_activity_filtered_separately.rs +++ b/tracing/test-log-support/tests/span_activity_filtered_separately.rs @@ -21,7 +21,7 @@ fn span_activity_filtered_separately() { let foo = span!(Level::TRACE, "foo"); // Creating a span goes to the `tracing::span` target. - test.assert_logged("foo"); + test.assert_logged("foo;"); foo.in_scope(|| { // enter should not be logged @@ -35,7 +35,7 @@ fn span_activity_filtered_separately() { drop(foo); // drop should be logged - test.assert_logged("-- foo"); + test.assert_logged("-- foo;"); trace!(foo = 1, bar = 2, "hello world"); test.assert_logged("hello world foo=1 bar=2"); @@ -57,7 +57,7 @@ fn span_activity_filtered_separately() { let bar = span!(Level::INFO, "bar"); // lifecycles for INFO spans should be logged - test.assert_logged("bar"); + test.assert_logged("bar;"); bar.in_scope(|| { // entering the INFO span should not be logged @@ -68,9 +68,9 @@ fn span_activity_filtered_separately() { drop(foo); // drop should be logged - test.assert_logged("-- foo"); + test.assert_logged("-- foo;"); drop(bar); // dropping the INFO should be logged. - test.assert_logged("-- bar"); + test.assert_logged("-- bar;"); } diff --git a/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs b/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs index 8ff515f9fe..38041fd4b5 100644 --- a/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs +++ b/tracing/test-log-support/tests/span_lifecycle_can_be_enabled.rs @@ -19,21 +19,21 @@ fn span_lifecycle_can_be_enabled() { 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(|| { // enter should be logged - 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"); }); // exit should be logged - test.assert_logged("<- foo"); + test.assert_logged("<- foo;"); drop(foo); // drop should be logged - test.assert_logged("-- foo"); + test.assert_logged("-- foo;"); trace!(foo = 1, bar = 2, "hello world"); test.assert_logged("hello world foo=1 bar=2"); @@ -44,10 +44,10 @@ fn span_lifecycle_can_be_enabled() { foo.in_scope(|| { // entering the span should be logged - test.assert_logged("-> foo"); + test.assert_logged("-> foo;"); }); // exiting the span should be logged - test.assert_logged("<- foo"); + test.assert_logged("<- foo;"); foo.record("baz", &true); // recording a field should be logged @@ -55,20 +55,20 @@ fn span_lifecycle_can_be_enabled() { let bar = span!(Level::INFO, "bar"); // lifecycles for INFO spans should be logged - test.assert_logged("bar"); + test.assert_logged("bar;"); bar.in_scope(|| { // entering the INFO span should be logged - test.assert_logged("-> bar"); + test.assert_logged("-> bar;"); }); // exiting the INFO span should be logged - test.assert_logged("<- bar"); + test.assert_logged("<- bar;"); drop(foo); // drop should be logged. - test.assert_logged("-- foo"); + test.assert_logged("-- foo;"); drop(bar); // dropping the INFO should be logged. - test.assert_logged("-- bar"); + test.assert_logged("-- bar;"); } diff --git a/tracing/tests/future_send.rs b/tracing/tests/future_send.rs new file mode 100644 index 0000000000..5e5f9f18bc --- /dev/null +++ b/tracing/tests/future_send.rs @@ -0,0 +1,22 @@ +// These tests reproduce the following issues: +// - https://github.com/tokio-rs/tracing/issues/1487 +// - https://github.com/tokio-rs/tracing/issues/1793 + +use core::future::{self, Future}; +#[test] +fn async_fn_is_send() { + async fn some_async_fn() { + tracing::info!("{}", future::ready("test").await); + } + + assert_send(some_async_fn()) +} + +#[test] +fn async_block_is_send() { + assert_send(async { + tracing::info!("{}", future::ready("test").await); + }) +} + +fn assert_send(_f: F) {}