From f94ccf2c98b24e72bb4993d64dc81839b4c92e36 Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 12 Sep 2019 14:27:52 -0700
Subject: [PATCH 1/6] tracing: don't emit log events if a subscriber has been
 set

Motivation:

Currently, when `tracing`'s `log` feature is enabled, all spans and
events will emit `log` records as well as `tracing` events. When
`tracing-log` is being used to convert `log` records into `tracing`
events, this results in duplicate events being observed: those emitted
by the event macros directly, and those generated from the log records
they emit by `tracing-log`.

Solution:

In `tracing-core` 0.1.6, we added an internal API for checking if a
`tracing` subscriber has ever been set. In addition to the performance
optimizations which this was initially intended to enable, this also
gives us a way for `tracing` macros in libraries to check if a
downstream application that depends on those libraries is actually using
`tracing`. If `tracing` is in use and a subscriber has been set, the
macros can be disabled.

In a handful of cases, users _may_ wish to collect `log` records and
`tracing` events totally separately. For example, `log` records might be
output to the console while `tracing` is used to generate metrics or for
performance profiling. In this case, there is an additional `log-always`
feature flag which applications can set to enable all of `tracing`'s log
records regardless of whether a subscriber is in use. In most cases
where the `log` feature is currently used (libraries that want to emit
both `tracing` and `log` diagnostics for their users), this will not be
necessary.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 tracing/Cargo.toml    |  2 +-
 tracing/src/lib.rs    | 12 ++++++----
 tracing/src/macros.rs | 52 ++++++++++++++++++++++++++++++-------------
 tracing/src/span.rs   | 38 ++++++++++++++++++-------------
 4 files changed, 68 insertions(+), 36 deletions(-)

diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml
index fc66b65e22..3e24192b90 100644
--- a/tracing/Cargo.toml
+++ b/tracing/Cargo.toml
@@ -28,7 +28,7 @@ keywords = ["logging", "tracing", "metrics", "async"]
 edition = "2018"
 
 [dependencies]
-tracing-core = { version = "0.1.5", path = "../tracing-core", default-features = false }
+tracing-core = { version = "0.1.6", default-features = false }
 log = { version = "0.4", optional = true }
 tracing-attributes = "0.1.2"
 cfg-if = "0.1.9"
diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs
index 3bcab355d8..1872a32b32 100644
--- a/tracing/src/lib.rs
+++ b/tracing/src/lib.rs
@@ -577,10 +577,16 @@
 //!
 //! * A set of features controlling the [static verbosity level].
 //! * `log`: causes trace instrumentation points to emit [`log`] records as well
-//!   as trace events. This is intended for use in libraries whose users may be
-//!   using either `tracing` or `log`.
+//!   as trace events, if a default `tracing` subscriber has not been set. This
+//!   is intended for use in libraries whose users may be using either `tracing`
+//!   or `log`.
 //!   **Note:** `log` support will not work when `tracing` is renamed in `Cargo.toml`,
 //!   due to oddities in macro expansion.
+//! * `log-always`: Emit `log` records from all `tracing` spans and events, even
+//!   a `tracing` subscriber has been set. This should be set only by
+//!   applications which intend to collect traces and logs separately; if an
+//!   adapter is used to convert `log` records into `tracing` events, this will
+//!   cause duplicate events to occur.
 //! * `std`: Depend on the Rust standard library (enabled by default).
 //!
 //!   `no_std` users may disable this feature with `default-features = false`:
