diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 76a74ac8dc..49fcac3060 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -584,6 +584,58 @@ //! Once a subscriber has been set, instrumentation points may be added to the //! executable using the `tracing` crate's macros. //! +//! ## `log` Compatibility +//! +//! The [`log`] crate provides a simple, lightweight logging facade for Rust. +//! While `tracing` builds upon `log`'s foundation with richer structured +//! diagnostic data, `log`'s simplicity and ubiquity make it the "lowest common +//! denominator" for text-based logging in Rust — a vast majority of Rust +//! libraries and applications either emit or consume `log` records. Therefore, +//! `tracing` provides multiple forms of interoperability with `log`: `tracing` +//! instrumentation can emit `log` records, and a compatibility layer enables +//! `tracing` [`Subscriber`]s to consume `log` records as `tracing` [`Event`]s. +//! +//! ### Emitting `log` Records +//! +//! This crate provides two feature flags, "log" and "log-always", which will +//! cause [spans] and [events] to emit `log` records. When the "log" feature is +//! enabled, if no `tracing` `Subscriber` is active, invoking an event macro or +//! creating a span with fields will emit a `log` record. This is intended +//! primarily for use in libraries which wish to emit diagnostics that can be +//! consumed by applications using `tracing` *or* `log`, without paying the +//! additional overhead of emitting both forms of diagnostics when `tracing` is +//! in use. +//! +//! Enabling the "log-always" feature will cause `log` records to be emitted +//! even if a `tracing` `Subscriber` _is_ set. This is intended to be used in +//! applications where a `log` `Logger` is being used to record a textual log, +//! and `tracing` is used only to record other forms of diagnostics (such as +//! metrics, profiling, or distributed tracing data). Unlike the "log" feature, +//! libraries generally should **not** enable the "log-always" feature, as doing +//! so will prevent applications from being able to opt out of the `log` records. +//! +//! See [here][flags] for more details on this crate's feature flags. +//! +//! The generated `log` records' messages will be a string representation of the +//! span or event's fields, and all additional information recorded by `log` +//! (target, verbosity level, module path, file, and line number) will also be +//! populated. Additionally, `log` records are also generated when spans are +//! entered, exited, and closed. Since these additional span lifecycle logs have +//! the potential to be very verbose, and don't include additional fields, they +//! are categorized under a separate `log` target, "tracing::span", which may be +//! enabled or disabled separately from other `log` records emitted by `tracing`. +//! +//! ### Consuming `log` Records +//! +//! The [`tracing-log`] crate provides a compatibility layer which +//! allows a `tracing` [`Subscriber`] to consume `log` records as though they +//! were `tracing` [events]. This allows applications using `tracing` to record +//! the logs emitted by dependencies using `log` as events within the context of +//! the application's trace tree. See [that crate's documentation][log-tracer] +//! for details. +//! +//! [log-tracer]: https://docs.rs/tracing-log/latest/tracing_log/#convert-log-records-to-tracing-events +//! //! ## Related Crates //! //! In addition to `tracing` and `tracing-core`, the [`tokio-rs/tracing`] repository @@ -640,7 +692,7 @@ //! undergoing active development. They may be less stable than `tracing` and //! `tracing-core`. //! -//! ## Crate Feature Flags +//! ## Crate Feature Flags //! //! The following crate feature flags are available: //! @@ -677,6 +729,7 @@ //! [`Span`]: span/struct.Span.html //! [`in_scope`]: span/struct.Span.html#method.in_scope //! [`Event`]: struct.Event.html +//! [event]: struct.Event.html //! [`Subscriber`]: subscriber/trait.Subscriber.html //! [Subscriber::event]: subscriber/trait.Subscriber.html#tymethod.event //! [`enter`]: subscriber/trait.Subscriber.html#tymethod.enter @@ -696,6 +749,7 @@ //! [`FmtSubscriber`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/struct.Subscriber.html //! [static verbosity level]: level_filters/index.html#compile-time-filters //! [instrument]: https://docs.rs/tracing-attributes/latest/tracing_attributes/attr.instrument.html +//! [flags]: #crate-feature-flags #![cfg_attr(not(feature = "std"), no_std)] #![cfg_attr(docsrs, feature(doc_cfg))] #![doc(html_root_url = "https://docs.rs/tracing/0.1.13")] diff --git a/tracing/src/span.rs b/tracing/src/span.rs index c79aef13ac..edfec6e598 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -364,6 +364,10 @@ pub struct Entered<'a> { span: &'a Span, } +/// `log` target for span lifecycle (creation/enter/exit/close) records. +#[cfg(feature = "log")] +const LIFECYCLE_LOG_TARGET: &'static str = "tracing::span"; + // ===== impl Span ===== impl Span { @@ -486,7 +490,12 @@ impl Span { }; if_log_enabled! {{ - span.log(format_args!("++ {}; {}", meta.name(), FmtAttrs(attrs))); + let target = if attrs.is_empty() { + LIFECYCLE_LOG_TARGET + } else { + meta.target() + }; + span.log(target, format_args!("++ {}{}", meta.name(), FmtAttrs(attrs))); }} span @@ -565,7 +574,7 @@ impl Span { if_log_enabled! {{ if let Some(ref meta) = self.meta { - self.log(format_args!("-> {}", meta.name())); + self.log(LIFECYCLE_LOG_TARGET, format_args!("-> {}", meta.name())); } }} @@ -698,7 +707,12 @@ impl Span { if_log_enabled! {{ if let Some(ref meta) = self.meta { - self.log(format_args!("{}; {}", meta.name(), FmtValues(&record))); + let target = if record.is_empty() { + LIFECYCLE_LOG_TARGET + } else { + meta.target() + }; + self.log(target, format_args!("{}{}", meta.name(), FmtValues(&record))); } }} @@ -799,23 +813,35 @@ impl Span { #[cfg(feature = "log")] #[inline] - fn log(&self, message: fmt::Arguments<'_>) { + fn log(&self, target: &str, message: fmt::Arguments<'_>) { if let Some(ref meta) = self.meta { let logger = log::logger(); let log_meta = log::Metadata::builder() .level(level_to_log!(meta.level())) - .target(meta.target()) + .target(target) .build(); if logger.enabled(&log_meta) { - logger.log( - &log::Record::builder() - .metadata(log_meta) - .module_path(meta.module_path()) - .file(meta.file()) - .line(meta.line()) - .args(message) - .build(), - ); + if let Some(ref inner) = self.inner { + logger.log( + &log::Record::builder() + .metadata(log_meta) + .module_path(meta.module_path()) + .file(meta.file()) + .line(meta.line()) + .args(format_args!("{}; span={}", message, inner.id.into_u64())) + .build(), + ); + } else { + logger.log( + &log::Record::builder() + .metadata(log_meta) + .module_path(meta.module_path()) + .file(meta.file()) + .line(meta.line()) + .args(message) + .build(), + ); + } } } } @@ -912,7 +938,7 @@ impl Drop for Span { if_log_enabled!({ if let Some(ref meta) = self.meta { - self.log(format_args!("-- {}", meta.name())); + self.log(LIFECYCLE_LOG_TARGET, format_args!("-- {}", meta.name())); } }) } @@ -993,7 +1019,7 @@ impl<'a> Drop for Entered<'a> { if_log_enabled! {{ if let Some(ref meta) = self.span.meta { - self.span.log(format_args!("<- {}", meta.name())); + self.span.log(LIFECYCLE_LOG_TARGET, format_args!("<- {}", meta.name())); } }} } @@ -1006,8 +1032,10 @@ struct FmtValues<'a>(&'a Record<'a>); 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, "{}={:?} ", k, v); + res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v); + is_first = false; }); res } @@ -1020,8 +1048,10 @@ struct FmtAttrs<'a>(&'a Attributes<'a>); 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, "{}={:?} ", k, v); + res = write!(f, "{} {}={:?}", if is_first { ";" } else { "" }, k, v); + is_first = false; }); res } diff --git a/tracing/test-log-support/src/lib.rs b/tracing/test-log-support/src/lib.rs index b7e6822f00..7e76428892 100644 --- a/tracing/test-log-support/src/lib.rs +++ b/tracing/test-log-support/src/lib.rs @@ -10,17 +10,25 @@ struct State { last_log: Mutex>, } -struct Logger(Arc); +struct Logger { + filters: Vec<(&'static str, LevelFilter)>, + state: Arc, +} impl Log for Logger { - fn enabled(&self, _: &Metadata) -> bool { - true + fn enabled(&self, meta: &Metadata) -> bool { + for (target, level) in &self.filters { + if meta.target().starts_with(target) { + return meta.level() <= *level; + } + } + false } fn log(&self, record: &Record) { let line = format!("{}", record.args()); println!("{:<5} {} {}", record.level(), record.target(), line); - if let Ok(mut last) = self.0.last_log.lock() { + if let Ok(mut last) = self.state.last_log.lock() { *last = Some(line); } } @@ -30,25 +38,50 @@ impl Log for Logger { impl Test { pub fn start() -> Self { + Self::with_filters(&[("", LevelFilter::Trace)]) + } + + pub fn with_filters<'a>( + filters: impl IntoIterator, + ) -> Self { let me = Arc::new(State { last_log: Mutex::new(None), }); let state = me.clone(); - log::set_boxed_logger(Box::new(Logger(me))).unwrap(); - log::set_max_level(LevelFilter::Trace); - Test { - state, - } + let mut max = LevelFilter::Off; + let filters = filters + .into_iter() + .cloned() + .inspect(|(_, f)| { + if f > &max { + max = *f; + } + }) + .collect(); + let logger = Logger { filters, state: me }; + log::set_boxed_logger(Box::new(logger)).unwrap(); + log::set_max_level(max); + Test { state } } pub fn assert_logged(&self, expected: &str) { let last = match self.state.last_log.lock().unwrap().take() { Some(last) => last, - _ => panic!("test failed: expected \"{}\", but nothing was logged", expected), + _ => panic!( + "test failed: expected \"{}\", but nothing was logged", + expected + ), }; assert_eq!(last.as_str().trim(), expected); } + pub fn assert_not_logged(&self) { + if let Some(last) = self.state.last_log.lock().unwrap().take() { + panic!( + "test failed: nothing to be logged, but \"{}\" was logged", + last + ); + } + } } - diff --git a/tracing/test-log-support/tests/log_no_trace.rs b/tracing/test-log-support/tests/log_no_trace.rs index 6cebb715f0..97b4ce75ec 100644 --- a/tracing/test-log-support/tests/log_no_trace.rs +++ b/tracing/test-log-support/tests/log_no_trace.rs @@ -19,7 +19,7 @@ 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"); diff --git a/tracing/test-log-support/tests/log_with_trace.rs b/tracing/test-log-support/tests/log_with_trace.rs index 23ae8071e3..85c541c869 100644 --- a/tracing/test-log-support/tests/log_with_trace.rs +++ b/tracing/test-log-support/tests/log_with_trace.rs @@ -12,7 +12,9 @@ impl tracing::Subscriber for NopSubscriber { true } fn new_span(&self, _: &tracing::span::Attributes) -> tracing::span::Id { - tracing::span::Id::from_u64(1) + use std::sync::atomic::{AtomicU64, Ordering::Relaxed}; + static NEXT: AtomicU64 = AtomicU64::new(1); + tracing::span::Id::from_u64(NEXT.fetch_add(1, Relaxed)) } fn record(&self, _: &tracing::span::Id, _: &tracing::span::Record) {} fn record_follows_from(&self, _: &tracing::span::Id, _: &tracing::span::Id) {} @@ -25,7 +27,7 @@ impl tracing::Subscriber for NopSubscriber { } #[test] -fn test_always_log() { +fn log_with_trace() { tracing::subscriber::set_global_default(NopSubscriber).expect("set global should succeed"); let test = Test::start(); @@ -46,24 +48,24 @@ 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; span=1"); foo.in_scope(|| { - test.assert_logged("-> foo"); + test.assert_logged("-> foo; span=1"); 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; span=1"); drop(foo); - test.assert_logged("-- foo"); + test.assert_logged("-- foo; span=1"); let foo = span!(Level::TRACE, "foo", bar = 3, baz = false); - test.assert_logged("++ foo; bar=3 baz=false"); + test.assert_logged("++ foo; bar=3 baz=false; span=2"); drop(foo); - test.assert_logged("-- foo"); + test.assert_logged("-- foo; span=2"); trace!(foo = 1, bar = 2, "hello world"); test.assert_logged("hello world foo=1 bar=2"); diff --git a/tracing/test-log-support/tests/span_lifecycle_can_be_filtered.rs b/tracing/test-log-support/tests/span_lifecycle_can_be_filtered.rs new file mode 100644 index 0000000000..e5e11c62b6 --- /dev/null +++ b/tracing/test-log-support/tests/span_lifecycle_can_be_filtered.rs @@ -0,0 +1,77 @@ +#[macro_use] +extern crate tracing; +extern crate test_log_support; + +use test_log_support::Test; +use tracing::Level; + +#[test] +fn span_lifecycle_can_be_filtered() { + let test = Test::with_filters(&[ + ("span_lifecycle_can_be_filtered", log::LevelFilter::Trace), + ("tracing::span", log::LevelFilter::Info), + ]); + + error!(foo = 5); + test.assert_logged("foo=5"); + + warn!("hello {};", "world"); + test.assert_logged("hello world;"); + + info!(message = "hello world;", thingy = 42, other_thingy = 666); + test.assert_logged("hello world; thingy=42 other_thingy=666"); + + let foo = span!(Level::TRACE, "foo"); + test.assert_not_logged(); + + foo.in_scope(|| { + // enter should not be logged + test.assert_not_logged(); + + trace!({foo = 3, bar = 4}, "hello {};", "san francisco"); + test.assert_logged("hello san francisco; foo=3 bar=4"); + }); + // exit should not be logged + test.assert_not_logged(); + + drop(foo); + // drop should not be logged + test.assert_not_logged(); + + trace!(foo = 1, bar = 2, "hello world"); + test.assert_logged("hello world foo=1 bar=2"); + + let foo = span!(Level::TRACE, "foo", bar = 3, baz = false); + // creating a span with fields _should_ be logged. + test.assert_logged("foo; bar=3 baz=false"); + + foo.in_scope(|| { + // entering the span should not be logged + test.assert_not_logged(); + }); + // exiting the span should not be logged + test.assert_not_logged(); + + foo.record("baz", &true); + // recording a field should be logged + test.assert_logged("foo; baz=true"); + + let bar = span!(Level::INFO, "bar"); + // lifecycles for INFO spans should be logged + test.assert_logged("bar"); + + bar.in_scope(|| { + // entering the INFO span should be logged + test.assert_logged("-> bar"); + }); + // exiting the INFO span should be logged + test.assert_logged("<- bar"); + + drop(foo); + // drop should not be logged. + test.assert_not_logged(); + + drop(bar); + // dropping the INFO should be logged. + test.assert_logged("-- bar"); +} diff --git a/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs b/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs new file mode 100644 index 0000000000..2e5dd6d0bf --- /dev/null +++ b/tracing/test-log-support/tests/span_lifecycle_defaults_off.rs @@ -0,0 +1,59 @@ +#[macro_use] +extern crate tracing; +extern crate test_log_support; + +use test_log_support::Test; +use tracing::Level; + +#[test] +fn span_lifecycle_defaults_off() { + let test = Test::with_filters(&[("span_lifecycle_defaults_off", log::LevelFilter::Trace)]); + + error!(foo = 5); + test.assert_logged("foo=5"); + + warn!("hello {};", "world"); + test.assert_logged("hello world;"); + + info!(message = "hello world;", thingy = 42, other_thingy = 666); + test.assert_logged("hello world; thingy=42 other_thingy=666"); + + let foo = span!(Level::TRACE, "foo"); + test.assert_not_logged(); + + foo.in_scope(|| { + // enter should not be logged + test.assert_not_logged(); + + trace!({foo = 3, bar = 4}, "hello {};", "san francisco"); + test.assert_logged("hello san francisco; foo=3 bar=4"); + }); + // exit should not be logged + test.assert_not_logged(); + + drop(foo); + // drop should not be logged + test.assert_not_logged(); + + trace!(foo = 1, bar = 2, "hello world"); + test.assert_logged("hello world foo=1 bar=2"); + + let foo = span!(Level::TRACE, "foo", bar = 3, baz = false); + // creating a span with fields _should_ be logged. + test.assert_logged("foo; bar=3 baz=false"); + + foo.in_scope(|| { + // entering the span should not be logged + test.assert_not_logged(); + }); + // exiting the span should not be logged + test.assert_not_logged(); + + foo.record("baz", &true); + // recording a field should be logged + test.assert_logged("foo; baz=true"); + + drop(foo); + // drop should not be logged. + test.assert_not_logged(); +}