fix(registry/client): idempotent Close; pool reconnect keeps its cause, logs at Debug, backs off, retries on a healthy conn

[TeoSlayer]

Client-side fixes for two verified findings from the 2026-09-24 reliability sweep: item 8 (a Close panic in every nightly) and item 5 (pool reconnect churn, 57% of daemon.log). The server-side part of item 5 (the rendezvous limiter closing connections with no error frame) is out of scope here.

Item 8: Client.Close is idempotent and race-free

Bug. Close always ran close(c.pool.done), so a second Close panicked with close of closed channel. This happens in every nightly since 07-26 (common v0.5.10 to v0.5.13), for example run 35825441421. The daemon's forceReconnectRegistry runs go old.Close(), which races the Close in Stop(). The panic also aborts gotestsum's rerun pass, so every other nightly failure shows as (unknown). I reproduced it on origin/main with two concurrent Close calls on a DialPool(…, 4) client.

Fix.

• The teardown runs once (sync.Once). Later and concurrent Close calls return nil.
• The teardown closes every pool connection exactly once. The dropped-conn and redial paths coordinate with it under c.mu, so nothing closes a connection twice.
• Close no longer waits for in-flight pooled requests. It closes their connections, and those requests return ErrClosed.
• A redial that finishes after Close closes its own connection, so it is not leaked into a closed client.
• Close first closes a done channel. That wakes requests waiting for a free pool entry or sleeping in reconnect backoff. The single-conn path sleeps with c.mu held, so without this Close would wait out the backoff.
• New sentinel ErrClosed, with errors.Is(ErrClosed, ErrNoRegistry) == true. Every Send after Close, and every request Close interrupted, returns it, never a panic. The interrupted ones wrap the I/O error. Callers that already treat "no registry" as recoverable need no change. The old "client closed" substring is kept.
• BinaryClient.Close gets the same treatment: idempotent, ErrClosed afterwards, and its time.Sleep backoff (which also runs under c.mu) now wakes on Close.

Still needed in web4 (not in this PR): have forceReconnectRegistry return early once stopCh is closed, and close newConn if Stop won the race. With this PR the race can no longer panic, but a reconnect that runs after Stop still dials a pool nobody uses.

Item 5 (client side): reconnects keep their cause, log quietly, back off, and try another conn first

Problem. sendPool reconnected and retried, but threw away the error that caused it. It logged every successful redial at INFO: 113,804 registry pool conn reconnected lines in 5.5 days, 57% of the log. It also redialed immediately, even when the registry's limiter was shedding the connection.

Fix.

1. The cause is kept.
   • Each drop is logged at Debug as registry conn dropped, with err, conn_age and rapid_close.
   • Each redial is logged at Debug, and each failed dial at WARN, with cause=<triggering error>.
   • When the redial fails, the returned error wraps both errors: send failed and reconnect failed: recv: EOF (reconnect: reconnect failed after 5 attempts: dial …: connection refused). errors.Is works on both.
   • When the redial works but the retry fails, the retry's error adds (retried after reconnect; first failure: …).
2. Debug per reconnect, INFO summary at most once a minute. registry pool conn reconnected and registry reconnected move to Debug. The first event in a window arms a timer. One minute later it logs one INFO line registry reconnect summary with window, reconnects, failed_dials, rapid_closes, served_by_other_conn, rate_limit_suspected, backoff_streak and last_cause. Close flushes the last window. So a burst is still reported even if nothing follows it.
3. Jittered exponential backoff.
   • A client-wide cooldown before a redial grows with:
     • rapid closes: the peer closes or resets a connection younger than 30s, with no error frame. This is the registry limiter's signature: EOF on the first denied request after the 5s grace.
     • reconnects that fail every dial attempt.
   • The cooldown starts at 250ms, doubles, and is capped at 2s, with jitter in [d/2, d]. The cap stays well under the daemon's 8s withRegistryDeadline, so backoff alone does not trigger the half-open forced reconnect.
   • The cooldown resets after an answer on a connection at least 30s old, after a successful redial (failure streak only), or after a quiet minute.
   • A close on an older connection (idle or NAT timeout) redials immediately, as before.
   • Within one reconnect, the 5 dial attempts keep the 0.5s doubling backoff, now jittered and capped at 8s. The loop no longer sleeps after the final attempt; that sleep was 8s of dead time before returning the error.
4. Retry on another healthy conn before redialing.
   • After a closed-connection error (EOF, reset, broken pipe, locally closed), the request is retried once on another idle, healthy pool entry.
   • The dropped entry is marked broken and its file descriptor is closed at once.
   • Requests prefer healthy entries. A broken entry is redialed lazily, only when it is next needed, so a lightly loaded daemon keeps fewer connections open and churns less.
   • The other-entry attempt is bounded: its whole exchange (write and read) gets otherConnTimeout (2s) instead of the 30s read deadline, and ends early when ctx is done (deadline or cancellation). An entry that times out or is abandoned is retired, because a late reply could still arrive on it.
   • If the other entry is dead too, the client redials and retries once, as before. Timeouts (half-open connections) skip the other-entry retry.
   • So a pooled request can reach the registry up to 3 times (own conn, other conn, redialed conn); a single-conn request at most twice, as before. The SendContext doc says so, and warns that an operation that is not safe to repeat may have been applied even when an error comes back. However many attempts fail, one request extends the rapid-close backoff streak once.
5. SendContext now honours ctx while waiting for a free pool entry and during the other-entry retry. A reconnect whose ctx is already done returns at once, and a dial abandoned for ctx is not logged or counted as a failed dial.

