Legacy Client pooling messes tower::TraceLayer tracing

[ashtuchkin]

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!

[seanmonstar]

Yea, I've seen that happen before (such as in tokio-console). I don't have an easy solution from a tracing perspective.

We could make calling in_current_span configurable on the TokioExecutor type, as one possible solution.

[ashtuchkin]

Thanks for the response! I see a bit more context for adding tracing in hyperium/hyper-util#166.

In the discussion there, there was exactly this concern:

I think an issue when doing this automatically is that some tasks that are spawned live longer than the initial context. For example, if a new connection is created when trying to serve a request, and then that connection is put in a pool and used for later requests, the context is no longer the same.

Amusingly, kube-rs was mentioned as one of the crates that would benefit from this :)

I'm not 100% sure how to fix it, but adding in_current_span to connection-level futures does not seem to be the right way. Maybe we can store the span more explicitly in request-level structs/closures and activate it manually?

[ashtuchkin]

I wonder if @alpeb or @olix0r as original authors of hyperium/hyper-util#166 have any ideas of how can we make it respect the request lifecycle?

Also for reference and more context, here's an issue in kube-rs: kube-rs/kube#1775

[olix0r]

We could make calling in_current_span configurable on the TokioExecutor type, as one possible solution.

Isn't this already the case via the tracing feature?

@ashtuchkin My understanding is that the only real solution for this would be for Hyper to integrate directly with tracing to ensure the task-context accounting is correct. [edit: i don't even think that's necessarily right -- there are probably bigger lifecycle issues to think through, see below]

[olix0r]

Additionally: the connection itself probably should not have the request context associated with it, but instead only the connection-level metadata. There's a fundamental mismatch between the lifecycle of TraceLayer and the way these connections/pools are instantiated. It is also probably the case that this could be addressed in kube-rs by structuring the stack differently. (I'm not saying this is easy, just that it's in the solution-space).

[ashtuchkin]

the connection itself probably should not have the request context associated with it, but instead only the connection-level metadata.

Totally agree here. Alas the way it's written right now, connections implicitly clone & store the "current" span that was active at request time due to in_current_span construction.

There's a fundamental mismatch between the lifecycle of TraceLayer and the way these connections/pools are instantiated.

The way I see it is that TraceLayer works correctly here. It creates a tracing span at the beginning of request and makes sure it's dropped at the end of response. The fact that hyper Client unexpectedly holds on to that span and attaches it to a connection-level task which outlives request seems unexpected.

In fact, I struggle to see a use case where this arrangement is expected. Do we ever want to attach a span to a connection that can be shared between requests? Does it work for your use case? Is it because with HTTP/2 it's a different codepath (I haven't looked deep into it)?

It is also probably the case that this could be addressed in kube-rs by structuring the stack differently. (I'm not saying this is easy, just that it's in the solution-space).

I'm curious if you have any ideas how to do that!