Repository: getsentry/sentry-rust
Pull request #686 (2024-09-25 17:56:08)

fix(sentry-tracing): switch sentry spans on enter and exit
I've been facing a bug with Sentry Trace where concurrent spans end up wrongly nested. At first, I thought this was some strange autogrouping bug and event sent a feedback (sorry Sentry support member 😅).

After digging a little bit, I discovered that the current tracing layer implementation sets the sentry span as active as soon as a tracing span is _created_, which should not be the case, as spans are only active once _entered_. Following the same logic, it also reverts to the parent span only when a span is _closed_, and not when it's exited.

A span can be entered and exited multiple times, for example, when a tracing `Instrumented` future polls and returns Pending. In case of concurrent Instrumented futures, the current impl ends up nesting Futures under the first created one.

### `sentry-tracing` layer (wrong)
<img width="479" alt="Screenshot 2024-09-25 at 14 22 57" src="https://github.com/user-attachments/assets/8e5e32df-1312-459e-aa7c-89f9d852aea3">

### `tracing-opentelemetry` layer (correct)
<img width="520" alt="Screenshot 2024-09-25 at 14 28 11" src="https://github.com/user-attachments/assets/cd99db29-230a-4dec-bb3a-4398a43456d3">

> I'd say that the best idea would be to not use `sentry_core::configure_scope(|s| s.get_span());` when creating a new span to get the parent, and get it from the span extensions instead, but the current behavior might be relied upon already by someone.


Swatinem: > In case of concurrent Instrumented futures, the current impl ends up nesting Futures under the first created one.

For those cases, one should usually fork the Sentry Hub in order to have them fully isolated.

