Skip to content

Commit

Permalink
log: forward LogTracer::enabled to the subscriber (#1254)
Browse files Browse the repository at this point in the history 
PRs #1247, #1248, and #1251 improve `tracing`'s behavior for the `log`
crate's `log_enabled!` macro when a max-level hint is set. However, this
*doesn't* get us correct behavior when a particular target is not
enabled but the level is permitted by the max-level filter. In this
case, `log_enabled!` will still return `true` when using `LogTracer`,
because it doesn't currently call `Subscriber::enabled` on the current
subscriber in its `Log::enabled` method. Instead, `Subscriber::enabled`
is only checked when actually recording an event.

This means that when a target is disabled by a target-specific filter
but it's below the max level, `log::log_enabled!` will erroneously
return `true`. This also means that skipping disabled `log` records in
similar cases will construct the `log::Record` struct even when it isn't
necessary to do so.

This PR improves this behavior by adding a call to `Subscriber::enabled`
in `LogTracer`'s `Log::enabled` method. I've also added to the existing
tests for filtering `log` records to ensure that we also handle the
`log_enabled!` macro correctly.

While I was here, I noticed that the `Log::log` method for `LogTracer`
is somewhat inefficient --- it gets the current dispatcher *three*
times, and checks `enabled` twice. Currently, we check if the event
would be enabled, and then call the`format_trace` function, which *also*
checks if the event is enabled, and then dispatches it if it is. This is
not great. :/ I fixed this by moving the check-and-dispatch inside of a
single `dispatcher::get_default` block, and removing the duplicate
check.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
  • Loading branch information
@hawkw
hawkw committed Feb 19, 2021
1 parent 8a9995e commit a295604
Show file tree
Hide file tree
Showing 4 changed files with 172 additions and 109 deletions.
161 changes: 103 additions & 58 deletions tracing-log/src/lib.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -177,35 +177,43 @@ pub use log;

/// Format a log record as a trace event in the current span.
pub fn format_trace(record: &log::Record<'_>) -> io::Result<()> {
let filter_meta = record.as_trace();
if !dispatcher::get_default(|dispatch| dispatch.enabled(&filter_meta)) {
return Ok(());
};

let (cs, keys) = loglevel_to_cs(record.level());

let log_module = record.module_path();
let log_file = record.file();
let log_line = record.line();

let module = log_module.as_ref().map(|s| s as &dyn field::Value);
let file = log_file.as_ref().map(|s| s as &dyn field::Value);
let line = log_line.as_ref().map(|s| s as &dyn field::Value);

let meta = cs.metadata();
Event::dispatch(
&meta,
&meta.fields().value_set(&[
(&keys.message, Some(record.args() as &dyn field::Value)),
(&keys.target, Some(&record.target())),
(&keys.module, module),
(&keys.file, file),
(&keys.line, line),
]),
);
dispatch_record(record);
Ok(())
}

// XXX(eliza): this is factored out so that we don't have to deal with the pub
// function `format_trace`'s `Result` return type...maybe we should get rid of
// that in 0.2...
pub(crate) fn dispatch_record(record: &log::Record<'_>) {
dispatcher::get_default(|dispatch| {
let filter_meta = record.as_trace();
if !dispatch.enabled(&filter_meta) {
return;
}

let (_, keys, meta) = loglevel_to_cs(record.level());

let log_module = record.module_path();
let log_file = record.file();
let log_line = record.line();

let module = log_module.as_ref().map(|s| s as &dyn field::Value);
let file = log_file.as_ref().map(|s| s as &dyn field::Value);
let line = log_line.as_ref().map(|s| s as &dyn field::Value);

dispatch.event(&Event::new(
meta,
&meta.fields().value_set(&[
(&keys.message, Some(record.args() as &dyn field::Value)),
(&keys.target, Some(&record.target())),
(&keys.module, module),
(&keys.file, file),
(&keys.line, line),
]),
));
});
}

/// Trait implemented for `tracing` types that can be converted to a `log`
/// equivalent.
pub trait AsLog: crate::sealed::Sealed {
Expand Down Expand Up @@ -235,6 +243,24 @@ impl<'a> AsLog for Metadata<'a> {
.build()
}
}
impl<'a> crate::sealed::Sealed for log::Metadata<'a> {}

impl<'a> AsTrace for log::Metadata<'a> {
type Trace = Metadata<'a>;
fn as_trace(&self) -> Self::Trace {
let cs_id = identify_callsite!(loglevel_to_cs(self.level()).0);
Metadata::new(
"log record",
self.target(),
self.level().as_trace(),
None,
None,
None,
field::FieldSet::new(FIELD_NAMES, cs_id),
Kind::EVENT,
)
}
}

struct Fields {
message: field::Field,
Expand Down Expand Up @@ -271,62 +297,81 @@ impl Fields {
}

macro_rules! log_cs {
($level:expr) => {{
struct Callsite;
static CALLSITE: Callsite = Callsite;
static META: Metadata<'static> = Metadata::new(
($level:expr, $cs:ident, $meta:ident, $ty:ident) => {
struct $ty;
static $cs: $ty = $ty;
static $meta: Metadata<'static> = Metadata::new(
"log event",
"log",
$level,
None,
None,
None,
field::FieldSet::new(FIELD_NAMES, identify_callsite!(&CALLSITE)),
field::FieldSet::new(FIELD_NAMES, identify_callsite!(&$cs)),
Kind::EVENT,
);

impl callsite::Callsite for Callsite {
impl callsite::Callsite for $ty {
fn set_interest(&self, _: subscriber::Interest) {}
fn metadata(&self) -> &'static Metadata<'static> {
&META
&$meta
}
}

&CALLSITE
}};
};
}

static TRACE_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::TRACE);
static DEBUG_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::DEBUG);
static INFO_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::INFO);
static WARN_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::WARN);
static ERROR_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::ERROR);
log_cs!(
tracing_core::Level::TRACE,
TRACE_CS,
TRACE_META,
TraceCallsite
);
log_cs!(
tracing_core::Level::DEBUG,
DEBUG_CS,
DEBUG_META,
DebugCallsite
);
log_cs!(tracing_core::Level::INFO, INFO_CS, INFO_META, InfoCallsite);
log_cs!(tracing_core::Level::WARN, WARN_CS, WARN_META, WarnCallsite);
log_cs!(
tracing_core::Level::ERROR,
ERROR_CS,
ERROR_META,
ErrorCallsite
);

