trace: Allow trace instrumentation to emit log records (#992)

## Motivation

`tokio-trace` currently offers a strategy for compatibility with the
`log` crate: its macros can be dropped in as a replacement for `log`'s
macros, and a subscriber can be used that translates trace events to log
records. However, this requires the application to be aware of
`tokio-trace` and manually set up this subscriber.

Many libraries currently emit `log` records, and would like to be able
to emit `tokio-trace` instrumentation instead. The `tokio` runtimes are
one such example. However, with the current log compatibility strategy,
replacing existing logging with trace instrumentation would break
`tokio`'s logs for any downstream user which is using only `log` and not
`tokio-trace`. It is desirable for libraries to have the option to emit
both `log` _and_ `tokio-trace` diagnostics from the same instrumentation
points.

## Solution

This branch adds a `log` feature flag to the `tokio-trace` crate, which
when set, causes `tokio-trace` instrumentation to emit log records as well
as `tokio-trace` instrumentation. 

## Notes

In order to allow spans to log their names when they are entered and 
exited even when the span is disabled, this branch adds an 
`&'static Metadata` to the `Span` type. This was previously stored in
the `Inner` type and was thus only present when the span was enabled.
This makes disabled spans one word longer, but enabled spans remain
the same size.

Fixes: #949

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

.cirrus.yml

@@ -32,6 +32,7 @@ task:
   test_script:
     - . $HOME/.cargo/env
     - cargo test --all --no-fail-fast
+    - (cd tokio-trace/test-log-support && cargo test)
     - (cd tokio-trace/test_static_max_level_features && cargo test)
     - cargo doc --all
   i686_test_script:

azure-pipelines.yml

@@ -47,6 +47,7 @@ jobs:
       - tokio-timer
       - tokio-trace
       - tokio-trace/tokio-trace-core
+      - tokio-trace/test-log-support
       - tokio-trace/test_static_max_level_features
 
 - template: ci/azure-cargo-check.yml

tokio-trace/Cargo.toml

@@ -16,13 +16,19 @@ publish = false
 
 [dependencies]
 tokio-trace-core = "0.1"
+log = { version = "0.4", optional = true }
 cfg-if = "0.1.7"
 
 [dev-dependencies]
 ansi_term = "0.11"
 humantime = "1.1.1"
 futures = "0.1"
 log = "0.4"
+# These are used for the "basic" example from the tokio-trace-prototype repo,
+# which is currently not included as it used the `tokio-trace-log` crate, and
+# that crate is currently unstable.
+# env_logger = "0.5"
+# tokio-trace-log = { path = "../tokio-trace-log" }
 
 [features]
 max_level_off   = []
@@ -39,8 +45,3 @@ release_max_level_info  = []
 release_max_level_debug = []
 release_max_level_trace = []
 
-# These are used for the "basic" example from the tokio-trace-prototype repo,
-# which is currently not included as it used the `tokio-trace-log` crate, and
-# that crate is currently unstable.
-# env_logger = "0.5"
-# tokio-trace-log = { path = "../tokio-trace-log" }

tokio-trace/examples/sloggish/sloggish_subscriber.rs

@@ -158,7 +158,7 @@ impl SloggishSubscriber {
             stderr: io::stderr(),
             stack: Mutex::new(vec![]),
             spans: Mutex::new(HashMap::new()),
-            ids: AtomicUsize::new(0),
+            ids: AtomicUsize::new(1),
         }
     }
 

tokio-trace/src/lib.rs

@@ -313,6 +313,10 @@
 extern crate cfg_if;
 extern crate tokio_trace_core;
 
+#[cfg(feature = "log")]
+#[doc(hidden)]
+pub extern crate 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)]

tokio-trace/src/macros.rs

