debug(tracing): Instrument cross-thread span flake [DO NOT MERGE]

sentry-tracing/src/layer/mod.rs

@@ -294,6 +294,21 @@ where
     /// When a new Span gets created, run the filter and start a new sentry span
     /// if it passes, setting it as the *current* sentry span.
     fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) {
+        // TEMPORARY debug instrumentation; remove before merge.
+        // Log EVERY span the subscriber sees, *before* the span filter can
+        // ignore it, so we catch library-emitted (e.g. trace/debug) spans.
+        // `contextual_parent` is the current span at creation time; if it is
+        // our span's id, this new span clones it as its parent and pins its
+        // ref_count until this new span closes.
+        crate::repro_diag::record(format!(
+            "on_new_span(ALL) name={:?} level={} id={:?} contextual_parent={:?} thread={:?}",
+            attrs.metadata().name(),
+            attrs.metadata().level(),
+            id,
+            ctx.current_span().id(),
+            std::thread::current().id(),
+        ));
+
         let span = match ctx.span(id) {
             Some(span) => span,
             None => return,
@@ -329,6 +344,18 @@ where
                 tx.into()
             }
         };
+        // TEMPORARY debug instrumentation; remove before merge.
+        crate::repro_diag::record(format!(
+            "on_new_span name={:?} id={:?} kind={} thread={:?}",
+            sentry_name,
+            id,
+            match &sentry_span {
+                TransactionOrSpan::Transaction(_) => "Transaction",
+                TransactionOrSpan::Span(_) => "Span",
+            },
+            std::thread::current().id(),
+        ));
+
         // Add the data from the original span to the sentry span.
         // This comes from typically the `fields` in `tracing::instrument`.
         record_fields(&sentry_span, data);
@@ -376,13 +403,28 @@ where
             SPAN_GUARDS.with(|guards| {
                 guards.borrow_mut().push(id.clone(), guard);
             });