@@ -669,8 +675,6 @@ pub mod subscriber;
 pub mod __macro_support {
     pub use crate::stdlib::sync::atomic::{AtomicUsize, Ordering};
 
-    pub const LOG_ENABLED: bool = cfg!(feature = "log");
-
     #[cfg(feature = "std")]
     pub use crate::stdlib::sync::Once;
 
diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs
index 8dcd649cc3..d2d1f77706 100644
--- a/tracing/src/macros.rs
+++ b/tracing/src/macros.rs
@@ -2291,23 +2291,43 @@ macro_rules! __mk_format_args {
 #[macro_export]
 macro_rules! __tracing_log {
     (target: $target:expr, $level:expr, $($field:tt)+ ) => {
-        use $crate::log;
-        let level = $crate::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(file!()))
-                    .module_path(Some(module_path!()))
-                    .line(Some(line!()))
-                    .metadata(log_meta)
-                    .args($crate::__mk_format_args!($($field)+))
-                    .build());
+        if $crate::__tracing_should_log!() {
+            use $crate::log;
+            let level = $crate::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(file!()))
+                        .module_path(Some(module_path!()))
+                        .line(Some(line!()))
+                        .metadata(log_meta)
+                        .args($crate::__mk_format_args!($($field)+))
+                        .build());
+                }
             }
         }
     };
 }
+
+#[cfg(all(feature = "log", not(feature = "log-always")))]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __tracing_should_log {
+    () => {
+       !$crate::dispatcher::has_been_set()
+    }
+}
+
+#[cfg(all(feature = "log", feature = "log-always"))]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! __tracing_should_log {
+    () => {
+        true
+    }
+}
\ No newline at end of file
diff --git a/tracing/src/span.rs b/tracing/src/span.rs
index 1883bbb4a9..7eb7bc707f 100644
--- a/tracing/src/span.rs
+++ b/tracing/src/span.rs
@@ -386,6 +386,17 @@ pub struct Entered<'a> {
 
 // ===== impl Span =====
 
+macro_rules! if_log {
+    ($e:expr;) => { if_log!{ $e }};
+    ($if_log:expr) => {
+        #[cfg(feature = "log")] {
+            if __tracing_should_log!() {
+                $if_log
+            }
+        }
+    }
+}
+
 impl Span {
     /// Constructs a new `Span` with the given [metadata] and set of
     /// [field values].
@@ -505,8 +516,9 @@ impl Span {
             meta: Some(meta),
         };
 
-        #[cfg(feature = "log")]
-        span.log(format_args!("++ {}; {}", meta.name(), FmtAttrs(attrs)));
+        if_log! {
+            span.log(format_args!("++ {}; {}", meta.name(), FmtAttrs(attrs)));
+        }
 
         span
     }
@@ -588,8 +600,7 @@ impl Span {
             inner.subscriber.enter(&inner.id);
         }
 
