has_just_one callsite short-path caches Interest::Never when a subscriber-less thread first registers the callsite
Bug: has_just_one callsite short-path caches Interest::Never when a subscriber-less thread first registers the callsite
Version
tracing-core 0.1.36 (v0.1 line; master may differ — the Rebuilder::JustOne arm is present there).
Platform
x86_64 — observed on Windows 11 (MSVC) and Linux.
Description
When exactly one Dispatch is registered process-wide, callsite::rebuild_callsite_interest takes the has_just_one short path. The Rebuilder::JustOne arm evaluates interest via dispatcher::get_default(f) — the thread-local default of whichever thread first registers the callsite — instead of evaluating the one registered Dispatch.
If a thread without any dispatcher/subscriber is the first to touch a static callsite (e.g. an error! macro) while a scoped capture Dispatch (installed via tracing::subscriber::with_default) lives on another thread, Interest::never() is cached into that callsite. A later event emitted on the capture thread is then discarded before reaching the subscriber; the instance-local capture buffer stays empty even though the event macro executed under the scoped default.
Two concurrently registered dispatches avoid the bug, because then the general path over the global dispatch list is taken.
Source references (tracing-core 0.1.36)
dispatcher.rs
472: pub fn new<S>(subscriber: S) -> Self
479: callsite::register_dispatch(&me);
callsite.rs
484: pub(crate) fn register_dispatch(dispatch: &Dispatch) {
485: let dispatchers = DISPATCHERS.register_dispatch(dispatch);
487: CALLSITES.rebuild_interest(dispatchers);
496: let mut interest = None;
497: dispatchers.for_each(|dispatch| {
498: let this_interest = dispatch.register_callsite(meta);
505: let interest = interest.unwrap_or_else(Interest::never);
525: has_just_one: AtomicBool,
544: pub(super) fn rebuilder(&self) -> Rebuilder<'_> {
545: if self.has_just_one.load(Ordering::SeqCst) {
546: return Rebuilder::JustOne;
551: pub(super) fn register_dispatch(&self, dispatch: &dispatcher::Dispatch) -> Rebuilder<'_> {
554: dispatchers.push(dispatch.registrar());
555: self.has_just_one.store(dispatchers.len() <= 1, Ordering::SeqCst);
564: Rebuilder::JustOne => {
565: dispatcher::get_default(f);Deterministic reproduction (observed in our test suite)
- Thread A (no dispatcher at all) executes a static
error!callsite while no dispatch is registered → expected: nothing printed. - Thread B installs a scoped capture subscriber via
tracing::subscriber::with_defaultand emits to the same static callsite. - Flaky: the capture buffer stays empty —
Interest::neverwas cached at step 1 via theJustOne → get_defaultpath (thread A has no default), and the callsite is not rebuilt for thread B's scoped dispatch.
With a second, never-installed Dispatch registered (so has_just_one == false), the suite is 100 % green (20/20 full-suite runs; before: intermittent failures with a correctly emitted event producing an empty capture).
Workaround used downstream
Register an additional Dispatch that is never installed anywhere, forcing the general path over the global dispatch list. Documented with this issue as the upstream reference.
Related but distinct issues
- #3531 — scoped local subscribers and the global callsite/level cache across lifecycle changes (same family, different mechanism).
- #2874 —
Interest::Nevercached before any dispatcher exists and never invalidated (adjacent; our case additionally involves theJustOnearm specifically).
Question for maintainers
Is the Rebuilder::JustOne → dispatcher::get_default reading intentional (a deliberate optimization for the single-global-dispatcher case), or should the JustOne arm evaluate the one registered dispatch instead of the thread-local default of an arbitrary thread? Happy to provide a minimal standalone repro crate if useful.
Source: tokio-rs/tracing