bug(tracing): register_callsite doesn't get called

This branch contains code to reproduce an issue where 2 thread local
subscribers interfer so that when the first one takes too long to
complete `register_callsite()`, the second subscriber doesn't have
`register_callsite()` called at all.

It also contains an attempt at a fix by removing a race condition in
`DefaultCallsite::register`. This fix may be necessary anyway, but it
isn't sufficient.

The issue for this problem is #2743.

Author: hds

tracing-core/src/callsite.rs

@@ -310,31 +310,35 @@ impl DefaultCallsite {
     // 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();
+        loop {
+            // 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);
+                    break;
+                }
+                // Great, the callsite is already registered! Just load its
+                // previous cached interest.
+                Err(Self::REGISTERED) => break,
+                // Someone else is registering...
+                Err(_state) => {
+                    debug_assert_eq!(
+                        _state,
+                        Self::REGISTERING,
+                        "weird callsite registration state: {_state}"
+                    );
+                    // The callsite is being registered. We have to wait until
+                    // registration is finished, otherwise
+                    continue;
+                }
             }
         }
 

tracing-subscriber/src/fmt/format/mod.rs

@@ -953,6 +953,13 @@ where
 
             for span in scope.from_root() {
                 write!(writer, "{}", bold.paint(span.metadata().name()))?;
+                write!(
+                    writer,
+                    "[{}/{:#?}]",
+                    span.id().into_u64(),
+                    span.metadata() as *const _,
+                )?;
+
                 seen = true;
 
                 let ext = span.extensions();
@@ -1006,6 +1013,7 @@ where
             )?;
         }
 
+        write!(writer, "[/{:#?}]", event.metadata() as *const _,)?;
         ctx.format_fields(writer.by_ref(), event)?;
         writeln!(writer)
     }