fix(button-light): back off failed setAux sends — kill the ENETUNREACH hot loop
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
This commit is contained in:
@@ -192,11 +192,78 @@ describe("ButtonLightController truth table", () => {
|
|||||||
// First write (initial off) throws — must be swallowed.
|
// First write (initial off) throws — must be swallowed.
|
||||||
expect(() => ctl.start()).not.toThrow();
|
expect(() => ctl.start()).not.toThrow();
|
||||||
await flush();
|
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);
|
lane(true);
|
||||||
radar(true);
|
radar(true);
|
||||||
await flush();
|
await flush();
|
||||||
expect(ctl.confirmedOf(CONTROLLER)).toBe(true);
|
expect(ctl.confirmedOf(CONTROLLER)).toBe(true);
|
||||||
|
expect(attempts).toBe(before + 1);
|
||||||
ctl.stop();
|
ctl.stop();
|
||||||
});
|
});
|
||||||
|
|
||||||
|
|||||||
@@ -21,6 +21,14 @@ type LightState = "off" | "solid" | "blink";
|
|||||||
|
|
||||||
const DEFAULT_BLINK_MS = 500;
|
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). */
|
/** Per-lamp live state for the alert rule (one per radarAlert relay). */
|
||||||
interface LampState {
|
interface LampState {
|
||||||
/** The controller this lamp lives on (its deviceId) — for resolving the aux adapter. */
|
/** 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
|
/** 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). */
|
* overlap or reorder (UDP is unordered; concurrent toggles left the relay stuck). */
|
||||||
sending: boolean;
|
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<typeof setTimeout> | 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
|
/** Resolves a controller's live aux-output adapter. The default goes through the
|
||||||
@@ -111,6 +129,10 @@ export class ButtonLightController {
|
|||||||
desiredOn: false,
|
desiredOn: false,
|
||||||
confirmedOn: null,
|
confirmedOn: null,
|
||||||
sending: false,
|
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).
|
// Drop lamps whose controller no longer declares one (or was disabled/removed).
|
||||||
for (const [key, lamp] of this.#lamps) {
|
for (const [key, lamp] of this.#lamps) {
|
||||||
if (seen.has(key)) continue;
|
if (seen.has(key)) continue;
|
||||||
if (lamp.blink) {
|
this.#disarm(lamp);
|
||||||
clearInterval(lamp.blink);
|
|
||||||
lamp.blink = null;
|
|
||||||
}
|
|
||||||
this.#finalOff(lamp); // best-effort fail-OFF before forgetting it
|
this.#finalOff(lamp); // best-effort fail-OFF before forgetting it
|
||||||
this.#lamps.delete(key);
|
this.#lamps.delete(key);
|
||||||
}
|
}
|
||||||
@@ -207,10 +226,17 @@ export class ButtonLightController {
|
|||||||
* time. Because UDP is unordered, concurrent on/off sends previously raced and left
|
* 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
|
* 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 —
|
* (`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 {
|
#pump(lamp: LampState): void {
|
||||||
if (lamp.sending) return; // a send is already in flight; it'll re-check on completion
|
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 (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);
|
const aux = this.#resolveAux(lamp.controllerId);
|
||||||
if (!aux) return;
|
if (!aux) return;
|
||||||
const target = lamp.desiredOn;
|
const target = lamp.desiredOn;
|
||||||
@@ -219,15 +245,42 @@ export class ButtonLightController {
|
|||||||
.setAux(lamp.spec.relay, target)
|
.setAux(lamp.spec.relay, target)
|
||||||
.then(() => {
|
.then(() => {
|
||||||
lamp.confirmedOn = target;
|
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) => {
|
.catch((err: unknown) => {
|
||||||
// Leave confirmedOn unchanged so the next pump retries this state. Never escalates.
|
// Leave confirmedOn unchanged so the armed retry re-asserts the (then-current)
|
||||||
this.#logger.error(`button-light setAux failed (${lamp.controllerId} R${lamp.spec.relay}): ${(err as Error).message}`);
|
// 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(() => {
|
.finally(() => {
|
||||||
lamp.sending = false;
|
lamp.sending = false;
|
||||||
// Desired state may have changed (or the send failed) while we were busy —
|
// Desired state may have changed while we were busy — re-pump to converge (the
|
||||||
// re-pump to converge. This is what makes the final state authoritative.
|
// 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);
|
if (lamp.confirmedOn !== lamp.desiredOn) this.#pump(lamp);
|
||||||
});
|
});
|
||||||
}
|
}
|
||||||
@@ -261,20 +314,31 @@ export class ButtonLightController {
|
|||||||
this.#unsubInput = null;
|
this.#unsubInput = null;
|
||||||
this.#unsubLane = null;
|
this.#unsubLane = null;
|
||||||
for (const lamp of this.#lamps.values()) {
|
for (const lamp of this.#lamps.values()) {
|
||||||
if (lamp.blink) {
|
this.#disarm(lamp);
|
||||||
clearInterval(lamp.blink);
|
|
||||||
lamp.blink = null;
|
|
||||||
}
|
|
||||||
// Best-effort fail-OFF on shutdown.
|
// Best-effort fail-OFF on shutdown.
|
||||||
this.#finalOff(lamp);
|
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
|
/** 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
|
* 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 {
|
#finalOff(lamp: LampState): void {
|
||||||
lamp.desiredOn = false;
|
lamp.desiredOn = false;
|
||||||
|
lamp.retryAt = 0;
|
||||||
this.#pump(lamp);
|
this.#pump(lamp);
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
Reference in New Issue
Block a user