+
+            // TEMPORARY debug instrumentation; remove before merge.
+            crate::repro_diag::record(format!(
+                "on_enter id={:?} thread={:?}",
+                id,
+                std::thread::current().id(),
+            ));
         }
     }
 
     /// Drop the current span's [`HubSwitchGuard`] to restore the parent [`Hub`].
     fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) {
         let popped = SPAN_GUARDS.with(|guards| guards.borrow_mut().pop(id.clone()));
 
+        // TEMPORARY debug instrumentation; remove before merge.
+        crate::repro_diag::record(format!(
+            "on_exit id={:?} popped={} thread={:?}",
+            id,
+            popped.is_some(),
+            std::thread::current().id(),
+        ));
+
         // We should have popped a guard if the tracing span has `SentrySpanData` extensions.
         sentry_core::debug_assert_or_log!(
             popped.is_some()
@@ -401,16 +443,56 @@ where
     fn on_close(&self, id: span::Id, ctx: Context<'_, S>) {
         let span = match ctx.span(&id) {
             Some(span) => span,
-            None => return,
+            None => {
+                // TEMPORARY debug instrumentation; remove before merge.
+                crate::repro_diag::record(format!(
+                    "on_close id={:?} thread={:?} NO tracing span (no finish)",
+                    id,
+                    std::thread::current().id(),
+                ));
+                return;
+            }
         };
 
+        // TEMPORARY debug instrumentation; remove before merge.
+        let span_name = span.name();
+
         let mut extensions = span.extensions_mut();
         let SentrySpanData { sentry_span, .. } = match extensions.remove::<SentrySpanData>() {
             Some(data) => data,
-            None => return,
+            None => {
+                // TEMPORARY debug instrumentation; remove before merge.
+                crate::repro_diag::record(format!(
+                    "on_close name={:?} id={:?} thread={:?} NO SentrySpanData (no finish)",
+                    span_name,
+                    id,
+                    std::thread::current().id(),
+                ));
+                return;
+            }
         };
 
+        // TEMPORARY debug instrumentation; remove before merge.
+        crate::repro_diag::record(format!(
+            "on_close name={:?} id={:?} kind={} thread={:?} -> finish()",
+            span_name,
+            id,
+            match &sentry_span {
+                TransactionOrSpan::Transaction(_) => "Transaction",
+                TransactionOrSpan::Span(_) => "Span",
+            },
+            std::thread::current().id(),
+        ));
+
         sentry_span.finish();
+
+        // TEMPORARY debug instrumentation; remove before merge.
+        crate::repro_diag::record(format!(
+            "on_close name={:?} id={:?} thread={:?} finish() returned",
+            span_name,
+            id,
+            std::thread::current().id(),
+        ));
     }
 
     /// Implement the writing of extra data to span

sentry-tracing/src/lib.rs

@@ -245,6 +245,32 @@ mod layer;
 pub use converters::*;
 pub use layer::*;
 
+/// TEMPORARY debug instrumentation for the `future_cross_thread_info_span`
+/// flake. Records layer callbacks (transaction vs span creation, and whether
+/// `on_close`/`finish` runs and on which thread) into a global buffer that the
+/// failing test dumps. Not part of the public API; remove before merge.
+#[doc(hidden)]
+pub mod repro_diag {
+    use std::sync::Mutex;
+
+    static EVENTS: Mutex<Vec<String>> = Mutex::new(Vec::new());
+
+    /// Append a diagnostic line.
+    pub fn record(line: String) {
+        if let Ok(mut events) = EVENTS.lock() {
+            events.push(line);
+        }
+    }
+
+    /// Drain and return all recorded diagnostic lines.
+    pub fn take() -> Vec<String> {
+        EVENTS
+            .lock()
+            .map(|mut events| std::mem::take(&mut *events))
+            .unwrap_or_default()
+    }
+}
+
 const TAGS_PREFIX: &str = "tags.";
 const SENTRY_OP_FIELD: &str = "sentry.op";
 const SENTRY_NAME_FIELD: &str = "sentry.name";

sentry-tracing/tests/await_cross_thread_guard.rs

@@ -47,7 +47,21 @@ fn future_cross_thread_info_span() {
     #[cfg(not(debug_assertions))]
     thread2_result.expect("thread2 should not panic if debug_assertions are disabled");
 
-    assert_transaction(transport.fetch_and_clear_envelopes(), SPAN_NAME);
+    // TEMPORARY debug instrumentation; remove before merge.
+    sentry_tracing::repro_diag::record(format!(
+        "MAIN read transport on thread={:?}",
+        std::thread::current().id()
+    ));
+    let envelopes = transport.fetch_and_clear_envelopes();
+    if envelopes.len() != 1 {
+        let diag = sentry_tracing::repro_diag::take();
+        panic!(
+            "REPRO expected exactly one envelope, got {}. layer diagnostics (all spans, this test run):\n{}",
+            envelopes.len(),
+            diag.join("\n"),
+        );
+    }
+    assert_transaction(envelopes, SPAN_NAME);
 }
 
 /// Counterpart to [`future_cross_thread_info_span`]; here, we check that no panic occurs
@@ -105,17 +119,31 @@ fn futures_same_thread_info_span() {
 /// This function sets up the [`span_across_await`] future, then executes it such that
 /// the span gets entered and exited from different threads.
 fn futures_cross_thread_common(span: Span) -> Result<(), Box<dyn Any + Send + 'static>> {
+    // TEMPORARY debug instrumentation; remove before merge.
+    let name = span.metadata().map(|m| m.name()).unwrap_or("?").to_string();
+
     let mut future = Box::pin(span_across_await(span));
 
     let (tx, rx) = mpsc::channel();
 
+    let name1 = name.clone();
     let thread1 = thread::spawn(move || {
+        // TEMPORARY debug instrumentation; remove before merge.
+        sentry_tracing::repro_diag::record(format!(
+            "{name1} thread1 = {:?}",
+            std::thread::current().id()
+        ));
         let poll = future.as_mut().poll(&mut noop_context());
         assert!(poll.is_pending(), "future should be pending");
         tx.send(future).expect("failed to send future");
     });
 
     let thread2 = thread::spawn(move || {
+        // TEMPORARY debug instrumentation; remove before merge.
+        sentry_tracing::repro_diag::record(format!(
+            "{name} thread2 = {:?}",
+            std::thread::current().id()
+        ));
         let poll = rx
             .recv()
             .expect("failed to receive future")
@@ -151,11 +179,29 @@ fn assert_transaction(envelopes: Vec<Envelope>, name: &str) {
     );
 }
 
+/// TEMPORARY debug instrumentation; remove before merge.
+/// Logs the thread on which the future's own [`Span`] handle is dropped.
+struct DropLoggedSpan(Span);
+
+impl Drop for DropLoggedSpan {
+    fn drop(&mut self) {
+        sentry_tracing::repro_diag::record(format!(
+            "FUTURE span handle dropped on thread={:?}",
+            std::thread::current().id(),
+        ));
+    }
+}
+
 /// A helper function which and [`enter`s](tracing::Span::enter)
 /// a given [`Span`](tracing::Span), holding the returned
 /// [`Entered<'_>`](tracing::span::Entered) guard across an `.await` boundary.
 async fn span_across_await(span: Span) {
-    let _entered = span.enter();
+    // TEMPORARY debug instrumentation; remove before merge.
+    // Wrapping the span lets us log the thread where the future's own handle is
+    // dropped. Drop order: `_entered` first (-> on_exit), then `tracked`
+    // (-> logs the thread, then the inner Span drops -> try_close/on_close).
+    let tracked = DropLoggedSpan(span);
+    let _entered = tracked.0.enter();
     yield_once().await;
     // _entered dropped here, after .await call
 }