Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
vlovich opened this issue Feb 22, 2025 · 2 comments
Labels
C-bug Category: bug. Something is wrong. This is bad!

Comments

@vlovich
Copy link

vlovich commented Feb 22, 2025

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)
@vlovich vlovich added the C-bug Category: bug. Something is wrong. This is bad! label Feb 22, 2025
@vlovich vlovich changed the title Tracing span created on one thread dropped in another thread by GaiResolver 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? Feb 22, 2025
@vlovich
Copy link
Author

vlovich commented Feb 22, 2025

Here's a patch adding a minimal test case to src/client/legacy/connect/dns.rs that repros the issue. After looking into it, it looks like this is a supported pattern so either the test case is invalid (I believe it is valid since that's the whole point of with_subscriber) or maybe this is a deeper issue within tracing? Maybe someone with more expertise in this area can chime in?

diff --git a/Cargo.toml b/Cargo.toml
index 5d831f2..bb52222 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -37,6 +37,7 @@ http-body-util = "0.1.0"
 tokio = { version = "1", features = ["macros", "test-util", "signal"] }
 tokio-test = "0.4"
 pretty_env_logger = "0.5"
+tracing-subscriber = { version = "0.3.19", default-features = false, features = ["fmt"] }
 
 [target.'cfg(any(target_os = "linux", target_os = "macos"))'.dev-dependencies]
 pnet_datalink = "0.35.0"
diff --git a/src/client/legacy/connect/dns.rs b/src/client/legacy/connect/dns.rs
index 2a0b53f..b43568e 100644
--- a/src/client/legacy/connect/dns.rs
+++ b/src/client/legacy/connect/dns.rs
@@ -302,6 +302,8 @@ where
 mod tests {
     use super::*;
     use std::net::{Ipv4Addr, Ipv6Addr};
+    use tracing::instrument::WithSubscriber;
+    use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt};
 
     #[test]
     fn test_ip_addrs_split_by_preference() {
@@ -360,4 +362,27 @@ mod tests {
         assert_eq!(name.as_str(), DOMAIN);
         assert_eq!(name.to_string(), DOMAIN);
     }
+
+    #[tokio::test]
+    async fn test_multiple_tracing_subscribers() {
+        tracing_subscriber::registry()
+            .with(tracing_subscriber::filter::filter_fn(|m| {
+                true
+            }))
+            .init();
+
+        let override_default_registry =
+            tracing_subscriber::Registry::default().with(tracing_subscriber::filter::filter_fn(|m| {
+                true
+            }));
+
+        async move {
+            let mut resolver = GaiResolver::new();
+            let resolved = resolver.call(Name::new("localhost".into())).await.unwrap().collect::<Vec<_>>();
+            assert!(resolved.len() > 0);
+            assert!(resolved.iter().all(|addr| addr.ip().is_loopback()), "{resolved:?}");
+        }
+        .with_subscriber(override_default_registry)
+        .await;
+    }
 }

@seanmonstar
Copy link
Member

This certainly looks like an issue in tracing-subscriber, since we didn't misuse the documented API.

However, this change has been causing people several different issues, so I'm probably just going to back it out.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-bug Category: bug. Something is wrong. This is bad!
Projects
None yet
Development

No branches or pull requests

2 participants