diff --git a/CHANGELOG.md b/CHANGELOG.md index f5abb9850..4f2ab9389 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,12 @@ - Added a `Envelope::into_items` method, which returns an iterator over owned [`EnvelopeItem`s](https://docs.rs/sentry/0.46.2/sentry/protocol/enum.EnvelopeItem.html) in the [`Envelope`](https://docs.rs/sentry/0.46.2/sentry/struct.Envelope.html) ([#983](https://github.com/getsentry/sentry-rust/pull/983)). - Expose transport utilities ([#949](https://github.com/getsentry/sentry-rust/pull/949)) +### Fixes + +- Fixed thread corruption bug where `HubSwitchGuard` could be dropped on wrong thread ([#957](https://github.com/getsentry/sentry-rust/pull/957)). + - **Breaking change**: `sentry_core::HubSwitchGuard` is now `!Send`, preventing it from being moved across threads. Code that previously sent the guard to another thread will no longer compile. +- We now fork the `Hub` every time a span is entered. This prevents data from leaking across spans ([#957](https://github.com/getsentry/sentry-rust/pull/957)). + ## 0.46.2 ### New Features diff --git a/sentry-core/src/hub_impl.rs b/sentry-core/src/hub_impl.rs index 5786daa36..146caa871 100644 --- a/sentry-core/src/hub_impl.rs +++ b/sentry-core/src/hub_impl.rs @@ -1,5 +1,6 @@ use std::cell::{Cell, UnsafeCell}; -use std::sync::{Arc, LazyLock, PoisonError, RwLock}; +use std::marker::PhantomData; +use std::sync::{Arc, LazyLock, MutexGuard, PoisonError, RwLock}; use std::thread; use crate::Scope; @@ -19,10 +20,28 @@ thread_local! { ); } -/// A Hub switch guard used to temporarily swap -/// active hub in thread local storage. +/// A guard that temporarily swaps the active hub in thread-local storage. +/// +/// This type is `!Send` because it manages thread-local state and must be +/// dropped on the same thread where it was created. pub struct SwitchGuard { inner: Option<(Arc, bool)>, + /// Makes this type `!Send` while keeping it `Sync`. + /// + /// ```rust + /// # use sentry_core::HubSwitchGuard as SwitchGuard; + /// trait AssertSync: Sync {} + /// + /// impl AssertSync for SwitchGuard {} + /// ``` + /// + /// ```rust,compile_fail + /// # use sentry_core::HubSwitchGuard as SwitchGuard; + /// trait AssertSend: Send {} + /// + /// impl AssertSend for SwitchGuard {} + /// ``` + _not_send: PhantomData>, } impl SwitchGuard { @@ -41,7 +60,10 @@ impl SwitchGuard { let was_process_hub = is_process_hub.replace(false); Some((hub, was_process_hub)) }); - SwitchGuard { inner } + SwitchGuard { + inner, + _not_send: PhantomData, + } } fn swap(&mut self) -> Option> { diff --git a/sentry-core/src/macros.rs b/sentry-core/src/macros.rs index edb75dcd5..647ce252e 100644 --- a/sentry-core/src/macros.rs +++ b/sentry-core/src/macros.rs @@ -64,6 +64,37 @@ macro_rules! sentry_debug { } } +/// Panics in debug builds and logs through `sentry_debug!` in non-debug builds. +#[macro_export] +#[doc(hidden)] +macro_rules! debug_panic_or_log { + ($($arg:tt)*) => {{ + #[cfg(debug_assertions)] + panic!($($arg)*); + + #[cfg(not(debug_assertions))] + $crate::sentry_debug!($($arg)*); + }}; +} + +/// If the condition is false, panics in debug builds and logs in non-debug builds. +#[macro_export] +#[doc(hidden)] +macro_rules! debug_assert_or_log { + ($cond:expr $(,)?) => {{ + let condition = $cond; + if !condition { + $crate::debug_panic_or_log!("assertion failed: {}", stringify!($cond)); + } + }}; + ($cond:expr, $($arg:tt)+) => {{ + let condition = $cond; + if !condition { + $crate::debug_panic_or_log!($($arg)+); + } + }}; +} + #[allow(unused_macros)] macro_rules! minimal_unreachable { () => { @@ -73,3 +104,31 @@ macro_rules! minimal_unreachable { ); }; } + +#[cfg(test)] +mod tests { + #[test] + fn debug_assert_or_log_does_not_panic_when_condition_holds() { + crate::debug_assert_or_log!(2 + 2 == 4, "should not panic"); + } + + #[test] + #[cfg(debug_assertions)] + #[should_panic(expected = "assertion failed: 1 == 2")] + fn debug_assert_or_log_panics_with_default_message_when_condition_fails() { + crate::debug_assert_or_log!(1 == 2); + } + + #[test] + #[cfg(debug_assertions)] + #[should_panic(expected = "custom invariant message")] + fn debug_assert_or_log_panics_with_custom_message_when_condition_fails() { + crate::debug_assert_or_log!(false, "custom invariant message"); + } + + #[test] + #[cfg(not(debug_assertions))] + fn no_panic_without_debug_assertions() { + crate::debug_assert_or_log!(false, "should not panic"); + } +} diff --git a/sentry-tracing/src/layer.rs b/sentry-tracing/src/layer/mod.rs similarity index 86% rename from sentry-tracing/src/layer.rs rename to sentry-tracing/src/layer/mod.rs index d02c0496d..4d5961c1d 100644 --- a/sentry-tracing/src/layer.rs +++ b/sentry-tracing/src/layer/mod.rs @@ -5,7 +5,7 @@ use std::sync::Arc; use bitflags::bitflags; use sentry_core::protocol::Value; -use sentry_core::{Breadcrumb, TransactionOrSpan}; +use sentry_core::{Breadcrumb, Hub, HubSwitchGuard, TransactionOrSpan}; use tracing_core::field::Visit; use tracing_core::{span, Event, Field, Level, Metadata, Subscriber}; use tracing_subscriber::layer::{Context, Layer}; @@ -16,6 +16,9 @@ use crate::SENTRY_NAME_FIELD; use crate::SENTRY_OP_FIELD; use crate::SENTRY_TRACE_FIELD; use crate::TAGS_PREFIX; +use span_guard_stack::SpanGuardStack; + +mod span_guard_stack; bitflags! { /// The action that Sentry should perform for a given [`Event`] @@ -234,9 +237,7 @@ fn record_fields<'a, K: AsRef + Into>>( /// the *current* span. pub(super) struct SentrySpanData { pub(super) sentry_span: TransactionOrSpan, - parent_sentry_span: Option, hub: Arc, - hub_switch_guard: Option, } impl Layer for SentryLayer @@ -334,47 +335,66 @@ where set_default_attributes(&mut sentry_span, span.metadata()); let mut extensions = span.extensions_mut(); - extensions.insert(SentrySpanData { - sentry_span, - parent_sentry_span, - hub, - hub_switch_guard: None, - }); + extensions.insert(SentrySpanData { sentry_span, hub }); } - /// Sets entered span as *current* sentry span. A tracing span can be - /// entered and existed multiple times, for example, when using a `tracing::Instrumented` future. + /// Sets the entered span as *current* sentry span. + /// + /// A tracing span can be entered and exited multiple times, for example, + /// when using a `tracing::Instrumented` future. + /// + /// Spans must be exited on the same thread that they are entered. The + /// `sentry-tracing` integration's behavior is undefined if spans are + /// exited on threads other than the one they are entered from; + /// specifically, doing so will likely cause data to bleed between + /// [`Hub`]s in unexpected ways. fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { let span = match ctx.span(id) { Some(span) => span, None => return, }; - let mut extensions = span.extensions_mut(); - if let Some(data) = extensions.get_mut::() { - data.hub_switch_guard = Some(sentry_core::HubSwitchGuard::new(data.hub.clone())); - data.hub.configure_scope(|scope| { + let extensions = span.extensions(); + if let Some(data) = extensions.get::() { + // We fork the hub (based on the hub associated with the span) + // upon entering the span. This prevents data leakage if the span + // is entered and exited multiple times. + // + // Further, Hubs are meant to manage thread-local state, even + // though they can be shared across threads. As the span may being + // entered on a different thread than where it was created, we need + // to use a new hub to avoid altering state on the original thread. + let hub = Arc::new(Hub::new_from_top(&data.hub)); + + hub.configure_scope(|scope| { scope.set_span(Some(data.sentry_span.clone())); - }) - } - } + }); - /// Set exited span's parent as *current* sentry span. - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - let span = match ctx.span(id) { - Some(span) => span, - None => return, - }; + let guard = HubSwitchGuard::new(hub); - let mut extensions = span.extensions_mut(); - if let Some(data) = extensions.get_mut::() { - data.hub.configure_scope(|scope| { - scope.set_span(data.parent_sentry_span.clone()); + SPAN_GUARDS.with(|guards| { + guards.borrow_mut().push(id.clone(), guard); }); - data.hub_switch_guard.take(); } } + /// 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())); + + // We should have popped a guard if the tracing span has `SentrySpanData` extensions. + sentry_core::debug_assert_or_log!( + popped.is_some() + || ctx + .span(id) + .is_none_or(|span| span.extensions().get::().is_none()), + "[SentryLayer] missing HubSwitchGuard on exit for span {id:?}. \ + This span has been exited more times on this thread than it has been entered, \ + likely due to dropping an `Entered` guard in a different thread than where it was \ + entered. This mismatch will likely cause the sentry-tracing layer to leak memory." + ); + } + /// When a span gets closed, finish the underlying sentry span, and set back /// its parent as the *current* sentry span. fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { @@ -503,6 +523,11 @@ fn extract_span_data( thread_local! { static VISITOR_BUFFER: RefCell = const { RefCell::new(String::new()) }; + /// Hub switch guards keyed by span ID. + /// + /// Guard bookkeeping is thread-local by design. Correctness expects + /// balanced enter/exit callbacks on the same thread. + static SPAN_GUARDS: RefCell = RefCell::new(SpanGuardStack::new()); } /// Records all span fields into a `BTreeMap`, reusing a mutable `String` as buffer. diff --git a/sentry-tracing/src/layer/span_guard_stack.rs b/sentry-tracing/src/layer/span_guard_stack.rs new file mode 100644 index 000000000..753454a27 --- /dev/null +++ b/sentry-tracing/src/layer/span_guard_stack.rs @@ -0,0 +1,79 @@ +//! This module contains code for stack-like storage for `HubSwitchGuard`s keyed +//! by tracing span ID. + +use std::collections::hash_map::Entry; +use std::collections::HashMap; + +use sentry_core::HubSwitchGuard; +use tracing_core::span::Id as SpanId; + +/// Holds per-span stacks of `HubSwitchGuard`s to handle span re-entrancy. +/// +/// Each time a span is entered, we should push a new guard onto the stack. +/// When the span exits, we should pop the guard from the stack. +pub(super) struct SpanGuardStack { + /// The map of span IDs to their respective guard stacks. + guards: HashMap>, +} + +impl SpanGuardStack { + /// Creates an empty guard stack map. + pub(super) fn new() -> Self { + Self { + guards: HashMap::new(), + } + } + + /// Pushes a guard for the given span ID, creating the stack if needed. + pub(super) fn push(&mut self, id: SpanId, guard: HubSwitchGuard) { + self.guards.entry(id).or_default().push(guard); + } + + /// Pops the most recent guard for the span ID, removing the stack when empty. + #[must_use] + pub(super) fn pop(&mut self, id: SpanId) -> Option { + match self.guards.entry(id) { + Entry::Occupied(mut entry) => { + let stack = entry.get_mut(); + let guard = stack.pop(); + if stack.is_empty() { + entry.remove(); + } + guard + } + Entry::Vacant(_) => None, + } + } +} + +#[cfg(test)] +mod tests { + use super::SpanGuardStack; + use sentry_core::{Hub, HubSwitchGuard}; + use std::sync::Arc; + use tracing_core::span::Id as SpanId; + + #[test] + fn pop_is_lifo() { + let initial = Hub::current(); + let hub_a = Arc::new(Hub::new_from_top(initial.clone())); + let hub_b = Arc::new(Hub::new_from_top(hub_a.clone())); + + let mut stack = SpanGuardStack::new(); + let id = SpanId::from_u64(1); + + stack.push(id.clone(), HubSwitchGuard::new(hub_a.clone())); + assert!(Arc::ptr_eq(&Hub::current(), &hub_a)); + + stack.push(id.clone(), HubSwitchGuard::new(hub_b.clone())); + assert!(Arc::ptr_eq(&Hub::current(), &hub_b)); + + drop(stack.pop(id.clone()).expect("guard for hub_b")); + assert!(Arc::ptr_eq(&Hub::current(), &hub_a)); + + drop(stack.pop(id.clone()).expect("guard for hub_a")); + assert!(Arc::ptr_eq(&Hub::current(), &initial)); + + assert!(stack.pop(id).is_none()); + } +} diff --git a/sentry-tracing/tests/await_cross_thread_guard.rs b/sentry-tracing/tests/await_cross_thread_guard.rs new file mode 100644 index 000000000..ad78b0c05 --- /dev/null +++ b/sentry-tracing/tests/await_cross_thread_guard.rs @@ -0,0 +1,194 @@ +mod shared; + +use std::any::Any; +use std::future::{self, Future}; +use std::sync::mpsc; +use std::task::{Context, Poll, Waker}; +use std::thread; + +use sentry::protocol::{EnvelopeItem, Transaction}; +use sentry::{Envelope, Hub, HubSwitchGuard}; +use tracing::Span; + +/// Test that the [`sentry_tracing::SentryLayer`]'s `on_exit` implementation panics +/// (only when `debug_assertions` are enabled) if a span, captured by Sentry, is exited +/// on a different thread than where it was entered. +/// +/// Here, we specifically test a future that is awaited across threads, as that is +/// probably the most common scenario where this can occur. +/// +/// We use an info-level span, as that's the lowest level captured by Sentry by default. +#[test] +fn future_cross_thread_info_span() { + const SPAN_NAME: &str = "future_cross_thread_info_span"; + + let _guard = HubSwitchGuard::new(Hub::new_from_top(Hub::current()).into()); + let transport = shared::init_sentry(1.0); + + let span = tracing::info_span!(SPAN_NAME); + + let thread2_result = futures_cross_thread_common(span); + + // Panic should only occur when debug_assertions are enabled. + #[cfg(debug_assertions)] + { + let thread2_panic_message = thread2_result + .expect_err("thread2 did not panic, but it should have (debug_assertions enabled)") + .downcast::() + .expect("expected thread2 to panic with a String message"); + + assert!( + thread2_panic_message.starts_with("[SentryLayer] missing HubSwitchGuard on exit for span"), + "Thread 2 panicked, but not for the expected reason. It is also possible that the panic \ + message was changed without updating this test." + ); + } + + #[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); +} + +/// Counterpart to [`future_cross_thread_info_span`]; here, we check that no panic occurs +/// if the span is not captured by Sentry. +/// +/// No panic should occur because we do not change the [`Hub`] for spans that we don't capture, +/// and so, we should not expect to pop a [`HubSwitchGuard`]. +#[test] +fn future_cross_thread_trace_span() { + let _guard = HubSwitchGuard::new(Hub::new_from_top(Hub::current()).into()); + let transport = shared::init_sentry(1.0); + + let span = tracing::trace_span!("future_cross_thread_trace_span"); + + futures_cross_thread_common(span) + .expect("no panic should occur for spans not captured by Sentry"); + + assert!( + transport.fetch_and_clear_envelopes().is_empty(), + "No envelopes should be sent for spans not captured by Sentry" + ); +} + +/// Counterpart to [`future_cross_thread_info_span`]; here, we check that the panic asserted in +/// [`future_cross_thread`] is not triggered when the span is exited on the same thread +/// that it was entered on. +#[test] +fn futures_same_thread_info_span() { + let _guard = HubSwitchGuard::new(Hub::new_from_top(Hub::current()).into()); + let transport = shared::init_sentry(1.0); + + let span = tracing::info_span!("futures_same_thread_info_span"); + let mut future = Box::pin(span_across_await(span)); + + let thread = thread::spawn(move || { + assert!( + future.as_mut().poll(&mut noop_context()).is_pending(), + "first poll should be pending" + ); + assert!( + future.as_mut().poll(&mut noop_context()).is_ready(), + "second poll should be ready" + ); + }); + + thread.join().expect("thread should complete successfully"); + assert_transaction( + transport.fetch_and_clear_envelopes(), + "futures_same_thread_info_span", + ); +} + +/// Common logic for cross-thread tests. +/// +/// 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> { + let mut future = Box::pin(span_across_await(span)); + + let (tx, rx) = mpsc::channel(); + + let thread1 = thread::spawn(move || { + 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 || { + let poll = rx + .recv() + .expect("failed to receive future") + .as_mut() + .poll(&mut noop_context()); + + assert!(poll.is_ready(), "future should be ready"); + }); + + thread1 + .join() + .expect("thread 1 panicked, but should have completed"); + + thread2.join() +} + +/// Assert that the given envelopes contain exactly one [`Envelope`], +/// containing exactly one [`EnvelopeItem`], which is a [`Transaction`], +/// with given [`name`](Transaction::name). +fn assert_transaction(envelopes: Vec, name: &str) { + let envelope = get_and_assert_only_item(envelopes, "expected exactly one envelope"); + let item = get_and_assert_only_item(envelope.into_items(), "expected exactly one item"); + + assert!( + matches!( + item, + EnvelopeItem::Transaction(Transaction { + name: Some(expected_name), + .. + }) if expected_name == name + ), + "expected a Transaction item with name {name:?}" + ); +} + +/// 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(); + yield_once().await; + // _entered dropped here, after .await call +} + +/// Helper function that yields exactly once, then finishes. +async fn yield_once() { + let mut yielded = false; + + future::poll_fn(|_| { + if yielded { + Poll::Ready(()) + } else { + yielded = true; + Poll::Pending + } + }) + .await; +} + +/// Helper function to create a new no-op [`Context`]. +fn noop_context() -> Context<'static> { + Context::from_waker(Waker::noop()) +} + +/// Helper function to get and assert that there is exactly one item in the iterator. +/// Extracts the only item from the iterator and returns it, or panics with the +/// provided message if there are zero or multiple items. +fn get_and_assert_only_item(item_iter: I, message: &str) -> I::Item +where + I: IntoIterator, +{ + let mut iter = item_iter.into_iter(); + let item = iter.next().expect(message); + assert!(iter.next().is_none(), "{message}"); + item +} diff --git a/sentry-tracing/tests/span_cross_thread.rs b/sentry-tracing/tests/span_cross_thread.rs new file mode 100644 index 000000000..5eaa2cdd3 --- /dev/null +++ b/sentry-tracing/tests/span_cross_thread.rs @@ -0,0 +1,77 @@ +mod shared; + +use sentry::protocol::Context; +use std::thread; +use std::time::Duration; + +#[test] +fn cross_thread_span_entries_share_transaction() { + let transport = shared::init_sentry(1.0); + + let span = tracing::info_span!("foo"); + let span2 = span.clone(); + + let handle1 = thread::spawn(move || { + let _guard = span.enter(); + let _bar_span = tracing::info_span!("bar").entered(); + thread::sleep(Duration::from_millis(100)); + }); + + let handle2 = thread::spawn(move || { + thread::sleep(Duration::from_millis(10)); + let _guard = span2.enter(); + let _baz_span = tracing::info_span!("baz").entered(); + thread::sleep(Duration::from_millis(50)); + }); + + handle1.join().unwrap(); + handle2.join().unwrap(); + + let data = transport.fetch_and_clear_envelopes(); + let transactions: Vec<_> = data + .into_iter() + .flat_map(|envelope| { + envelope + .items() + .filter_map(|item| match item { + sentry::protocol::EnvelopeItem::Transaction(transaction) => { + Some(transaction.clone()) + } + _ => None, + }) + .collect::>() + }) + .collect(); + + assert_eq!( + transactions.len(), + 1, + "expected a single transaction for cross-thread span entries" + ); + + let transaction = &transactions[0]; + assert_eq!(transaction.name.as_deref(), Some("foo")); + + let trace = match transaction + .contexts + .get("trace") + .expect("transaction should include trace context") + { + Context::Trace(trace) => trace, + unexpected => panic!("expected trace context but got {unexpected:?}"), + }; + + let bar_span = transaction + .spans + .iter() + .find(|span| span.description.as_deref() == Some("bar")) + .expect("expected span \"bar\" to be recorded in the transaction"); + let baz_span = transaction + .spans + .iter() + .find(|span| span.description.as_deref() == Some("baz")) + .expect("expected span \"baz\" to be recorded in the transaction"); + + assert_eq!(bar_span.parent_span_id, Some(trace.span_id)); + assert_eq!(baz_span.parent_span_id, Some(trace.span_id)); +} diff --git a/sentry-tracing/tests/span_reentrancy.rs b/sentry-tracing/tests/span_reentrancy.rs new file mode 100644 index 000000000..8fc55aad4 --- /dev/null +++ b/sentry-tracing/tests/span_reentrancy.rs @@ -0,0 +1,70 @@ +use sentry::protocol::EnvelopeItem; + +mod shared; + +/// Ensures re-entering the same span does not corrupt the current tracing state, +/// so subsequent spans are still recorded under a single transaction. +#[test] +fn reentering_span_preserves_parent() { + let transport = shared::init_sentry(1.0); + + { + // Create a span and enter it, then re-enter the same span to simulate + // common async polling behavior where a span can be entered multiple times. + let span_a = tracing::info_span!("a"); + let _enter_a = span_a.enter(); + { + let _reenter_a = span_a.enter(); + } + + // Create another span while the original span is still entered to ensure + // it is recorded on the same transaction rather than starting a new one. + let span_b = tracing::info_span!("b"); + { + let _enter_b = span_b.enter(); + } + } + + let transactions: Vec<_> = transport + .fetch_and_clear_envelopes() + .into_iter() + .flat_map(|envelope| envelope.into_items()) + .filter_map(|item| match item { + EnvelopeItem::Transaction(transaction) => Some(transaction), + _ => None, + }) + .collect(); + + assert_eq!( + transactions.len(), + 1, + "expected a single transaction when reentering a span" + ); + + let transaction = &transactions[0]; + assert_eq!(transaction.name.as_deref(), Some("a")); + + let trace = match transaction + .contexts + .get("trace") + .expect("transaction should include trace context") + { + sentry::protocol::Context::Trace(trace) => trace, + unexpected => panic!("expected trace context but got {unexpected:?}"), + }; + + let b_span = transaction + .spans + .iter() + .find(|span| span.description.as_deref() == Some("b")) + .expect("expected span \"b\" to be recorded in the transaction"); + + assert_eq!(b_span.parent_span_id, Some(trace.span_id)); + assert!( + !transaction + .spans + .iter() + .any(|span| span.description.as_deref() == Some("a")), + "expected the transaction root span not to be duplicated in span list" + ); +}