tracing: less noisy, more useful log records for spans

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")]

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
     }

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

@@ -10,17 +10,25 @@ struct State {
     last_log: Mutex<Option<String>>,
 }
 
-struct Logger(Arc<State>);
+struct Logger {
+    filters: Vec<(&'static str, LevelFilter)>,
+    state: Arc<State>,
+}
 
 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<Item = &'a (&'static str, LevelFilter)>,
+    ) -> 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
+            );
+        }
+    }
 }
-

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");

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");