Fix logging with interest cache

tracing-core/src/dispatcher.rs

@@ -123,8 +123,11 @@
 //! currently default `Dispatch`. This is used primarily by `tracing`
 //! instrumentation.
 //!
+
 use crate::{
-    callsite, span,
+    callsite,
+    lazy::Lazy,
+    span,
     subscriber::{self, NoSubscriber, Subscriber},
     Event, LevelFilter, Metadata,
 };
@@ -133,14 +136,14 @@ use crate::stdlib::{
     any::Any,
     fmt,
     sync::{
-        atomic::{AtomicBool, AtomicUsize, Ordering},
+        atomic::{AtomicBool, AtomicPtr, AtomicUsize, Ordering},
         Arc,
     },
 };
 
 #[cfg(feature = "std")]
 use crate::stdlib::{
-    cell::{Cell, RefCell, RefMut},
+    cell::{Cell, RefCell},
     error,
     sync::Weak,
 };
@@ -168,6 +171,20 @@ const INITIALIZING: usize = 1;
 const INITIALIZED: usize = 2;
 
 static mut GLOBAL_DISPATCH: Option<Dispatch> = None;
+// The global default dispatch that should be used by [`Enter::with_current`]
+// when there is no explicit local dispatch set.
+//
+// By default this is initialized to [`NO_DISPATCH`] and will be set to
+// [`GLOBAL_DISPATCH`] when this is being set.
+static GLOBAL_DEFAULT_DISPATCH: Lazy<AtomicPtr<Dispatch>> =
+    Lazy::new(|| AtomicPtr::new(unsafe { &mut *NO_DISPATCH as *mut _ }));
+
+// This is only `mut` to make it work as default value of [`GLOBAL_DEFAULT_DISPATCH`].
+//
+// We can not use `new` as we don't want this to be registered at the callsites.
+static mut NO_DISPATCH: Lazy<Dispatch> = Lazy::new(|| Dispatch {
+    subscriber: Arc::new(NoSubscriber::default()),
+});
 
 /// The dispatch state of a thread.
 #[cfg(feature = "std")]
@@ -273,6 +290,10 @@ pub fn set_global_default(dispatcher: Dispatch) -> Result<(), SetGlobalDefaultEr
     {
         unsafe {
             GLOBAL_DISPATCH = Some(dispatcher);
+            GLOBAL_DEFAULT_DISPATCH.store(
+                GLOBAL_DISPATCH.as_mut().unwrap() as *mut _,
+                Ordering::SeqCst,
+            );
         }
         GLOBAL_INIT.store(INITIALIZED, Ordering::SeqCst);
         EXISTS.store(true, Ordering::Release);
@@ -334,12 +355,12 @@ where
     CURRENT_STATE
         .try_with(|state| {
             if let Some(entered) = state.enter() {
-                return f(&*entered.current());
+                return entered.with_current(|current| f(current));
             }
 
-            f(&Dispatch::none())
+            f(unsafe { &NO_DISPATCH })
         })
-        .unwrap_or_else(|_| f(&Dispatch::none()))
+        .unwrap_or_else(|_| f(unsafe { &NO_DISPATCH }))
 }
 
 /// Executes a closure with a reference to this thread's current [dispatcher].
@@ -356,7 +377,7 @@ pub fn get_current<T>(f: impl FnOnce(&Dispatch) -> T) -> Option<T> {
     CURRENT_STATE
         .try_with(|state| {
             let entered = state.enter()?;
-            Some(f(&*entered.current()))
+            Some(entered.with_current(f))
         })
         .ok()?
 }
@@ -382,10 +403,11 @@ where
     if let Some(d) = get_global() {
         f(d)
     } else {
-        f(&Dispatch::none())
+        f(unsafe { &NO_DISPATCH })
     }
 }
 
+#[cfg(not(feature = "std"))]
 fn get_global() -> Option<&'static Dispatch> {
     if GLOBAL_INIT.load(Ordering::SeqCst) != INITIALIZED {
         return None;
@@ -406,9 +428,7 @@ impl Dispatch {
     /// Returns a new `Dispatch` that discards events and spans.
     #[inline]
     pub fn none() -> Self {
-        Dispatch {
-            subscriber: Arc::new(NoSubscriber::default()),
-        }
+        unsafe { NO_DISPATCH.clone() }
     }
 
     /// Returns a `Dispatch` that forwards to the given [`Subscriber`].
@@ -711,11 +731,11 @@ impl State {
 #[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 with_current<T>(&self, f: impl FnOnce(&Dispatch) -> T) -> T {
+        match &*self.0.default.borrow() {
+            Some(default) => f(default),
+            None => unsafe { f(&*GLOBAL_DEFAULT_DISPATCH.load(Ordering::SeqCst)) },
+        }
     }
 }
 

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 interests_cache_works() {
+    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());
+}