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 <[email protected]>
This commit is contained in:
Eliza Weisman
2019-03-26 16:43:05 -07:00
committed by GitHub
parent ceca2a3cd6
commit d8177f81ac
12 changed files with 372 additions and 106 deletions
+1
View File
@@ -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:
+1
View File
@@ -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
+6 -5
View File
@@ -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" }
@@ -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),
}
}
+4
View File
@@ -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)]
+122 -30
View File
@@ -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)
};
}
+132 -58
View File
@@ -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<'a> fmt::Debug for Span {
impl Hash for Span {
fn hash<H: Hasher>(&self, hasher: &mut H) {
self.inner.hash(hasher);
}
}
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);
}
.finish()
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);
}
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: &Record) {
self.subscriber.record(&self.id, values)
}
fn record(&mut self, values: &field::ValueSet) {
if values.callsite() == self.meta.callsite() {
self.subscriber.record(&self.id, &Record::new(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
}
}
+10
View File
@@ -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"] }
@@ -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;
}
+5 -5
View File
@@ -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,
+5 -5
View File
@@ -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,
+14 -2
View File
@@ -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 {