From 33a88f3d835c8f9aaa8922425f518e85bd9cfdfc Mon Sep 17 00:00:00 2001 From: Kamil Krzywda Date: Sat, 26 Sep 2026 08:50:27 +0000 Subject: [PATCH] Watchdog tracks decoded frames, not raw bytes; buffer-overflow backstop (v0.21.2) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Second production zombie slipped past v0.21.1's watchdog: text+telemetry RX dead for >1 h while TX worked and the watchdog never fired. Root cause proven at runtime via /proc/net/snmp — InSegs delta = 2 segments per 30 s (OutSegs 0): the bridge peer keeps dribbling small NON-frame bytes (~every 15 s, keepalive noise or a desynced stream) and v0.21.1 updated lastPacketAt on EVERY socket chunk, so 'no traffic for MESH_IDLE_TIMEOUT_MS' was never true even though zero valid Meshtastic frames decoded. - The 'data' handler no longer updates lastPacketAt per chunk; it is updated only when extractFrames yields >=1 valid packet (the reset in the 'connect' handler is unchanged), so a stream that decodes nothing trips the watchdog after MESH_IDLE_TIMEOUT_MS even while raw bytes keep arriving. - Buffer-overflow backstop: if the undecoded frame buffer exceeds MESH_MAX_FRAME_BUFFER (new env, default 256000) — e.g. one data event of a desynced stream that never forms frames — log ERROR and destroy the socket; the existing close -> scheduleReconnect loop self-heals it. The undecoded buffer is also reset on every (re)connect so leftover garbage from a dead session can't re-trigger the backstop or corrupt the first frames of a healthy new stream. Tests: 169 -> 171 — raw non-frame bytes do NOT keep the watchdog alive (garbage-only stream forces disconnect + reconnect, today's incident shape), and an undecoded chunk over MESH_MAX_FRAME_BUFFER triggers destroy + a fresh session that decodes normally (cap env-overridden to 100 since Node delivers socket data in ~64 KB events, far below the 256_000 default). --- AGENTS.md | 2 +- CHANGELOG.md | 6 ++++ package.json | 2 +- src/mesh/mesh.service.spec.ts | 63 +++++++++++++++++++++++++++++++++++ src/mesh/mesh.service.ts | 40 ++++++++++++++++------ 5 files changed, 100 insertions(+), 13 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index e9a8d8a..e04856c 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -12,7 +12,7 @@ ## Verification 1. **Local checks** — `npm run build` (nest build) and `npm test` (vitest; no e2e suite yet). Both must pass before a PR is opened. -2. **Docker** — `docker compose build`, then after `docker compose up -d`: `curl -s -H "Host: bot.dev.kkhost.pl" http://localhost/api/status` returns JSON (`{ connected, myNodeNum, host, port }`). `"connected":false` is normal while the bridge/device is down — the service retries every 5 s. An idle watchdog also force-reconnects an ESTABLISHED-but-silent connection (zombie bridge: outbound works, inbound dead) when no packet arrives from the bridge for `MESH_IDLE_TIMEOUT_MS` ms (default 600000 = 10 min; checked every 30 s), and the socket has TCP keepalive enabled (30 s). +2. **Docker** — `docker compose build`, then after `docker compose up -d`: `curl -s -H "Host: bot.dev.kkhost.pl" http://localhost/api/status` returns JSON (`{ connected, myNodeNum, host, port }`). `"connected":false` is normal while the bridge/device is down — the service retries every 5 s. An idle watchdog also force-reconnects an ESTABLISHED-but-silent connection (zombie bridge: outbound works, inbound dead) when no DECODED FRAME arrives from the bridge for `MESH_IDLE_TIMEOUT_MS` ms (default 600000 = 10 min; checked every 30 s — raw non-frame bytes do NOT count), an undecoded frame buffer over `MESH_MAX_FRAME_BUFFER` bytes (default 256000) forces a reconnect as a stream-desync backstop, and the socket has TCP keepalive enabled (30 s). ## API diff --git a/CHANGELOG.md b/CHANGELOG.md index 5d58506..7b750a2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,11 @@ # Changelog +## v0.21.2 — 2026-09-26 08:47 + +- Idle watchdog now tracks DECODED FRAMES, not raw bytes (fixes a second production zombie that slipped past v0.21.1): text+telemetry RX was dead for >1 h while TX worked and the watchdog never fired — /proc/net/snmp showed InSegs delta = 2 segments per 30 s, i.e. the bridge peer keeps dribbling small NON-frame bytes (~every 15 s) that kept resetting `lastPacketAt` on every socket chunk even though zero valid Meshtastic frames decoded. The `'data'` handler no longer updates `lastPacketAt` per chunk; it is updated only when `extractFrames` yields ≥1 valid packet (the reset in the `'connect'` handler is unchanged), so a stream that decodes nothing trips the watchdog after `MESH_IDLE_TIMEOUT_MS` even while raw bytes keep arriving. +- Buffer-overflow backstop: if the undecoded frame buffer exceeds `MESH_MAX_FRAME_BUFFER` (new env, default **256000** = 250 KB) the service logs ERROR ("frame buffer overflow — stream desync, forcing reconnect") and destroys the socket → existing close→scheduleReconnect self-heals a desynced stream. The undecoded buffer is also reset on every (re)connect so leftover garbage from a dead session can't re-trigger the backstop or corrupt the first frames of a healthy new stream. +- Tests: 169 → 171 — raw non-frame bytes do NOT keep the watchdog alive (garbage-only stream forces disconnect + reconnect, exactly today's incident shape), and an undecoded chunk over `MESH_MAX_FRAME_BUFFER` triggers destroy + a fresh session that decodes normally. The existing valid-frames-reset-the-clock test now exercises frame-based tracking unchanged. + ## v0.21.1 — 2026-09-26 06:47 - Bridge zombie-connection fix (production incident: outbound sends kept working ~10 h while inbound packets stopped entirely and `/api/status` stayed `connected:true`). New **idle watchdog**: the service tracks `lastPacketAt`, updated on EVERY chunk received from the bridge in the lowest-level socket `'data'` path (any frame kind, decodable or not) and reset when a connection successfully starts. A 30 s interval checks: if connected AND no inbound traffic for `MESH_IDLE_TIMEOUT_MS` (new env, default **600000** = 10 min), it logs WARN ("no bridge traffic for X ms — forcing reconnect") and destroys the socket — the EXISTING connect/retry loop (`MESH_RECONNECT_MS`) then re-establishes with a fresh sync. No changes to connect-error retry/backoff behavior; this only adds detection for established-but-silent connections. diff --git a/package.json b/package.json index 4b0b281..ffb2621 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "mesh-bot", - "version": "0.21.1", + "version": "0.21.2", "description": "", "author": "", "private": true, diff --git a/src/mesh/mesh.service.spec.ts b/src/mesh/mesh.service.spec.ts index be0cffa..2c95975 100644 --- a/src/mesh/mesh.service.spec.ts +++ b/src/mesh/mesh.service.spec.ts @@ -280,6 +280,69 @@ describe('MeshService idle watchdog', () => { } }); + it('raw non-frame bytes do NOT keep the watchdog alive — a garbage-only stream forces a reconnect', async () => { + const bridge = await startBridge(); + process.env.MESH_HOST = '127.0.0.1'; + process.env.MESH_PORT = String(bridge.port); + process.env.MESH_RECONNECT_MS = '50'; // fast retry so the re-establishment is observable + process.env.MESH_IDLE_TIMEOUT_MS = '100'; // override — the default (600000) would never fire in a test + const svc = new MeshService(); + try { + svc.onModuleInit(); + await waitFor( + () => bridge.sockets.length === 1 && svc.status().connected, + ); + + // today's incident: the peer keeps dribbling small non-frame bytes (keepalive noise / desynced stream) — raw chunks must not reset the idle clock + const garbage = Buffer.from('zz-no-frames-here'); // pure ASCII — never forms a 0x94 0xc3 frame header + for (let i = 0; i < 6; i++) { + await sleep(50); // ~300 ms wall time, well past the timeout + bridge.sockets[0].write(garbage); + } + + svc.checkIdle(); + await waitFor(() => bridge.sockets.length >= 2 && svc.status().connected); + } finally { + delete process.env.MESH_RECONNECT_MS; + delete process.env.MESH_IDLE_TIMEOUT_MS; + svc.onModuleDestroy(); + bridge.close(); + } + }); + + it('forces a reconnect when the undecoded frame buffer exceeds MESH_MAX_FRAME_BUFFER', async () => { + const bridge = await startBridge(); + process.env.MESH_HOST = '127.0.0.1'; + process.env.MESH_PORT = String(bridge.port); + process.env.MESH_RECONNECT_MS = '50'; // fast retry so the re-establishment is observable + process.env.MESH_MAX_FRAME_BUFFER = '100'; // tiny cap — Node delivers socket data in ~64 KB events, far below the 256_000 default + const svc = new MeshService(); + try { + svc.onModuleInit(); + await waitFor( + () => bridge.sockets.length === 1 && svc.status().connected, + ); + + // non-frame bytes (0x42 is not part of any frame header) — a desynced stream that never forms frames; the first ~64 KB data event alone exceeds the cap + bridge.sockets[0].write(Buffer.alloc(300_000, 0x42)); + + // overflow forced a reconnect — fresh session + await waitFor(() => bridge.sockets.length >= 2 && svc.status().connected); + + // the new socket starts with a clean buffer and decodes valid frames normally (the myInfo frame is well under the cap) + const fr = create(P.Mesh.FromRadioSchema, { + payloadVariant: { case: 'myInfo', value: { myNodeNum: 777 } }, + }); + bridge.sockets[1].write(frame(toBinary(P.Mesh.FromRadioSchema, fr))); + await waitFor(() => svc.status().myNodeNum === 777); + } finally { + delete process.env.MESH_RECONNECT_MS; + delete process.env.MESH_MAX_FRAME_BUFFER; + svc.onModuleDestroy(); + bridge.close(); + } + }); + it('inbound traffic keeps resetting the idle clock — no false trigger while packets arrive', async () => { const bridge = await startBridge(); process.env.MESH_HOST = '127.0.0.1'; diff --git a/src/mesh/mesh.service.ts b/src/mesh/mesh.service.ts index 704f829..d9246be 100644 --- a/src/mesh/mesh.service.ts +++ b/src/mesh/mesh.service.ts @@ -210,11 +210,16 @@ export class MeshService implements OnModuleInit, OnModuleDestroy { ); // how often the poller re-upserts the history buffer into SQLite (ms) private readonly pollMs = parseInt(process.env.MESH_POLL_MS ?? '1000', 10); - // idle watchdog: force a reconnect when an ESTABLISHED connection goes silent — the zombie-bridge case where outbound sends keep working but inbound packets stop entirely. Read at construction like the other env config. + // idle watchdog: force a reconnect when an ESTABLISHED connection stops decoding frames — the zombie-bridge case where outbound sends keep working but inbound frame flow is dead (raw non-frame bytes do NOT reset the clock). Read at construction like the other env config. private readonly idleTimeoutMs = parseInt( process.env.MESH_IDLE_TIMEOUT_MS ?? '600000', 10, ); + // cap on undecoded frame buffer: a desynced stream that never forms frames would grow it without bound — force a reconnect instead. Env-overridable so tests can trigger it (Node caps socket 'data' events at ~64 KB). + private readonly maxFrameBuffer = parseInt( + process.env.MESH_MAX_FRAME_BUFFER ?? '256000', + 10, + ); /** SQLite database backing the message history; null = persistence disabled (tests construct without one). */ private db: DatabaseSync | null = null; @@ -262,7 +267,7 @@ export class MeshService implements OnModuleInit, OnModuleDestroy { // telemetry history (newest kept, capped at HISTORY_LIMIT) private telemetryHistory: TelemetryRecord[] = []; private reconnectTimer: NodeJS.Timeout | null = null; - /** epoch ms of the last inbound chunk from the bridge (any frame kind); reset on connect — idle watchdog baseline */ + /** epoch ms when the last valid frame was decoded from the bridge; reset on connect — idle watchdog baseline */ private lastPacketAt = Date.now(); private idleTimer: NodeJS.Timeout | null = null; private shuttingDown = false; @@ -662,7 +667,9 @@ export class MeshService implements OnModuleInit, OnModuleDestroy { // fresh connection — reset the idle clock so it can't self-trigger before any traffic arrives this.lastPacketAt = Date.now(); // fresh sync on every (re)connect — drop stale channels/nodes/device info/telemetry from the old session; - // message history is NOT reset: it's an append-only log backed by SQLite and survives reconnects + // message history is NOT reset: it's an append-only log backed by SQLite and survives reconnects. + // The undecoded frame buffer goes too: leftover desync garbage must not re-trigger the overflow backstop on a healthy new stream. + this.buffer = new Uint8Array(0); this.channelMap = new Map(); this.nodeMap = new Map(); this.metadata = null; @@ -680,14 +687,22 @@ export class MeshService implements OnModuleInit, OnModuleDestroy { this.logger.log(`requested initial sync (want_config_id=${nonce})`); }); socket.on('data', (chunk) => { - // lowest-level receive path: every inbound chunk counts as bridge traffic, decodable or not — this is what the idle watchdog watches - this.lastPacketAt = Date.now(); const merged = new Uint8Array(this.buffer.length + chunk.length); merged.set(this.buffer, 0); merged.set(chunk, this.buffer.length); + // buffer-overflow backstop: a desynced stream that never forms frames would grow the buffer without bound — cap it and self-heal via reconnect + if (merged.length > this.maxFrameBuffer) { + this.logger.error( + 'frame buffer overflow — stream desync, forcing reconnect', + ); + socket.destroy(); + return; + } this.buffer = merged; const { packets, rest } = extractFrames(this.buffer); this.buffer = rest; + // the watchdog tracks DECODED FRAMES, not raw bytes: non-frame noise (keepalives, desynced streams) must not keep a dead connection alive + if (packets.length) this.lastPacketAt = Date.now(); for (const p of packets) { decodeFromRadio(p) .then((fr) => this.handleFromRadio(fr)) @@ -714,17 +729,20 @@ export class MeshService implements OnModuleInit, OnModuleDestroy { } /** - * Idle watchdog tick: force a reconnect when an ESTABLISHED connection has seen no inbound bridge - * traffic for MESH_IDLE_TIMEOUT_MS — the zombie case where outbound sends keep working but inbound - * packets stop. Destroying the socket routes through 'close' → onDown → scheduleReconnect, so the - * existing connect/retry loop re-establishes with a fresh sync; no new retry machinery here. - * Public so tests can drive a tick without waiting for the real interval (like flushHistory()). + * Idle watchdog tick: force a reconnect when an ESTABLISHED connection has decoded no frames from + * the bridge for MESH_IDLE_TIMEOUT_MS — the zombie case where outbound sends keep working but inbound + * frame flow is dead (raw non-frame bytes arriving on the socket do not count). Destroying the socket + * routes through 'close' → onDown → scheduleReconnect, so the existing connect/retry loop re-establishes + * with a fresh sync; no new retry machinery here. Public so tests can drive a tick without waiting for + * the real interval (like flushHistory()). */ checkIdle(): void { if (!this.connected) return; // disconnected state is owned by the connect/retry loop const idle = Date.now() - this.lastPacketAt; if (idle > this.idleTimeoutMs) { - this.logger.warn(`no bridge traffic for ${idle} ms — forcing reconnect`); + this.logger.warn( + `no decoded bridge frames for ${idle} ms — forcing reconnect`, + ); this.socket?.destroy(); } }