log: make span enter/exit targets always TRACE (#833)

## Motivation

Currently, `tracing`'s `log` feature emits log records for creating,
entering, exiting, and dropping a `Span` at the `log` equivalent of that
span's `tracing` level. If the span has any fields, the span creation
logs are sent to the same target that the span would have, since the
fields provide high-value information that users enabling that target
will probably want to see. However, the other events for entering,
exiting, and dropping a span do not include fields, and are much more
verbose, so they are sent to a special `tracing::span` target. This
allows them to be filtered independently, and only enabled when needed.

However, some `log` users have noted that when using _blanket_ `log`
filters, like setting the level to `info` globally, the more verbose
activity logs will still be enabled for spans whose level matches. This
can be annoying.

## Solution

Therefore, this branch changes the span activity and lifecycle logs to
_always_ have the `Trace` `log` level, even when the span that generated
them has a less-verbose level. When fields are recorded, the emitted log
records are sent to the span's target instead, since users probably want
this information if they have enabled the span's level for its target.

Additionally, I've added a sub-target of `tracing::span` for the
enter/exit logs in particular (`tracing::span::active`). This allows
them to be filtered independently of the less frequent creation/drop
logs.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

tracing/src/lib.rs

@@ -644,8 +644,12 @@
 //! 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`.
+//! will always be emitted at the `Trace` level, rather than inheriting the
+//! level of the span that generated them. Furthermore, they are are categorized
+//! under a separate `log` target, "tracing::span" (and its sub-target,
+//! "tracing::span::active", for the logs on entering and exiting a span), which
+//! may be enabled or disabled separately from other `log` records emitted by
+//! `tracing`.
 //!
 //! ### Consuming `log` Records
 //!

tracing/src/span.rs

@@ -381,9 +381,12 @@ pub struct Entered<'a> {
     span: &'a Span,
 }
 
-/// `log` target for span lifecycle (creation/enter/exit/close) records.
+/// `log` target for all span lifecycle (creation/enter/exit/close) records.
 #[cfg(feature = "log")]
 const LIFECYCLE_LOG_TARGET: &str = "tracing::span";
+/// `log` target for span activity (enter/exit) records.
+#[cfg(feature = "log")]
+const ACTIVITY_LOG_TARGET: &str = "tracing::span::active";
 
 // ===== impl Span =====
 
@@ -512,7 +515,7 @@ impl Span {
             } else {
                 meta.target()
             };
-            span.log(target, format_args!("++ {}{}", meta.name(), FmtAttrs(attrs)));
+            span.log(target, level_to_log!(meta.level()), format_args!("++ {}{}", meta.name(), FmtAttrs(attrs)));
         }}
 
         span
@@ -716,7 +719,7 @@ impl Span {
 
         if_log_enabled! {{
             if let Some(ref meta) = self.meta {
-                self.log(LIFECYCLE_LOG_TARGET, format_args!("-> {}", meta.name()));
+                self.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("-> {}", meta.name()));
             }
         }}
 
@@ -888,7 +891,7 @@ impl Span {
                 } else {
                     meta.target()
                 };
-                self.log(target, format_args!("{}{}", meta.name(), FmtValues(&record)));
+                self.log(target, level_to_log!(meta.level()), format_args!("{}{}", meta.name(), FmtValues(&record)));
             }
         }}
 
