Open general

ws_client: zero backoff on repeated clean closes creates a 20Hz reconnect storm and ~1GB/day log spam when a relay backend is dead behind a live proxy

Drew Owens · 7d ago

Type: Bug · ws_client reconnects with backoff=0 forever when the server closes cleanly, producing a ~20Hz reconnect storm and ~1GB/day of log spam

Symptom

Three cloud relay connections in my AD (gallia, AdomPNP, factoryOS) sit in a tight loop, each cycle ~130-160ms:

[15:01:59][app_lib::ws_client][INFO] [gallia] WebSocket connected
[15:01:59][app_lib::ws_client][INFO] [gallia] Authenticated - clientId: unknown
[15:01:59][app_lib::ws_client][INFO] [gallia] Server sent close frame
[15:01:59][app_lib::ws_client][INFO] [gallia] WS closed cleanly after 142.979ms - backoff=0, reconnecting immediately
[15:01:59][app_lib::ws_client][INFO] [gallia] Connecting to wss://drew2-gallia-....adom.cloud/proxy/8765/...

Three relays at ~150ms per cycle is roughly 20 reconnects/sec aggregate. The log wrote 22.9MB in 34 minutes (about 1GB/day pace), hit the rotation cap, and rotated away all history, so I can no longer see when the storm started.

Trigger

The peer endpoints are half-dead: the Cloudflare proxy in front of each accepts the WS upgrade fast (~130ms round trip, HTTP 400 on plain GET as expected for WS-only), but the relay server behind it is gone or mismatched, so auth never yields a clientId ("Authenticated - clientId: unknown") and the server closes immediately. My side; I will fix the backends. But any user with a stale/dead relay entry will reproduce this.

The AD bug

ws_client treats a clean server close as grounds to reconnect immediately with zero backoff, forever. A dead-but-proxied endpoint therefore turns into an infinite tight loop: CPU + network churn, log spam that defeats rotation, and the real history destroyed exactly when you want to debug.

Suggested fix

  1. Exponential backoff on repeated clean closes: if a connection closes cleanly within N seconds of connecting (i.e. it never did useful work), back off like an error close would: e.g. 1s, 2s, 5s, 15s, 60s cap, with jitter. A close after a healthy long-lived session can keep the fast reconnect.
  2. Treat "authenticated but no clientId" as auth failure, not success: it currently logs as Authenticated then acts surprised at the close. If no clientId arrives, count it as a failed attempt for backoff purposes.
  3. Log throttle: collapse repeated identical connect/close cycles into a periodic summary line ("[gallia] 1,240 reconnect cycles in last 60s, backing off"), so rotation stops eating real history.

Environment

AD 1.9.217, Windows laptop adom_drew2, embedded under HD. Main laptop relay unaffected throughout (commands flow normally). Endpoints: drew2-gallia-*.adom.cloud/proxy/8765, drew2-adompnp-*.adom.cloud/proxy/8765, factoryos-relay-*.adom.cloud.

Log excerpts and timing measurements available on request; the loop is trivially reproducible by pointing a relay entry at a proxied host whose backend is down.

2 Replies

John Lauer · 7d ago

Fixed in AD 1.9.219 (commit 8002648). Your diagnosis was exact: the clean-close path set backoff=0 unconditionally, forever. It was written for one legitimate case - the relay's kick_all Close frame during a relay restart, where an instant redial is the point - and never considered the dead-backend-behind-a-live-proxy shape you hit.

The fix splits clean closes on connection lifetime, the same test the error path already used: a clean close after >10s connected keeps the instant reconnect (the kick_all case); a clean close after <=10s escalates exactly like a quick failure, 1s -> 2s -> ... -> 30s cap. A healthy long-lived session resets the ladder. So your three half-dead relays converge to one attempt per 30s per relay instead of ~20/sec aggregate, and the log volume drops proportionally (also relevant: since 1.9.216 the log file holds ~a day at 24MB with janitor-bounded rotation, so a storm no longer instantly destroys the history you need to debug it).

Your side note about auth never yielding a clientId is worth keeping open on your end - AD now backs off politely, but a relay whose proxy is alive with no backend behind it will still read as 'reconnecting' in the Connections panel rather than something more diagnostic. If that distinction matters to you, file it as a follow-up and we can surface 'backend unreachable behind proxy' when auth dies fast repeatedly.

John Lauer · 1d ago

Already fixed in v1.9.219 — the short-lived clean-close path now escalates backoff (0→1s→2s→…→30s cap) exactly like a quick error, so a dead relay behind a live proxy (accepts the upgrade, closes ~150ms later) can't produce the 20Hz storm. A long-lived (>10s) clean close still reconnects immediately (the kick_all restart case), which can't storm because each cycle costs >10s of uptime. Closing as resolved.

Log in to reply.