From fa7b2c89670b43023c4ed0249a42d3139a459b5d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Fri, 17 Jun 2022 15:08:27 +0200 Subject: [PATCH] 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 https://github.com/tokio-rs/tracing/pull/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 | 47 +++++++- tracing-log/src/interest_cache.rs | 2 +- ...nterests_cache_before_global_subscriber.rs | 101 ++++++++++++++++++ 3 files changed, 144 insertions(+), 6 deletions(-) create mode 100644 tracing-log/tests/init_interests_cache_before_global_subscriber.rs diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index 741744437c..d5596b1e20 100644 --- a/tracing-core/src/dispatcher.rs +++ b/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, }; @@ -695,14 +697,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()), + }, + } } } diff --git a/tracing-log/src/interest_cache.rs b/tracing-log/src/interest_cache.rs index aabf9ebaf7..5ad9c1362e 100644 --- a/tracing-log/src/interest_cache.rs +++ b/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> = Lazy::new(Mutex::new); + static LOCK: Lazy> = Lazy::new(|| Mutex::new(())); match LOCK.lock() { Ok(guard) => guard, diff --git a/tracing-log/tests/init_interests_cache_before_global_subscriber.rs b/tracing-log/tests/init_interests_cache_before_global_subscriber.rs new file mode 100644 index 0000000000..ad2ad5b3c3 --- /dev/null +++ b/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)>, +} + +#[derive(PartialEq, Debug)] +struct OwnedMetadata { + name: String, + target: String, + level: Level, + module_path: Option, + file: Option, + line: Option, +} + +struct TestSubscriber(Arc); + +impl Subscriber for TestSubscriber { + fn enabled(&self, meta: &Metadata<'_>) -> bool { + dbg!(meta); + true + } + + fn max_level_hint(&self) -> Option { + 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) { + 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()); +}