From 6c394a709df23dee8e83254cd0d7e1527d737b17 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 09:56:17 -0700 Subject: [PATCH 1/7] add tests reproducing #1793 These pass without the `log` feature enabled, but fail when `log` is enabled. Thanks @Noah-Kennedy for the original MCRE! --- tracing/tests/future_send.rs | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) create mode 100644 tracing/tests/future_send.rs diff --git a/tracing/tests/future_send.rs b/tracing/tests/future_send.rs new file mode 100644 index 0000000000..0eb28014fd --- /dev/null +++ b/tracing/tests/future_send.rs @@ -0,0 +1,19 @@ +use std::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) {} \ No newline at end of file From 0dca9793668b407935cb8ffa02c54efd59d5b866 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 10:08:59 -0700 Subject: [PATCH 2/7] fix send + sync issues with `log` Signed-off-by: Eliza Weisman --- tracing/src/lib.rs | 19 +++++++++++++++++++ tracing/src/macros.rs | 22 ++++++++-------------- 2 files changed, 27 insertions(+), 14 deletions(-) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 2d7198896c..014c1f30e8 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -1090,6 +1090,25 @@ 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: &ValueSet<'_>, + ) { + let meta = self.metadata(); + logger.log( + &log::Record::builder() + .file(meta.file()) + .module_path(meta.module_path()) + .line(meta.line()) + .metadata(log_meta) + .args(format_args!("{}", LogValueSet(values))) + .build(), + ); + } } impl Callsite for MacroCallsite { diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 4dbe275037..28c59319f8 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -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(); @@ -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)*) ); } @@ -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)*) ); } @@ -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) } } }} From 95190aeb1da72225ff9d9c59cc88acc7f6e9bb6e Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 10:13:34 -0700 Subject: [PATCH 3/7] LogValueSet need no longer be `pub` Signed-off-by: Eliza Weisman --- tracing/src/lib.rs | 113 ++++++++++++++++++++------------------------- 1 file changed, 50 insertions(+), 63 deletions(-) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 014c1f30e8..db9577e8a8 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -1096,8 +1096,57 @@ pub mod __macro_support { &self, logger: &'static dyn log::Log, log_meta: log::Metadata<'_>, - values: &ValueSet<'_>, + values: &tracing_core::ValueSet<'_>, ) { + use tracing_core::field::{Field, ValueSet, Visit}; + + /// Utility to format [`ValueSet`] for logging. + struct LogValueSet<'a>(&'a ValueSet<'a>); + + 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) + }; + 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 meta = self.metadata(); logger.log( &log::Record::builder() @@ -1137,68 +1186,6 @@ pub mod __macro_support { .finish() } } - - #[cfg(feature = "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>); - - #[cfg(feature = "log")] - 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 - } - } - - #[cfg(feature = "log")] - struct LogVisitor<'a, 'b> { - f: &'a mut fmt::Formatter<'b>, - is_first: bool, - result: fmt::Result, - } - - #[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) - } - } 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) - } - } - } } mod sealed { From 2f2100850e3ca8c473233b2d13d668663a5638d2 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 10:26:29 -0700 Subject: [PATCH 4/7] de-duplicate log support code Signed-off-by: Eliza Weisman --- tracing/src/lib.rs | 113 +++++++++++++++++++++++--------------------- tracing/src/span.rs | 44 ++++------------- 2 files changed, 68 insertions(+), 89 deletions(-) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index db9577e8a8..0a631c2565 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -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)] @@ -1096,25 +1092,62 @@ pub mod __macro_support { &self, logger: &'static dyn log::Log, log_meta: log::Metadata<'_>, - values: &tracing_core::ValueSet<'_>, + values: &tracing_core::field::ValueSet<'_>, ) { - use tracing_core::field::{Field, ValueSet, Visit}; + 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))) + .build(), + ); + } + } + + impl Callsite for MacroCallsite { + fn set_interest(&self, interest: Interest) { + let interest = match () { + _ if interest.is_never() => 0, + _ if interest.is_always() => 2, + _ => 1, + }; + self.interest.store(interest, Ordering::SeqCst); + } - /// Utility to format [`ValueSet`] for logging. - struct LogValueSet<'a>(&'a ValueSet<'a>); + #[inline(always)] + fn metadata(&self) -> &Metadata<'static> { + self.meta + } + } - 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 - } - } + impl fmt::Debug for MacroCallsite { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("MacroCallsite") + .field("interest", &self.interest) + .field("meta", &self.meta) + .field("register", &self.register) + .field("registration", &self.registration) + .finish() + } + } +} +#[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`]s for logging. + pub(crate) struct LogValueSet<'a>(pub(crate) &'a ValueSet<'a>); + + impl<'a> fmt::Display for LogValueSet<'a> { + #[inline] + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { struct LogVisitor<'a, 'b> { f: &'a mut fmt::Formatter<'b>, is_first: bool, @@ -1147,43 +1180,13 @@ pub mod __macro_support { } } - let meta = self.metadata(); - logger.log( - &log::Record::builder() - .file(meta.file()) - .module_path(meta.module_path()) - .line(meta.line()) - .metadata(log_meta) - .args(format_args!("{}", LogValueSet(values))) - .build(), - ); - } - } - - impl Callsite for MacroCallsite { - fn set_interest(&self, interest: Interest) { - let interest = match () { - _ if interest.is_never() => 0, - _ if interest.is_always() => 2, - _ => 1, + let mut visit = LogVisitor { + f, + is_first: true, + result: Ok(()), }; - self.interest.store(interest, Ordering::SeqCst); - } - - #[inline(always)] - fn metadata(&self) -> &Metadata<'static> { - self.meta - } - } - - impl fmt::Debug for MacroCallsite { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.debug_struct("MacroCallsite") - .field("interest", &self.interest) - .field("meta", &self.meta) - .field("register", &self.register) - .field("registration", &self.registration) - .finish() + self.0.record(&mut visit); + visit.result } } } diff --git a/tracing/src/span.rs b/tracing/src/span.rs index f379c76e32..58e80578fb 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -570,7 +570,11 @@ impl Span { } else { meta.target() }; - span.log(target, level_to_log!(*meta.level()), format_args!("++ {}{}", meta.name(), FmtAttrs(attrs))); + span.log( + target, + level_to_log!(*meta.level()), + format_args!("++ {}{}", meta.name(), crate::log::LogValueSet(attrs.values())), + ); }} span @@ -1220,7 +1224,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)), + ); }} } @@ -1581,38 +1589,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::*; From 9feecfab58cc6b3673fe0c42be10777cb710956c Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 10:38:12 -0700 Subject: [PATCH 5/7] minor test cleanup Signed-off-by: Eliza Weisman --- tracing/tests/future_send.rs | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/tracing/tests/future_send.rs b/tracing/tests/future_send.rs index 0eb28014fd..eb6f4dedce 100644 --- a/tracing/tests/future_send.rs +++ b/tracing/tests/future_send.rs @@ -1,4 +1,8 @@ -use std::future::{self, Future}; +// 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() { From d0afec4f42cff3656cf10f161f23f3060a310cfc Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 11:11:56 -0700 Subject: [PATCH 6/7] disembreak span lifecycle log formatting Signed-off-by: Eliza Weisman --- tracing/src/lib.rs | 17 ++++++++++---- tracing/src/span.rs | 13 ++++++----- tracing/test-log-support/src/lib.rs | 2 ++ .../test-log-support/tests/log_no_trace.rs | 8 +++---- .../test-log-support/tests/log_with_trace.rs | 2 +- .../span_activity_filtered_separately.rs | 10 ++++----- .../tests/span_lifecycle_can_be_enabled.rs | 22 +++++++++---------- 7 files changed, 43 insertions(+), 31 deletions(-) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 0a631c2565..4def4a76ee 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -1101,7 +1101,13 @@ pub mod __macro_support { .module_path(meta.module_path()) .line(meta.line()) .metadata(log_meta) - .args(format_args!("{}", crate::log::LogValueSet(values))) + .args(format_args!( + "{}", + crate::log::LogValueSet { + values, + is_first: true + } + )) .build(), ); } @@ -1143,7 +1149,10 @@ pub mod log { use tracing_core::field::{Field, ValueSet, Visit}; /// Utility to format [`ValueSet`]s for logging. - pub(crate) struct LogValueSet<'a>(pub(crate) &'a ValueSet<'a>); + pub(crate) struct LogValueSet<'a> { + pub(crate) values: &'a ValueSet<'a>, + pub(crate) is_first: bool, + } impl<'a> fmt::Display for LogValueSet<'a> { #[inline] @@ -1182,10 +1191,10 @@ pub mod log { let mut visit = LogVisitor { f, - is_first: true, + is_first: self.is_first, result: Ok(()), }; - self.0.record(&mut visit); + self.values.record(&mut visit); visit.result } } diff --git a/tracing/src/span.rs b/tracing/src/span.rs index 58e80578fb..1460593979 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -570,10 +570,11 @@ impl Span { } else { meta.target() }; + let values = attrs.values(); span.log( target, level_to_log!(*meta.level()), - format_args!("++ {}{}", meta.name(), crate::log::LogValueSet(attrs.values())), + format_args!("++ {};{}", meta.name(), crate::log::LogValueSet { values, is_first: false }), ); }} @@ -1039,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())); } }} } @@ -1056,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())); } }} } @@ -1227,7 +1228,7 @@ impl Span { self.log( target, level_to_log!(*_meta.level()), - format_args!("{}{}", _meta.name(), crate::log::LogValueSet(values)), + format_args!("{};{}", _meta.name(), crate::log::LogValueSet { values, is_first: false }), ); }} } @@ -1333,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 { @@ -1454,7 +1455,7 @@ impl Drop for Span { self.log( LIFECYCLE_LOG_TARGET, log::Level::Trace, - format_args!("-- {}", meta.name()), + format_args!("-- {};", meta.name()), ); } }} 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 b0b4f99d24..f963feacc5 100644 --- a/tracing/test-log-support/tests/log_with_trace.rs +++ b/tracing/test-log-support/tests/log_with_trace.rs @@ -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"); 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;"); } From 4ec8349069d35cc565fbc6c52d77387b41aab86d Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 14 Apr 2022 11:33:56 -0700 Subject: [PATCH 7/7] rustfmt --- tracing/tests/future_send.rs | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tracing/tests/future_send.rs b/tracing/tests/future_send.rs index eb6f4dedce..5e5f9f18bc 100644 --- a/tracing/tests/future_send.rs +++ b/tracing/tests/future_send.rs @@ -19,5 +19,4 @@ fn async_block_is_send() { }) } - -fn assert_send(_f: F) {} \ No newline at end of file +fn assert_send(_f: F) {}