Hacktoberfest 2026：メンテナが10月に向けて印を付けた、オープンで初心者向けの issue。 Hacktoberfest の issue を見る

`sentry-tracing`: Instrumenteded sqlx queries sometimes missing from their transaction (span closed late on sqlx worker thread)

オープン
  • 何か問題がありますか？
#1,354 コメント 2 件 リアクション 0 件 担当者 0 名 GitHub で見る

メンテナーはふだん 1 日以内に返信

まだ誰も着手していません。

評価

難易度
4/5
見積もり時間
3〜5日
初心者へのやさしさ
45/100
issue の種類
バグ
明瞭さ
おおむね明確
活発さ
活発
技術スタック
rust
領域
backend, observability

調査の方向性

Start by reading the tracing integration’s span lifecycle handling, especially the on_close path described in the report, and compare it with the reproduction using sqlx 0.8.6. Check how a span retained on another thread affects transaction inclusion; the report also identifies a thread-local subscriber behavior tied to tokio-rs/tracing#1656. Done means the integration’s behavior is specified or corrected and a regression test covers the reported missing-span case.

索引モデルが issue の本文から書いたものです。

説明

Bug Rust

Hi Sentry folks. This is an issue I encountered while debugging a seemingly flaky test around some performance tracing code.

Since such issues are quite tricky to find (and this only happened under a certain pressure), I turned to Claude Code, which helped me to come up with the following report and reproducer:

How do you use Sentry?

Self-hosted / on-premises

SDK version

0.49.3

Environment
  • sentry / sentry-tracing 0.49.3
  • sqlx 0.8.6 (SQLite, runtime-tokio)
  • tracing 0.1, tracing-subscriber 0.3.23
  • Linux, rustc 1.99.1
Steps to reproduce
  1. Wrap a sqlx SQLite query in a function annotated with #[tracing::instrument].
  2. Call it inside a Sentry transaction, then finish the transaction right after the query returns. My server code does the same with sentry-tower's SentryHttpLayer.
  3. Repeat many times while the machine is under load.

Minimal reproduction (a global subscriber is used on purpose, to rule out tokio-rs/tracing#1656):

Cargo.toml 
[package]
name = "sentry-sqlx-repro"
version = "0.1.0"
edition = "2024"

[dependencies]
sentry = { version = "=0.49.3", default-features = false, features = ["test", "tracing"] }
sqlx = { version = "=0.8.6", default-features = false, features = ["runtime-tokio", "sqlite"] }
tokio = { version = "1", features = ["full"] }
tracing = "0.1"
tracing-subscriber = "0.3"
src/main.rs 
//! A `#[tracing::instrument]`ed sqlx query inside a Sentry transaction. The span is expected to be
//! part of the transaction, but sometimes it is missing.

use std::sync::{
    Arc,
    atomic::{AtomicUsize, Ordering},
};

use sentry::{
    ClientOptions, Hub, SentryFutureExt, TransactionContext,
    protocol::EnvelopeItem,
    test::with_captured_envelopes_options,
};
use sqlx::SqlitePool;
use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};

/// Number of `query` spans closed on a sqlx worker thread instead of the calling thread.
static CLOSED_ON_WORKER: AtomicUsize = AtomicUsize::new(0);

struct CloseThreadLayer;

impl<S> tracing_subscriber::Layer<S> for CloseThreadLayer
where
    S: tracing::Subscriber + for<'a> tracing_subscriber::registry::LookupSpan<'a>,
{
    fn on_close(&self, id: tracing::span::Id, ctx: tracing_subscriber::layer::Context<'_, S>) {
        let on_worker = std::thread::current()
            .name()
            .is_some_and(|name| name.starts_with("sqlx-sqlite-worker"));
        if on_worker && ctx.span(&id).is_some_and(|span| span.name() == "query") {
            CLOSED_ON_WORKER.fetch_add(1, Ordering::Relaxed);
        }
    }
}

#[tracing::instrument(skip_all)]
async fn query(pool: &SqlitePool) {
    sqlx::query("SELECT 1").execute(pool).await.unwrap();
}

