From e2d5105da24af149de653ced1a042e4771ca5fb7 Mon Sep 17 00:00:00 2001 From: Julian Cuni Date: Fri, 10 Jul 2026 08:29:33 +0200 Subject: [PATCH] =?UTF-8?q?fix(button-light):=20back=20off=20failed=20setA?= =?UTF-8?q?ux=20sends=20=E2=80=94=20kill=20the=20ENETUNREACH=20hot=20loop?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An unreachable controller rejects the UDP send instantly, and #pump's failure re-pump retried inline: a tight loop logging hundreds of identical errors per minute (park-buzi, 2026-07-07). Failed sends now arm a 1s→30s exponential retry (reset on success); desiredOn keeps tracking the truth table meanwhile and the armed retry converges to it. Logging is rate-limited: first failure of a streak in full, then one summary/minute, one info line on recovery. #finalOff waives the backoff so the last-gasp OFF on drop/shutdown still gets an immediate try. Claude-Session: https://claude.ai/code/session_01Xcm6ikLgGoCxxHrxtjkk5V --- apps/server/src/button-light.test.ts | 69 ++++++++++++++++++++- apps/server/src/button-light.ts | 92 +++++++++++++++++++++++----- 2 files changed, 146 insertions(+), 15 deletions(-) diff --git a/apps/server/src/button-light.test.ts b/apps/server/src/button-light.test.ts index 90d7e93..7b3b5fc 100644 --- a/apps/server/src/button-light.test.ts +++ b/apps/server/src/button-light.test.ts @@ -192,11 +192,78 @@ describe("ButtonLightController truth table", () => { // First write (initial off) throws — must be swallowed. expect(() => ctl.start()).not.toThrow(); await flush(); - // Subsequent writes work; driving to solid still converges to ON. + // The failure arms a backoff (1s) rather than retrying inline; desired-state + // changes during the window just update the target the retry will assert. + lane(true); + radar(true); + await flush(); + expect(ctl.confirmedOf(CONTROLLER)).toBeNull(); // still backing off + await vi.advanceTimersByTimeAsync(1000); // retry fires; aux is healthy again + expect(ctl.confirmedOf(CONTROLLER)).toBe(true); // converged to solid ON + ctl.stop(); + }); + + it("an unreachable controller backs off (1s→30s), not a hot retry loop", async () => { + let attempts = 0; + const aux: AuxOutputDevice = { + async setAux() { + attempts += 1; + throw new Error("send ENETUNREACH 10.0.10.5:60000"); + }, + }; + const errors: string[] = []; + const logger = silentLogger(); + (logger as { error: (msg: string) => void }).error = (msg) => errors.push(msg); + const ctl = new ButtonLightController(db, logger, () => aux); + ctl.start(); // initial OFF write → attempt 1 fails at t=0 + await flush(); + expect(attempts).toBe(1); // the old code hot-looped here + + // Failures at t≈0,1,3,7,15,31 (doubling, capped 30s) → 6 attempts in the first + // minute instead of thousands. + await vi.advanceTimersByTimeAsync(60_000); + expect(attempts).toBeGreaterThanOrEqual(5); + expect(attempts).toBeLessThanOrEqual(7); + + // Only the FIRST failure was logged so far; the next log is a ≥60s summary. + expect(errors).toHaveLength(1); + await vi.advanceTimersByTimeAsync(35_000); // t≈95s → the t=61s attempt logged a summary + expect(errors.length).toBe(2); + expect(errors[1]).toContain("still failing"); + ctl.stop(); + }); + + it("logs a single recovery line and resets the backoff after success", async () => { + let failing = true; + let attempts = 0; + const aux: AuxOutputDevice = { + async setAux() { + attempts += 1; + if (failing) throw new Error("send ENETUNREACH 10.0.10.5:60000"); + }, + }; + const infos: string[] = []; + const logger = silentLogger(); + (logger as { info: (msg: string) => void }).info = (msg) => infos.push(msg); + const ctl = new ButtonLightController(db, logger, () => aux); + ctl.start(); + await flush(); + await vi.advanceTimersByTimeAsync(3_000); // attempts at t=0,1,3 all fail + const failed = attempts; + expect(failed).toBeGreaterThanOrEqual(3); + + failing = false; // controller reachable again + await vi.advanceTimersByTimeAsync(8_000); // next armed retry succeeds + expect(ctl.confirmedOf(CONTROLLER)).toBe(false); // OFF asserted on the device + expect(infos.filter((m) => m.includes("recovered"))).toHaveLength(1); + + // Backoff reset: a fresh state change sends immediately (no lingering retryAt). + const before = attempts; lane(true); radar(true); await flush(); expect(ctl.confirmedOf(CONTROLLER)).toBe(true); + expect(attempts).toBe(before + 1); ctl.stop(); }); diff --git a/apps/server/src/button-light.ts b/apps/server/src/button-light.ts index c413cca..008430f 100644 --- a/apps/server/src/button-light.ts +++ b/apps/server/src/button-light.ts @@ -21,6 +21,14 @@ type LightState = "off" | "solid" | "blink"; const DEFAULT_BLINK_MS = 500; +// Failed-send retry backoff: 1s doubling to 30s, reset on success. Without this an +// unreachable controller (ENETUNREACH) became a hot loop — the failure re-pump retried +// instantly, thousands of sends + error lines per minute (field incident 2026-07-07). +const RETRY_BASE_MS = 1_000; +const RETRY_MAX_MS = 30_000; +/** After the first failure of a streak, log at most one summary line per this window. */ +const FAIL_LOG_EVERY_MS = 60_000; + /** Per-lamp live state for the alert rule (one per radarAlert relay). */ interface LampState { /** The controller this lamp lives on (its deviceId) — for resolving the aux adapter. */ @@ -44,6 +52,16 @@ interface LampState { /** True while a send is in flight for this lamp — serializes UDP so on/off can't * overlap or reorder (UDP is unordered; concurrent toggles left the relay stuck). */ sending: boolean; + /** Consecutive failed sends (0 = healthy). Drives the backoff delay + log summaries. */ + failCount: number; + /** Epoch ms before which #pump must not send (0 = no backoff). The armed retry + * timer re-pumps when it elapses; desired-state changes in between just update + * `desiredOn` and are picked up by that same retry. */ + retryAt: number; + /** The armed backoff retry, if any. */ + retryTimer: ReturnType | null; + /** Epoch ms of the last failure line we actually logged (rate-limits the flood). */ + lastFailLogAt: number; } /** Resolves a controller's live aux-output adapter. The default goes through the @@ -111,6 +129,10 @@ export class ButtonLightController { desiredOn: false, confirmedOn: null, sending: false, + failCount: 0, + retryAt: 0, + retryTimer: null, + lastFailLogAt: 0, }); } } @@ -118,10 +140,7 @@ export class ButtonLightController { // Drop lamps whose controller no longer declares one (or was disabled/removed). for (const [key, lamp] of this.#lamps) { if (seen.has(key)) continue; - if (lamp.blink) { - clearInterval(lamp.blink); - lamp.blink = null; - } + this.#disarm(lamp); this.#finalOff(lamp); // best-effort fail-OFF before forgetting it this.#lamps.delete(key); } @@ -207,10 +226,17 @@ export class ButtonLightController { * time. Because UDP is unordered, concurrent on/off sends previously raced and left * the relay stuck on a stale packet. Here a single in-flight send is guaranteed * (`sending` guard); when it resolves, if the desired state moved on we send again — - * so the LAST desired state is always the one finally asserted on the device. */ + * so the LAST desired state is always the one finally asserted on the device. + * + * Failures back off (1s → 30s, reset on success) instead of retrying inline: an + * unreachable controller rejects instantly, and an immediate re-pump was a hot loop. + * During backoff `desiredOn` keeps tracking the truth table; the armed retry timer + * converges to whatever it says when it fires. Only the FIRST failure of a streak is + * logged, then one summary per minute, and an info line on recovery. */ #pump(lamp: LampState): void { if (lamp.sending) return; // a send is already in flight; it'll re-check on completion if (lamp.confirmedOn === lamp.desiredOn) return; // already there — no redundant UDP + if (Date.now() < lamp.retryAt) return; // backing off — the retry timer will re-pump const aux = this.#resolveAux(lamp.controllerId); if (!aux) return; const target = lamp.desiredOn; @@ -219,15 +245,42 @@ export class ButtonLightController { .setAux(lamp.spec.relay, target) .then(() => { lamp.confirmedOn = target; + if (lamp.failCount > 0) { + this.#logger.info( + `button-light setAux recovered (${lamp.controllerId} R${lamp.spec.relay}) after ${lamp.failCount} failed attempts`, + ); + } + lamp.failCount = 0; + lamp.retryAt = 0; + lamp.lastFailLogAt = 0; }) .catch((err: unknown) => { - // Leave confirmedOn unchanged so the next pump retries this state. Never escalates. - this.#logger.error(`button-light setAux failed (${lamp.controllerId} R${lamp.spec.relay}): ${(err as Error).message}`); + // Leave confirmedOn unchanged so the armed retry re-asserts the (then-current) + // desired state. Never escalates — a dead lamp is "no hint", never a fault. + lamp.failCount += 1; + const delay = Math.min(RETRY_BASE_MS * 2 ** (lamp.failCount - 1), RETRY_MAX_MS); + lamp.retryAt = Date.now() + delay; + const now = Date.now(); + if (lamp.failCount === 1 || now - lamp.lastFailLogAt >= FAIL_LOG_EVERY_MS) { + lamp.lastFailLogAt = now; + const streak = + lamp.failCount > 1 ? ` — still failing (attempt ${lamp.failCount}, retrying ≤${RETRY_MAX_MS / 1000}s)` : ""; + this.#logger.error( + `button-light setAux failed (${lamp.controllerId} R${lamp.spec.relay}): ${(err as Error).message}${streak}`, + ); + } + if (lamp.retryTimer) clearTimeout(lamp.retryTimer); + lamp.retryTimer = setTimeout(() => { + lamp.retryTimer = null; + this.#pump(lamp); + }, delay); + lamp.retryTimer.unref?.(); }) .finally(() => { lamp.sending = false; - // Desired state may have changed (or the send failed) while we were busy — - // re-pump to converge. This is what makes the final state authoritative. + // Desired state may have changed while we were busy — re-pump to converge (the + // backoff gate above makes this a no-op right after a failure). This is what + // makes the final state authoritative. if (lamp.confirmedOn !== lamp.desiredOn) this.#pump(lamp); }); } @@ -261,20 +314,31 @@ export class ButtonLightController { this.#unsubInput = null; this.#unsubLane = null; for (const lamp of this.#lamps.values()) { - if (lamp.blink) { - clearInterval(lamp.blink); - lamp.blink = null; - } + this.#disarm(lamp); // Best-effort fail-OFF on shutdown. this.#finalOff(lamp); } } + /** Stop a lamp's timers (blink + backoff retry) without touching the device. */ + #disarm(lamp: LampState): void { + if (lamp.blink) { + clearInterval(lamp.blink); + lamp.blink = null; + } + if (lamp.retryTimer) { + clearTimeout(lamp.retryTimer); + lamp.retryTimer = null; + } + } + /** Drive a lamp OFF as a one-shot (used when dropping/stopping a lamp): set desired * OFF and pump. The serialized worker still applies, so this can't collide with an - * in-flight send — it converges to OFF. */ + * in-flight send — it converges to OFF. Any backoff is waived so the last-gasp OFF + * gets one immediate try (a lamp mid-backoff may just have recovered). */ #finalOff(lamp: LampState): void { lamp.desiredOn = false; + lamp.retryAt = 0; this.#pump(lamp); }