Watchdog tracks decoded frames, not raw bytes; buffer-overflow backstop (v0.21.2)
CI / build + unit (pull_request) Failing after 39s

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).
This commit is contained in:
2026-09-26 08:50:27 +00:00
parent 306756c63b
commit 33a88f3d83
5 changed files with 100 additions and 13 deletions
+63
View File
@@ -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';
+29 -11
View File
@@ -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();
}
}