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>

12 files changed, 372 insertions, 106 deletions

diff --git a/.cirrus.yml b/.cirrus.yml
index 053ce41e..922c5bee 100644
--- a/.cirrus.yml
+++ b/.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:
diff --git a/azure-pipelines.yml b/azure-pipelines.yml
index 4170b017..e15e5c55 100644
--- a/azure-pipelines.yml
+++ b/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
diff --git a/tokio-trace/Cargo.toml b/tokio-trace/Cargo.toml
index 0d4bdcbb..e554fd97 100644
--- a/tokio-trace/Cargo.toml
+++ b/tokio-trace/Cargo.toml
@@ -16,6 +16,7 @@ publish = false
 
 [dependencies]
 tokio-trace-core = "0.1"
+log = { version = "0.4", optional = true }
 cfg-if = "0.1.7"
 
 [dev-dependencies]
@@ -23,6 +24,11 @@ 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" }
diff --git a/tokio-trace/examples/sloggish/sloggish_subscriber.rs b/tokio-trace/examples/sloggish/sloggish_subscriber.rs
index 6d288644..aed43c83 100644
--- a/tokio-trace/examples/sloggish/sloggish_subscriber.rs
+++ b/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),
         }
     }
 
diff --git a/tokio-trace/src/lib.rs b/tokio-trace/src/lib.rs
index 6182b552..da544c57 100644
--- a/tokio-trace/src/lib.rs
+++ b/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)]
diff --git a/tokio-trace/src/macros.rs b/tokio-trace/src/macros.rs
index 84791747..4dcd677f 100644
--- a/tokio-trace/src/macros.rs
+++ b/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)
+    };
+}
diff --git a/tokio-trace/src/span.rs b/tokio-trace/src/span.rs
index bc1aa8e0..822fa620 100644
--- a/tokio-trace/src/span.rs
+++ b/tokio-trace/src/span.rs
@@ -130,10 +130,7 @@ use std::{
     cmp, fmt,
     hash::{Hash, Hasher},
 };
-use {
-    dispatcher::{self, Dispatch},
-    field, Metadata,
-};
+use {dispatcher::Dispatch, field, Metadata};
 
 /// A handle representing a span, with the capability to enter the span if it
 /// exists.
@@ -141,12 +138,13 @@ use {
 /// If the span was rejected by the current `Subscriber`'s filter, entering the
 /// span will silently do nothing. Thus, the handle can be used in the same
 /// manner regardless of whether or not the trace is currently being collected.
-#[derive(Clone, PartialEq, Hash)]
+#[derive(Clone)]
 pub struct Span {
     /// A handle used to enter the span when it is not executing.
     ///
     /// If this is `None`, then the span has either closed or was never enabled.
-    inner: Option<Inner<'static>>,
+    inner: Option<Inner>,
+    meta: &'static Metadata<'static>,
 }
 
 /// A handle representing the capacity to enter a span which is known to exist.
@@ -155,7 +153,7 @@ pub struct Span {
 /// enabled by the current filter. This type is primarily used for implementing
 /// span handles; users should typically not need to interact with it directly.
 #[derive(Debug)]
-pub(crate) struct Inner<'a> {
+pub(crate) struct Inner {
     /// The span's ID, as provided by `subscriber`.
     id: Id,
 
@@ -164,8 +162,6 @@ pub(crate) struct Inner<'a> {
     /// This should be the same subscriber that provided this span with its
     /// `id`.
     subscriber: Dispatch,
-
-    meta: &'a Metadata<'a>,
 }
 
 /// A guard representing a span which has been entered and is currently
@@ -178,8 +174,8 @@ pub(crate) struct Inner<'a> {
 /// typically not need to interact with it directly.
 #[derive(Debug)]
 #[must_use = "once a span has been entered, it should be exited"]
-struct Entered<'a> {
-    inner: Inner<'a>,
+struct Entered {
+    inner: Inner,
 }
 
 // ===== impl Span =====
@@ -244,17 +240,19 @@ impl Span {
 
     /// Constructs a new disabled span.
     #[inline(always)]
-    pub fn new_disabled() -> Span {
-        Span { inner: None }
+    pub fn new_disabled(meta: &'static Metadata<'static>) -> Span {
+        Span { inner: None, meta }
     }
 
-    #[inline(always)]
     fn make(meta: &'static Metadata<'static>, new_span: Attributes) -> Span {
-        let inner = dispatcher::get_default(move |dispatch| {
-            let id = dispatch.new_span(&new_span);
-            Some(Inner::new(id, dispatch, meta))
+        let attrs = &new_span;
+        let inner = ::dispatcher::get_default(move |dispatch| {
+            let id = dispatch.new_span(attrs);
+            Some(Inner::new(id, dispatch))
         });
-        Self { inner }
+        let span = Self { inner, meta };
+        span.log(format_args!("{}; {}", meta.name(), FmtAttrs(&new_span)));
+        span
     }
 
     /// Executes the given function in the context of this span.
@@ -266,7 +264,8 @@ impl Span {
     ///
     /// Returns the result of evaluating `f`.
     pub fn enter<F: FnOnce() -> T, T>(&mut self, f: F) -> T {
-        match self.inner.take() {
+        self.log(format_args!("-> {}", self.meta.name));
+        let result = match self.inner.take() {
             Some(inner) => {
                 let guard = inner.enter();
                 let result = f();
@@ -274,7 +273,9 @@ impl Span {
                 result
             }
             None => f(),
-        }
+        };
+        self.log(format_args!("<- {}", self.meta.name));
+        result
     }
 
     /// Returns a [`Field`](::field::Field) for the field with the given `name`, if
@@ -283,9 +284,7 @@ impl Span {
     where
         Q: Borrow<str>,
     {
-        self.inner
-            .as_ref()
-            .and_then(|inner| inner.meta.fields().field(name))
+        self.metadata().and_then(|meta| meta.fields().field(name))
     }
 
     /// Returns true if this `Span` has a field for the given
@@ -305,24 +304,25 @@ impl Span {
         Q: field::AsField,
         V: field::Value,
     {
-        if let Some(ref mut inner) = self.inner {
-            let meta = inner.metadata();
-            if let Some(field) = field.as_field(meta) {
-                inner.record(
-                    &meta
-                        .fields()
-                        .value_set(&[(&field, Some(value as &field::Value))]),
-                )
-            }
+        if let Some(field) = field.as_field(self.meta) {
+            self.record_all(
+                &self
+                    .meta
+                    .fields()
+                    .value_set(&[(&field, Some(value as &field::Value))]),
+            );
         }
+
         self
     }
 
     /// Visit all the fields in the span
     pub fn record_all(&mut self, values: &field::ValueSet) -> &mut Self {
+        let record = Record::new(values);
         if let Some(ref mut inner) = self.inner {
-            inner.record(&values);
+            inner.record(&record);
         }
+        self.log(format_args!("{}; {}", self.meta.name(), FmtValues(&record)));
         self
     }
 
@@ -361,19 +361,78 @@ impl Span {
 
     /// Returns this span's `Metadata`, if it is enabled.
     pub fn metadata(&self) -> Option<&'static Metadata<'static>> {
-        self.inner.as_ref().map(Inner::metadata)
+        if self.inner.is_some() {
+            Some(self.meta)
+        } else {
+            None
+        }
+    }
+
+    #[cfg(feature = "log")]
+    #[inline]
+    fn log(&self, message: fmt::Arguments) {
+        use log;
+        let logger = log::logger();
+        let log_meta = log::Metadata::builder()
+            .level(level_to_log!(self.meta.level))
+            .target(self.meta.target)
+            .build();
+        if logger.enabled(&log_meta) {
+            logger.log(
+                &log::Record::builder()
+                    .metadata(log_meta)
+                    .module_path(self.meta.module_path)
+                    .file(self.meta.file)
+                    .line(self.meta.line)
+                    .args(message)
+                    .build(),
+            );
+        }
+    }
+
+    #[cfg(not(feature = "log"))]
+    #[inline]
+    fn log(&self, _: fmt::Arguments) {}
+}
+
+impl cmp::PartialEq for Span {
+    fn eq(&self, other: &Self) -> bool {
+        self.meta.callsite() == other.meta.callsite() && self.inner == other.inner
+    }
+}
+
+impl Hash for Span {
+    fn hash<H: Hasher>(&self, hasher: &mut H) {
+        self.inner.hash(hasher);
     }
 }
 
-impl<'a> fmt::Debug for Span {
+impl fmt::Debug for Span {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
         let mut span = f.debug_struct("Span");
+        span.field("name", &self.meta.name())
+            .field("level", &self.meta.level())
+            .field("target", &self.meta.target());
+
         if let Some(ref inner) = self.inner {
-            span.field("id", &inner.id())
+            span.field("id", &inner.id());
         } else {
-            span.field("disabled", &true)
+            span.field("disabled", &true);
+        }
+
+        if let Some(ref path) = self.meta.module_path() {
+            span.field("module_path", &path);
+        }
+
+        if let Some(ref line) = self.meta.line() {
+            span.field("line", &line);
+        }
+
+        if let Some(ref file) = self.meta.file() {
+            span.field("file", &file);
         }
-        .finish()
+
+        span.finish()
     }
 }
 
@@ -385,14 +444,14 @@ impl<'a> Into<Option<Id>> for &'a Span {
 
 // ===== impl Inner =====
 
-impl<'a> Inner<'a> {
+impl Inner {
     /// Enters the span, returning a guard that may be used to exit the span and
     /// re-enter the prior span.
     ///
     /// This is used internally to implement `Span::enter`. It may be used for
     /// writing custom span handles, but should generally not be called directly
     /// when entering a span.
-    fn enter(self) -> Entered<'a> {
+    fn enter(self) -> Entered {
         self.subscriber.enter(&self.id);
         Entered { inner: self }
     }
@@ -421,61 +480,76 @@ impl<'a> Inner<'a> {
         self.id.clone()
     }
 
-    /// Returns the span's metadata.
-    fn metadata(&self) -> &'a Metadata<'a> {
-        self.meta
-    }
-
-    fn record(&mut self, values: &field::ValueSet) {
-        if values.callsite() == self.meta.callsite() {
-            self.subscriber.record(&self.id, &Record::new(values))
-        }
+    fn record(&mut self, values: &Record) {
+        self.subscriber.record(&self.id, values)
     }
 
-    fn new(id: Id, subscriber: &Dispatch, meta: &'a Metadata<'a>) -> Self {
+    fn new(id: Id, subscriber: &Dispatch) -> Self {
         Inner {
             id,
             subscriber: subscriber.clone(),
-            meta,
         }
     }
 }
 
-impl<'a> cmp::PartialEq for Inner<'a> {
+impl cmp::PartialEq for Inner {
     fn eq(&self, other: &Self) -> bool {
         self.id == other.id
     }
 }
 
-impl<'a> Hash for Inner<'a> {
+impl Hash for Inner {
     fn hash<H: Hasher>(&self, state: &mut H) {
         self.id.hash(state);
     }
 }
 
-impl<'a> Drop for Inner<'a> {
+impl Drop for Inner {
     fn drop(&mut self) {
         self.subscriber.drop_span(self.id.clone());
     }
 }
 
-impl<'a> Clone for Inner<'a> {
+impl Clone for Inner {
     fn clone(&self) -> Self {
         Inner {
             id: self.subscriber.clone_span(&self.id),
             subscriber: self.subscriber.clone(),
-            meta: self.meta,
         }
     }
 }
 
 // ===== impl Entered =====
 
-impl<'a> Entered<'a> {
+impl Entered {
     /// Exit the `Entered` guard, returning an `Inner` handle that may be used
     /// to re-enter the span.
-    fn exit(self) -> Inner<'a> {
+    fn exit(self) -> Inner {
         self.inner.subscriber.exit(&self.inner.id);
         self.inner
     }
 }
+
+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(());
+        self.0.record(&mut |k: &field::Field, v: &fmt::Debug| {
+            res = write!(f, "{}={:?} ", k, v);
+        });
+        res
+    }
+}
+
+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(());
+        self.0.record(&mut |k: &field::Field, v: &fmt::Debug| {
+            res = write!(f, "{}={:?} ", k, v);
+        });
+        res
+    }
+}
diff --git a/tokio-trace/test-log-support/Cargo.toml b/tokio-trace/test-log-support/Cargo.toml
new file mode 100644
index 00000000..f749e635
--- /dev/null
+++ b/tokio-trace/test-log-support/Cargo.toml
@@ -0,0 +1,10 @@
+[workspace]
+
+[package]
+name = "test_log_support"
+version = "0.1.0"
+publish = false
+
+[dependencies]
+tokio-trace = { path = "..", features = ["log"] }
+log = { version = "0.4", features = ["std"] }
diff --git a/tokio-trace/test-log-support/tests/log_no_trace.rs b/tokio-trace/test-log-support/tests/log_no_trace.rs
new file mode 100644
index 00000000..25eba9f0
--- /dev/null
+++ b/tokio-trace/test-log-support/tests/log_no_trace.rs
@@ -0,0 +1,71 @@
+extern crate log;
+#[macro_use]
+extern crate tokio_trace;
+
+use log::{LevelFilter, Log, Metadata, Record};
+use std::sync::{Arc, Mutex};
+
+struct State {
+    last_log: Mutex<Option<String>>,
+}
+
+struct Logger(Arc<State>);
+
+impl Log for Logger {
+    fn enabled(&self, _: &Metadata) -> bool {
+        true
+    }
+
+    fn log(&self, record: &Record) {
+        let line = format!("{}", record.args());
+        println!("{:<5} {} {}", record.level(), record.target(), line);
+        *self.0.last_log.lock().unwrap() = Some(line);
+    }
+
+    fn flush(&self) {}
+}
+
+#[test]
+fn test_always_log() {
+    let me = Arc::new(State {
+        last_log: Mutex::new(None),
+    });
+    let a = me.clone();
+    log::set_boxed_logger(Box::new(Logger(me))).unwrap();
+    log::set_max_level(LevelFilter::Trace);
+
+    error!(foo = 5);
+    last(&a, "foo=5");
+    warn!("hello {};", "world");
+    last(&a, "hello world;");
+    info!(message = "hello world;", thingy = 42, other_thingy = 666);
+    last(&a, "hello world; thingy=42 other_thingy=666");
+
+    let mut foo = span!("foo");
+    last(&a, "foo;");
+    foo.enter(|| {
+        last(&a, "-> foo");
+
+        trace!({foo = 3, bar = 4}, "hello {};", "san francisco");
+        last(&a, "hello san francisco; foo=3 bar=4");
+    });
+    last(&a, "<- foo");
+
+    span!("foo", bar = 3, baz = false);
+    last(&a, "foo; bar=3 baz=false");
+
+    let mut span = span!("foo", bar, baz);
+    span.record("bar", &3);
+    last(&a, "foo; bar=3");
+    span.record("baz", &"a string");
+    last(&a, "foo; baz=\"a string\"");
+}
+
+fn last(state: &State, expected: &str) {
+    let mut lock = state.last_log.lock().unwrap();
+    {
+        let last = lock.as_ref().map(|s| s.as_str().trim());
+        assert_eq!(last, Some(expected));
+    }
+    *lock = None;
+}
diff --git a/tokio-trace/tests/event.rs b/tokio-trace/tests/event.rs
index e5fcd818..b2c39cdb 100644
--- a/tokio-trace/tests/event.rs
+++ b/tokio-trace/tests/event.rs
@@ -4,11 +4,7 @@ mod support;
 
 use self::support::*;
 
-use tokio_trace::{
-    field::{debug, display},
-    subscriber::with_default,
-    Level,
-};
+use tokio_trace::{field::display, subscriber::with_default, Level};
 
 #[test]
 fn event_without_message() {
@@ -133,7 +129,11 @@ fn borrowed_field() {
 }
 
 #[test]
+// If emitting log instrumentation, this gets moved anyway, breaking the test.
+#[cfg(not(feature = "log"))]
 fn move_field_out_of_struct() {
+    use tokio_trace::field::debug;
+
     #[derive(Debug)]
     struct Position {
         x: f32,
diff --git a/tokio-trace/tests/span.rs b/tokio-trace/tests/span.rs
index 1c1bc003..3ff0d95f 100644
--- a/tokio-trace/tests/span.rs
+++ b/tokio-trace/tests/span.rs
@@ -4,11 +4,7 @@ mod support;
 
 use self::support::*;
 use std::thread;
-use tokio_trace::{
-    field::{debug, display},
-    subscriber::with_default,
-    Level, Span,
-};
+use tokio_trace::{field::display, subscriber::with_default, Level, Span};
 
 #[test]
 fn handles_to_the_same_span_are_equal() {
@@ -307,7 +303,11 @@ fn borrowed_field() {
 }
 
 #[test]
+// If emitting log instrumentation, this gets moved anyway, breaking the test.
+#[cfg(not(feature = "log"))]
 fn move_field_out_of_struct() {
+    use tokio_trace::field::debug;
+
     #[derive(Debug)]
     struct Position {
         x: f32,
diff --git a/tokio-trace/tokio-trace-core/src/field.rs b/tokio-trace/tokio-trace-core/src/field.rs
index 84b01543..0d85e671 100644
--- a/tokio-trace/tokio-trace-core/src/field.rs
+++ b/tokio-trace/tokio-trace-core/src/field.rs
@@ -222,11 +222,11 @@ pub trait Value: ::sealed::Sealed {
 }
 
 /// A `Value` which serializes as a string using `fmt::Display`.
-#[derive(Debug, Clone)]
+#[derive(Clone)]
 pub struct DisplayValue<T: fmt::Display>(T);
 
 /// A `Value` which serializes as a string using `fmt::Debug`.
-#[derive(Debug, Clone)]
+#[derive(Clone)]
 pub struct DebugValue<T: fmt::Debug>(T);
 
 /// Wraps a type implementing `fmt::Display` as a `Value` that can be
@@ -360,6 +360,12 @@ where
     }
 }
 
+impl<T: fmt::Display> fmt::Debug for DisplayValue<T> {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        write!(f, "{}", self.0)
+    }
+}
+
 // ===== impl DebugValue =====
 
 impl<T: fmt::Debug> ::sealed::Sealed for DebugValue<T> {}
@@ -373,6 +379,12 @@ where
     }
 }
 
+impl<T: fmt::Debug> fmt::Debug for DebugValue<T> {
+    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        write!(f, "{:?}", self.0)
+    }
+}
+
 // ===== impl Field =====
 
 impl Field {