-        #[cfg(feature = "log")]
-        {
+        if_log! {
             if let Some(ref meta) = self.meta {
                 self.log(format_args!("-> {}", meta.name()));
             }
@@ -690,8 +701,7 @@ impl Span {
             inner.record(&record);
         }
 
-        #[cfg(feature = "log")]
-        {
+        if_log! {
             if let Some(ref meta) = self.meta {
                 self.log(format_args!("{}; {}", meta.name(), FmtValues(&record)));
             }
@@ -839,13 +849,12 @@ impl Drop for Span {
             ref subscriber,
         }) = self.inner
         {
-            if subscriber.try_close(id.clone()) {
-                #[cfg(feature = "log")]
-                {
-                    if let Some(ref meta) = self.meta {
-                        self.log(format_args!("-- {}", meta.name()));
-                    }
-                }
+            subscriber.try_close(id.clone());
+        }
+
+        if_log! {
+            if let Some(ref meta) = self.meta {
+                self.log(format_args!("-- {}", meta.name()));
             }
         }
     }
@@ -924,8 +933,7 @@ impl<'a> Drop for Entered<'a> {
             inner.subscriber.exit(&inner.id);
         }
 
-        #[cfg(feature = "log")]
-        {
+        if_log! {
             if let Some(ref meta) = self.span.meta {
                 self.span.log(format_args!("<- {}", meta.name()));
             }

From 5dd613eefc7ba1509ddcc0bd9b78b6b8d0da06c4 Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 12 Sep 2019 14:39:03 -0700
Subject: [PATCH 2/6] rustfmt

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 tracing/src/macros.rs | 8 ++++----
 tracing/src/span.rs   | 9 ++++++---
 2 files changed, 10 insertions(+), 7 deletions(-)

diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs
index d2d1f77706..0e3fefece9 100644
--- a/tracing/src/macros.rs
+++ b/tracing/src/macros.rs
@@ -2319,8 +2319,8 @@ macro_rules! __tracing_log {
 #[macro_export]
 macro_rules! __tracing_should_log {
     () => {
-       !$crate::dispatcher::has_been_set()
-    }
+        !$crate::dispatcher::has_been_set()
+    };
 }
 
 #[cfg(all(feature = "log", feature = "log-always"))]
@@ -2329,5 +2329,5 @@ macro_rules! __tracing_should_log {
 macro_rules! __tracing_should_log {
     () => {
         true
-    }
-}
\ No newline at end of file
+    };
+}
diff --git a/tracing/src/span.rs b/tracing/src/span.rs
index 7eb7bc707f..aa7bc04216 100644
--- a/tracing/src/span.rs
+++ b/tracing/src/span.rs
@@ -387,14 +387,17 @@ pub struct Entered<'a> {
 // ===== impl Span =====
 
 macro_rules! if_log {
-    ($e:expr;) => { if_log!{ $e }};
+    ($e:expr;) => {
+        if_log! { $e }
+    };
     ($if_log:expr) => {
-        #[cfg(feature = "log")] {
+        #[cfg(feature = "log")]
+        {
             if __tracing_should_log!() {
                 $if_log
             }
         }
-    }
+    };
 }
 
 impl Span {

From 2baaee3073b5964948a4c77d6a014582444c918e Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 12 Sep 2019 15:41:01 -0700
Subject: [PATCH 3/6] unify macros

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 tracing/src/macros.rs | 67 ++++++++++++++++++++++++++++++++++---------
 tracing/src/span.rs   | 34 +++++++---------------
 2 files changed, 63 insertions(+), 38 deletions(-)

diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs
index 0e3fefece9..81f95efc53 100644
--- a/tracing/src/macros.rs
+++ b/tracing/src/macros.rs
@@ -2141,9 +2141,13 @@ macro_rules! __tracing_mk_span {
                     &$crate::valueset!(meta.fields(), $($fields)*),
                 )
             } else {
-                let span = $crate::Span::new_disabled(meta);
-                span.record_all(&$crate::valueset!(meta.fields(), $($fields)*));
-                span
+                $crate::if_log_enabled! {{
+                    let span = $crate::Span::new_disabled(meta);
+                    span.record_all(&$crate::valueset!(meta.fields(), $($fields)*));
+                    span
+                } else {
+                    $crate::Span::none()
+                }}
             }
         }
     };
@@ -2165,9 +2169,13 @@ macro_rules! __tracing_mk_span {
                     &$crate::valueset!(meta.fields(), $($fields)*),
                 )
             } else {
-                let span = $crate::Span::new_disabled(meta);
-                span.record_all(&$crate::valueset!(meta.fields(), $($fields)*));
-                span
+                $crate::if_log_enabled! {{
+                    let span = $crate::Span::new_disabled(meta);
+                    span.record_all(&$crate::valueset!(meta.fields(), $($fields)*));
+                    span
+                } else {
+                    $crate::Span::none()
+                }}
             }
         }
     };