While you are right that enter/exit is a better fit, and when someone is *manually* hooking up spans, this distinction can lead to some confusion.
However, Hub isolation is the proper solution to this. Hooking into enter/exit in order to set/unset the active Span in the Sentry scope would not fully fix the problem of concurrently running futures.
szokeasaurusrex: Hi @saiintbrisson, are you able to solve this problem with [hub isolation](https://docs.rs/sentry/latest/sentry/struct.Hub.html)?

I would honestly be a bit hesitant to change how we enter and exit Sentry spans, since others might be relying on the current behavior. But, we can look into it if you are unable to find a way to work around this problem.
saiintbrisson: > Hi @saiintbrisson, are you able to solve this problem with [hub isolation](https://docs.rs/sentry/latest/sentry/struct.Hub.html)?
> 
> I would honestly be a bit hesitant to change how we enter and exit Sentry spans, since others might be relying on the current behavior. But, we can look into it if you are unable to find a way to work around this problem.

I ended up just using my fork at my company. Hub isolation is pretty verbose as I would have to bind it to every future as it currently stand. I already isolate it for my root future (I have a Axum middleware binding a hub to the handler call). The problem arises on child futures, like `join!`ing two function futures. If both functions are `tracing::instrument`ed, the first one will create a span when first polled, and when the second one is polled, its span will be considered a child to the first function, because the first span will only end after it returns Poll::Ready, which seems objectively wrong to me, as shown in the prints. Probably manually binding a hub to every call inside my join would work, but I don't want to make my coworkers to handle this kind of detail during development.
Swatinem: > Hub isolation is pretty verbose as I would have to bind it to every future as it currently stand.

Yes that is a bit unfortunate, but ultimately the correct thing to do. Apart from proper span hierarchy, this also relates to Sentrys Scope and other concepts, which could go out of sync if multiple concurrent futures are messing with them.
saiintbrisson: > > Hub isolation is pretty verbose as I would have to bind it to every future as it currently stand.
> 
> Yes that is a bit unfortunate, but ultimately the correct thing to do. Apart from proper span hierarchy, this also relates to Sentrys Scope and other concepts, which could go out of sync if multiple concurrent futures are messing with them.

I don't think I understand how Scopes are to be used. I currently create a new Hub, create a transaction and set it to the created Hub, that I than use to bind it to the handler call. The way you described it, it seems like every future should have its own Scope?

In any case, I expected `sentry-tracing` to behave like what `tracing-subscriber` defines, thus my confusion as someone familiar with other impls (like tracing-opentelemetry). Because I use the tracing layer, I was wishing I could forget sentry Scopes altogether in favor of tracing spans/events/instrumentation. The current behavior should probably be described in the README for the crate.

Let me know if you folks come to any conclusion about this PR. For now, I'll create my own layer impl and move the `fn get_span_id`to #687.

Thanks for your time and keep up the good work, we've been enjoying Sentry a lot around here :).
Swatinem: All in all, thank you for the great feedback, this is very valuable.

> I don't think I understand how Scopes are to be used. I currently create a new Hub, create a transaction and set it to the created Hub, that I than use to bind it to the handler call (one scope per request). The way you described it, it seems like every future should have its own Scope?

I might have added a bit to the confusion here. The Rust SDK still has a couple of concepts that have since been removed from the wider "Sentry unified API". For example, there are no `Hub`s anymore, and no `Transaction`s either.
There is just Scopes and Spans. Though the Rust SDK is unfortunately quite behind on all of this :-(

Anyhow, in essence you want every future to have its own Scope (which in the Rust SDK is still named `Hub`) as you want to have isolation between them, for example:

- When you set tags like `file_id`, you want those to be unique to each concurrently running future, as any error being logged should have the correct `file_id`.
- Similarly, log messages which are being converted to breadcrumbs should also be isolated between concurrent futures. Otherwise a log line like "Starting to process `file X`" would be intermingled with other breadcrumbs unrelated to the operation.

The `#[tracing]` macro conveniently wraps the resulting future in `Instrumented` as you noted, which makes sure to push/pop the currently active span to a thread local. Sentry is completely outside of that, so you would have to do the equivalent for the Sentry `Hub` manually. Which then does the same management of a thread-local with appropriate state.

As I mentioned, the Rust SDK is quite a bit behind in terms of features. By now, the Sentry JS SDK has fully embraced opentelemetry, the SDK and instrumentation side that is. I could maybe imagine Sentry doing something similar in the sense of not duplicating all this span tracking, etc, but fully embracing `tracing` and build on top of that. Though that would be a ton of work. :-D
nrxus: I think this is useful even outside of Futures.

My application doesn't do any async but whenever we create a new thread we also create a new tracing span for that thread. The span is created before the new thread (to inherit the current span as the parent) but then only enter it inside the new thread. If I am understanding this issue correctly, currently any events between the creation of the span and the entering of the span will have the wrong span information. While I understand this is a change in behavior I think the current behavior is fairly unexpected and not intuitive. 
DoumanAsh: I just noticed that my PR https://github.com/getsentry/sentry-rust/pull/700 does the same thing

So I might as well close it, but I would like to point few obvious things with the way sentry does things.
Sentry hubs are stored in static variables so that's actual root of the issue for tracing implementation

Moving scope change to enter/exit will solve majority of issues aside from multi threaded environments.
To work it around you can also just pin tasks to threads (work stealing runtimes were a mistake) or use bind_hub https://docs.rs/sentry/0.34.0/sentry/trait.SentryFutureExt.html#method.bind_hub

But you cannot make tracing span works without changing scope setting to the on enter/exit as it SHOULD be because task can be moved and tracing layer will not have access to the static variable (due to it being thread local) afterwards:
https://github.com/getsentry/sentry-rust/blob/1b65b5c99af975496880e7325218479e0037d097/sentry-core/src/hub_impl.rs#L17-L22
saiintbrisson: > I just noticed that my PR #700 does the same thing
> 
> So I might as well close it, but I would like to point few obvious things with the way sentry does things. Sentry hubs are stored in static variables so that's actual root of the issue for tracing implementation
> 
> Moving scope change to enter/exit will solve majority of issues aside from multi threaded environments. To work it around you can also just pin tasks to threads (work stealing runtimes were a mistake) or use bind_hub [docs.rs/sentry/0.34.0/sentry/trait.SentryFutureExt.html#method.bind_hub](https://docs.rs/sentry/0.34.0/sentry/trait.SentryFutureExt.html#method.bind_hub)
> 
> But you cannot make tracing span works without changing scope setting to the on enter/exit

I'm with you. Though this might not fix everything, it surely fixes most of it. I've been using my fork at my employer and haven't really had any issues up to now.
DoumanAsh: I looked over code again and how bind_hub works
And I think tracing layer could use the same Switch guard https://github.com/getsentry/sentry-rust/blob/master/sentry-core/src/hub_impl.rs#L24

Hub could be stored together with span and on every `enter`, you could create guard, and then drop guard on every `exit`

This should ensure tracing span will retain the same hub across any thread, if I understood its purpose properly
DoumanAsh: @saiintbrisson Can you maybe rebase your work on current master? I'm thinking to use patched version of sentry and maybe will make PR against yours to add Switch hub guard
DoumanAsh: I created prototype of my idea:
https://github.com/saiintbrisson/sentry-rust/pull/1

It will capture Hub on span creation and create switch guard on every enter of the span while dropping guard in exit
DoumanAsh: @saiintbrisson Can you apply comments on your PR?
DoumanAsh: >use of deprecated type alias `std::panic::PanicInfo`: use `PanicHookInfo` instead

This is due to Rust team introducing unnecessary lints with each version

Do you want to silence it? 
Using PanicHookInfo requires 1.81
saiintbrisson: Hi! Yeah, I'll push fixes in a few hours, thanks for the patience 😅 
saiintbrisson: @Swatinem I think this is good to go now. Thanks again for your time and the team for the amazing product. 

And thanks @DoumanAsh for the support and getting it to the final solution.
Swatinem: Thank you for your patience and persistence here :-)

Patch:
diff --git a/sentry-core/src/hub_impl.rs b/sentry-core/src/hub_impl.rs
index 1a2de2c..59c91bf 100644
--- a/sentry-core/src/hub_impl.rs
+++ b/sentry-core/src/hub_impl.rs
@@ -21,12 +21,17 @@ thread_local! {
     );
 }
 
-pub(crate) struct SwitchGuard {
+/// A Hub switch guard used to temporarily swap
+/// active hub in thread local storage.
+pub struct SwitchGuard {
     inner: Option<(Arc<Hub>, bool)>,
 }
 
 impl SwitchGuard {
-    pub(crate) fn new(mut hub: Arc<Hub>) -> Self {
+    /// Swaps the current thread's Hub by the one provided
+    /// and returns a guard that, when dropped, replaces it
+    /// to the previous one.
+    pub fn new(mut hub: Arc<Hub>) -> Self {
         let inner = THREAD_HUB.with(|(thread_hub, is_process_hub)| {
             // SAFETY: `thread_hub` will always be a valid thread local hub,
             // by definition not shared between threads.
diff --git a/sentry-core/src/lib.rs b/sentry-core/src/lib.rs
index 1f7d8c3..5cc39cd 100644
--- a/sentry-core/src/lib.rs
+++ b/sentry-core/src/lib.rs
@@ -149,8 +149,9 @@ pub mod metrics;
 mod session;
 #[cfg(all(feature = "client", feature = "metrics"))]
 mod units;
+
 #[cfg(feature = "client")]
-pub use crate::client::Client;
+pub use crate::{client::Client, hub_impl::SwitchGuard as HubSwitchGuard};
 
 // test utilities
 #[cfg(feature = "test")]
diff --git a/sentry-core/src/performance.rs b/sentry-core/src/performance.rs
index 59cca2a..140d312 100644
--- a/sentry-core/src/performance.rs
+++ b/sentry-core/src/performance.rs
@@ -717,6 +717,12 @@ impl Span {
         transaction.context.clone()
     }
 
+    /// Get the current span ID.
+    pub fn get_span_id(&self) -> protocol::SpanId {
+        let span = self.span.lock().unwrap();
+        span.span_id
+    }
+
     /// Get the status of the Span.
     pub fn get_status(&self) -> Option<protocol::SpanStatus> {
         let span = self.span.lock().unwrap();
diff --git a/sentry-tracing/src/layer.rs b/sentry-tracing/src/layer.rs
index 01930f8..0540fe7 100644
--- a/sentry-tracing/src/layer.rs
+++ b/sentry-tracing/src/layer.rs
@@ -1,6 +1,7 @@
 use std::borrow::Cow;
 use std::cell::RefCell;
 use std::collections::BTreeMap;
+use std::sync::Arc;
 
 use sentry_core::protocol::Value;
 use sentry_core::{Breadcrumb, TransactionOrSpan};
@@ -197,6 +198,8 @@ fn record_fields<'a, K: AsRef<str> + Into<Cow<'a, str>>>(
 pub(super) struct SentrySpanData {
     pub(super) sentry_span: TransactionOrSpan,
     parent_sentry_span: Option<TransactionOrSpan>,
+    hub: Arc<sentry_core::Hub>,
+    hub_switch_guard: Option<sentry_core::HubSwitchGuard>,
 }
 
 impl<S> Layer<S> for SentryLayer<S>
@@ -256,7 +259,9 @@ where
             }
         });
 
-        let parent_sentry_span = sentry_core::configure_scope(|s| s.get_span());
+        let hub = sentry_core::Hub::current();
+        let parent_sentry_span = hub.configure_scope(|scope| scope.get_span());
+
         let sentry_span: sentry_core::TransactionOrSpan = match &parent_sentry_span {
             Some(parent) => parent.start_child(op, &description).into(),
             None => {
@@ -268,15 +273,48 @@ where
         // This comes from typically the `fields` in `tracing::instrument`.
         record_fields(&sentry_span, data);
 
-        sentry_core::configure_scope(|scope| scope.set_span(Some(sentry_span.clone())));
-
         let mut extensions = span.extensions_mut();
         extensions.insert(SentrySpanData {
             sentry_span,
             parent_sentry_span,
+            hub,
+            hub_switch_guard: None,
         });
     }
 
+    /// 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.
+    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::<SentrySpanData>() {
+            data.hub_switch_guard = Some(sentry_core::HubSwitchGuard::new(data.hub.clone()));
+            data.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 mut extensions = span.extensions_mut();
+        if let Some(data) = extensions.get_mut::<SentrySpanData>() {
+            data.hub.configure_scope(|scope| {
+                scope.set_span(data.parent_sentry_span.clone());
+            });
+            data.hub_switch_guard.take();
+        }
+    }
+
     /// 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>) {
@@ -286,16 +324,12 @@ where
         };
 
         let mut extensions = span.extensions_mut();
-        let SentrySpanData {
-            sentry_span,
-            parent_sentry_span,
-        } = match extensions.remove::<SentrySpanData>() {
+        let SentrySpanData { sentry_span, .. } = match extensions.remove::<SentrySpanData>() {
             Some(data) => data,
             None => return,
         };
 
         sentry_span.finish();
-        sentry_core::configure_scope(|scope| scope.set_span(parent_sentry_span));
     }
 
     /// Implement the writing of extra data to span


Test patch:
diff --git a/sentry-tracing/tests/tracing.rs b/sentry-tracing/tests/tracing.rs
new file mode 100644
index 0000000..c77183c
--- /dev/null
+++ b/sentry-tracing/tests/tracing.rs
@@ -0,0 +1,76 @@
+use sentry::{ClientOptions, Hub};
+use sentry_core::test::TestTransport;
+
+use std::sync::Arc;
+
+fn init_sentry() -> Arc<TestTransport> {
+    use tracing_subscriber::prelude::*;
+
+    let transport = TestTransport::new();
+    let options = ClientOptions {
+        dsn: Some("https://test@sentry-tracing.com/test".parse().unwrap()),
+        transport: Some(Arc::new(transport.clone())),
+        sample_rate: 1.0,
+        traces_sample_rate: 1.0,
+        ..ClientOptions::default()
+    };
+    Hub::current().bind_client(Some(Arc::new(options.into())));
+
+    let _ = tracing_subscriber::registry()
+        .with(sentry_tracing::layer().enable_span_attributes())
+        .try_init();
+
+    transport
+}
+
+#[tracing::instrument(fields(tags.tag = "key", not_tag = "value"))]
+fn function_with_tags(value: i32) {
+    tracing::error!(value, "event");
+}
+
+#[test]
+fn should_instrument_function_with_event() {
+    let transport = init_sentry();
+
+    function_with_tags(1);
+
+    let data = transport.fetch_and_clear_envelopes();
+    assert_eq!(data.len(), 2);
+    let event = data.first().expect("should have 1 event");
+    let event = match event.items().next().unwrap() {
+        sentry::protocol::EnvelopeItem::Event(event) => event,
+        unexpected => panic!("Expected event, but got {:#?}", unexpected),
+    };
+
+    //Validate transaction is created
+    let trace = match event.contexts.get("trace").expect("to get 'trace' context") {
+        sentry::protocol::Context::Trace(trace) => trace,
+        unexpected => panic!("Expected trace context but got {:?}", unexpected),
+    };
+    assert_eq!(trace.op.as_deref().unwrap(), "function_with_tags");
+
+    //Confirm transaction values
+    let transaction = data.get(1).expect("should have 1 transaction");
+    let transaction = match transaction.items().next().unwrap() {
+        sentry::protocol::EnvelopeItem::Transaction(transaction) => transaction,
+        unexpected => panic!("Expected transaction, but got {:#?}", unexpected),
+    };
+    assert_eq!(transaction.tags.len(), 1);
+    assert_eq!(transaction.extra.len(), 2);
+
+    let tag = transaction
+        .tags
+        .get("tag")
+        .expect("to have tag with name 'tag'");
+    assert_eq!(tag, "key");
+    let not_tag = transaction
+        .extra
+        .get("not_tag")
+        .expect("to have extra with name 'not_tag'");
+    assert_eq!(not_tag, "value");
+    let value = transaction
+        .extra
+        .get("value")
+        .expect("to have extra with name 'value'");
+    assert_eq!(value, 1);
+}