Executor client connect timeout - #3748
Conversation
Also removes the DROP rules on drop, and skips the timing tests where TEST-NET-1 has no route and so fails instantly rather than hanging.
Both clients carried the same single-flight lifecycle in duplicate. Folding it into one type also fixes a cohort cancelled after its connect succeeded leaving the established connection parked with nobody to use it. Test gates now key off the absence of a default route and a probed connect rather than inferring the environment, so no run silently covers half the suite or passes without reproducing anything.
tcp_keepalive and buffer_size were plumbed through for experiments that did not help; buffer_size's own doc recorded the negative result. The healthy-peer test now counts connections instead of only timing them, so the sharing claim has coverage that runs without CAP_NET_ADMIN: 16 concurrent calls over 1 connection, and 16 over 16 when sharing is disabled. Timings are indistinguishable either way, so the count is the only signal that can catch it. Client construction and the probe call are extracted rather than repeated in every test.
They needed CAP_NET_ADMIN and skipped without it, which meant a plain cargo test quietly proved nothing and CI never ran them at all. Each now re-runs itself under unshare --user --map-root-user --net, so it holds that capability over nothing but its own loopback and the whole namespace goes away when the child exits. No sudo, no setup, and a machine that cannot do it says so instead of passing. Using a blackholed local port rather than TEST-NET-1 also drops the dependency on the host having a route that swallows packets, which is what previously made the two halves of the suite unable to run in one place.
Clearing an attempt as soon as it succeeded left a window in which the connection was in neither map. A caller that looked for an established connection just before the attempt landed, and for an attempt just after it was cleared, found nothing and opened a second one. Narrow, but wide enough to hit: the connection-counting test failed once in eight full-suite runs under load, and once more in eight after publishing before clearing. Successful attempts are now left in place and only failed ones are cleared, which closes it. Ten consecutive full-suite runs, all at one connection. Eviction has to clear both maps now, or a dead channel would be handed straight back out.
tonic reports a request_timeout as Cancelled and still attaches a transport error, so the eviction predicate could not tell it from a broken connection. worker-executor's registry client sets request_timeout to 30s, so any call running long tore down the channel every caller shares. Verified: Cancelled, "Timeout expired", transport_source=true. Collapses the two connection maps into one. A settled successful attempt already serves every later caller, so the second map was a duplicate, and forget() now spares an attempt still in flight rather than cancelling one that other callers are waiting on. Test names are derived rather than written out, and the parent insists on hearing from the child before believing it: the harness filters by substring and exits 0 when nothing matches, so a renamed test would otherwise pass having run nothing.
The connect-failure arm, the reconnect arm and the metric calls were byte-identical in both call() methods, which is why several fixes in this area had to be written twice. They now differ only in how each client fetches and drops its own connection. Also renames the blackhole eviction test to what it actually proves. Mutation testing showed it passes with eviction disabled, because tonic's Reconnect layer recovers once the peer answers again; the test that eviction is load-bearing is concurrent_calls_to_unreachable_peer_fail_within_one_connect_timeout, which does go red without it.
Two tests renamed last round kept passing their old names to the child process. The harness filters by substring and exits 0 when nothing matches, so both had been running nothing since 83c7e1e: the parent saw a successful child and returned. Timed at 0.037s where they now take 13s. Names are derived from the function itself, and the child announces that it ran before the parent will believe it, so a stale filter fails loudly instead of passing. The request-timeout test had the same shape of problem: it used a peer that answers instantly, so it finished in 0.003s without anything timing out and passed whatever the eviction predicate did. It now uses a peer that accepts TCP and goes silent, times out at 501ms, and fails at 2 connections when timeouts are treated as dead.
Nothing asserted the half of the keep-alive claim that matters most: what bounds a connection already open when its peer goes quiet. Measured at 3.0s with keep-alive on, against 13.0s falling through to the kernel when the interval is not applied. The retry-round count in the SYN cohort test was one too many, since failed_attempt stops once attempts reach max_attempts, which had loosened its bound. The accept-and-hold peer existed in three copies; two now use the helper.
CI red: tc reported "Specified qdisc kind is unknown" because sch_netem cannot be loaded from inside a user namespace, so the runner has no qdisc to offer. Round 4 flagged the hard dependency on netem and I kept it; that call was wrong. The same slow-but-successful connect comes from dropping the first SYN and letting the retransmit through, which needs only iptables. Still red when drive() clears a successful attempt, which is the bug it exists for.
scc's get_async takes the bucket's writer lock, and with 50 targets the map sits at two buckets, so every call in the process serialised on one of two cache lines. Both cache lookups only read. Median throughput at 64 concurrent callers went 89.0k to 96.1k calls/s over seven samples each; the ranges overlap, so treat that as a direction rather than a figure. Also stops rebuilding the endpoint for callers that reuse or join an attempt. build_endpoint is 94ns with TLS off but 17.9us with it on, because tonic parses the CA, client certificate and key into a fresh rustls config each time. Only the caller that starts an attempt pays it now, which matters in exactly the reconnect storm this type exists for.
There was a problem hiding this comment.
Please check the following three items the agentic review found:
[P1] Single-flight does not cover callers already queued in tonic's cached channel
On a cache hit (golem-service-base/src/grpc/client.rs:398-408), callers retain clones of the existing tonic Channel and its shared Tower buffer. Once that channel is dead, tonic's Reconnect exposes a failed reconnect to one buffered request, consumes that error, and starts another reconnect for the next buffered request. Removing the map entry after the first result (client.rs:373-375) cannot rescue requests that already own clones of the old buffer, while Connections only participates on a cache miss. Those requests can therefore still pay queue_depth × connect_timeout, which is the incident behavior this PR is intended to eliminate.
The regression test does not cover this sequence: grpc_client.rs:715-731 waits for a separate call to retire the stale channel before launching the concurrent cohort. The cohort consequently starts after eviction and tests only fresh callers. Please add coverage where callers are queued on the dead cached channel and ensure they are all invalidated or moved onto the shared replacement attempt.
[P2] A late failure from an old connection can evict its replacement
Eviction is keyed only by URI (client.rs:373-375, with the analogous single-target take() at client.rs:266-268). If two callers retain connection A, the first failure can remove A and install replacement B; when the second caller's failure arrives later, it unconditionally removes B and its settled SharedConnect, causing connection C to be opened.
A local reproducer with two staggered Unavailable results opened three TCP connections instead of the expected initial connection plus one replacement. Cached typed clients need a generation/identity, and eviction must remove an entry only when it is still the connection used by the failing call.
[P2] Successful-call latency now excludes connection establishment
Both call loops await connected_client() before starting the success timer (client.rs:252-260 and client.rs:359-368). Previously get() returned a lazy channel, so establishment occurred inside the timed RPC future. A cold attempt that spends 10 seconds connecting and 80 ms in the RPC now records only 80 ms in internal_grpc_success_seconds, masking the latency this change is intended to improve.
Please start the per-attempt timer before connected_client() (or record establishment separately) so successful cold/reconnect attempts retain observable caller latency.
|
One more: |
2 participants
The symptom
Killing a worker-executor pod stalled every request already queued against it for about two minutes, even though the shard-manager recovered in under nine seconds.
Chaos run S5 on golem-dev (2026-08-19, run 32272077341) killed one executor. It left the routing table 1.3s later and its shards were reassigned at 8.4s. Despite that, 496 operations submitted in a 32-second window each stalled around 120s. One traced request spent 119,781ms on a single attempt, then succeeded in 86ms on retry against the replacement.
Correctness held throughout: retries under the same idempotency key succeeded, read-back was clean, 250 of 250 agents consistent. This is an availability bug.
What was broken
All of it lives in
golem-service-base/src/grpc/client.rs, so all of it applies to every gRPC client: shard-manager, registry, compilation and debugging services, not only worker-service.requires_reconnectmatched onlyCode::Unavailable. A dead transport arrives asUnknown, and a connection that closes with requests still on it arrives asCancelled, the commonest of the three at 277 of 400 concurrent calls against a peer killed mid-burst. Broken channels stayed cached indefinitely, so every later request queued onto a connection that could never work again.None. A peer that accepts TCP but never finishes the HTTP/2 handshake, which is what a pod mid-teardown looks like, hung with no bound at all. I gave up and stopped the test at 180s.connect_timeoutcovers only the TCP connect, andrequest_timeoutstays unset because agent invocations run arbitrarily long.Channelis a towerBufferand serves requests one at a time, so each queued request waited for all those ahead of it to burn a fullconnect_timeoutbefore its own connect began. Worst casequeue_depth x connect_timeout. Divide 119,781ms by the 10sconnect_timeoutand that request sat about twelfth in line. Sharing one attempt per target is not enough on its own: tonic reconnects below anything we can reach, serially inside the oneBufferworker, which is the incident's own path.Channel, and theBufferworker task tower spawned for it, for the life of the process. Measured at one leaked task per pod.internal_grpc_success_secondstimed only the RPC, and only the final attempt of it, so a call that spent ten seconds connecting and 80ms on the wire recorded 80ms.What it does now
One connect attempt per target, shared by every waiter through a
Sharedfuture bounded byconnect_timeoutand driven by a task of its own, so losing every waiter cannot strand it. A successful attempt is kept and reused; a failed one is never handed on.One cache, holding the client rather than the channel underneath it, so the client is built with the connection instead of after it.
GrpcClientisMultiTargetGrpcClientwith its target filled in rather than a second copy of the same logic; the two had drifted while they were separate, and the single-target call loop the stall lived in had no test reaching it.Each connection carries an identity and a retirement. Eviction matches on the identity, so only the connection that actually failed is dropped. The retirement records two things separately: that the connection is retired, which any failure sets, and that it is gone, which only a failed transport sets. Being gone also releases every request still riding the connection as soon as any one of them proves it dead, which is what reaches the callers tonic would otherwise re-dial for one at a time. A status the peer sent back leaves those requests running.
A caller handed a connection a sibling retired in the meantime goes back for another, up to three times, rather than passing that sibling's failure on. Measured with 16 callers sharing a peer that retires one call in ten, going back takes callers failing outright from 9.5% to 1.5%, 0.25% and 0.03% over the three turns, for 6%, 9% and 8% more connections opened: what the caller sees decays geometrically while what it costs saturates after the second turn.
A connection counts as dead on
Unavailable,UnknownorCancelledcarrying a transport error: respectively a blackholed connect or an expired keep-alive ping, a connection the kernel gave up on, and a connection that closed with requests still on it. A request timeout is excluded by itstonic::TimeoutExpiredsource rather than by its code, and the codes tonic derives from an HTTP/2 reset are excluded by their code, since a reset ends one stream and leaves the connection carrying everyone else. Pinned against a peer that resets every stream withENHANCE_YOUR_CALM, which arrives asResourceExhaustedwith a transport error attached.HTTP/2 keep-alive is on by default at 10s interval and 10s timeout, pinging while idle, which bounds detection at roughly 20s without capping how long a request may run.
A target nothing has called for ten minutes has its connection dropped, and built again on the next call. The sweep runs on any call once a minute has passed since the last one, rather than on a call that missed the cache: a miss means a target nobody has reached before, and a cluster whose targets are all connected stops producing them. A connection counts as in use while a request is riding it, however long ago it was handed out, so a long invocation is not swept out from under itself.
Measured
With
connect_timeout = 1s, eight concurrent calls to an unreachable peer went from 8.008s to 1.002s, and the same eight queued on a cached channel whose peer had died went from 8.008s to 1.089s. The healthy path is unchanged, 16 concurrent calls over a single connection in 43ms. A connection already open when its peer went quiet is bounded at 3.0s, against 13.0s falling through to the kernel.On golem-dev, against an earlier build of this branch: the S5 rerun went from 340 retries during the fault to 0, and worst fault p99 from 143,447ms to 11,912ms. S13's five rolling restarts produced 0 retries across 109,716 operations, with 300 of 300 agents consistent. The current head has not had a chaos run.
Behaviour changes worth knowing
retries_on_unavailablestill governs both. The publiccall()is unchanged.request_timeoutstays unset for agent invocations.internal_grpc_success_secondscovers the whole call: establishing the connection, every attempt, and the backoff between them. Cold and reconnecting calls read higher than they did before.GrpcClientdelegates toMultiTargetGrpcClient. Its one connection is still exempt from the idle sweep, and its tracing span now carries the endpoint, which it did not before.133039638, which raises the recursion limit ingolem-worker-executor-test-utils. Not this PR's defect:1.5.xdoes not build under rustc 1.98 without it, and it is cherry-picked here so CI can run. It drops out on rebase once the branch it came from lands.http2_keep_alive_interval,http2_keep_alive_timeout,http2_keep_alive_while_idle. All are overridable per service in the usual way.Known imprecision
A status the peer sent back still rebuilds the connection, because
requires_reconnectmatches anyUnavailablewhatever its source. That predates this change, but the retirement now sticks, so callers holding that connection go and build their own instead of reusing it. Measured with 64 concurrent callers and 5% of calls answeredUnavailable: 15% of them run out of turns and fall back to the outer retry, and connections opened go from 0.014 to 0.04 per call. Narrowing the predicate to require a transport source would remove it, at the cost of keeping a connection the peer is draining until the transport actually closes, so it belongs in its own change with its own chaos run.REFUSED_STREAMresets a single stream but arrives asUnavailable, which is also where an expired keep-alive ping arrives, so no status code separates the two. A server that sends GOAWAY and then refuses streams abovelast_stream_idwill have its still-valid streams cut short. That costs a reconnect and a retry rather than a wrong answer, which is the cheaper way to be wrong.