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 <eliza@buoyant.io>

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();
+    dispatch_record(record);
-    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),
-        ]),
-    );
     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) => {{
+    ($level:expr, $cs:ident, $meta:ident, $ty:ident) => {
-        struct Callsite;
+        struct $ty;
-        static CALLSITE: Callsite = Callsite;
+        static $cs: $ty = $ty;
-        static META: Metadata<'static> = Metadata::new(
+        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);
+log_cs!(
-static DEBUG_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::DEBUG);
+    tracing_core::Level::TRACE,
-static INFO_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::INFO);
+    TRACE_CS,
-static WARN_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::WARN);
+    TRACE_META,
-static ERROR_CS: &'static dyn Callsite = log_cs!(tracing_core::Level::ERROR);
+    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 TRACE_FIELDS: Fields = Fields::new(&TRACE_CS);
-    static ref DEBUG_FIELDS: Fields = Fields::new(DEBUG_CS);
+    static ref DEBUG_FIELDS: Fields = Fields::new(&DEBUG_CS);
-    static ref INFO_FIELDS: Fields = Fields::new(INFO_CS);
+    static ref INFO_FIELDS: Fields = Fields::new(&INFO_CS);
-    static ref WARN_FIELDS: Fields = Fields::new(WARN_CS);
+    static ref WARN_FIELDS: Fields = Fields::new(&WARN_CS);
-    static ref ERROR_FIELDS: Fields = Fields::new(ERROR_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::TRACE => (&TRACE_CS, &*TRACE_FIELDS),
-        Level::DEBUG => (DEBUG_CS, &*DEBUG_FIELDS),
+        Level::DEBUG => (&DEBUG_CS, &*DEBUG_FIELDS),
-        Level::INFO => (INFO_CS, &*INFO_FIELDS),
+        Level::INFO => (&INFO_CS, &*INFO_FIELDS),
-        Level::WARN => (WARN_CS, &*WARN_FIELDS),
+        Level::WARN => (&WARN_CS, &*WARN_FIELDS),
-        Level::ERROR => (ERROR_CS, &*ERROR_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::Trace => (&TRACE_CS, &*TRACE_FIELDS, &TRACE_META),
-        log::Level::Debug => (DEBUG_CS, &*DEBUG_FIELDS),
+        log::Level::Debug => (&DEBUG_CS, &*DEBUG_FIELDS, &DEBUG_META),
-        log::Level::Info => (INFO_CS, &*INFO_FIELDS),
+        log::Level::Info => (&INFO_CS, &*INFO_FIELDS, &INFO_META),
-        log::Level::Warn => (WARN_CS, &*WARN_FIELDS),
+        log::Level::Warn => (&WARN_CS, &*WARN_FIELDS, &WARN_META),
-        log::Level::Error => (ERROR_CS, &*ERROR_FIELDS),
+        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(),

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
+//! [logger interface]: log::Log
-//! [`log`]: https://docs.rs/log/0.4.8/log/
+//! [`init`]: LogTracer.html#method.init
-//! [logger interface]: https://docs.rs/log/0.4.8/log/trait.Log.html
+//! [`init_with_filter`]: LogTracer.html#method.init_with_filter
-//! [`init`]: struct.LogTracer.html#method.init.html
+//! [builder]: LogTracer::builder()
-//! [`init_with_filter`]: struct.LogTracer.html#method.init_with_filter.html
+//! [ignore]: Builder::ignore_crate()
-//! [builder]: struct.LogTracer.html#method.builder
+use crate::AsTrace;
-//! [ignore]: struct.Builder.html#method.ignore_crate
-use crate::{format_trace, 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 !self.ignore_crates.is_empty() {
-            // If we don't, just enable it.
+            // If we are ignoring certain module paths, ensure that the metadata
-            return true;
+            // 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
+        // Finally, check if the current `tracing` dispatcher cares about this.
-        // does not start with one of those paths.
+        dispatcher::get_default(|dispatch| dispatch.enabled(&metadata.as_trace()))
-        let target = metadata.target();
-        !self
-            .ignore_crates
-            .iter()
-            .any(|ignored| target.starts_with(ignored))
     }
 
     fn log(&self, record: &log::Record<'_>) {
-        let enabled = dispatcher::get_default(|dispatch| {
+        crate::dispatch_record(record);
-            // 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();
-        }
     }
 
     fn flush(&self) {}

tracing-log/tests/log_tracer.rs

@@ -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
     }
 
@@ -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<OwnedMetadata>) {
-    let metadata = state.last_normalized_metadata.lock().unwrap();
+    let lock = state.last_normalized_metadata.lock().unwrap();
-    assert_eq!(metadata.0, should_be_log);
+    let (is_log, metadata) = &*lock;
-    assert_eq!(metadata.1, expected);
+    dbg!(&metadata);
+    assert_eq!(dbg!(*is_log), should_be_log);
+    assert_eq!(metadata.as_ref(), expected.as_ref());
 }

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, || {
+    // Note: we have to set the global default in order to set the `log` max
-        my_module::do_test();
+    // 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();
 }