screentinker/server/lib/status-log-writer.js
ScreenTinker 81e7d58099 fix(#146): reconnect/heartbeat storm containment (beta5)
Second head of the OTA-loop root cause (#144), on the connection/heartbeat
layer: unbounded device-driven work with no circuit-breaker. Symptoms in Bold
prod — devices shown OFFLINE in CMS while online+playing, loop-lag simmer
(p99 300-1145ms), device_status_log grown to 1.1M rows.

False-offline (two causes, both fixed):
- evicted-socket re-arm race: evictPriorSocket runs before registerConnection,
  so the evicted old socket's disconnect armed a fresh offline timer for a
  just-reconnected device. Tag evicted socket ids and bail in the disconnect
  handler (ws/deviceSocket.js).
- heartbeat checker false-positive: a device with a live socket in /device is
  UP even if its in-memory lastHeartbeat is stale under lag; skip it instead of
  marking offline (services/heartbeat.js).

Storm containment:
- batched/coalescing device_status_log writer (lib/status-log-writer.js): net
  state per device per flush, breaking the storm->bloat->slow-write->lag loop.
- newest-N-per-device row-count cap in the global sweep (db/database.js): hard
  bound regardless of churn; trims the existing 1.1M backlog on the first sweep.
  Per-device prune unified to statusLogRetentionDays (was hardcoded 7d).
- reconnect-throttle idle-bucket sweep (lib/reconnect-throttle.js): the #142
  throttle already existed; added the memory-bound sweep it lacked (wired in
  server.js). No second breaker.
- cosmetic: cap the OTA breaker level counter (lib/ota-breaker.js).
- best-effort status-log flush on the crash path (server.js).

Tests: load harness (test/reconnect-storm-load.test.js) proves breaker engage,
clean offline-clear, no-throttle-on-normal-reconnect, batched writes, bounded
loop-lag; cause-1 re-arm race proven with teeth (test/evicted-socket-rearm.test.js).
Both mutation-checked (fail without their fix). Full suite 240/240.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
2026-06-29 22:12:13 -05:00

80 lines
3.3 KiB
JavaScript

// #146 — batched, coalescing writer for device_status_log.
//
// Before: every device status transition (online/offline/offline_timeout) did its
// own synchronous INSERT on the hot path (deviceSocket.logDeviceStatus + the
// heartbeat checker). Under a reconnect storm that is one row PER flap, which both
// (a) bloats the table — it reached 1.1M rows in prod — and (b) makes each write
// slower as the table grows, lagging status processing further. A textbook feedback
// loop, the connection-layer twin of the OTA loop #144 contained.
//
// After: transitions are buffered in memory and flushed on an interval. The buffer
// keeps only the LATEST (net) status per device, so a device that flaps
// online->offline->online within a flush window collapses to at most one row — and
// if it ends where it started, zero rows. devices.status (the dashboard's source of
// truth) is still updated immediately by the callers; only the AUDIT log is batched,
// so coalescing storm noise loses nothing the uptime view needs.
//
// State is in-memory and resets on restart (like the throttle / breaker buckets).
const { db } = require('../db/database');
const config = require('../config');
const pending = new Map(); // deviceId -> latest desired status (net state)
const lastWritten = new Map(); // deviceId -> last status actually inserted
let timer = null;
const insertStmt = () => db.prepare('INSERT INTO device_status_log (device_id, status) VALUES (?, ?)');
// Per-device age prune — the #146 fix for the old hardcoded 7-day window in
// deviceSocket.js (now a single source of truth: config.statusLogRetentionDays).
const pruneDeviceStmt = () =>
db.prepare("DELETE FROM device_status_log WHERE device_id = ? AND timestamp < strftime('%s','now') - ?");
// Record a transition. Cheap and allocation-light: just remembers the latest state.
function record(deviceId, status) {
if (!deviceId || !status) return;
pending.set(deviceId, status);
}
// Write all buffered transitions whose net state differs from what's on disk.
// Returns the number of rows actually inserted (for tests/observability).
function flush() {
if (pending.size === 0) return 0;
const batch = [];
for (const [deviceId, status] of pending) {
if (lastWritten.get(deviceId) !== status) batch.push([deviceId, status]);
}
pending.clear();
if (batch.length === 0) return 0;
try {
const ins = insertStmt();
const prune = pruneDeviceStmt();
const ageSec = Math.round(config.statusLogRetentionDays * 86400);
const writeAll = db.transaction((rows) => {
for (const [deviceId, status] of rows) {
ins.run(deviceId, status);
lastWritten.set(deviceId, status);
prune.run(deviceId, ageSec);
}
});
writeAll(batch);
return batch.length;
} catch (_) {
// table might not exist yet (early boot) — drop silently, same as the old path
return 0;
}
}
function start() {
if (timer) return timer;
timer = setInterval(flush, config.statusLogFlushMs);
if (timer.unref) timer.unref(); // don't keep the process alive on the flush timer
return timer;
}
// Test-only: force a synchronous flush and clear coalescing memory.
function flushNow() { return flush(); }
function __reset() { pending.clear(); lastWritten.clear(); }
module.exports = { record, flush, flushNow, start, __reset };