diff --git a/tracing-core/src/callsite.rs b/tracing-core/src/callsite.rs index 38ff14a2f0..273fecec4e 100644 --- a/tracing-core/src/callsite.rs +++ b/tracing-core/src/callsite.rs @@ -1,74 +1,23 @@ //! Callsites represent the source locations from which spans or events //! originate. use crate::stdlib::{ + any::TypeId, fmt, hash::{Hash, Hasher}, - sync::Mutex, + ptr, + sync::{ + atomic::{AtomicBool, AtomicPtr, AtomicU8, Ordering}, + Mutex, + }, vec::Vec, }; use crate::{ - dispatcher::{self, Dispatch}, + dispatcher::Dispatch, metadata::{LevelFilter, Metadata}, subscriber::Interest, }; -crate::lazy_static! { - static ref REGISTRY: Mutex = Mutex::new(Registry { - callsites: Vec::new(), - dispatchers: Vec::new(), - }); -} - -struct Registry { - callsites: Vec<&'static dyn Callsite>, - dispatchers: Vec, -} - -impl Registry { - fn rebuild_callsite_interest(&self, callsite: &'static dyn Callsite) { - let meta = callsite.metadata(); - - // Iterate over the subscribers in the registry, and — if they are - // active — register the callsite with them. - let mut interests = self - .dispatchers - .iter() - .filter_map(|registrar| registrar.try_register(meta)); - - // Use the first subscriber's `Interest` as the base value. - let interest = if let Some(interest) = interests.next() { - // Combine all remaining `Interest`s. - interests.fold(interest, Interest::and) - } else { - // If nobody was interested in this thing, just return `never`. - Interest::never() - }; - - callsite.set_interest(interest) - } - - fn rebuild_interest(&mut self) { - let mut max_level = LevelFilter::OFF; - self.dispatchers.retain(|registrar| { - if let Some(dispatch) = registrar.upgrade() { - // If the subscriber did not provide a max level hint, assume - // that it may enable every level. - let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE); - if level_hint > max_level { - max_level = level_hint; - } - true - } else { - false - } - }); - - self.callsites.iter().for_each(|&callsite| { - self.rebuild_callsite_interest(callsite); - }); - LevelFilter::set_max(max_level); - } -} +use self::dispatchers::Dispatchers; /// Trait implemented by callsites. /// @@ -84,6 +33,28 @@ pub trait Callsite: Sync { /// /// [metadata]: super::metadata::Metadata fn metadata(&self) -> &Metadata<'_>; + + /// This method is an *internal implementation detail* of `tracing-core`. It + /// is *not* intended to be called or overridden from downstream code. + /// + /// The `Private` type can only be constructed from within `tracing-core`. + /// Because this method takes a `Private` as an argument, it cannot be + /// called from (safe) code external to `tracing-core`. Because it must + /// *return* a `Private`, the only valid implementation possible outside of + /// `tracing-core` would have to always unconditionally panic. + /// + /// THIS IS BY DESIGN. There is currently no valid reason for code outside + /// of `tracing-core` to override this method. + // TODO(eliza): this could be used to implement a public downcasting API + // for `&dyn Callsite`s in the future. + #[doc(hidden)] + #[inline] + fn private_type_id(&self, _: private::Private<()>) -> private::Private + where + Self: 'static, + { + private::Private(TypeId::of::()) + } } /// Uniquely identifies a [`Callsite`] @@ -104,6 +75,15 @@ pub struct Identifier( pub &'static dyn Callsite, ); +/// A default [`Callsite`] implementation. +#[derive(Debug)] +pub struct DefaultCallsite { + interest: AtomicU8, + registration: AtomicU8, + meta: &'static Metadata<'static>, + next: AtomicPtr, +} + /// Clear and reregister interest on every [`Callsite`] /// /// This function is intended for runtime reconfiguration of filters on traces @@ -124,8 +104,7 @@ pub struct Identifier( /// [`Interest::sometimes()`]: super::subscriber::Interest::sometimes /// [`Subscriber`]: super::subscriber::Subscriber pub fn rebuild_interest_cache() { - let mut registry = REGISTRY.lock().unwrap(); - registry.rebuild_interest(); + CALLSITES.rebuild_interest(DISPATCHERS.rebuilder()); } /// Register a new `Callsite` with the global registry. @@ -133,15 +112,137 @@ pub fn rebuild_interest_cache() { /// This should be called once per callsite after the callsite has been /// constructed. pub fn register(callsite: &'static dyn Callsite) { - let mut registry = REGISTRY.lock().unwrap(); - registry.rebuild_callsite_interest(callsite); - registry.callsites.push(callsite); + rebuild_callsite_interest(callsite, &DISPATCHERS.rebuilder()); + + // Is this a `DefaultCallsite`? If so, use the fancy linked list! + if callsite.private_type_id(private::Private(())).0 == TypeId::of::() { + let callsite = unsafe { + // Safety: the pointer cast is safe because the type id of the + // provided callsite matches that of the target type for the cast + // (`DefaultCallsite`). Because user implementations of `Callsite` + // cannot override `private_type_id`, we can trust that the callsite + // is not lying about its type ID. + &*(callsite as *const dyn Callsite as *const DefaultCallsite) + }; + CALLSITES.push_default(callsite); + return; + } + + CALLSITES.push_dyn(callsite); } -pub(crate) fn register_dispatch(dispatch: &Dispatch) { - let mut registry = REGISTRY.lock().unwrap(); - registry.dispatchers.push(dispatch.registrar()); - registry.rebuild_interest(); +static CALLSITES: Callsites = Callsites { + list_head: AtomicPtr::new(ptr::null_mut()), + has_locked_callsites: AtomicBool::new(false), +}; + +static DISPATCHERS: Dispatchers = Dispatchers::new(); + +crate::lazy_static! { + static ref LOCKED_CALLSITES: Mutex> = Mutex::new(Vec::new()); +} + +struct Callsites { + list_head: AtomicPtr, + has_locked_callsites: AtomicBool, +} + +// === impl DefaultCallsite === + +impl DefaultCallsite { + const UNREGISTERED: u8 = 0; + const REGISTERING: u8 = 1; + const REGISTERED: u8 = 2; + + const INTEREST_NEVER: u8 = 0; + const INTEREST_SOMETIMES: u8 = 1; + const INTEREST_ALWAYS: u8 = 2; + + /// Returns a new `DefaultCallsite` with the specified `Metadata`. + pub const fn new(meta: &'static Metadata<'static>) -> Self { + Self { + interest: AtomicU8::new(0xFF), + meta, + next: AtomicPtr::new(ptr::null_mut()), + registration: AtomicU8::new(Self::UNREGISTERED), + } + } + + /// Registers this callsite with the global callsite registry. + /// + /// If the callsite is already registered, this does nothing. When using + /// [`DefaultCallsite`], this method should be preferred over + /// [`tracing_core::callsite::register`], as it ensures that the callsite is + /// only registered a single time. + /// + /// Other callsite implementations will generally ensure that + /// callsites are not re-registered through another mechanism. + #[inline(never)] + // This only happens once (or if the cached interest value was corrupted). + #[cold] + pub fn register(&'static self) -> Interest { + // Attempt to advance the registration state to `REGISTERING`... + match self.registration.compare_exchange( + Self::UNREGISTERED, + Self::REGISTERING, + Ordering::AcqRel, + Ordering::Acquire, + ) { + Ok(_) => { + // Okay, we advanced the state, try to register the callsite. + rebuild_callsite_interest(self, &DISPATCHERS.rebuilder()); + CALLSITES.push_default(self); + self.registration.store(Self::REGISTERED, Ordering::Release); + } + // Great, the callsite is already registered! Just load its + // previous cached interest. + Err(Self::REGISTERED) => {} + // Someone else is registering... + Err(_state) => { + debug_assert_eq!( + _state, + Self::REGISTERING, + "weird callsite registration state" + ); + // Just hit `enabled` this time. + return Interest::sometimes(); + } + } + + match self.interest.load(Ordering::Relaxed) { + Self::INTEREST_NEVER => Interest::never(), + Self::INTEREST_ALWAYS => Interest::always(), + _ => Interest::sometimes(), + } + } + + /// Returns the callsite's cached `Interest`, or registers it for the + /// first time if it has not yet been registered. + #[inline] + pub fn interest(&'static self) -> Interest { + match self.interest.load(Ordering::Relaxed) { + Self::INTEREST_NEVER => Interest::never(), + Self::INTEREST_SOMETIMES => Interest::sometimes(), + Self::INTEREST_ALWAYS => Interest::always(), + _ => self.register(), + } + } +} + +impl Callsite for DefaultCallsite { + fn set_interest(&self, interest: Interest) { + let interest = match () { + _ if interest.is_never() => Self::INTEREST_NEVER, + _ if interest.is_always() => Self::INTEREST_ALWAYS, + _ => Self::INTEREST_SOMETIMES, + }; + self.interest.store(interest, Ordering::SeqCst); + } + + #[inline(always)] + fn metadata(&self) -> &Metadata<'static> { + self.meta + } } // ===== impl Identifier ===== @@ -171,3 +272,221 @@ impl Hash for Identifier { (self.0 as *const dyn Callsite).hash(state) } } + +// === impl Callsites === + +impl Callsites { + /// Rebuild `Interest`s for all callsites in the registry. + /// + /// This also re-computes the max level hint. + fn rebuild_interest(&self, dispatchers: dispatchers::Rebuilder<'_>) { + let mut max_level = LevelFilter::OFF; + dispatchers.for_each(|dispatch| { + // If the subscriber did not provide a max level hint, assume + // that it may enable every level. + let level_hint = dispatch.max_level_hint().unwrap_or(LevelFilter::TRACE); + if level_hint > max_level { + max_level = level_hint; + } + }); + + self.for_each(|callsite| { + rebuild_callsite_interest(callsite, &dispatchers); + }); + LevelFilter::set_max(max_level); + } + + /// Push a `dyn Callsite` trait object to the callsite registry. + /// + /// This will attempt to lock the callsites vector. + fn push_dyn(&self, callsite: &'static dyn Callsite) { + let mut lock = LOCKED_CALLSITES.lock().unwrap(); + self.has_locked_callsites.store(true, Ordering::Release); + lock.push(callsite); + } + + /// Push a `DefaultCallsite` to the callsite registry. + /// + /// If we know the callsite being pushed is a `DefaultCallsite`, we can push + /// it to the linked list without having to acquire a lock. + fn push_default(&self, callsite: &'static DefaultCallsite) { + let mut head = self.list_head.load(Ordering::Acquire); + + loop { + callsite.next.store(head, Ordering::Release); + + assert_ne!( + callsite as *const _, head, + "Attempted to register a `DefaultCallsite` that already exists! \ + This will cause an infinite loop when attempting to read from the \ + callsite cache. This is likely a bug! You should only need to call \ + `DefaultCallsite::register` once per `DefaultCallsite`." + ); + + match self.list_head.compare_exchange( + head, + callsite as *const _ as *mut _, + Ordering::AcqRel, + Ordering::Acquire, + ) { + Ok(_) => { + break; + } + Err(current) => head = current, + } + } + } + + /// Invokes the provided closure `f` with each callsite in the registry. + fn for_each(&self, mut f: impl FnMut(&'static dyn Callsite)) { + let mut head = self.list_head.load(Ordering::Acquire); + + while let Some(cs) = unsafe { head.as_ref() } { + f(cs); + + head = cs.next.load(Ordering::Acquire); + } + + if self.has_locked_callsites.load(Ordering::Acquire) { + let locked = LOCKED_CALLSITES.lock().unwrap(); + for &cs in locked.iter() { + f(cs); + } + } + } +} + +pub(crate) fn register_dispatch(dispatch: &Dispatch) { + let dispatchers = DISPATCHERS.register_dispatch(dispatch); + CALLSITES.rebuild_interest(dispatchers); +} + +fn rebuild_callsite_interest( + callsite: &'static dyn Callsite, + dispatchers: &dispatchers::Rebuilder<'_>, +) { + let meta = callsite.metadata(); + + let mut interest = None; + dispatchers.for_each(|dispatch| { + let this_interest = dispatch.register_callsite(meta); + interest = match interest.take() { + None => Some(this_interest), + Some(that_interest) => Some(that_interest.and(this_interest)), + } + }); + + let interest = interest.unwrap_or_else(Interest::never); + callsite.set_interest(interest) +} + +mod private { + /// Don't call this function, it's private. + #[allow(missing_debug_implementations)] + pub struct Private(pub(crate) T); +} + +#[cfg(feature = "std")] +mod dispatchers { + use crate::dispatcher; + use std::sync::{ + atomic::{AtomicBool, Ordering}, + RwLock, RwLockReadGuard, RwLockWriteGuard, + }; + + pub(super) struct Dispatchers { + has_just_one: AtomicBool, + } + + crate::lazy_static! { + static ref LOCKED_DISPATCHERS: RwLock> = RwLock::new(Vec::new()); + } + + pub(super) enum Rebuilder<'a> { + JustOne, + Read(RwLockReadGuard<'a, Vec>), + Write(RwLockWriteGuard<'a, Vec>), + } + + impl Dispatchers { + pub(super) const fn new() -> Self { + Self { + has_just_one: AtomicBool::new(true), + } + } + + pub(super) fn rebuilder(&self) -> Rebuilder<'_> { + if self.has_just_one.load(Ordering::SeqCst) { + return Rebuilder::JustOne; + } + Rebuilder::Read(LOCKED_DISPATCHERS.read().unwrap()) + } + + pub(super) fn register_dispatch(&self, dispatch: &dispatcher::Dispatch) -> Rebuilder<'_> { + let mut dispatchers = LOCKED_DISPATCHERS.write().unwrap(); + dispatchers.retain(|d| d.upgrade().is_some()); + dispatchers.push(dispatch.registrar()); + self.has_just_one + .store(dispatchers.len() <= 1, Ordering::SeqCst); + Rebuilder::Write(dispatchers) + } + } + + impl Rebuilder<'_> { + pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { + let iter = match self { + Rebuilder::JustOne => { + dispatcher::get_default(f); + return; + } + Rebuilder::Read(vec) => vec.iter(), + Rebuilder::Write(vec) => vec.iter(), + }; + iter.filter_map(dispatcher::Registrar::upgrade) + .for_each(|dispatch| f(&dispatch)) + } + } +} + +#[cfg(not(feature = "std"))] +mod dispatchers { + use crate::dispatcher; + + pub(super) struct Dispatchers(()); + pub(super) struct Rebuilder<'a>(Option<&'a dispatcher::Dispatch>); + + impl Dispatchers { + pub(super) const fn new() -> Self { + Self(()) + } + + pub(super) fn rebuilder(&self) -> Rebuilder<'_> { + Rebuilder(None) + } + + pub(super) fn register_dispatch<'dispatch>( + &self, + dispatch: &'dispatch dispatcher::Dispatch, + ) -> Rebuilder<'dispatch> { + // nop; on no_std, there can only ever be one dispatcher + Rebuilder(Some(dispatch)) + } + } + + impl Rebuilder<'_> { + #[inline] + pub(super) fn for_each(&self, mut f: impl FnMut(&dispatcher::Dispatch)) { + if let Some(dispatch) = self.0 { + // we are rebuilding the interest cache because a new dispatcher + // is about to be set. on `no_std`, this should only happen + // once, because the new dispatcher will be the global default. + f(dispatch) + } else { + // otherwise, we are rebuilding the cache because the subscriber + // configuration changed, so use the global default. + // on no_std, there can only ever be one dispatcher + dispatcher::get_default(f) + } + } + } +} diff --git a/tracing-core/src/dispatcher.rs b/tracing-core/src/dispatcher.rs index d6b5c6e6a1..741744437c 100644 --- a/tracing-core/src/dispatcher.rs +++ b/tracing-core/src/dispatcher.rs @@ -134,7 +134,7 @@ use crate::stdlib::{ fmt, sync::{ atomic::{AtomicBool, AtomicUsize, Ordering}, - Arc, Weak, + Arc, }, }; @@ -142,6 +142,7 @@ use crate::stdlib::{ use crate::stdlib::{ cell::{Cell, RefCell, RefMut}, error, + sync::Weak, }; /// `Dispatch` trace data to a [`Subscriber`]. @@ -387,6 +388,7 @@ fn get_global() -> Option<&'static Dispatch> { } } +#[cfg(feature = "std")] pub(crate) struct Registrar(Weak); impl Dispatch { @@ -412,6 +414,7 @@ impl Dispatch { me } + #[cfg(feature = "std")] pub(crate) fn registrar(&self) -> Registrar { Registrar(Arc::downgrade(&self.subscriber)) } @@ -651,14 +654,8 @@ where } } +#[cfg(feature = "std")] impl Registrar { - pub(crate) fn try_register( - &self, - metadata: &'static Metadata<'static>, - ) -> Option { - self.0.upgrade().map(|s| s.register_callsite(metadata)) - } - pub(crate) fn upgrade(&self) -> Option { self.0.upgrade().map(|subscriber| Dispatch { subscriber }) } diff --git a/tracing-mock/src/subscriber.rs b/tracing-mock/src/subscriber.rs index 8fbffbb396..17e1a7ed73 100644 --- a/tracing-mock/src/subscriber.rs +++ b/tracing-mock/src/subscriber.rs @@ -198,7 +198,9 @@ where Interest::never() } } + fn max_level_hint(&self) -> Option { + println!("[{}] max_level_hint -> {:?}", self.name, self.max_level); self.max_level } diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml index 4f5e1deccf..558fd3332b 100644 --- a/tracing/Cargo.toml +++ b/tracing/Cargo.toml @@ -28,7 +28,7 @@ edition = "2018" rust-version = "1.49.0" [dependencies] -tracing-core = { path = "../tracing-core", version = "0.1.22", default-features = false } +tracing-core = { path = "../tracing-core", version = "0.1.26", default-features = false } log = { version = "0.4", optional = true } tracing-attributes = { path = "../tracing-attributes", version = "0.1.20", optional = true } cfg-if = "1.0.0" diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index f9c0669cb9..fdd12bd3eb 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -967,13 +967,8 @@ pub mod subscriber; #[doc(hidden)] pub mod __macro_support { pub use crate::callsite::Callsite; - use crate::stdlib::{ - fmt, - sync::atomic::{AtomicUsize, Ordering}, - }; use crate::{subscriber::Interest, Metadata}; pub use core::concat; - use tracing_core::Once; /// Callsite implementation used by macro-generated code. /// @@ -983,138 +978,70 @@ pub mod __macro_support { /// by the `tracing` macros, but it is not part of the stable versioned API. /// Breaking changes to this module may occur in small-numbered versions /// without warning. - pub struct MacroCallsite { - interest: AtomicUsize, - meta: &'static Metadata<'static>, - registration: Once, - } - - impl MacroCallsite { - /// Returns a new `MacroCallsite` with the specified `Metadata`. - /// - /// /!\ WARNING: This is *not* a stable API! /!\ - /// This method, and all code contained in the `__macro_support` module, is - /// a *private* API of `tracing`. It is exposed publicly because it is used - /// by the `tracing` macros, but it is not part of the stable versioned API. - /// Breaking changes to this module may occur in small-numbered versions - /// without warning. - pub const fn new(meta: &'static Metadata<'static>) -> Self { - Self { - interest: AtomicUsize::new(0xDEAD), - meta, - registration: Once::new(), - } - } - - /// Registers this callsite with the global callsite registry. - /// - /// If the callsite is already registered, this does nothing. - /// - /// /!\ WARNING: This is *not* a stable API! /!\ - /// This method, and all code contained in the `__macro_support` module, is - /// a *private* API of `tracing`. It is exposed publicly because it is used - /// by the `tracing` macros, but it is not part of the stable versioned API. - /// Breaking changes to this module may occur in small-numbered versions - /// without warning. - #[inline(never)] - // This only happens once (or if the cached interest value was corrupted). - #[cold] - pub fn register(&'static self) -> Interest { - self.registration - .call_once(|| crate::callsite::register(self)); - match self.interest.load(Ordering::Relaxed) { - 0 => Interest::never(), - 2 => Interest::always(), - _ => Interest::sometimes(), - } - } - - /// Returns the callsite's cached Interest, or registers it for the - /// first time if it has not yet been registered. - /// - /// /!\ WARNING: This is *not* a stable API! /!\ - /// This method, and all code contained in the `__macro_support` module, is - /// a *private* API of `tracing`. It is exposed publicly because it is used - /// by the `tracing` macros, but it is not part of the stable versioned API. - /// Breaking changes to this module may occur in small-numbered versions - /// without warning. - #[inline] - pub fn interest(&'static self) -> Interest { - match self.interest.load(Ordering::Relaxed) { - 0 => Interest::never(), - 1 => Interest::sometimes(), - 2 => Interest::always(), - _ => self.register(), - } - } - - pub fn is_enabled(&self, interest: Interest) -> bool { - interest.is_always() - || crate::dispatcher::get_default(|default| default.enabled(self.meta)) - } - - #[inline] - #[cfg(feature = "log")] - pub fn disabled_span(&self) -> crate::Span { - crate::Span::new_disabled(self.meta) - } - - #[inline] - #[cfg(not(feature = "log"))] - pub fn disabled_span(&self) -> crate::Span { - crate::Span::none() - } + pub use tracing_core::callsite::DefaultCallsite as MacroCallsite; - #[cfg(feature = "log")] - pub fn log( - &self, - logger: &'static dyn log::Log, - log_meta: log::Metadata<'_>, - values: &tracing_core::field::ValueSet<'_>, - ) { - let meta = self.metadata(); - logger.log( - &crate::log::Record::builder() - .file(meta.file()) - .module_path(meta.module_path()) - .line(meta.line()) - .metadata(log_meta) - .args(format_args!( - "{}", - crate::log::LogValueSet { - values, - is_first: true - } - )) - .build(), - ); - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, and all code contained in the `__macro_support` module, is + /// a *private* API of `tracing`. It is exposed publicly because it is used + /// by the `tracing` macros, but it is not part of the stable versioned API. + /// Breaking changes to this module may occur in small-numbered versions + /// without warning. + pub fn __is_enabled(meta: &Metadata<'static>, interest: Interest) -> bool { + interest.is_always() || crate::dispatcher::get_default(|default| default.enabled(meta)) } - impl Callsite for MacroCallsite { - fn set_interest(&self, interest: Interest) { - let interest = match () { - _ if interest.is_never() => 0, - _ if interest.is_always() => 2, - _ => 1, - }; - self.interest.store(interest, Ordering::SeqCst); - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, and all code contained in the `__macro_support` module, is + /// a *private* API of `tracing`. It is exposed publicly because it is used + /// by the `tracing` macros, but it is not part of the stable versioned API. + /// Breaking changes to this module may occur in small-numbered versions + /// without warning. + #[inline] + #[cfg(feature = "log")] + pub fn __disabled_span(meta: &'static Metadata<'static>) -> crate::Span { + crate::Span::new_disabled(meta) + } - #[inline(always)] - fn metadata(&self) -> &Metadata<'static> { - self.meta - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, and all code contained in the `__macro_support` module, is + /// a *private* API of `tracing`. It is exposed publicly because it is used + /// by the `tracing` macros, but it is not part of the stable versioned API. + /// Breaking changes to this module may occur in small-numbered versions + /// without warning. + #[inline] + #[cfg(not(feature = "log"))] + pub fn __disabled_span(_: &'static Metadata<'static>) -> crate::Span { + crate::Span::none() } - impl fmt::Debug for MacroCallsite { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - f.debug_struct("MacroCallsite") - .field("interest", &self.interest) - .field("meta", &self.meta) - .field("registration", &self.registration) - .finish() - } + /// /!\ WARNING: This is *not* a stable API! /!\ + /// This function, and all code contained in the `__macro_support` module, is + /// a *private* API of `tracing`. It is exposed publicly because it is used + /// by the `tracing` macros, but it is not part of the stable versioned API. + /// Breaking changes to this module may occur in small-numbered versions + /// without warning. + #[cfg(feature = "log")] + pub fn __tracing_log( + meta: &Metadata<'static>, + logger: &'static dyn log::Log, + log_meta: log::Metadata<'_>, + values: &tracing_core::field::ValueSet<'_>, + ) { + logger.log( + &crate::log::Record::builder() + .file(meta.file()) + .module_path(meta.module_path()) + .line(meta.line()) + .metadata(log_meta) + .args(format_args!( + "{}", + crate::log::LogValueSet { + values, + is_first: true + } + )) + .build(), + ); } } diff --git a/tracing/src/macros.rs b/tracing/src/macros.rs index 825c0d8689..bca42933b3 100644 --- a/tracing/src/macros.rs +++ b/tracing/src/macros.rs @@ -24,7 +24,7 @@ macro_rules! span { (target: $target:expr, parent: $parent:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { { use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $name, kind: $crate::metadata::Kind::SPAN, target: $target, @@ -34,7 +34,7 @@ macro_rules! span { let mut interest = $crate::subscriber::Interest::never(); if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() } - && CALLSITE.is_enabled(interest) + && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) { let meta = CALLSITE.metadata(); // span with explicit parent @@ -44,7 +44,7 @@ macro_rules! span { &$crate::valueset!(meta.fields(), $($fields)*), ) } else { - let span = CALLSITE.disabled_span(); + let span = $crate::__macro_support::__disabled_span(CALLSITE.metadata()); $crate::if_log_enabled! { $lvl, { span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); }}; @@ -55,7 +55,7 @@ macro_rules! span { (target: $target:expr, $lvl:expr, $name:expr, $($fields:tt)*) => { { use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $name, kind: $crate::metadata::Kind::SPAN, target: $target, @@ -65,7 +65,7 @@ macro_rules! span { let mut interest = $crate::subscriber::Interest::never(); if $crate::level_enabled!($lvl) && { interest = CALLSITE.interest(); !interest.is_never() } - && CALLSITE.is_enabled(interest) + && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) { let meta = CALLSITE.metadata(); // span with contextual parent @@ -74,7 +74,7 @@ macro_rules! span { &$crate::valueset!(meta.fields(), $($fields)*), ) } else { - let span = CALLSITE.disabled_span(); + let span = $crate::__macro_support::__disabled_span(CALLSITE.metadata()); $crate::if_log_enabled! { $lvl, { span.record_all(&$crate::valueset!(CALLSITE.metadata().fields(), $($fields)*)); }}; @@ -584,7 +584,7 @@ macro_rules! error_span { macro_rules! event { (target: $target:expr, parent: $parent:expr, $lvl:expr, { $($fields:tt)* } )=> ({ use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $crate::__macro_support::concat!( "event ", file!(), @@ -599,7 +599,7 @@ macro_rules! event { let enabled = $crate::level_enabled!($lvl) && { let interest = CALLSITE.interest(); - !interest.is_never() && CALLSITE.is_enabled(interest) + !interest.is_never() && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) }; if enabled { (|value_set: $crate::field::ValueSet| { @@ -641,7 +641,7 @@ macro_rules! event { ); (target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $crate::__macro_support::concat!( "event ", file!(), @@ -655,7 +655,7 @@ macro_rules! event { }; let enabled = $crate::level_enabled!($lvl) && { let interest = CALLSITE.interest(); - !interest.is_never() && CALLSITE.is_enabled(interest) + !interest.is_never() && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) }; if enabled { (|value_set: $crate::field::ValueSet| { @@ -965,7 +965,7 @@ macro_rules! enabled { (kind: $kind:expr, target: $target:expr, $lvl:expr, { $($fields:tt)* } )=> ({ if $crate::level_enabled!($lvl) { use $crate::__macro_support::Callsite as _; - static CALLSITE: $crate::__macro_support::MacroCallsite = $crate::callsite2! { + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite2! { name: $crate::__macro_support::concat!( "enabled ", file!(), @@ -978,7 +978,7 @@ macro_rules! enabled { fields: $($fields)* }; let interest = CALLSITE.interest(); - if !interest.is_never() && CALLSITE.is_enabled(interest) { + if !interest.is_never() && $crate::__macro_support::__is_enabled(CALLSITE.metadata(), interest) { let meta = CALLSITE.metadata(); $crate::dispatcher::get_default(|current| current.enabled(meta)) } else { @@ -2096,7 +2096,6 @@ macro_rules! callsite { level: $lvl:expr, fields: $($fields:tt)* ) => {{ - use $crate::__macro_support::MacroCallsite; static META: $crate::Metadata<'static> = { $crate::metadata! { name: $name, @@ -2107,7 +2106,7 @@ macro_rules! callsite { kind: $kind, } }; - static CALLSITE: MacroCallsite = MacroCallsite::new(&META); + static CALLSITE: $crate::callsite::DefaultCallsite = $crate::callsite::DefaultCallsite::new(&META); CALLSITE.register(); &CALLSITE }}; @@ -2147,7 +2146,6 @@ macro_rules! callsite2 { level: $lvl:expr, fields: $($fields:tt)* ) => {{ - use $crate::__macro_support::MacroCallsite; static META: $crate::Metadata<'static> = { $crate::metadata! { name: $name, @@ -2158,7 +2156,7 @@ macro_rules! callsite2 { kind: $kind, } }; - MacroCallsite::new(&META) + $crate::callsite::DefaultCallsite::new(&META) }}; } @@ -2428,13 +2426,14 @@ macro_rules! __tracing_log { use $crate::log; let level = $crate::level_to_log!($level); if level <= log::max_level() { + let meta = $callsite.metadata(); let log_meta = log::Metadata::builder() .level(level) - .target(CALLSITE.metadata().target()) + .target(meta.target()) .build(); let logger = log::logger(); if logger.enabled(&log_meta) { - $callsite.log(logger, log_meta, $value_set) + $crate::__macro_support::__tracing_log(meta, logger, log_meta, $value_set) } } }} diff --git a/tracing/tests/register_callsite_deadlock.rs b/tracing/tests/register_callsite_deadlock.rs new file mode 100644 index 0000000000..e4c116c75f --- /dev/null +++ b/tracing/tests/register_callsite_deadlock.rs @@ -0,0 +1,47 @@ +use std::{sync::mpsc, thread, time::Duration}; +use tracing::{ + metadata::Metadata, + span, + subscriber::{self, Interest, Subscriber}, + Event, +}; + +#[test] +fn register_callsite_doesnt_deadlock() { + pub struct EvilSubscriber; + + impl Subscriber for EvilSubscriber { + fn register_callsite(&self, meta: &'static Metadata<'static>) -> Interest { + tracing::info!(?meta, "registered a callsite"); + Interest::always() + } + + fn enabled(&self, _: &Metadata<'_>) -> bool { + true + } + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, _: &Event<'_>) {} + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} + } + + subscriber::set_global_default(EvilSubscriber).unwrap(); + + // spawn a thread, and assert it doesn't hang... + let (tx, didnt_hang) = mpsc::channel(); + let th = thread::spawn(move || { + tracing::info!("hello world!"); + tx.send(()).unwrap(); + }); + + didnt_hang + // Note: 60 seconds is *way* more than enough, but let's be generous in + // case of e.g. slow CI machines. + .recv_timeout(Duration::from_secs(60)) + .expect("the thread must not have hung!"); + th.join().expect("thread should join successfully"); +}