tracing: log span lifecycle events under a separate target

## Motivation

Currently, the `tracing` crate's "log" feature always logs span
lifecycle (creation/enter/exit/close) events, even when the span has no
fields. This can be quite noisy. Since the enter, exit, and close logs
don't include the span's fields, it doesn't add that much additional
context to the surrounding log records.

## Solution

In order to continue recording this data while improving the
signal-to-noise ratio of `tracing`-generated logs, this commit changes
the log integration to log span lifecycle events under a separate
target, "tracing::span". This way, log users can opt in to this data
when it is desired, but logs are generally much less noisy. Span
creation is still logged to the default target when the span has fields,
as this often provides useful information, but is sent to the
"tracing-span" target when there are no fields.

Fixes #607

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 dbg!(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,12 +813,12 @@ 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(
@@ -912,7 +926,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 +1007,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()));
             }
         }}
     }

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(dbg!(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/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");
+}

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();
+}