Skip to content

fix: drop idle S3 connections before S3 closes them - #36

Open
dhufnagel wants to merge 2 commits into
nxcite:masterfrom
dhufnagel:fix/s3-pool-idle-timeout
Open

dhufnagel wants to merge 2 commits into
nxcite:masterfrom
dhufnagel:fix/s3-pool-idle-timeout

Conversation

@dhufnagel

Copy link
Copy Markdown

get_object fails with IncompleteMessage on pooled connections that S3 has already closed. The server answers 500, and nx aborts the whole run with Misconfigured remote cache endpoint, even when every task passed.

S3 closes keep-alive connections after ~20 s idle; hyper's pool keeps them for 90 s (aws-smithy-http-client default). This sets pool_idle_timeout to 15 s.

Seen in ~15 of our last 20 failed CI runs (v1.3.0, GitLab runners outside AWS). The pattern each time: a burst of lookups at startup fills the pool, tasks run for 1–3 min without cache traffic, then the next batch fails together, e.g. 18 get_object errors within 1.5 ms:

ERROR nx_cache_server::infra::aws: S3 get_object failed: Unhandled(Unhandled { source: DispatchFailure(DispatchFailure { source: ConnectorError { kind: Other(Some(TransientError)), source: hyper_util::client::legacy::Error(SendRequest, hyper::Error(IncompleteMessage)), connection: Unknown } }), ... })

The SDK classifies this as transient and retries, but the retries draw from the same stale pool. #18 (more attempts) is complementary; this removes the cause.

Not compiled locally. The call matches the Builder::pool_idle_timeout doc example in aws-smithy-http-client 1.2.0, the version in Cargo.lock.

🤖 Generated with Claude Code

S3 closes keep-alive connections after about 20 s idle, while hyper's
pool keeps them for 90 s. A request handed one of those sockets fails
with IncompleteMessage, and the retries draw from the same stale pool,
so the server answers 500 and nx fails the run. Idle connections now
leave the pool after 15 s.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

@joh-klein joh-klein left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for digging into this, and for the detailed write-up. The log excerpt and the "burst, then idle, then a whole batch fails together" pattern make it easy to follow.

The change looks good to me. I checked it against the locked versions: pool_idle_timeout is defined on impl<Any> Builder<Any> in aws-smithy-http-client 1.2.0, so calling it after .tls_provider() works, and the SDK installs the TokioTimer itself, so the timeout actually takes effect. The cost is one extra TLS handshake after 15 s of idle, which is nothing for a cache server.

One thing I'd gently suggest adjusting is the explanation in the code comment. hyper 1.7 keeps polling idle client connections for EOF (require_empty_read in src/proto/h1/conn.rs, which traces "found EOF on idle connection, closing"), and hyper-util's pool skips closed connections at checkout. So if S3 closed a connection at ~20 s and the FIN reached the runner, hyper would drop that socket right away and the 90 s default wouldn't come into play. Failing after 1–3 minutes of idle suggests the close never reached the client. My guess would be a NAT, firewall or proxy between your runners and S3 that drops idle flows silently. The fix still helps for exactly that reason: it keeps the idle age below whatever is cutting the connections, which from your logs is somewhere under 90 s.

Maybe something like:

// Pooled connections idle for less than hyper's 90 s default were found dead
// on networks outside AWS, and requests on them failed with IncompleteMessage.
// Drop idle connections well before that.

That way nobody later bumps it to 19 s on the assumption that S3's limit is 20 s.

If you get the chance to run a build of this branch in your CI for a few days, a short note here on whether the failures stopped would make this an easy merge.

The previous comment blamed S3 closing connections after ~20 s. hyper
drops a pooled connection as soon as the peer's close arrives, so the
connections were cut without a close reaching the client, most likely
by a NAT or firewall in between. The comment now states only what was
observed, so nobody tunes the value against a limit S3 doesn't have.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@dhufnagel

Copy link
Copy Markdown
Author

Thanks for the review. You're right: I checked require_empty_read in hyper 1.7.0, and a close from S3 would have been picked up while the connection sat idle. The connections must be cut somewhere between our runners (outside AWS) and S3 without a FIN reaching us, so "S3 closes after ~20 s" was the wrong explanation.

I've replaced the comment with your wording.

We're running a build of this branch in our CI from today and I'll report back here in a few days on whether the IncompleteMessage failures stopped.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants