Hacktoberfest 2026: die Issues, die Maintainer für den Oktober markiert haben – offen und einsteigerfreundlich. Hacktoberfest-Issues durchsuchen

Legacy Client pooling messes tower::TraceLayer tracing

Geschlossen
  • Stimmt etwas nicht?
#3,904 14 Kommentare 1 Reaktion 0 zugewiesene Personen Auf GitHub ansehen

Maintainer antworten meist innerhalb von 2 Tagen

Dieses Issue hat noch niemand übernommen.

Bewertung

Schwierigkeit
4/5
Geschätzter Aufwand
3-5 Tage
Anfängerfreundlichkeit
52/100
Issue-Typ
Bug
Klarheit
Größtenteils klar
Aktivitätsstatus
Aktiv
Tech-Stack
rust
Bereich
networking, observability

Rechercherichtung

Beginne in hyper-util/src/client/legacy/client.rs bei connect_to und in hyper-util/src/rt/tokio.rs bei der tracing-Instrumentierung des Executors. Reproduziere eine HTTP/1-Anfrage über TraceLayer mit aktiviertem Connection Pooling und untersuche anschließend, wie der Request-Span vom Hintergrund-Dispatcher beibehalten wird. Die Aufgabe ist erledigt, wenn Request-Spans mit der Antwort beendet werden und nicht, wenn die inaktive gepoolte Verbindung freigegeben wird.

Vom Indexierungsmodell aus dem Issue-Text verfasst.

Beschreibung

C-bug K-hyper-util

Version
hyper 1.6.0
hyper-util 0.1.12
tower 0.5.2
tower-http 0.6.4

Platform
Linux 6.10.14-linuxkit #1 SMP Tue Apr 15 16:00:54 UTC 2025 aarch64 GNU/Linux

Description
When using tower_http::TraceLayer with hyper_util::client::legacy::Client, with HTTP/1 requests, the request spans are kept alive all the way until the underlying idle connection is disposed (90s by default). This prevents us from effectively monitoring kubernetes controller written with kube-rs (which uses this combination).

After looking deeper into it, here's what's happening:

  • TraceLayer correctly creates a new span.
  • Client creates a new TCP connection via send_request -> try_send_request -> connection_for -> one_connection_for -> connect_to.
  • After the handshake, connect_to creates a background dispatcher task to manage the connection.
  • TokioExecutor spawns that task after wrapping it with .in_current_span(), which copies the span.
  • Now original request finishes, response is processed and original copy of span is dropped. This is where the span should ideally be dropped, reporting the end of the request.
  • Instead, the underlying connection is moved to the pool as "idle" and the dispatcher task keeps a reference to the span. Only after the connection is disposed (90s by default), do we see the span dropped and span data reported to the OTEL server.
  • We see a lot of requests with duration around 90s, which makes it hard to work with the reported metrics.
