Skip to content

Commit

Permalink
tracing: fix macros "use of moved value" with log (#1823)
Browse files Browse the repository at this point in the history
## Motivation

Fixes: #196, #1739

Previously, the `field` token trees would be substituted into the log
macro invocation and the `ValueSet`, potentially meaning they are
executed more than once. 


## Solution

This changes the `event!` macro (and all the upstream macros like `info!`),
so that it only uses each field once when the log feature is enabled. It
does this by generating the log using the `ValueSet` meaning the token
trees are only substituted once.
  • Loading branch information
Skepfyr authored Jan 29, 2022
1 parent dacf855 commit 8bbd5d6
Show file tree
Hide file tree
Showing 5 changed files with 184 additions and 165 deletions.
4 changes: 2 additions & 2 deletions tracing-core/src/field.rs
Original file line number Diff line number Diff line change
Expand Up @@ -747,8 +747,8 @@ impl<'a> ValueSet<'a> {

/// Visits all the fields in this `ValueSet` with the provided [visitor].
///
/// [visitor]: super::Visit
pub(crate) fn record(&self, visitor: &mut dyn Visit) {
/// [visitor]: Visit
pub fn record(&self, visitor: &mut dyn Visit) {
let my_callsite = self.callsite();
for (field, value) in self.values {
if field.callsite() != my_callsite {
Expand Down
34 changes: 33 additions & 1 deletion tracing/benches/global_subscriber.rs
Original file line number Diff line number Diff line change
@@ -1,3 +1,5 @@
use std::fmt::Write;

use criterion::{black_box, criterion_group, criterion_main, Criterion};
use tracing::Level;

Expand Down Expand Up @@ -43,11 +45,39 @@ impl tracing::Collect for EnabledCollector {
}
}

const NOP_LOGGER: NopLogger = NopLogger;

struct NopLogger;

impl log::Log for NopLogger {
fn enabled(&self, _metadata: &log::Metadata) -> bool {
true
}

fn log(&self, record: &log::Record) {
if self.enabled(record.metadata()) {
let mut this = self;
let _ = write!(this, "{}", record.args());
}
}

fn flush(&self) {}
}

impl Write for &NopLogger {
fn write_str(&mut self, s: &str) -> std::fmt::Result {
black_box(s);
Ok(())
}
}

const N_SPANS: usize = 100;

fn criterion_benchmark(c: &mut Criterion) {
let mut c = c.benchmark_group("global/collector");
let _ = tracing::collect::set_global_default(EnabledCollector);
let _ = log::set_logger(&NOP_LOGGER);
log::set_max_level(log::LevelFilter::Trace);
c.bench_function("span_no_fields", |b| b.iter(|| span!(Level::TRACE, "span")));

c.bench_function("event", |b| {
Expand Down Expand Up @@ -87,8 +117,10 @@ fn criterion_benchmark(c: &mut Criterion) {
}

fn bench_dispatch(c: &mut Criterion) {
let _ = tracing::collect::set_global_default(EnabledCollector);
let mut group = c.benchmark_group("global/dispatch");
let _ = tracing::collect::set_global_default(EnabledCollector);
let _ = log::set_logger(&NOP_LOGGER);
log::set_max_level(log::LevelFilter::Trace);
group.bench_function("get_ref", |b| {
b.iter(|| {
tracing::dispatch::get_default(|current| {
Expand Down
62 changes: 62 additions & 0 deletions tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1112,6 +1112,68 @@ pub mod __macro_support {
.finish()
}
}

#[cfg(feature = "log")]
use tracing_core::field::{Field, ValueSet, Visit};

/// Utility to format [`ValueSet`] for logging, used by macro-generated code.
///
/// /!\ WARNING: This is *not* a stable API! /!\
/// This type, and all code contained in the `__macro_support` module, is
/// a *private* API of `tracing`. It is exposed publicly because it is used
/// by the `tracing` macros, but it is not part of the stable versioned API.
/// Breaking changes to this module may occur in small-numbered versions
/// without warning.
#[cfg(feature = "log")]
#[allow(missing_debug_implementations)]
pub struct LogValueSet<'a>(pub &'a ValueSet<'a>);

#[cfg(feature = "log")]
impl<'a> fmt::Display for LogValueSet<'a> {
fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
let mut visit = LogVisitor {
f,
is_first: true,
result: Ok(()),
};
self.0.record(&mut visit);
visit.result
}
}

#[cfg(feature = "log")]
struct LogVisitor<'a, 'b> {
f: &'a mut fmt::Formatter<'b>,
is_first: bool,
result: fmt::Result,
}

#[cfg(feature = "log")]
impl Visit for LogVisitor<'_, '_> {
fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
let res = if self.is_first {
self.is_first = false;
if field.name() == "message" {
write!(self.f, "{:?}", value)
} else {
write!(self.f, "{}={:?}", field.name(), value)
}
} else {
write!(self.f, " {}={:?}", field.name(), value)
};
if let Err(err) = res {
self.result = self.result.and(Err(err));
}
}

fn record_str(&mut self, field: &Field, value: &str) {
if field.name() == "message" {
self.record_debug(field, &format_args!("{}", value))
} else {
self.record_debug(field, &value)
}
}
}
}

mod sealed {
Expand Down
Loading

0 comments on commit 8bbd5d6

Please sign in to comment.