Skip to content

Commit

Permalink
tracing: don't emit log events if a subscriber has been set (#346)
Browse files Browse the repository at this point in the history 
## 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.

Fixes #204

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
@hawkw
hawkw committed Sep 13, 2019
1 parent 86946f6 commit 22a285a
Show file tree
Hide file tree
Showing 6 changed files with 114 additions and 55 deletions.
3 changes: 2 additions & 1 deletion tracing/Cargo.toml
View file
Expand Up @@ -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"
Expand Down Expand Up @@ -59,6 +59,7 @@ release_max_level_trace = []
async-await = []

std = ["tracing-core/std"]
log-always = ["log"]

[[bench]]
name = "subscriber"
Expand Down
12 changes: 8 additions & 4 deletions tracing/src/lib.rs
View file
Expand Up @@ -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`:
Expand Down Expand Up @@ -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;

Expand Down
103 changes: 81 additions & 22 deletions tracing/src/macros.rs
View file
Expand Up @@ -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()
}}
}
}
};
Expand All @@ -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()
}}
}
}
};
Expand Down Expand Up @@ -2291,23 +2299,74 @@ 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());
$crate::if_log_enabled! {{
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(not(feature = "log"))]
#[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! 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! 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
};
}
35 changes: 16 additions & 19 deletions tracing/src/span.rs
View file
Expand Up @@ -505,8 +505,9 @@ impl Span {
meta: Some(meta),
};

#[cfg(feature = "log")]
span.log(format_args!("++ {}; {}", meta.name(), FmtAttrs(attrs)));
if_log_enabled! {{
span.log(format_args!("++ {}; {}", meta.name(), FmtAttrs(attrs)));
}}

span
}
Expand Down Expand Up @@ -588,12 +589,11 @@ impl Span {
inner.subscriber.enter(&inner.id);
}

#[cfg(feature = "log")]
{
if_log_enabled! {{
if let Some(ref meta) = self.meta {
self.log(format_args!("-> {}", meta.name()));
}
}
}}

Entered { span: self }
}
Expand Down Expand Up @@ -690,12 +690,11 @@ impl Span {
inner.record(&record);
}

#[cfg(feature = "log")]
{
if_log_enabled! {{
if let Some(ref meta) = self.meta {
self.log(format_args!("{}; {}", meta.name(), FmtValues(&record)));
}
}
}}

self
}
Expand Down Expand Up @@ -839,15 +838,14 @@ 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_enabled!({
if let Some(ref meta) = self.meta {
self.log(format_args!("-- {}", meta.name()));
}
})
}
}

Expand Down Expand Up @@ -924,12 +922,11 @@ impl<'a> Drop for Entered<'a> {
inner.subscriber.exit(&inner.id);
}

#[cfg(feature = "log")]
{
if_log_enabled! {{
if let Some(ref meta) = self.span.meta {
self.span.log(format_args!("<- {}", meta.name()));
}
}
}}
}
}

Expand Down
2 changes: 1 addition & 1 deletion tracing/test-log-support/Cargo.toml
View file
Expand Up @@ -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"] }
14 changes: 6 additions & 8 deletions tracing/test-log-support/tests/log_no_trace.rs
View file
Expand Up @@ -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);
}

0 comments on commit 22a285a

Please sign in to comment.