Skip to content

GaiResolver insta-panic if the async request has a custom subscriber installed because GaiResolver drops a span on a different thread than the one that created it? #3848

@vlovich

Description

@vlovich

Version
hyper 1.6.0
hyper-util 0.1.10 (where the crash occurs)

Platform
Linux archlinux 6.12.9-arch1-1 #1 SMP PREEMPT_DYNAMIC Fri, 10 Jan 2025 00:39:41 +0000 x86_64 GNU/Linux

Description

I tried this code:

#[tokio::main]
async fn main() {
    tracing_subscriber::registry()
        .with(tracing_subscriber::fmt::layer())
        .init();

    let override_default_registry =
        tracing_subscriber::Registry::default().with(tracing_subscriber::fmt::layer());
    async move {
        tracing::info!("Starting request");
        reqwest::Client::new()
            .post("http://localhost:8787/ping")
            .body("")
            .send()
            .await
           .expect("HTTP request failed");
        tracing::info!("Finished request");
    }
    .with_subscriber(override_default_registry)
    .await;
}

What it looks like is that a span is created on 1 thread & then dropped on the blocking thread. I think this is a misuse of tracing given the note at https://docs.rs/tracing/latest/tracing/struct.Span.html

Note: The returned [EnteredSpan](https://docs.rs/tracing/latest/struct.EnteredSpan.html) guard does not implement Send. Dropping the guard will exit this span, and if the guard is sent to another thread and dropped there, that thread may never have entered this span. Thus, EnteredSpans should not be sent between threads.

I expected to see this happen: "Starting request" followed by "HTTP request failed" or "Finished request"

Instead, this happened:

2025-02-22T15:15:43.460425Z  INFO mycrate: Starting request
2025-02-22T15:15:43.461298Z TRACE hyper_util::client::legacy::pool: checkout waiting for idle connection: ("http", localhost:8787)
2025-02-22T15:15:43.461428Z DEBUG reqwest::connect: starting new connection: http://localhost:8787/    
2025-02-22T15:15:43.461486Z TRACE hyper_util::client::legacy::connect::http: Http::connect; scheme=Some("http"), host=Some("localhost"), port=Some(Port(8787))

thread 'tokio-runtime-worker' panicked at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/registry/sharded.rs:350:21:
tried to drop a ref to Id(1), but no such span exists!
stack backtrace:
   0: rust_begin_unwind
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:692:5
   1: core::panicking::panic_fmt
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panicking.rs:75:14
   2: <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::try_close
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/registry/sharded.rs:350:21
   3: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::try_close
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/layer/layered.rs:186:12
   4: tracing_core::dispatcher::Dispatch::try_close
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.33/src/dispatcher.rs:703:9
   5: <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::exit::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/registry/sharded.rs:303:52
   6: tracing_core::dispatcher::get_default
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.33/src/dispatcher.rs:389:16
   7: <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::exit
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/registry/sharded.rs:303:17
   8: <tracing_subscriber::layer::layered::Layered<L,S> as tracing_core::subscriber::Subscriber>::exit
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-subscriber-0.3.19/src/layer/layered.rs:162:9
   9: tracing_core::dispatcher::Dispatch::exit
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-core-0.1.33/src/dispatcher.rs:636:9
  10: tracing::span::Span::do_exit
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/span.rs:1054:13
  11: <tracing::span::Entered as core::ops::drop::Drop>::drop
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/span.rs:1562:9
  12: core::ptr::drop_in_place<tracing::span::Entered>
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:523:1
  13: <hyper_util::client::legacy::connect::dns::GaiResolver as tower_service::Service<hyper_util::client::legacy::connect::dns::Name>>::call::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/dns.rs:127:9
  14: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/blocking/task.rs:42:21
  15: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/core.rs:331:17
  16: tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/loom/std/unsafe_cell.rs:16:9
  17: tokio::runtime::task::core::Core<T,S>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/core.rs:320:13
  18: tokio::runtime::task::harness::poll_future::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:532:19
  19: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/panic/unwind_safe.rs:272:9
  20: std::panicking::try::do_call
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:584:40
  21: __rust_try
  22: std::panicking::try
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:547:19
  23: std::panic::catch_unwind
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panic.rs:358:14
  24: tokio::runtime::task::harness::poll_future
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:520:18
  25: tokio::runtime::task::harness::Harness<T,S>::poll_inner
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:209:27
  26: tokio::runtime::task::harness::Harness<T,S>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/harness.rs:154:15
  27: tokio::runtime::task::raw::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/raw.rs:271:5
  28: tokio::runtime::task::raw::RawTask::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/raw.rs:201:18
  29: tokio::runtime::task::UnownedTask<S>::run
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/task/mod.rs:486:9
  30: tokio::runtime::blocking::pool::Task::run
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/blocking/pool.rs:161:9
  31: tokio::runtime::blocking::pool::Inner::run
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/blocking/pool.rs:511:17
  32: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/blocking/pool.rs:469:13
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

thread 'main' panicked at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/dns.rs:150:21:
gai background task failed: JoinError::Panic(Id(33), "tried to drop a ref to Id(1), but no such span exists!", ...)
stack backtrace:
   0: rust_begin_unwind
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/std/src/panicking.rs:692:5
   1: core::panicking::panic_fmt
             at /rustc/4d91de4e48198da2e33413efdcd9cd2cc0c46688/library/core/src/panicking.rs:75:14
   2: <hyper_util::client::legacy::connect::dns::GaiFuture as core::future::future::Future>::poll::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/dns.rs:150:21
   3: core::task::poll::Poll<T>::map
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/task/poll.rs:54:43
   4: <hyper_util::client::legacy::connect::dns::GaiFuture as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/dns.rs:143:9
   5: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/future/map.rs:55:37
   6: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
   7: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:124:9
   8: hyper_util::client::legacy::connect::dns::resolve::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/dns.rs:299:28
   9: hyper_util::client::legacy::connect::http::HttpConnector<R>::call_async::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/http.rs:443:18
  10: <hyper_util::client::legacy::connect::http::HttpConnector<R> as tower_service::Service<http::uri::Uri>>::call::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/http.rs:376:62
  11: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:124:9
  12: <hyper_util::client::legacy::connect::http::HttpConnecting<R> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/connect/http.rs:526:9
  13: <hyper_rustls::connector::HttpsConnector<T> as tower_service::Service<http::uri::Uri>>::call::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-rustls-0.27.5/src/connector.rs:75:54
  14: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:124:9
  15: reqwest::connect::ConnectorService::connect_with_maybe_proxy::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/reqwest-0.12.12/src/connect.rs:468:41
  16: reqwest::connect::with_timeout::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/reqwest-0.12.12/src/connect.rs:606:11
  17: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:124:9
  18: <hyper_util::service::oneshot::Oneshot<S,Req> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/service/oneshot.rs:55:38
  19: <F as futures_core::future::TryFuture>::try_poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-core-0.3.31/src/future.rs:92:9
  20: <futures_util::future::try_future::into_future::IntoFuture<Fut> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/try_future/into_future.rs:34:9
  21: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/future/map.rs:55:37
  22: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
  23: <futures_util::future::try_future::MapErr<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
  24: <F as futures_core::future::TryFuture>::try_poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-core-0.3.31/src/future.rs:92:9
  25: <futures_util::future::try_future::into_future::IntoFuture<Fut> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/try_future/into_future.rs:34:9
  26: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/future/map.rs:55:37
  27: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
  28: <futures_util::future::try_future::MapOk<Fut,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
  29: <F as futures_core::future::TryFuture>::try_poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-core-0.3.31/src/future.rs:92:9
  30: <futures_util::future::try_future::try_flatten::TryFlatten<Fut,<Fut as futures_core::future::TryFuture>::Ok> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/try_future/try_flatten.rs:49:61
  31: <futures_util::future::try_future::TryFlatten<Fut1,Fut2> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
  32: <futures_util::future::try_future::AndThen<Fut1,Fut2,F> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/lib.rs:86:13
  33: <futures_util::future::either::Either<A,B> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/either.rs:108:32
  34: <hyper_util::common::lazy::Lazy<F,R> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/common/lazy.rs:64:20
  35: futures_util::future::future::FutureExt::poll_unpin
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/future/mod.rs:558:9
  36: <futures_util::future::select::Select<A,B> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/futures-util-0.3.31/src/future/select.rs:118:35
  37: hyper_util::client::legacy::client::Client<C,B>::one_connection_for::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/client.rs:445:49
  38: hyper_util::client::legacy::client::Client<C,B>::connection_for::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/client.rs:396:61
  39: hyper_util::client::legacy::client::Client<C,B>::try_send_request::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/client.rs:280:14
  40: hyper_util::client::legacy::client::Client<C,B>::send_request::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/client.rs:248:70
  41: <hyper_util::client::legacy::client::ResponseFuture as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/hyper-util-0.1.10/src/client/legacy/client.rs:714:9
  42: <reqwest::async_impl::client::PendingRequest as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/reqwest-0.12.12/src/async_impl/client.rs:2673:53
  43: <reqwest::async_impl::client::Pending as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/reqwest-0.12.12/src/async_impl/client.rs:2643:51
  44: mycrate::main::{{closure}}::{{closure}}
             at ./mycrate/src/main.rs:732:14
  45: <tracing::instrument::WithDispatch<T> as core::future::future::Future>::poll
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tracing-0.1.41/src/instrument.rs:388:9
  46: mycrate::main::{{closure}}
             at ./mycrate/src/main.rs:737:6
  47: tokio::runtime::park::CachedParkThread::block_on::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/park.rs:284:63
  48: tokio::runtime::coop::with_budget
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/coop.rs:107:5
  49: tokio::runtime::coop::budget
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/coop.rs:73:5
  50: tokio::runtime::park::CachedParkThread::block_on
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/park.rs:284:31
  51: tokio::runtime::context::blocking::BlockingRegionGuard::block_on
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/context/blocking.rs:66:9
  52: tokio::runtime::scheduler::multi_thread::MultiThread::block_on::{{closure}}
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/scheduler/multi_thread/mod.rs:87:13
  53: tokio::runtime::context::runtime::enter_runtime
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/context/runtime.rs:65:16
  54: tokio::runtime::scheduler::multi_thread::MultiThread::block_on
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/scheduler/multi_thread/mod.rs:86:9
  55: tokio::runtime::runtime::Runtime::block_on_inner
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/runtime.rs:370:45
  56: tokio::runtime::runtime::Runtime::block_on
             at /home/me/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.43.0/src/runtime/runtime.rs:342:13
  57: mycrate::main
             at ./mycrate/src/main.rs:726:5
  58: core::ops::function::FnOnce::call_once
             at /home/me/.rustup/toolchains/stable-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
2025-02-22T15:15:43.779563Z TRACE hyper_util::client::legacy::pool: checkout dropped for ("http", localhost:8787)

Metadata

Metadata

Assignees

No one assigned

    Labels

    C-bugCategory: bug. Something is wrong. This is bad!

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions