chore: improve tracing in non-loom tests (#472)

This fixes an issue where the non-`loom` test wrappers would eat logs
from spawned threads, because the thread-local `tracing` subscriber was
not propagated correctly.

maitake-sync/src/loom.rs

@@ -120,16 +120,33 @@ mod inner {
 
     #[cfg(test)]
     pub(crate) mod thread {
+
         pub(crate) use std::thread::{yield_now, JoinHandle};
+
         pub(crate) fn spawn<F, T>(f: F) -> JoinHandle<T>
         where
             F: FnOnce() -> T + Send + 'static,
             T: Send + 'static,
         {
+            use super::atomic::{AtomicUsize, Ordering::Relaxed};
+            thread_local! {
+                static CHILDREN: AtomicUsize = const { AtomicUsize::new(1) };
+            }
+
             let track = super::alloc::track::Registry::current();
+            let subscriber = tracing::Dispatch::default();
+            let span = tracing::Span::current();
+            let num = CHILDREN.with(|children| children.fetch_add(1, Relaxed));
             std::thread::spawn(move || {
+                let _tracing = tracing::dispatcher::set_default(&subscriber);
+                let _span = tracing::info_span!(parent: span, "thread", message = num).entered();
+
+                tracing::info!(num, "spawned child thread");
                 let _tracking = track.map(|track| track.set_default());
-                f()
+                let res = f();
+                tracing::info!(num, "child thread completed");
+
+                res
             })
         }
     }
@@ -156,17 +173,26 @@ mod inner {
             }
 
             pub(crate) fn check(&self, f: impl FnOnce()) {
+                let _trace = crate::util::test::trace_init();
+                let _span = tracing::info_span!(
+                    "test",
+                    message = std::thread::current().name().unwrap_or("<unnamed>")
+                )
+                .entered();
                 let registry = super::alloc::track::Registry::default();
                 let _tracking = registry.set_default();
+
+                tracing::info!("started test...");
                 f();
+                tracing::info!("test completed successfully!");
+
                 registry.check();
             }
         }
     }
 
     #[cfg(test)]
     pub(crate) fn model(f: impl FnOnce()) {
-        let _trace = crate::util::test::trace_init();
         model::Builder::new().check(f)
     }
 

maitake/src/loom.rs

@@ -117,16 +117,34 @@ mod inner {
 
     #[cfg(test)]
     pub(crate) mod thread {
+
         pub(crate) use std::thread::{yield_now, JoinHandle};
+
         pub(crate) fn spawn<F, T>(f: F) -> JoinHandle<T>
         where
             F: FnOnce() -> T + Send + 'static,
             T: Send + 'static,
         {
+            use super::atomic::{AtomicUsize, Ordering::Relaxed};
+            thread_local! {
+                static CHILDREN: AtomicUsize = const { AtomicUsize::new(1) };
+            }
+
             let track = super::alloc::track::Registry::current();
+            let subscriber = tracing_02::Dispatch::default();
+            let span = tracing_02::Span::current();
+            let num = CHILDREN.with(|children| children.fetch_add(1, Relaxed));
             std::thread::spawn(move || {
+                let _tracing = tracing_02::dispatch::set_default(&subscriber);
+                let _span =
+                    tracing_02::info_span!(parent: span.id(), "thread", message = num).entered();
+
+                tracing_02::info!(num, "spawned child thread");
                 let _tracking = track.map(|track| track.set_default());
-                f()
+                let res = f();
+                tracing_02::info!(num, "child thread completed");
+
+                res
             })
         }
     }
@@ -153,17 +171,26 @@ mod inner {
             }
 
             pub(crate) fn check(&self, f: impl FnOnce()) {
+                let _trace = crate::util::test::trace_init();
+                let _span = tracing_02::info_span!(
+                    "test",
+                    message = std::thread::current().name().unwrap_or("<unnamed>")
+                )
+                .entered();
                 let registry = super::alloc::track::Registry::default();
                 let _tracking = registry.set_default();
+
+                tracing_02::info!("started test...");
                 f();
+                tracing_02::info!("test completed successfully!");
+
                 registry.check();
             }
         }
     }
 
     #[cfg(test)]
     pub(crate) fn model(f: impl FnOnce()) {
-        let _trace = crate::util::test::trace_init();
         model::Builder::new().check(f)
     }