@@ -101,7 +101,7 @@ macro_rules! span {
         $name:expr,
         $($k:ident $( = $val:expr )* ),*
     ) => {
-        if $lvl <= $crate::level_filters::STATIC_MAX_LEVEL {
+        {
             use $crate::callsite;
             use $crate::callsite::Callsite;
             let callsite = callsite! {
@@ -110,18 +110,20 @@ macro_rules! span {
                 level: $lvl,
                 fields: $($k),*
             };
-            if is_enabled!(callsite) {
-                let meta = callsite.metadata();
+            let meta = callsite.metadata();
+
+            if $lvl <= $crate::level_filters::STATIC_MAX_LEVEL && is_enabled!(callsite) {
                 $crate::Span::child_of(
                     $parent,
                     meta,
                     &valueset!(meta.fields(), $($k $( = $val)*),*),
                 )
             } else {
-                $crate::Span::new_disabled()
+                 __tokio_trace_disabled_span!(
+                    meta,
+                    &valueset!(meta.fields(), $($k $( = $val)*),*)
+                )
             }
-        } else {
-            $crate::Span::new_disabled()
         }
     };
     (
@@ -130,7 +132,7 @@ macro_rules! span {
         $name:expr,
         $($k:ident $( = $val:expr )* ),*
     ) => {
-        if $lvl <= $crate::level_filters::STATIC_MAX_LEVEL {
+        {
             use $crate::callsite;
             use $crate::callsite::Callsite;
             let callsite = callsite! {
@@ -139,18 +141,21 @@ macro_rules! span {
                 level: $lvl,
                 fields: $($k),*
             };
-            if is_enabled!(callsite) {
-                let meta = callsite.metadata();
+            let meta = callsite.metadata();
+
+            if $lvl <= $crate::level_filters::STATIC_MAX_LEVEL && is_enabled!(callsite) {
                 $crate::Span::new(
                     meta,
                     &valueset!(meta.fields(), $($k $( = $val)*),*),
                 )
             } else {
-                $crate::Span::new_disabled()
+                __tokio_trace_disabled_span!(
+                    meta,
+                    &valueset!(meta.fields(), $($k $( = $val)*),*)
+                )
             }
-        } else {
-            $crate::Span::new_disabled()
         }
+
     };
     (target: $target:expr, level: $lvl:expr, parent: $parent:expr, $name:expr) => {
         span!(target: $target, level: $lvl, parent: $parent, $name,)
@@ -338,24 +343,32 @@ macro_rules! span {
 #[macro_export(local_inner_macros)]
 macro_rules! event {
     (target: $target:expr, $lvl:expr, { $( $k:ident = $val:expr ),* $(,)*} )=> ({
-        if $lvl <= $crate::level_filters::STATIC_MAX_LEVEL {
-            #[allow(unused_imports)]
-            use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}};
-            use $crate::callsite::Callsite;
-            let callsite = callsite! {
-                name: __tokio_trace_concat!(
-                    "event ",
-                    __tokio_trace_file!(),
-                    ":",
-                    __tokio_trace_line!()
-                ),
+        {
+            __tokio_trace_log!(
                 target: $target,
-                level: $lvl,
-                fields: $( $k ),*
-            };
-            if is_enabled!(callsite) {
-                let meta = callsite.metadata();
-                Event::dispatch(meta, &valueset!(meta.fields(), $( $k = $val),* ));
+                $lvl,
+                $( $k = $val ),*
+            );
+
+            if $lvl <= $crate::level_filters::STATIC_MAX_LEVEL {
+                #[allow(unused_imports)]
+                use $crate::{callsite, dispatcher, Event, field::{Value, ValueSet}};
+                use $crate::callsite::Callsite;
+                let callsite = callsite! {
+                    name: __tokio_trace_concat!(
+                        "event ",
+                        __tokio_trace_file!(),
+                        ":",
+                        __tokio_trace_line!()
+                    ),
+                    target: $target,
+                    level: $lvl,
+                    fields: $( $k ),*
+                };
+                if is_enabled!(callsite) {
+                    let meta = callsite.metadata();
+                    Event::dispatch(meta, &valueset!(meta.fields(), $( $k = $val),* ));
+                }
             }
         }
     });
@@ -526,7 +539,7 @@ macro_rules! trace {
 /// let pos = Position { x: 3.234, y: -1.223 };
 ///
 /// debug!(x = field::debug(pos.x), y = field::debug(pos.y));
-/// debug!(target: "app_events", { position = field::debug(pos) }, "New position");
+/// debug!(target: "app_events", { position = field::debug(&pos) }, "New position");
 /// # }
 /// ```
 #[macro_export(local_inner_macros)]
@@ -1007,3 +1020,82 @@ macro_rules! __tokio_trace_stringify {
         stringify!($s)
     };
 }
+
+#[cfg(feature = "log")]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! level_to_log {
+    ($level:expr) => {
+        match $level {
+            $crate::Level::ERROR => $crate::log::Level::Error,
+            $crate::Level::WARN => $crate::log::Level::Warn,
+            $crate::Level::INFO => $crate::log::Level::Info,
+            $crate::Level::DEBUG => $crate::log::Level::Debug,
+            _ => $crate::log::Level::Trace,
+        }
+    };
+}
+
+#[cfg(feature = "log")]
+#[doc(hidden)]
+#[macro_export(local_inner_macros)]
+macro_rules! __tokio_trace_log {
+    (target: $target:expr, $level:expr, $( $key:ident $( = $val:expr )* ),* $(,)* ) => {
+        use $crate::log;
+        let level = level_to_log!($level);
+        if level <= log::STATIC_MAX_LEVEL {
+            let log_meta = log::Metadata::builder()
+                .level(level)
+                .target($target)
+                .build();
+            let logger = log::logger();
+            if logger.enabled(&log_meta) {
+                logger.log(&log::Record::builder()
+                    .file(Some(__tokio_trace_file!()))
+                    .module_path(Some(__tokio_trace_module_path!()))
+                    .line(Some(__tokio_trace_line!()))
+                    .metadata(log_meta)
+                    .args(__tokio_trace_format_args!(
+                        __tokio_trace_concat!(
+                            $(__tokio_trace_log!(@key $key)),*
+                        ),
+                        $(
+                            __tokio_trace_log!(@val_or $key $( = $val)* )
+                        ),*
+                    ))
+                    .build());
+            }
+        }
+    };
+    (@key message) => { "{} " };
+    (@key $key:ident) => { __tokio_trace_concat!(__tokio_trace_stringify!( $key ), "={:?} ") };
+    (@val_or $k:ident = $v:expr) => { $v };
+    (@val_or $k:ident ) => { __tokio_trace_format_args!("?") };
+}
+
+#[cfg(not(feature = "log"))]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __tokio_trace_log {
+    (target: $target:expr, $level:expr, $( $key:ident $( = $val:expr )* ),* $(,)* ) => {};
+}
+
+#[cfg(feature = "log")]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __tokio_trace_disabled_span {
+    ($meta:expr, $valueset:expr) => {{
+        let mut span = $crate::Span::new_disabled($meta);
+        span.record_all(&$valueset);
+        span
+    }};
+}
+
+#[cfg(not(feature = "log"))]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __tokio_trace_disabled_span {
+    ($meta:expr, $valueset:expr) => {
+        $crate::Span::new_disabled($meta)
+    };
+}