lazy_static! {
static ref TRACE_FIELDS: Fields = Fields::new(TRACE_CS);
static ref DEBUG_FIELDS: Fields = Fields::new(DEBUG_CS);
static ref INFO_FIELDS: Fields = Fields::new(INFO_CS);
static ref WARN_FIELDS: Fields = Fields::new(WARN_CS);
static ref ERROR_FIELDS: Fields = Fields::new(ERROR_CS);
static ref TRACE_FIELDS: Fields = Fields::new(&TRACE_CS);
static ref DEBUG_FIELDS: Fields = Fields::new(&DEBUG_CS);
static ref INFO_FIELDS: Fields = Fields::new(&INFO_CS);
static ref WARN_FIELDS: Fields = Fields::new(&WARN_CS);
static ref ERROR_FIELDS: Fields = Fields::new(&ERROR_CS);
}

fn level_to_cs(level: Level) -> (&'static dyn Callsite, &'static Fields) {
match level {
Level::TRACE => (TRACE_CS, &*TRACE_FIELDS),
Level::DEBUG => (DEBUG_CS, &*DEBUG_FIELDS),
Level::INFO => (INFO_CS, &*INFO_FIELDS),
Level::WARN => (WARN_CS, &*WARN_FIELDS),
Level::ERROR => (ERROR_CS, &*ERROR_FIELDS),
Level::TRACE => (&TRACE_CS, &*TRACE_FIELDS),
Level::DEBUG => (&DEBUG_CS, &*DEBUG_FIELDS),
Level::INFO => (&INFO_CS, &*INFO_FIELDS),
Level::WARN => (&WARN_CS, &*WARN_FIELDS),
Level::ERROR => (&ERROR_CS, &*ERROR_FIELDS),
}
}

