From a295604d6cd03055227301efb95d91058d2951af Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 19 Feb 2021 13:25:55 -0800 Subject: [PATCH] log: forward `LogTracer::enabled` to the subscriber (#1254) 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 --- tracing-log/src/lib.rs | 161 ++++++++++++++++--------- tracing-log/src/log_tracer.rs | 49 +++----- tracing-log/tests/log_tracer.rs | 12 +- tracing-subscriber/tests/filter_log.rs | 59 ++++++--- 4 files changed, 172 insertions(+), 109 deletions(-) diff --git a/tracing-log/src/lib.rs b/tracing-log/src/lib.rs index 6ee180280a..7d4e813a98 100644 --- a/tracing-log/src/lib.rs +++ b/tracing-log/src/lib.rs @@ -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 { @@ -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, @@ -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), } } @@ -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(), diff --git a/tracing-log/src/log_tracer.rs b/tracing-log/src/log_tracer.rs index a5a7e55261..e0038bb489 100644 --- a/tracing-log/src/log_tracer.rs +++ b/tracing-log/src/log_tracer.rs @@ -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; @@ -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) {} diff --git a/tracing-log/tests/log_tracer.rs b/tracing-log/tests/log_tracer.rs index c8589e83b1..6945aecc97 100644 --- a/tracing-log/tests/log_tracer.rs +++ b/tracing-log/tests/log_tracer.rs @@ -21,7 +21,8 @@ struct OwnedMetadata { struct TestSubscriber(Arc); impl Subscriber for TestSubscriber { - fn enabled(&self, _: &Metadata<'_>) -> bool { + fn enabled(&self, meta: &Metadata<'_>) -> bool { + dbg!(meta); true } @@ -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 { @@ -107,7 +109,9 @@ fn normalized_metadata() { } fn last(state: &State, should_be_log: bool, expected: Option) { - 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()); } diff --git a/tracing-subscriber/tests/filter_log.rs b/tracing-subscriber/tests/filter_log.rs index 21cbda527a..ec1f2481e9 100644 --- a/tracing-subscriber/tests/filter_log.rs +++ b/tracing-subscriber/tests/filter_log.rs @@ -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"); @@ -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(); }