@@ -989,13 +992,10 @@ impl Span {
 
     #[cfg(feature = "log")]
     #[inline]
-    fn log(&self, target: &str, message: fmt::Arguments<'_>) {
+    fn log(&self, target: &str, level: log::Level, 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(target)
-                .build();
+            let log_meta = log::Metadata::builder().level(level).target(target).build();
             if logger.enabled(&log_meta) {
                 if let Some(ref inner) = self.inner {
                     logger.log(
@@ -1114,7 +1114,11 @@ impl Drop for Span {
 
         if_log_enabled!({
             if let Some(ref meta) = self.meta {
-                self.log(LIFECYCLE_LOG_TARGET, format_args!("-- {}", meta.name()));
+                self.log(
+                    LIFECYCLE_LOG_TARGET,
+                    log::Level::Trace,
+                    format_args!("-- {}", meta.name()),
+                );
             }
         })
     }
@@ -1195,7 +1199,7 @@ impl<'a> Drop for Entered<'a> {
 
         if_log_enabled! {{
             if let Some(ref meta) = self.span.meta {
-                self.span.log(LIFECYCLE_LOG_TARGET, format_args!("<- {}", meta.name()));
+                self.span.log(ACTIVITY_LOG_TARGET, log::Level::Trace, format_args!("<- {}", meta.name()));
             }
         }}
     }

tracing/test-log-support/tests/span_activity_filtered_separately.rs

@@ -0,0 +1,79 @@
+#[macro_use]
+extern crate tracing;
+extern crate test_log_support;
+
+use test_log_support::Test;
+use tracing::Level;
+
+#[test]
+fn span_activity_filtered_separately() {
+    let test = Test::with_filters(&[
+        (module_path!(), log::LevelFilter::Trace),
+        ("tracing::span::active", log::LevelFilter::Off), // Disable enter/exit events.
+        ("tracing::span", log::LevelFilter::Trace),       // Enable lifecycle events
+    ]);
+
+    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");
+    // Creating a span goes to the `tracing::span` target.
+    test.assert_logged("foo");
+
+    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 be logged
+    test.assert_logged("-- foo");
+
+    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 not be logged
+        test.assert_not_logged();
+    });
+    // exiting the INFO span should not be logged
+    test.assert_not_logged();
+
+    drop(foo);
+    // drop should be logged
+    test.assert_logged("-- foo");
+
+    drop(bar);
+    // dropping the INFO should be logged.
+    test.assert_logged("-- bar");
+}

tracing/test-log-support/tests/span_lifecycle_can_be_enabled.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_enabled() {
+    let test = Test::with_filters(&[
+        (module_path!(), log::LevelFilter::Trace),
+        ("tracing::span", 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_logged("foo");
+
+    foo.in_scope(|| {
+        // enter should be logged
+        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");
+
+    drop(foo);
+    // drop should be logged
+    test.assert_logged("-- foo");
+
+    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 be logged
+        test.assert_logged("-> foo");
+    });
+    // exiting the span should be logged
+    test.assert_logged("<- foo");
+
+    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 be logged.
+    test.assert_logged("-- foo");
+
+    drop(bar);
+    // dropping the INFO should be logged.
+    test.assert_logged("-- bar");
+}

tracing/test-log-support/tests/span_lifecycle_defaults_off.rs

@@ -7,7 +7,7 @@ use tracing::Level;
 
 #[test]
 fn span_lifecycle_defaults_off() {
-    let test = Test::with_filters(&[("span_lifecycle_defaults_off", log::LevelFilter::Trace)]);
+    let test = Test::with_filters(&[(module_path!(), log::LevelFilter::Trace)]);
 
     error!(foo = 5);
     test.assert_logged("foo=5");

tracing/test-log-support/tests/span_lifecycle_can_be_filtered.rs → tracing/test-log-support/tests/span_lifecycle_is_trace.rs

@@ -6,10 +6,10 @@ use test_log_support::Test;
 use tracing::Level;
 
 #[test]
-fn span_lifecycle_can_be_filtered() {
+fn span_lifecycle_is_trace() {
     let test = Test::with_filters(&[
-        ("span_lifecycle_can_be_filtered", log::LevelFilter::Trace),
-        ("tracing::span", log::LevelFilter::Info),
+        (module_path!(), log::LevelFilter::Trace),
+        ("", log::LevelFilter::Info),
     ]);
 
     error!(foo = 5);
@@ -22,6 +22,7 @@ fn span_lifecycle_can_be_filtered() {
     test.assert_logged("hello world; thingy=42 other_thingy=666");
 
     let foo = span!(Level::TRACE, "foo");
+    // A span without fields should not be logged
     test.assert_not_logged();
 
     foo.in_scope(|| {
@@ -56,22 +57,7 @@ fn span_lifecycle_can_be_filtered() {
     // 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");
 }