@@ -2291,7 +2299,7 @@ macro_rules! __mk_format_args {
 #[macro_export]
 macro_rules! __tracing_log {
     (target: $target:expr, $level:expr, $($field:tt)+ ) => {
-        if $crate::__tracing_should_log!() {
+        $crate::if_log_enabled! {{
             use $crate::log;
             let level = $crate::level_to_log!(&$level);
             if level <= log::STATIC_MAX_LEVEL {
@@ -2310,24 +2318,55 @@ macro_rules! __tracing_log {
                         .build());
                 }
             }
-        }
+        }}
+    };
+}
+
+#[cfg(all(not(feature = "log"), not(feature = "log-always")))]
+#[doc(hidden)]
+#[macro_export]
+macro_rules! if_log_enabled {
+    ($e:expr;) => {
+        $crate::if_log_enabled! {{ $e }}
+    };
+    ($if_log:block) => {
+        $crate::if_log_enabled! { $if_log else {} }
+    };
+    ($if_log:block else $else_block:block) => {
+        $else_block
     };
 }
 
 #[cfg(all(feature = "log", not(feature = "log-always")))]
 #[doc(hidden)]
 #[macro_export]
-macro_rules! __tracing_should_log {
-    () => {
-        !$crate::dispatcher::has_been_set()
+macro_rules! if_log_enabled {
+    ($e:expr;) => {
+        $crate::if_log_enabled! {{ $e }}
+    };
+    ($if_log:block) => {
+        $crate::if_log_enabled! { $if_log else {} }
+    };
+    ($if_log:block else $else_block:block) => {
+        if !$crate::dispatcher::has_been_set() {
+            $if_log
+        } else {
+            $else_block
+        }
     };
 }
 
 #[cfg(all(feature = "log", feature = "log-always"))]
 #[doc(hidden)]
 #[macro_export]
-macro_rules! __tracing_should_log {
-    () => {
-        true
+macro_rules! if_log_enabled {
+    ($e:expr;) => {
+        $crate::if_log_enabled! {{ $e }}
+    };
+    ($if_log:block) => {
+        $crate::if_log_enabled! { $if_log else {} }
+    };
+    ($if_log:block else $else_block:block) => {
+        $if_log
     };
 }
diff --git a/tracing/src/span.rs b/tracing/src/span.rs
index aa7bc04216..23cf4e35ed 100644
--- a/tracing/src/span.rs
+++ b/tracing/src/span.rs
@@ -386,20 +386,6 @@ pub struct Entered<'a> {
 
 // ===== impl Span =====
 
-macro_rules! if_log {
-    ($e:expr;) => {
-        if_log! { $e }
-    };
-    ($if_log:expr) => {
-        #[cfg(feature = "log")]
-        {
-            if __tracing_should_log!() {
-                $if_log
-            }
-        }
-    };
-}
-
 impl Span {
     /// Constructs a new `Span` with the given [metadata] and set of
     /// [field values].
@@ -519,9 +505,9 @@ impl Span {
             meta: Some(meta),
         };
 
-        if_log! {
+        if_log_enabled! {{
             span.log(format_args!("++ {}; {}", meta.name(), FmtAttrs(attrs)));
-        }
+        }}
 
         span
     }
@@ -603,11 +589,11 @@ impl Span {
             inner.subscriber.enter(&inner.id);
         }
 
-        if_log! {
+        if_log_enabled! {{
             if let Some(ref meta) = self.meta {
                 self.log(format_args!("-> {}", meta.name()));
             }
-        }
+        }}
 
         Entered { span: self }
     }
@@ -704,11 +690,11 @@ impl Span {
             inner.record(&record);
         }
 
-        if_log! {
+        if_log_enabled! {{
             if let Some(ref meta) = self.meta {
                 self.log(format_args!("{}; {}", meta.name(), FmtValues(&record)));
             }
-        }
+        }}
 
         self
     }
@@ -855,11 +841,11 @@ impl Drop for Span {
             subscriber.try_close(id.clone());
         }
 
-        if_log! {
+        if_log_enabled!({
             if let Some(ref meta) = self.meta {
                 self.log(format_args!("-- {}", meta.name()));
             }
-        }
+        })
     }
 }
 
