Repository navigation
investigate(relay): bound idle receiver reconnect gaps and stale-room attaches #163
Description
Context
Follow-up to #161 and the independent Claude investigation of published v1.0.0-rc.2 (fe9d8d8). This is a plausible amplifier, not a proven root cause of the public Relay outage.
The server waits up to 60 s for an idle receiver but only 10 s for a client. The receiver calls relay_stream(..., attach_timeout=65); relay_listener resets its 0.5–5 s backoff only after an attach, so ordinary idle expiry can leave repeated reconnect gaps. Server ping is 10/10; an attached but unusable receiver leg is also possible. The RC2 soak saw waitingRooms vary from 0 to 3 and 78/140 Relay route probes succeed while direct probes were 105/105. Those aggregates do not establish that room gaps caused any specific failure. In a normal 30–64 min interval, the same code had nearly no Relay failures, arguing against a deterministic code-only explanation.
Investigation / candidate work
- Reproduce the 60/65 s idle-expiry cycle in a deterministic fixture. Measure receiver room absence and whether a client arriving in that interval can exceed the 10 s wait.
- Correlate privacy-filtered receiver reconnect stage, elapsed time and gap length with Relay attach/close events and client failure time. Record receiver WebSocket age, last pong age if actually available, and close reason without identities, payloads, tokens, cookies or raw exceptions.
- Distinguish an absent receiver room from a stale/attached receiver whose E2E peer handshake times out. Do not infer either from
waitingRoomssnapshots or server 101 alone. - If evidence establishes a product-side amplifier, implement the smallest lifecycle correction with tests for idle expiry, restart, delayed/failed reconnect, stale attach, cancellation and no duplicate native effect. Preserve auth, state and message replay semantics.
- Review draft PR fix(relay): diagnose route failures and safely retry setup timeouts #162 separately: its stage diagnostics and pre-submit setup retry do not establish that the receiver lifecycle is correct or fix the underlying transport fault.
Acceptance
A failing fixture and/or time-correlated live trace demonstrates the specific mechanism before claiming a fix. Corrected behavior is verified with deterministic tests and affected RC3 live routes. If the mechanism cannot be established, report the negative/ambiguous result and leave #161 open; do not widen timeouts or claim recovery from retry-only success.
No production rollout, Cloudflare/Caddy/OCI setting change, receiver swap, or release publication is authorized by this issue. The previously prepared 15-minute receiver wrapper was gated on a completed RC2 four-hour run; that run ended around minute 172 without complete, so the old gate did not open. A new live investigation needs separately scoped authorization.
Independent review addendum (2026-09-23)
Claude's read-only review of the RC2 code and #162 adds these hypotheses and test requirements, not a confirmed root cause:
- The T120 planned restart did not restore the US→mini Relay route within 69 s (
planned_restart ok=false). Include the restart/reconnect window in time-correlation; it is not by itself proof of why recovery failed. - Normal 60/65 s idle-expiry gaps may be absorbed by the client's 10 s wait when transport is healthy. A fixture that only tests healthy/low-latency reconnect cannot falsify the amplification hypothesis. Inject admission/setup delay or a stalled leg and test the combined condition.
- A stale receiver leg could consume the only waiting room at pairing; if it never receives
relayAttached, no replacement room may appear until the leg closes or the receiver attach wait expires. Verify this sequence explicitly; do not state it occurred in the soak without paired receiver evidence. - Deterministic fixture cases: (a) client arrives just after idle expiry, (b) admission delay >10 s, (c) pairing followed by unresponsive receiver leg, and (d) a subsequent client/retry while the only room is absent. Assert distinguishable stage/timing/close results and no duplicate native effect.
The live 15-minute wrapper remains blocked by its unmet original completion gate. New receiver instrumentation requires separate scoped authorization.
Activity
abruption commentedon Sep 23, 2026
2026-09-23 scoped RC2 observation (new user approval)
A fresh, probe-only observation ran with installed
session-peer 1.0.0rc2and the existing hash-pinnedflow_trace.pywrapper. T0 was 10:45:23.675 KST. Mac mini and MacBook receiver Relay WSS connections were ready at T0+1.79 s and T0+2.11 s. No RC3 candidate or PR #162 runtime was installed.op=probecalls: six mini→book and six book→mini, one per randomized minute slot; no retry, native send, or ACK. All 12 sender traces endedok=true, route=relay. End-to-end probe durations were 1.934–4.429 s (mean 2.643 s); the final probe started at T0+741.67 s and the campaign ended at T0+745.04 s.relay-connectentry with status 101. This confirms the observed connection path, not long-term delivery reliability.unauthorizedRejectedstayed 2→2; rate/capacity rejection counters remained zero; Control, Relay, and Caddy stayed active withNRestarts=0. Relay counters wereforwardedFrames28→112 andforwardedBytes14,466→75,412. Aggregate counters do not identify an individual room.ConnectionClosedOKto the next receiverwebsocket_ready: mini 10 cycles, 1.527–2.237 s (mean 1.786 s); book 11 cycles, 1.524–2.503 s (mean 1.881 s). No >10 s reconnect gap was observed in this healthy window.ps/lock check happened at T0+907 s, 7 s later than the planned T0+900 verification point; task-owned processes had already exited within the cap according to their status records. This procedural timing deviation is retained explicitly.Interpretation: No failing probe occurred, so this sample does not distinguish room absence, stale pairing, or CF↔KR transport stall. It neither establishes a root cause nor falsifies the intermittent amplifier hypothesis; #161/#163 remain open. No Cloudflare, OCI, Caddy, Control, Relay, repository source, timeout, retry policy, or production setting was changed. Raw KR TCP metadata remains private on KR; no packet payloads, tokens, cookies, message bodies, or private keys were collected. The temporary evidence is retained on the three test hosts under task-owned 0700 directories.
abruption commentedon Sep 23, 2026
Observation procedure clarification
Two follow-up questions exposed limits in the previous result report:
First Mac mini background launch in the aborted attempt: cause unknown. It left an empty launch log and no status/trace; there is no evidence tying it to the session-peer-skill v0.2.0 update or proving a process-lifecycle cause. For the completed retry we used a detached
subprocess.Popen(..., start_new_session=True)launcher. It immediately returned a parent PID;bounded_run.pythen wrote its child status andflow_trace.pywrotewebsocket_ready. We checked those artifacts about T0+6 s, found both Mac receivers ready, and did not relaunch either receiver. Had that second launch failed, there was no automatic relaunch or automatic T0+60 readiness abort in the campaign script.Boundary enforcement was mixed, not wholly automatic. The readiness check used trace UTC
timeagainst T0 (mini T0+1.790 s; book T0+2.111 s), but a human inspected those values; the script did not parsewebsocket_readyor enforce T0+60. Per-hostmonotonicfields were recorded but cannot be directly subtracted across hosts. The probe script automatically scheduled one randomized probe per minute slot and skipped starts at/after T0+780; the observed final start was T0+741.67. Receiver--secondsvalues (850 mini, 840 book) and KR collector--until T0+870bounded normal lifetime; their actual end times were verified from status records, not by an automated T0+870 gate. Independentbounded_run.pywatchdogs did automatically enforce absolute T0+885 SIGTERM and T0+895 SIGKILL for their task-owned children if still alive. T0+900 zero-process verification was manual and occurred at T0+907, 7 s late.These are procedural limitations of this observation, not evidence that the Relay fault is fixed. A future live campaign should implement machine-checked readiness and T0+900 verification before treating those gates as satisfied automatically. No further live test or operational change is made by this clarification.
abruption commentedon Sep 23, 2026
Interpretation limit: probe cadence resets receiver backoff
Claude highlighted an important sampling bias, confirmed against the installed RC2
relay_listenercode and this run's receiver traces. RC2 initializes reconnect delay at 0.5 s, doubles it after each ordinary relay exception up to 5 s, and resets it to 0.5 s only after an attach. The observation probed each receiver about every two minutes. Each receiver had six attaches, and its trace showed at most two consecutive idleConnectionClosedOKexpiries between attaches (mini: 10 total idle expiries; book: 11). The measured 1.5–2.5 s reconnect gaps therefore sample low backoff stages; they do not characterize the 5 s capped stage that may arise when a receiver goes about five minutes between attaches, as in the earlier RC2 soak.Accordingly, 12/12 successes in this 15-minute window are non-observation of the intermittent fault, not disproof of #161/#163. A future separately approved test should preserve longer receiver-idle intervals or group reconnect gaps by consecutive expiry count before drawing a lifecycle conclusion. No new test, code change, or operational change is made here. The prior procedural clarification comment already records the first-launch cause as unknown and distinguishes manual from automatic time-gate checks.
test(relay): skip receiver reconnect tests without relay extras
fix(relay): diagnose route failures and safely retry setup timeouts (#…
fix(relay): shorten receiver reconnect gaps and count role_busy refusals
test(relay): skip receiver reconnect tests without relay extras
fix(relay): shorten receiver reconnect gaps and count role_busy refus…
release: prepare 1.0.0rc3 for Relay stability validation (#169)
abruption commentedon Sep 24, 2026
Offline deterministic reproduction and a+b A/B showed reduced idle reconnect gaps and faster stalled-leg detection; #168 shipped these mitigations. In rc4-rerun-02, health was 241/241, probes 147/147, waiting rooms stayed at 3 in all 241 samples, and the receiver reconnect gap p95 was about 1.94 s on mini. This validates the product-side amplifier mitigation. It does not establish or repair the external Cloudflare↔KR stall root cause; #161 remains open for v1.0.1 monitoring. Closing this scoped lifecycle issue.