Here's the full stack trace of when the span is getting cloned 

   3: tracing_core::dispatcher::Dispatch::clone_span
             at <index.crates.io>/tracing-core-0.1.32/src/dispatcher.rs:659:13
   4: tracing::span::Span::current::{{closure}}
             at <index.crates.io>/tracing-0.1.40/src/span.rs:552:26
   5: tracing_core::dispatcher::get_default
             at <index.crates.io>/tracing-core-0.1.32/src/dispatcher.rs:391:16
   6: tracing::span::Span::current
             at <index.crates.io>/tracing-0.1.40/src/span.rs:550:9
   7: tracing::instrument::Instrument::in_current_span
             at <index.crates.io>/tracing-0.1.40/src/instrument.rs:129:25
   8: <hyper_util::rt::tokio::TokioExecutor as hyper::rt::Executor<Fut>>::execute
             at <index.crates.io>/hyper-util-0.1.12/src/rt/tokio.rs:112:22
   9: hyper_util::common::exec::Exec::execute
             at <index.crates.io>/hyper-util-0.1.12/src/common/exec.rs:34:17
  10: hyper_util::client::legacy::client::Client<C,B>::connect_to::{{closure}}::{{closure}}::{{closure}}
             at <index.crates.io>/hyper-util-0.1.12/src/client/legacy/client.rs:585:37
  11: <core::pin::Pin<P> as core::future::future::Future>::poll
             at <rust-lib>/core/src/future/future.rs:124:9
  12: <futures_util::future::either::Either<A,B> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/either.rs:109:32
  13: <F as futures_core::future::TryFuture>::try_poll
             at <index.crates.io>/futures-core-0.3.30/src/future.rs:82:9
  14: <futures_util::future::try_future::try_flatten::TryFlatten<Fut,<Fut as futures_core::future::TryFuture>::Ok> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/try_future/try_flatten.rs:57:41
  15: <futures_util::future::try_future::TryFlatten<Fut1,Fut2> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/lib.rs:91:13
  16: <futures_util::future::try_future::AndThen<Fut1,Fut2,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/lib.rs:91:13
  17: <futures_util::future::either::Either<A,B> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/either.rs:109:32
  18: <hyper_util::common::lazy::Lazy<F,R> as core::future::future::Future>::poll
             at <index.crates.io>/hyper-util-0.1.12/src/common/lazy.rs:64:20
  19: futures_util::future::future::FutureExt::poll_unpin
             at <index.crates.io>/futures-util-0.3.30/src/future/future/mod.rs:558:9
  20: <futures_util::future::select::Select<A,B> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/select.rs:118:35
  21: hyper_util::client::legacy::client::Client<C,B>::one_connection_for::{{closure}}
             at <index.crates.io>/hyper-util-0.1.12/src/client/legacy/client.rs:435:49
  22: hyper_util::client::legacy::client::Client<C,B>::connection_for::{{closure}}
             at <index.crates.io>/hyper-util-0.1.12/src/client/legacy/client.rs:386:61
  23: hyper_util::client::legacy::client::Client<C,B>::try_send_request::{{closure}}
             at <index.crates.io>/hyper-util-0.1.12/src/client/legacy/client.rs:281:14
  24: hyper_util::client::legacy::client::Client<C,B>::send_request::{{closure}}
             at <index.crates.io>/hyper-util-0.1.12/src/client/legacy/client.rs:249:70
  25: <hyper_util::client::legacy::client::ResponseFuture as core::future::future::Future>::poll
             at <index.crates.io>/hyper-util-0.1.12/src/client/legacy/client.rs:704:9
  26: <F as futures_core::future::TryFuture>::try_poll
             at <index.crates.io>/futures-core-0.3.30/src/future.rs:82:9
  27: <futures_util::future::try_future::into_future::IntoFuture<Fut> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/try_future/into_future.rs:34:9
  28: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/future/map.rs:55:37
  29: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/lib.rs:91:13
  30: <futures_util::future::try_future::MapErr<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/lib.rs:91:13
  31: <tower::util::map_err::MapErrFuture<F,N> as core::future::future::Future>::poll
             at <index.crates.io>/tower-0.5.2/src/macros.rs:38:17
  32: <tower_http::trace::future::ResponseFuture<Fut,C,OnResponseT,OnBodyChunkT,OnEosT,OnFailureT> as core::future::future::Future>::poll
             at <index.crates.io>/tower-http-0.6.4/src/trace/future.rs:64:29
  33: <tower::filter::future::AsyncResponseFuture<P,S,Request> as core::future::future::Future>::poll
             at <index.crates.io>/tower-0.5.2/src/filter/future.rs:93:28
  34: <tower::util::either::EitherResponseFuture<A,B> as core::future::future::Future>::poll
             at <index.crates.io>/tower-0.5.2/src/util/either.rs:85:42
  35: <tower::util::either::EitherResponseFuture<A,B> as core::future::future::Future>::poll
             at <index.crates.io>/tower-0.5.2/src/util/either.rs:84:41
  36: <tower_http::map_response_body::ResponseFuture<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/tower-http-0.6.4/src/map_response_body.rs:182:26
  37: <core::pin::Pin<P> as core::future::future::Future>::poll
             at <rust-lib>/core/src/future/future.rs:124:9
  38: <tower_http::map_response_body::ResponseFuture<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/tower-http-0.6.4/src/map_response_body.rs:182:26
  39: <F as futures_core::future::TryFuture>::try_poll
             at <index.crates.io>/futures-core-0.3.30/src/future.rs:82:9
  40: <futures_util::future::try_future::into_future::IntoFuture<Fut> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/try_future/into_future.rs:34:9
  41: <futures_util::future::future::map::Map<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/future/future/map.rs:55:37
  42: <futures_util::future::future::Map<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/lib.rs:91:13
  43: <futures_util::future::try_future::MapErr<Fut,F> as core::future::future::Future>::poll
             at <index.crates.io>/futures-util-0.3.30/src/lib.rs:91:13
  44: <tower::util::map_err::MapErrFuture<F,N> as core::future::future::Future>::poll
             at <index.crates.io>/tower-0.5.2/src/macros.rs:38:17
  45: <core::pin::Pin<P> as core::future::future::Future>::poll
             at <rust-lib>/core/src/future/future.rs:124:9
  46: <tower::buffer::future::ResponseFuture<F> as core::future::future::Future>::poll
             at <index.crates.io>/tower-0.5.2/src/buffer/future.rs:75:59
  47: kube_client::client::Client::send::{{closure}}
             at <index.crates.io>/kube-client-1.0.0/src/client/mod.rs:213:14
  48: kube_client::client::Client::request_text::{{closure}}
             at <index.crates.io>/kube-client-1.0.0/src/client/mod.rs:285:54
  49: kube_client::client::Client::request::{{closure}}
             at <index.crates.io>/kube-client-1.0.0/src/client/mod.rs:274:47
  50: kube_client::client::Client::apiserver_version::{{closure}}
             at <index.crates.io>/kube-client-1.0.0/src/client/mod.rs:410:10

One option to resolve this is to switch off the tracing feature, but it's a bit hard to do in our case because we depend on hyper_utils via kube-client - kube crates. Plus it looks like the opposite direction of what we want to do (we want more tracing, not less).

The other option is to switch off the pooling. Not great as well.

I wonder if you have any ideas of how to maybe make it smarter than just .in_current_span()? Conceptually it seems to be mixing request lifecycle and connection lifecycle, which will always be different when pooling is involved.

Thank you!

Vorherrschende Sprache
Rust
Sterne
16.3k
Forks
1.8k
Ø Merge
4 T. 10 Std.
Gemergte PRs (30 T.)
21

Entwicklungsumgebung

Erste Schritte

  1. Lesen Sie das ganze Issue und danach den Beitragsleitfaden des Projekts.
  2. Schreiben Sie ins Issue, dass Sie es übernehmen — das erspart doppelte Arbeit.
  3. Forken Sie das Repository und arbeiten Sie in einem Branch.
  4. Öffnen Sie einen Pull Request, der die Issue-Nummer nennt.

Mehr aus hyperium/hyper

Alle Issues in hyperium/hyper

Ähnliche Issues

Weitere Issues zu Rust

Neue Issues direkt in Ihr Postfach

Eine kurze Übersicht über anfängerfreundliche GitHub-Issues.