Legacy Client pooling messes tower::TraceLayer tracing
Les mainteneurs répondent en général sous 1 jour
Personne n'a encore pris cette issue.
Évaluation
- Difficulté
- 4/5
- Temps estimé
- 3-5 jours
- Accessibilité débutants
- 52/100
- Type d'issue
- Bug
- Clarté
- Plutôt claire
- Activité
- Active
- Stack technique
- rust
- Domaine
- networking, observability
Piste de recherche
Commencez dans hyper-util/src/client/legacy/client.rs au niveau de connect_to et dans hyper-util/src/rt/tokio.rs au niveau de l’instrumentation tracing de l’exécuteur. Reproduisez une requête HTTP/1 via TraceLayer avec le connection pooling activé, puis examinez comment le span de la requête est conservé par le dispatcher en arrière-plan. La tâche est terminée lorsque les spans des requêtes se terminent avec la réponse, plutôt qu’au moment où la connexion inactive du pool est supprimée.
Rédigé par le modèle d'indexation à partir du texte de l'issue.
Description
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!
- Langage dominant
- Rust
- Étoiles
- 16.4k
- Forks
- 1.8k
- Merge moyen
- 1 j 10 h
- PR mergées (30 j)
- 13
Préparer son environnement
- Aucun Dockerfile ni fichier Docker Compose
- Aucun modèle de pull request
- Lire le guide de contribution
Par où commencer
- Lisez l'issue en entier, puis le guide de contribution du projet.
- Signalez en commentaire que vous la prenez — cela évite que deux personnes fassent le même travail.
- Forkez le dépôt et travaillez sur une branche.
- Ouvrez une pull request qui référence le numéro de l'issue.
Autres issues de hyperium/hyper
-
Publicly reexport the http crateOuverteC-feature
Difficulté 1/5 Moins d'une heure Accessibilité débutants 65/100
hyperium/hyper#2652 · 4 réactions ·
Les mainteneurs répondent en général sous 1 jour
-
Difficulté 4/5 3-5 jours Accessibilité débutants 52/100
Les mainteneurs répondent en général sous 1 jour
-
http1 server: let idle keep-alive connections hold no read/write buffers (opt-in buffer provider)OuverteA-http1 A-server B-rfc S-blocked
Difficulté 5/5 Plus d'une semaine Accessibilité débutants 25/100
hyperium/hyper#4240 · 1 commentaire ·
Les mainteneurs répondent en général sous 1 jour
-
bug(ci): some warnings are not enforced by `features` stepPeut-être pris @cratelyn l’a pris il y a 12 jours. OuverteA-tests C-bug
hyperium/hyper#4232 · 1 personne assignée ·
Les mainteneurs répondent en général sous 1 jour
-
Write a HIP for `Body::poll_progress()`Peut-être pris @cratelyn l’a pris il y a 18 jours. OuverteA-body B-rfc C-feature
hyperium/hyper#4228 · 1 commentaire · 1 personne assignée ·
Les mainteneurs répondent en général sous 1 jour
Toutes les issues de hyperium/hyper
Issues similaires
-
Difficulté 2/5 1-3 heures Accessibilité débutants 73/100
Les mainteneurs répondent en général sous 1 jour
-
C-bug needs-triage O-UEFI T-libs
Difficulté 2/5 1-3 heures Accessibilité débutants 78/100
Les mainteneurs répondent en général sous 1 jour
-
bug priority: P3 ready-for-agent
Difficulté 2/5 1-3 heures Accessibilité débutants 82/100
shep-pm/shep-kelpie#1332 ·
Les mainteneurs répondent en général sous 1 jour
-
enhancement
Difficulté 2/5 1-3 heures Accessibilité débutants 65/100
ramensoftware/windhawk#1156 · 2 commentaires ·
-
area/cli complexity:trivial good first issue Stellar Wave test
Difficulté 2/5 1-3 heures Accessibilité débutants 68/100
Externalize-Labs/externalize#23 ·
Les mainteneurs répondent en général sous 1 jour