tracing-core: registering a callsite from within dispatcher::get_default() sets interest to Never

[lilyball]

Bug Report

Version

└── tracing-core v0.1.27
├── tracing v0.1.34
│   ├── tracing-attributes v0.1.23 (proc-macro)
│   └── tracing-core v0.1.27 (*)
└── tracing-subscriber v0.3.5
    ├── tracing v0.1.34 (*)
    ├── tracing-core v0.1.27 (*)
    └── tracing-log v0.1.3
        └── tracing-core v0.1.27 (*)

Platform

darwin (macOS 13)

Crates

tracing-core

Description

I have an internal crate that implements a bridge to tracing, which includes its own Callsite implementation (this predates the introduction of DefaultCallsite). This was originally written against tracing-core 0.1.20. When testing today, it now registers an interest of Never against my callsites, thus disabling them.

This occurs when logging events created with tracing_core::Event::new(metadata, fields). If I create events with tracing_core::Event::new_child_of(Some(parent_id), metadata, fields) then it works fine (I haven't explicitly tested new_child_of(None, metadata, fields) but from the internal issue, I believe that fails also).

This code worked fine up through tracing-core 0.1.26 and breaks in tracing-core 0.1.27 (still broken in 0.1.30). I haven't narrowed down the cause yet, all I know so far is that when set_interest is called it's given Interest(Never). The call stack looks roughly like

   3: tracing_core::callsite::rebuild_callsite_interest
   4: tracing_core::callsite::register
   5: MyCallsite::register::{{closure}}
   6: std::sync::once::Once::call_once::{{closure}}
   7: std::sync::once::Once::call_inner
   8: std::sync::once::Once::call_once
   9: MyCallsite::register
  10: MyCallsite::interest
  11: MyBridgeCode::log::{{closure}}

In particular, my code is following the pattern where the logging code fetches/constructs the callsite, then calls interest(), which checks for cached interest, and since it has none it calls self.register(), which invokes tracing_core::callsite::register() if it hasn't already done so. This then invokes set_interest() with the Interest(Never) value.

I need to dig into this further, but I don't understand why I'm getting an Interest(Never) here, I've already set up the global subscriber. It feels almost like it thinks I have no subscriber yet, except this is only affecting my custom log bridge and isn't affecting native tracing events.

I think DefaultCallsite might be able to replace my custom one, so I'll try that, and if it doesn't work then I'll keep looking. But the fact that tracing-core 0.1.27 broke my existing code is very concerning.

[lilyball]

Hmm I think it's not actually Event::new vs Event::new_child_of(Some(…, I think it's actually whether I use tracing_core::dispatcher::get_default() at the point of logging versus stashing away tracing_core::dispatcher::get_default(|dispatch| dispatch.clone()) when setting up my logger (even though they should be the same dispatch as I'm setting up the global subscriber once before initializing my logging code).

This makes sense as upon further investigation I don't even get to the point of constructing the event before I've run into the never interest.

[lilyball]

I figured it out. I was calling callsite.interest() from within a call to tracing_core::dispatcher::get_default(). This used to work fine for registering the interest, but something changed in tracing-core 0.1.27 such that this fails. A recursive call to tracing_core::dispatcher::get_default() will of course return Dispatch::none() but I wasn't expecting this to affect calculation of interest for callsites.

Skimming the code it appears to be a consequence of the optimization in dispatchers::Rebuilder for the Rebuilder::JustOne case, as that ends up calling dispatcher::get_default() (and therefore gets Dispatch::none()).

In fact, just applying the following diff, which disables this optimization, causes my code to work:

 builder.init();
+tracing_core::dispatcher::with_default(&tracing_subscriber::fmt().finish().into(), || {});

This causes the most recent dispatch registration to occur when there's two dispatches, and therefore it skips the optimization. It's mildly interesting here that this also demonstrates that a dispatch going out of scope doesn't recalculate the optimization, it only does it when registering a new dispatch, which means temporarily switching to another dispatch will break the optimization.

[lilyball]

To clarify, in the broken case, my code basically did:

tracing_core::dispatcher::get_default(|dispatch| {
    let callsite = registry::callsite(record);
    let interest = callsite.interest();
    if !interest.is_never() {
        if interest.is_always() || dispatch.enabled(callsite.metadata()) {
            // …

The fix in my code was to move the first two lines out of the call to get_default(), but this used to work in tracing-core 0.1.26 and lower.