From 21435d73d4b68022a9404042876f4ae25b3f28d6 Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 10 Jul 2026 14:37:05 +0200 Subject: [PATCH 1/3] debug(tracing): Instrument cross-thread span flake TEMPORARY instrumentation to diagnose the flaky `future_cross_thread_info_span` test that intermittently observes 0 envelopes. Records, via a global buffer, whether `on_new_span` builds a Transaction or child Span, and whether `on_close`/`finish` runs (and on which thread). The test dumps the buffer when the envelope count is wrong. Not for merge; used to capture a real CI reproduction. Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01MUAsFPraMdxyRXe8Qpswaq --- sentry-tracing/src/layer/mod.rs | 56 ++++++++++++++++++- sentry-tracing/src/lib.rs | 26 +++++++++ .../tests/await_cross_thread_guard.rs | 12 +++- 3 files changed, 91 insertions(+), 3 deletions(-) diff --git a/sentry-tracing/src/layer/mod.rs b/sentry-tracing/src/layer/mod.rs index fba1a4e0a..205dccd7b 100644 --- a/sentry-tracing/src/layer/mod.rs +++ b/sentry-tracing/src/layer/mod.rs @@ -329,6 +329,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); @@ -401,16 +413,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::() { 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 diff --git a/sentry-tracing/src/lib.rs b/sentry-tracing/src/lib.rs index 51d293645..e71718eb8 100644 --- a/sentry-tracing/src/lib.rs +++ b/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> = 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 { + 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"; diff --git a/sentry-tracing/tests/await_cross_thread_guard.rs b/sentry-tracing/tests/await_cross_thread_guard.rs index 6ba209216..afa80db64 100644 --- a/sentry-tracing/tests/await_cross_thread_guard.rs +++ b/sentry-tracing/tests/await_cross_thread_guard.rs @@ -47,7 +47,17 @@ 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. + 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 From e492818083f75714dc2417adb8155f8308e511e6 Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 10 Jul 2026 16:03:48 +0200 Subject: [PATCH 2/3] debug(tracing): Add thread-id + drop-location signals Second instrumentation round for the cross-thread flake: - wrap the future's Span in a Drop-logging newtype to record the thread where the future's own handle is released; - tag thread1/thread2 ids (keyed by span name) and log on_enter/on_exit threads to build the cross-thread timeline; - add a "MAIN read transport" marker to order finish() vs the test read. Goal: determine whether on_close lands on a third thread (=> a second Span handle) or on the future's drop thread after a concurrent enter/exit (=> ordering). Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01MUAsFPraMdxyRXe8Qpswaq --- sentry-tracing/src/layer/mod.rs | 15 ++++++++ .../tests/await_cross_thread_guard.rs | 38 ++++++++++++++++++- 2 files changed, 52 insertions(+), 1 deletion(-) diff --git a/sentry-tracing/src/layer/mod.rs b/sentry-tracing/src/layer/mod.rs index 205dccd7b..2ea70be87 100644 --- a/sentry-tracing/src/layer/mod.rs +++ b/sentry-tracing/src/layer/mod.rs @@ -388,6 +388,13 @@ 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(), + )); } } @@ -395,6 +402,14 @@ where 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() diff --git a/sentry-tracing/tests/await_cross_thread_guard.rs b/sentry-tracing/tests/await_cross_thread_guard.rs index afa80db64..0250d295a 100644 --- a/sentry-tracing/tests/await_cross_thread_guard.rs +++ b/sentry-tracing/tests/await_cross_thread_guard.rs @@ -48,6 +48,10 @@ fn future_cross_thread_info_span() { thread2_result.expect("thread2 should not panic if debug_assertions are disabled"); // 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(); @@ -115,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> { + // 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") @@ -161,11 +179,29 @@ fn assert_transaction(envelopes: Vec, 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 } From 9b5662302839beb1a3d039bf83ff49e424b7b45d Mon Sep 17 00:00:00 2001 From: lcian <17258265+lcian@users.noreply.github.com> Date: Fri, 10 Jul 2026 17:12:29 +0200 Subject: [PATCH 3/3] debug(tracing): Log all spans pre-filter with contextual parent Log every span in on_new_span *before* the span filter ignores it, including its contextual parent id. This catches library-emitted trace/debug spans and reveals whether any span is created with our transaction's id as its contextual parent (which would clone it and pin its ref_count until that child closes). Co-Authored-By: Claude Opus 4.8 Claude-Session: https://claude.ai/code/session_01MUAsFPraMdxyRXe8Qpswaq --- sentry-tracing/src/layer/mod.rs | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/sentry-tracing/src/layer/mod.rs b/sentry-tracing/src/layer/mod.rs index 2ea70be87..b3aee1b7a 100644 --- a/sentry-tracing/src/layer/mod.rs +++ b/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,