@@ -936,11 +922,11 @@ impl<'a> Drop for Entered<'a> {
             inner.subscriber.exit(&inner.id);
         }
 
-        if_log! {
+        if_log_enabled! {{
             if let Some(ref meta) = self.span.meta {
                 self.span.log(format_args!("<- {}", meta.name()));
             }
-        }
+        }}
     }
 }
 

From 94cc069115b00b9f84a6d516dafee69d8db6cf0d Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 12 Sep 2019 15:51:42 -0700
Subject: [PATCH 4/6] Update tracing/src/macros.rs

Co-Authored-By: Sam Scott <sam@osohq.com>
---
 tracing/src/macros.rs | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs
index 81f95efc53..806d8cb687 100644
--- a/tracing/src/macros.rs
+++ b/tracing/src/macros.rs
@@ -2322,7 +2322,7 @@ macro_rules! __tracing_log {
     };
 }
 
-#[cfg(all(not(feature = "log"), not(feature = "log-always")))]
+#[cfg(not(feature = "log"))]
 #[doc(hidden)]
 #[macro_export]
 macro_rules! if_log_enabled {

From df761f7c9dafda437da3ee4d6fb9d3505ee93304 Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 12 Sep 2019 16:36:21 -0700
Subject: [PATCH 5/6] add missing feature flags

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 tracing/Cargo.toml | 1 +
 1 file changed, 1 insertion(+)

diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml
index 3e24192b90..fb53881d18 100644
--- a/tracing/Cargo.toml
+++ b/tracing/Cargo.toml
@@ -59,6 +59,7 @@ release_max_level_trace = []
 async-await = []
 
 std = ["tracing-core/std"]
+log-always = ["log"]
 
 [[bench]]
 name = "subscriber"

From 91afa83959fd78e2ee697d0615312e3273e36df6 Mon Sep 17 00:00:00 2001
From: Eliza Weisman <eliza@buoyant.io>
Date: Thu, 12 Sep 2019 16:36:34 -0700
Subject: [PATCH 6/6] fix tests

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
---
 tracing/test-log-support/Cargo.toml            |  2 +-
 tracing/test-log-support/tests/log_no_trace.rs | 14 ++++++--------
 2 files changed, 7 insertions(+), 9 deletions(-)

diff --git a/tracing/test-log-support/Cargo.toml b/tracing/test-log-support/Cargo.toml
index 54f0e22630..68675928c3 100644
--- a/tracing/test-log-support/Cargo.toml
+++ b/tracing/test-log-support/Cargo.toml
@@ -7,5 +7,5 @@ publish = false
 edition = "2018"
 
 [dependencies]
-tracing = { path = "..", features = ["log"] }
+tracing = { path = "..", features = ["log", "log-always"] }
 log = { version = "0.4", features = ["std"] }
diff --git a/tracing/test-log-support/tests/log_no_trace.rs b/tracing/test-log-support/tests/log_no_trace.rs
index 86c54db429..787e78ef82 100644
--- a/tracing/test-log-support/tests/log_no_trace.rs
+++ b/tracing/test-log-support/tests/log_no_trace.rs
@@ -29,14 +29,12 @@ fn test_always_log() {
     });
     test.assert_logged("<- foo");
 
-    span!(Level::TRACE, "foo", bar = 3, baz = false);
+    drop(foo);
+    test.assert_logged("-- foo");
+
+
+    let foo = span!(Level::TRACE, "foo", bar = 3, baz = false);
     test.assert_logged("foo; bar=3 baz=false");
 
-    // TODO(#1138): determine a new syntax for uninitialized span fields, and
-    // re-enable these.
-    // let span = span!(Level::TRACE, "foo", bar = _, baz = _);
-    // span.record("bar", &3);
-    // test.assert_logged("foo; bar=3");
-    // span.record("baz", &"a string");
-    // test.assert_logged("foo; baz=\"a string\"");
+    drop(foo);
 }