fn main() {
    // Global subscriber, to rule out tokio-rs/tracing#1656 (thread-local default subscriber)
    tracing_subscriber::registry()
        .with(sentry::integrations::tracing::layer())
        .with(CloseThreadLayer)
        .init();

    let iterations = 2000;
    let mut missing = 0;
    for _ in 0..iterations {
        let envelopes = with_captured_envelopes_options(
            || {
                let runtime = tokio::runtime::Runtime::new().unwrap();
                runtime.block_on(async {
                    let pool = SqlitePool::connect("sqlite::memory:").await.unwrap();
                    let hub = Arc::new(Hub::new_from_top(Hub::current()));
                    async {
                        let tx = sentry::start_transaction(TransactionContext::new("request", "http.server"));
                        sentry::configure_scope(|scope| scope.set_span(Some(tx.clone().into())));
                        query(&pool).await;
                        tx.finish();
                    }
                    .bind_hub(hub)
                    .await;
                });
            },
            ClientOptions::new().traces_sample_rate(1.0),
        );
        let spans: usize = envelopes
            .iter()
            .flat_map(|envelope| envelope.items())
            .filter_map(|item| match item {
                EnvelopeItem::Transaction(tx) => Some(tx.spans.len()),
                _ => None,
            })
            .sum();
        if spans == 0 {
            missing += 1;
        }
    }
    println!(
        "query span missing from transaction in {missing}/{iterations} iterations, \
         closed on sqlx worker thread in {}/{iterations} iterations",
        CLOSED_ON_WORKER.load(Ordering::Relaxed)
    );
}

First, build with cargo build --release.

Running 16 instances in parallel on a 16-core machine (for i in $(seq 16); do ./target/release/sentry-sqlx-repro & done; wait):

query span missing from transaction in 16/2000 iterations, closed on sqlx worker thread in 16/2000 iterations
query span missing from transaction in 15/2000 iterations, closed on sqlx worker thread in 15/2000 iterations
query span missing from transaction in 17/2000 iterations, closed on sqlx worker thread in 17/2000 iterations
...

Across all 16 instances, 234 of 32,000 query spans were missing (about 0.7%). In every instance, the number of missing spans equalled the number of spans closed on the sqlx worker thread. A single instance on an idle machine usually reports 0-1 misses.

Expected result

The query span is always part of the transaction, because the instrumented function has returned before finish() is called.

Actual result

The query span is occasionally missing from the transaction, without any error or log message.

Analysis
  • For every command, sqlx-sqlite sends a clone of Span::current() to its worker thread and enters it there (sqlx-sqlite 0.8.6, src/connection/worker.rs: command_tx: flume::Sender<(Command, tracing::Span)>, send_async((command(tx), Span::current())), and let _guard = span.enter(); in the worker loop).
  • The worker drops that clone after it has sent the result back. Under load, the async caller sometimes resumes, returns from the instrumented function and finishes the transaction before the worker drops its clone.
  • sentry-tracing finishes the Sentry span in on_close, i.e. only when the last handle to the tracing span is dropped. In those cases that's on the worker thread, after the transaction was already sent, so the finished child span is discarded.

The race is in sqlx's lifetime of the span handle, but the user-visible effect is in sentry-tracing: the duration and inclusion of a span depend on who else holds a clone. sqlx is just one example; any library that propagates Span::current() to another thread or task can cause the same.

A related, test-only symptom: when the subscriber is installed with set_default (thread-local), the parent spans are never closed at all. The Registry closes parents through the closing thread's default dispatcher (tokio-rs/tracing#1656), so a whole transaction built from tracing spans can go missing. That can make tests that use the tracing integration together with sqlx flaky, possibly similar to #1112.

Possible directions

Just suggestions, I don't know the codebase well:

  • Document that span inclusion depends on all clones of the tracing span being dropped, and that libraries like sqlx keep clones on other threads.
  • Optionally finish the Sentry span when the span is last exited instead of when it's closed (or offer a setting for this). This might conflict with spans that are re-entered later.
Workaround

I now create query spans with the Sentry API directly (start_child/finish around the awaited sqlx future) instead of #[instrument]. With that, the problem no longer occurs in my setup.

主要言語
Rust
スター
753
フォーク
193
平均マージ
10時間 10分
マージ済み PR（30日）
5

環境構築

  • Dockerfile・Docker Compose ファイルなし
  • プルリクエストのテンプレートあり
  • コントリビューションガイドなし

はじめの一歩

  1. issue を最後まで読み、次にプロジェクトのコントリビューションガイドを読みます。
  2. 着手することを issue にコメントします — 二人が同じ作業をするのを防げます。
  3. リポジトリをフォークし、ブランチを切って変更します。
  4. issue 番号を参照したプルリクエストを送ります。

getsentry/sentry-rust のほかの issue

getsentry/sentry-rust の issue をすべて見る

似ている issue

Rust の issue をもっと見る

新しい issue をメールで受け取る

初心者向けの GitHub issue を短くまとめたダイジェスト。