fn loglevel_to_cs(level: log::Level) -> (&'static dyn Callsite, &'static Fields) {
fn loglevel_to_cs(
level: log::Level,
) -> (
&'static dyn Callsite,
&'static Fields,
&'static Metadata<'static>,
) {
match level {
log::Level::Trace => (TRACE_CS, &*TRACE_FIELDS),
log::Level::Debug => (DEBUG_CS, &*DEBUG_FIELDS),
log::Level::Info => (INFO_CS, &*INFO_FIELDS),
log::Level::Warn => (WARN_CS, &*WARN_FIELDS),
log::Level::Error => (ERROR_CS, &*ERROR_FIELDS),
log::Level::Trace => (&TRACE_CS, &*TRACE_FIELDS, &TRACE_META),
log::Level::Debug => (&DEBUG_CS, &*DEBUG_FIELDS, &DEBUG_META),
log::Level::Info => (&INFO_CS, &*INFO_FIELDS, &INFO_META),
log::Level::Warn => (&WARN_CS, &*WARN_FIELDS, &WARN_META),
log::Level::Error => (&ERROR_CS, &*ERROR_FIELDS, &ERROR_META),
}
}

Expand Down Expand Up @@ -541,7 +586,7 @@ mod test {
.build();

let meta = record.as_trace();
let (cs, _keys) = loglevel_to_cs(record.level());
let (cs, _keys, _) = loglevel_to_cs(record.level());
let cs_meta = cs.metadata();
assert_eq!(
meta.callsite(),
Expand Down
49 changes: 18 additions & 31 deletions tracing-log/src/log_tracer.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,14 +19,12 @@
//! such as when a crate emits both `tracing` diagnostics _and_ log records by
//! default.
//!
//! [`LogTracer`]: struct.LogTracer.html
//! [`log`]: https://docs.rs/log/0.4.8/log/
//! [logger interface]: https://docs.rs/log/0.4.8/log/trait.Log.html
//! [`init`]: struct.LogTracer.html#method.init.html
//! [`init_with_filter`]: struct.LogTracer.html#method.init_with_filter.html
//! [builder]: struct.LogTracer.html#method.builder
//! [ignore]: struct.Builder.html#method.ignore_crate
use crate::{format_trace, AsTrace};
//! [logger interface]: log::Log
//! [`init`]: LogTracer.html#method.init
//! [`init_with_filter`]: LogTracer.html#method.init_with_filter
//! [builder]: LogTracer::builder()
//! [ignore]: Builder::ignore_crate()
use crate::AsTrace;
pub use log::SetLoggerError;
use tracing_core::dispatcher;

Expand Down Expand Up @@ -169,34 +167,23 @@ impl log::Log for LogTracer {

// Okay, it wasn't disabled by the max level — do we have any specific
// modules to ignore?
if self.ignore_crates.is_empty() {
// If we don't, just enable it.
return true;
if !self.ignore_crates.is_empty() {
// If we are ignoring certain module paths, ensure that the metadata
// does not start with one of those paths.
let target = metadata.target();
for ignored in &self.ignore_crates[..] {
if target.starts_with(ignored) {
return false;
}
}
}

// If we are ignoring certain module paths, ensure that the metadata
// does not start with one of those paths.
let target = metadata.target();
!self
.ignore_crates
.iter()
.any(|ignored| target.starts_with(ignored))
// Finally, check if the current `tracing` dispatcher cares about this.
dispatcher::get_default(|dispatch| dispatch.enabled(&metadata.as_trace()))
}

fn log(&self, record: &log::Record<'_>) {
let enabled = dispatcher::get_default(|dispatch| {
// TODO: can we cache this for each log record, so we can get
// similar to the callsite cache?
dispatch.enabled(&record.as_trace())
});

if enabled {
// TODO: if the record is enabled, we'll get the current dispatcher
// twice --- once to check if enabled, and again to dispatch the event.
// If we could construct events without dispatching them, we could
// re-use the dispatcher reference...
format_trace(record).unwrap();
}
crate::dispatch_record(record);
}

fn flush(&self) {}
Expand Down
12 changes: 8 additions & 4 deletions tracing-log/tests/log_tracer.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,8 @@ struct OwnedMetadata {
struct TestSubscriber(Arc<State>);

impl Subscriber for TestSubscriber {
fn enabled(&self, _: &Metadata<'_>) -> bool {
fn enabled(&self, meta: &Metadata<'_>) -> bool {
dbg!(meta);
true
}

Expand All @@ -34,6 +35,7 @@ impl Subscriber for TestSubscriber {
fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {}

fn event(&self, event: &Event<'_>) {
dbg!(event);
*self.0.last_normalized_metadata.lock().unwrap() = (
event.is_log(),
event.normalized_metadata().map(|normalized| OwnedMetadata {
Expand Down Expand Up @@ -107,7 +109,9 @@ fn normalized_metadata() {
}

fn last(state: &State, should_be_log: bool, expected: Option<OwnedMetadata>) {
let metadata = state.last_normalized_metadata.lock().unwrap();
assert_eq!(metadata.0, should_be_log);
assert_eq!(metadata.1, expected);
let lock = state.last_normalized_metadata.lock().unwrap();
let (is_log, metadata) = &*lock;
dbg!(&metadata);
assert_eq!(dbg!(*is_log), should_be_log);
assert_eq!(metadata.as_ref(), expected.as_ref());
}
59 changes: 43 additions & 16 deletions tracing-subscriber/tests/filter_log.rs
View file
Original file line number Diff line number Diff line change
@@ -1,21 +1,36 @@
mod support;
use self::support::*;
use tracing::{self, subscriber::with_default, Level};
use tracing::{self, Level};
use tracing_subscriber::{filter::EnvFilter, prelude::*};

mod my_module {
pub(crate) fn test_records() {
log::trace!("this should be disabled");
log::info!("this shouldn't be");
log::debug!("this should be disabled");
log::warn!("this should be enabled");
log::warn!(target: "something else", "this shouldn't be enabled");
log::error!("this should be enabled too");
}

pub(crate) fn test_log_enabled() {
assert!(
log::log_enabled!(log::Level::Info),
"info should be enabled inside `my_module`"
);
assert!(
!log::log_enabled!(log::Level::Debug),
"debug should not be enabled inside `my_module`"
);
assert!(
log::log_enabled!(log::Level::Warn),
"warn should be enabled inside `my_module`"
);
}
}

#[test]
fn log_is_enabled() {
mod my_module {
pub(crate) fn do_test() {
log::trace!("this should be disabled");
log::info!("this shouldn't be");
log::debug!("this should be disabled");
log::warn!("this should be enabled");
log::warn!(target: "something else", "this shouldn't be enabled");
log::error!("this should be enabled too");
}
}
tracing_log::LogTracer::init().expect("logger should be unset");
let filter: EnvFilter = "filter_log::my_module=info"
.parse()
.expect("filter should parse");
Expand All @@ -25,11 +40,23 @@ fn log_is_enabled() {
.event(event::mock().at_level(Level::ERROR))
.done()
.run_with_handle();
let subscriber = subscriber.with(filter);

with_default(subscriber, || {
my_module::do_test();
});
// Note: we have to set the global default in order to set the `log` max
// level, which can only be set once.
subscriber.with(filter).init();

my_module::test_records();
log::info!("this is disabled");

my_module::test_log_enabled();
assert!(
!log::log_enabled!(log::Level::Info),
"info should not be enabled outside `my_module`"
);
assert!(
!log::log_enabled!(log::Level::Warn),
"warn should not be enabled outside `my_module`"
);

finished.assert_finished();
}

0 comments on commit a295604

Please sign in to comment.