Fix logging with interest cache

When the interest cache is configured as part of initing the `LogTracer` before
the global dispatcher is set, the main thread fails to log. The problem
is that the interests cache registers a dummy callsite. With
tokio-rs#2083 the callsite registration
changed to use `dispatcher::get_default`. This call internally sets the
thread local `default` dispatcher to `Dispatch::none` when there isn't
yet any dispatcher set. This `default` dispatcher isn't overwritten when
setting the global dispatcher. The solution is to not store the
`Dispatch::none` as `default` dispatcher.

tracing-core/src/dispatcher.rs

@@ -123,6 +123,7 @@
 //! currently default `Dispatch`. This is used primarily by `tracing`
 //! instrumentation.
 //!
+
 use crate::{
     callsite, span,
     subscriber::{self, NoSubscriber, Subscriber},
@@ -142,6 +143,7 @@ use crate::stdlib::{
 use crate::stdlib::{
     cell::{Cell, RefCell, RefMut},
     error,
+    ops::Deref,
     sync::Weak,
 };
 
@@ -697,14 +699,49 @@ impl State {
 
 // ===== impl Entered =====
 
+/// Return value of [`Entered::current`].
+///
+/// [`Entered::current`]: Entered::current
+#[cfg(feature = "std")]
+enum Current<'a> {
+    /// There is a local default dispatch set or we just set the local
+    /// default to the global dispatch.
+    Default(RefMut<'a, Dispatch>),
+    /// There is no dispatch set, so we use the `none` dispatch.
+    None(Dispatch),
+}
+
+#[cfg(feature = "std")]
+impl<'a> Deref for Current<'a> {
+    type Target = Dispatch;
+
+    fn deref(&self) -> &Self::Target {
+        match self {
+            Self::Default(def) => def,
+            Self::None(none) => none,
+        }
+    }
+}
+
 #[cfg(feature = "std")]
 impl<'a> Entered<'a> {
     #[inline]
-    fn current(&self) -> RefMut<'a, Dispatch> {
-        let default = self.0.default.borrow_mut();
-        RefMut::map(default, |default| {
-            default.get_or_insert_with(|| get_global().cloned().unwrap_or_else(Dispatch::none))
-        })
+    fn current(&self) -> Current<'a> {
+        let mut default = self.0.default.borrow_mut();
+        match *default {
+            Some(_) => Current::Default(RefMut::map(default, |d| {
+                d.as_mut().expect("`default` is `Some(_)`")
+            })),
+            None => match get_global() {
+                Some(global) => {
+                    *default = Some(global.clone());
+                    Current::Default(RefMut::map(default, |d| {
+                        d.as_mut().expect("We just initialized the `Option`")
+                    }))
+                }
+                None => Current::None(Dispatch::none()),
+            },
+        }
     }
 }
 

tracing-log/src/interest_cache.rs

@@ -235,7 +235,7 @@ mod tests {
 
     fn lock_for_test() -> impl Drop {
         // We need to make sure only one test runs at a time.
-        static LOCK: Lazy<Mutex<()>> = Lazy::new(Mutex::new);
+        static LOCK: Lazy<Mutex<()>> = Lazy::new(|| Mutex::new(()));
 
         match LOCK.lock() {
             Ok(guard) => guard,

tracing-log/tests/init_interests_cache_before_global_subscriber.rs

@@ -0,0 +1,101 @@
+#![cfg(feature = "interest-cache")]
+
+use std::sync::{Arc, Mutex};
+use tracing::subscriber::set_global_default;
+use tracing_core::span::{Attributes, Record};
+use tracing_core::{span, Event, Level, LevelFilter, Metadata, Subscriber};
+use tracing_log::{LogTracer, NormalizeEvent};
+
+struct State {
+    last_normalized_metadata: Mutex<(bool, Option<OwnedMetadata>)>,
+}
+
+#[derive(PartialEq, Debug)]
+struct OwnedMetadata {
+    name: String,
+    target: String,
+    level: Level,
+    module_path: Option<String>,
+    file: Option<String>,
+    line: Option<u32>,
+}
+
+struct TestSubscriber(Arc<State>);
+
+impl Subscriber for TestSubscriber {
+    fn enabled(&self, meta: &Metadata<'_>) -> bool {
+        dbg!(meta);
+        true
+    }
+
+    fn max_level_hint(&self) -> Option<LevelFilter> {
+        Some(LevelFilter::from_level(Level::INFO))
+    }
+
+    fn new_span(&self, _span: &Attributes<'_>) -> span::Id {
+        span::Id::from_u64(42)
+    }
+
+    fn record(&self, _span: &span::Id, _values: &Record<'_>) {}
+
+    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 {
+                name: normalized.name().to_string(),
+                target: normalized.target().to_string(),
+                level: *normalized.level(),
+                module_path: normalized.module_path().map(String::from),
+                file: normalized.file().map(String::from),
+                line: normalized.line(),
+            }),
+        )
+    }
+
+    fn enter(&self, _span: &span::Id) {}
+
+    fn exit(&self, _span: &span::Id) {}
+}
+
+#[test]
+fn normalized_metadata() {
+    LogTracer::builder()
+        .with_interest_cache(tracing_log::InterestCacheConfig::default())
+        .init()
+        .unwrap();
+    let me = Arc::new(State {
+        last_normalized_metadata: Mutex::new((false, None)),
+    });
+    let state = me.clone();
+
+    set_global_default(TestSubscriber(me)).unwrap();
+
+    let log = log::Record::builder()
+        .args(format_args!("Error!"))
+        .level(log::Level::Info)
+        .build();
+    log::logger().log(&log);
+    last(
+        &state,
+        true,
+        Some(OwnedMetadata {
+            name: "log event".to_string(),
+            target: "".to_string(),
+            level: Level::INFO,
+            module_path: None,
+            file: None,
+            line: None,
+        }),
+    );
+}
+
+fn last(state: &State, should_be_log: bool, expected: Option<OwnedMetadata>) {
+    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());
+}