Trade-offs to be aware of. If the other idle connection is silently hung, the request now pays up to 2s before the redial (main redials at once). The 2s cap plus the 2s cooldown cap leaves half of the daemon's 8s deadline for the redial. The hung connection is retired in the process; on main the next request sent on it would stall for the full 30s.

While the registry keeps shedding connections past the grace period, the backoff adds 125ms to 2s before a redial that would otherwise have succeeded at once (inside the new connection's grace). That is the point: stop redialing into the limiter. It costs latency until the rendezvous fix lands: an error frame with retry_after_ms, and a resized or sharded global bucket.

Compatibility

• Public API is additive only (ErrClosed). No exported signatures change.
• Log messages and error substrings are unchanged. Only the levels change, as described above.
• web4 builds and passes against this branch. I ran go build ./... and go test -race ./pkg/daemon/, pointing web4 at this branch through a scratch -modfile replace. The web4 checkout was not modified.

Tests

New file registry/client/zz_client_close_reconnect_test.go. Its fake registry closes connections without an error frame, either after N requests or after a grace period.

• Close:
  • Double Close, and three concurrent Close calls racing 8 senders on Dial and DialPool, 20 iterations under -race. Every failure matches ErrClosed and ErrNoRegistry.
  • Each pool connection is closed exactly once (counting dialer).
  • Close during a redial.
  • Close waking a reconnect backoff, on both the pooled and the single-conn path.
  • BinaryClient: idempotent Close, and Close waking its backoff.
• Reconnect:
  • Debug records carry the cause; there are no per-reconnect INFO lines; the summary is periodic and flushed by Close.
  • Retry on another entry, lazy redial, and the fallback when both conns are dead.
  • The other-entry retry on a silently hung conn gives up after otherConnTimeout, retires that conn and is served on the redial. A ctx deadline or cancellation ends it, with no redial and no failed-dial WARN.
  • A pooled request reaches the registry at most 3 times and extends the streak once; a single-conn request at most twice.
  • A cancellation racing the end of a bounded exchange never leaves a deadline on the conn.
  • Both errors are kept when the redial fails, and the first failure is named when the retry fails.
  • Rapid-close backoff lower bounds; a grace-period server; streak reset after a healthy old conn; no backoff on an idle close; the failure streak and its reset.
  • Cooldown growth, jitter and cap; quiet reset; summary timer; error classification.
• Existing tests:
  • Two proxy tests now hold the other pool entry, so their dropped request still exercises the redial through the proxy.
  • Separate commit: TestDialPoolPartialSecondaryFailureClosesPrimary was flaky on origin/main (13 failures in 600 runs). It now fails the dial deterministically through WithDialer: 0 in 600.

Test runs. GOWORK=off go test -race ./... -count=1, go vet ./... (also with GOOS=windows and GOOS=linux) and staticcheck on the package are all clean. gofmt is clean on changed files; four untouched files were already unformatted on main. The package passed 10 runs at each of -cpu 1,4 under -race (again after the review fixes). Package coverage is 94.0%. The package test time dropped from ~31s to ~8s because the final-attempt sleep is gone.

Review fixes (3eb5b6b)

• F1 (medium): the other-entry retry could stall a request for 30s. It ran with the fixed 30s read deadline and ignored ctx. Reviewer repro (conn 1 closes on its first request, conn 2 reads but never replies): 30.2s with 3 requests at df4fc71; 2.2s now with the default policy (main: 1ms). The fix is the bound described in item 4.

• F2 (low): up to 3 transmissions, while the doc said "retried once". The doc now gives the real limits. Each failed transmission also extended the rapid-close streak, so one denial set the cooldown to jitter(500ms) instead of jitter(250ms). The streak now grows once per logical request: the reviewer's 3-transmission case takes 0.21s instead of 0.46s. I kept the third attempt and did not add a list of non-idempotent message types, for three reasons:

  • The limiter drops a request without processing it.
  • A duplicate needs two consecutive drops, each after the registry processed the request.
  • The one type that creates duplicates, Register without a key, is sent only by pilotctl, on a single-conn client (at most 2 sends, as on main). The daemon uses RegisterWithKeyOpts, which returns the same node_id.

  A per-type list over ~60 message types in a generic Send would also go stale.

• Re-checked after the fix:

  • The reviewer's Close stress tests pass (2 × 60 iterations of each mode, -race): every conn is closed exactly once, no send hangs or succeeds after Close, and goroutines return to baseline.
  • Close with 6 hung pooled sends still returns in under 0.2ms.
  • web4 builds, and go test -race ./pkg/daemon/ passes against this branch (through a scratch -modfile replace).

Follow-ups (not in this PR)

• rendezvous: send {type:error, error:"rate limited", retry_after_ms} before closing, charge the per-IP bucket from the first request, and resize the global bucket. Server half of item 5.
• web4: forceReconnectRegistry stop check (item 8), then bump common.
• Optional: an idle check or keepalive on pool entries.

🤖 Generated with Claude Code

[codecov]

Codecov Report

❌ Patch coverage is 88.54806% with 56 lines in your changes missing coverage. Please review.

Files with missing lines	Patch %	Lines
registry/client/client.go	89.53%	15 Missing and 14 partials ⚠️
registry/client/binary_client.go	65.75%	16 Missing and 9 partials ⚠️
registry/client/reconnect.go	98.56%	2 Missing ⚠️

📢 Thoughts on this report? Let us know!