All spans not attached to parent transaction

[ollipa]

How do you use Sentry?

Sentry SaaS (sentry.io)

SDK version

0.41.0

Steps to reproduce

We have multiple Rust applications where we have carefully built the tracing to make sure that all spans are attached to one parent transaction. We noticed that the spans are not grouped correctly anymore and many functions annotated with #[instrument] create their own transaction in Sentry.

I tested multiple versions and it seems that the issue has started in v0.38.0 and persists in v0.41.0.

Our application spans async tasks like this:

tokio::task::spawn(
    async move { handle_task().await }.in_current_span().bind_hub(Hub::current())
)

Sentry is installed with these features:

sentry = { version = "0.41.0", default-features = false, features = [
    "backtrace",
    "contexts",
    "panic",
    "anyhow",
    "tracing",
    "reqwest",
    "rustls",
] }

Expected result

Spans should be attached to parent transaction/span

Actual result

Spans are not attached to parent transaction/span and multiple transactions are sent to Sentry when only one transaction should be created.

[lcian]

Thanks @ollipa, will look into fixing this ASAP

[ollipa]

Thank you @lcian, let me know if you need more details

[lcian]

I don't think this ever worked as you intended, or if it did, it was only by chance.

• The way to achieve what you want is to create a span before polling the tasks and enter it, that will be your root span (= transaction).
• Then you should spawn the tasks, not reusing the current hub as you show in the example but forking it.

If you reuse the current hub, then (Sentry) spans from multiple tasks will race to set themselves as the current span on the same scope, hence the result will be non deterministic.

Full example:

use futures_util::future::join_all;
use sentry::{Hub, SentryFutureExt};
use std::sync::Arc;
use tracing::Instrument;
use tracing_subscriber::prelude::*;

fn main() {
    let _guard = sentry::init((
        "https://some@dsn/1",
        sentry::ClientOptions {
            traces_sample_rate: 1.0,
            send_default_pii: true,
            debug: true,
            before_send: Some(Arc::new(|e| {
                //dbg!(&e);
                Some(e)
            })),
            ..sentry::ClientOptions::default()
        },
    ));

    tracing_subscriber::registry()
        .with(sentry::integrations::tracing::layer())
        .init();

    let _root = tracing::info_span!("root").entered();

    tokio::runtime::Builder::new_multi_thread()
        .enable_all()
        .build()
        .unwrap()
        .block_on(async {
            let mut handles = vec![];
            for _ in 0..16 {
                let handle = tokio::task::spawn(
                    async move { top().await }.bind_hub(Hub::new_from_top(Hub::current())),
                );
                handles.push(handle);
            }
            join_all(handles).in_current_span().await;
        });
}

#[tracing::instrument]
async fn top() {
    child().await;
}

#[tracing::instrument]
async fn child() {
    println!("hello world");
}

Let me know if this works! @ollipa

[ollipa]

Here is a more complete example of our code:

#[instrument(skip_all)]
async fn handle_task(mut task_handler: impl TaskHandler + 'static) {
    sentry::configure_scope(|scope| {
        scope.set_transaction(Some(&format!(
            "{}::handle_task",
            task_handler.service_name()
        )));
    });

    let mut task = task::spawn(
        async move {
            task_handler
                .handle_task()
                .await
        }
        .in_current_span()
        .bind_hub(Hub::current()),
    );

    let result = task.await;
    match result {
        Ok(Ok(_)) => {
            info!("Task completed successfully");
        }
        Ok(Err(err)) => {
            error!("Task failed: {err:?}");
        }
    };
}

So the root span/transaction is created by using the tracing::instrument attribute in the enclosing function. Then we just rename the transaction using scope.set_transaction.

@lcian, did I understand correctly that this code should this work if I just update .bind_hub(Hub::current()) to .bind_hub(Hub::new_from_top(Hub::current())?

[lcian]

I assumed you were probably already in a span that created the transaction on Sentry but just added that part for completeness.
So yeah, this should be simply about updating the call to bind_hub to use a new Hub forked from the current 👍

[ollipa]

I delved into the code a bit more and we are using tokio::task::JoinSet to run multiple async task concurrently. The function that calls handle_task actually creates a new forked Hub. The code looks something like this:

use tokio::task::JoinSet;

async fn main() {
    let task_handler = TaskHandler::new();
    let mut set = JoinSet::new();

    loop {
        set.spawn(
            handle_task(task_handler)
            .bind_hub(Hub::new_from_top(Hub::current())),
        );
        if set.len() >= 10 {
            let _ = set.join_next().await;
        };
    }
}

I'll try moving the bind_hub(Hub::new_from_top(Hub::current())) call to the the handle_task function.

[ollipa]

@lcian, I tried bind_hub(Hub::new_from_top(Hub::current())) but that didn't help. Many of the spans are correctly attached to the parent span but some, seemingly random, spans create their own transaction.

In case it matters, another place where we create a new hub is this function which is used to execute blocking work inside the spawned async tasks:

/// Spawn a blocking task with tracing.
pub fn spawn_blocking_with_tracing<F, R>(f: F) -> JoinHandle<R>
where
    F: FnOnce() -> R + Send + 'static,
    R: Send + 'static,
{
    let current_span = tracing::Span::current();
    let current_hub = sentry::Hub::current();
    let new_hub = Arc::new(sentry::Hub::new_from_top(current_hub));
    task::spawn_blocking(move || sentry::Hub::run(new_hub, move || current_span.in_scope(f)))
}

[lcian]

Your approach looks correct, and running a similar sample locally it looks like everything is working as intended.
I imagine your real code might be more complicated though.
Having a small complete example that reproduces this would be really helpful.

Depending on how your code is structured, I'm thinking it might be affected by the problem reported in this other issue, so you could try the workaround proposed here #674 (comment) (initializing Sentry on a separate thread) and see what happens.

[ollipa]

I tried to find the commit that introduced the issue but then I noticed that I can reproduce the issue with older version than v38.0 and I'm not sure anymore when this issue started.

Initializing Sentry in separate thread doesn't seem to solve the issue. I first got a panic with the example code because I used Sentry related functions when initializing logging. I then moved the Sentry initialization before everything else but that didn't solve the the original issue.

I also tried to reproduce the problem with a smaller complete example but couldn't get the issue reproduced. I'll continue working with this and try to find a minimal code example that would reproduce the issue.

[lcian]

Thanks. With a small repro example, we could bisect and find the commit that introduced the issue, if any.

The most recent commit that could have affected this behavior is this one #686 but that should have only improved things.