feat(#146): /api/status.debug throughput counters (gauges -> gauges + work done)

The debug block exposed only gauges (buckets, quarantined, inFlight) — state, not work.
A real flapping Firestick reads as flap.buckets:36, quarantined:0, indistinguishable
from healthy. Add lightweight in-memory throughput counters (total + last-completed
rolling window) so the server tells the flapper/flood story itself.

- lib/rolling-counter.js: shared bounded scalar counter (total, curWindow, lastWindow,
  windowStart); rolls lazily on bump AND read (no timer), idle decays to 0.
  DEBUG_STATS_WINDOW_MS default 60000.
- flap-limiter: refused{Total,LastWindow} (every allow:false), quarantineStarts{Total,
  LastWindow} (a quarantine event stays visible after the gauge decays).
- ota-breaker: stats() rateBackoff{Total,LastWindow}.
- ota-download-guard: servedTotal/shedTotal alongside the per-window values.
- database: maintenance sweepsTotal (confirm the prune is firing, not stalled).
- routes/status: debug block gains ota_breaker + the new fields (aggregate-only, cheap).

Tests: rolling-counter window-roll + idle decay; each counter increments on the right
event; booted /api/status asserts the new fields present + numeric. Suite 285/285.
Fallout doc: observability section lists the fields + what each tells a soak-watcher.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
ScreenTinker 2026-06-30 23:24:32 -05:00
parent e5661c9894
commit fa3ab44c20
10 changed files with 190 additions and 20 deletions

View file

@ -75,6 +75,22 @@ watch, and the measured worst-case blocking cost per hot path.
`event_loop_lag` table lags real time by up to 10s (**/api/status is unaffected** — it
reads in-memory current, so real-time band/alerting is intact).
### `/api/status.debug` THROUGHPUT counters (soak observability)
Each subsystem now exposes gauges **and** throughput (running `Total` + last-completed-
`LastWindow`, `DEBUG_STATS_WINDOW_MS` default 60s) so the server tells the flapper/flood
story on its own — no client trust:
- `flap.refusedLastWindow` — refusals/window. **Climbing while `band=normal` = the limiter
absorbing a flapper cheaply (the healthy signature — this is what "36 buckets, 0
quarantined" looked like but couldn't show). Climbing WITH band elevated/critical =
investigate.**
- `flap.quarantineStartsTotal/LastWindow` — a quarantine EVENT is visible even though the
`quarantined` gauge decays.
- `ota_breaker.rateBackoffLastWindow` — a device=none 1.8.x update-check flood shows here.
- `ota_download.servedTotal/shedTotal` — a download flood: `shedTotal` climbing = the
global cap engaging (only under elevated/critical).
- `maintenance.sweepsTotal` — confirms the prune is FIRING on its interval, not stalled
(with `deleted`/`ms` for cost). All aggregate-only, cheap in-memory reads.
## Before / after — worst-case synchronous blocking (measured)
| Hot path | Before | After (measured) |
|---|---|---|

View file

@ -192,6 +192,9 @@ module.exports = {
otaDownloadMaxPerWindow: parseInt(process.env.OTA_DOWNLOAD_MAX_PER_WINDOW) || 120,
otaDownloadWindowMs: parseInt(process.env.OTA_DOWNLOAD_WINDOW_MS) || 60000,
otaApkRefreshMs: parseInt(process.env.OTA_APK_REFRESH_MS) || 60000,
// #146 observability: rolling window for the /api/status.debug throughput counters, so
// "lastWindow" is comparable across subsystems.
debugStatsWindowMs: parseInt(process.env.DEBUG_STATS_WINDOW_MS) || 60000,
// #146 Item E — coalescing log flush + batched event_loop_lag telemetry.
logCoalesceFlushMs: parseInt(process.env.LOG_COALESCE_FLUSH_MS) || 30000,
lagFlushMs: parseInt(process.env.LAG_FLUSH_MS) || 10000,

View file

@ -773,7 +773,8 @@ const { applyTenantDeleteCascade } = require('../lib/tenant-cascade-migration');
// Rides idx_device_status_log_device_ts(device_id, timestamp).
let _statusPruneRunning = false;
let _lastPrune = { deleted: 0, ms: 0, at: 0 }; // #146 P3.8: soak observability
function getMaintenanceStats() { return { ..._lastPrune, running: _statusPruneRunning }; }
let _sweepsTotal = 0; // #146: prune sweeps completed (confirm it's firing, not stalled)
function getMaintenanceStats() { return { ..._lastPrune, running: _statusPruneRunning, sweepsTotal: _sweepsTotal }; }
async function pruneStatusLog(opts = {}) {
if (_statusPruneRunning) return 0; // re-entrancy: work runs once
if (opts.bandGate && config.maintenanceBandGateEnabled && currentBand() !== 'normal') return 0;
@ -800,6 +801,7 @@ async function pruneStatusLog(opts = {}) {
}
if (total > 0) console.log(`[status-log] pruned ${total} row(s) (per-device, newest ${cap}/device + ${config.statusLogRetentionDays}d retention, batches of ${batch})`);
_lastPrune = { deleted: total, ms: Date.now() - _t0, at: Math.floor(Date.now() / 1000) };
_sweepsTotal += 1;
return total;
} catch (_) { return 0; } finally { _statusPruneRunning = false; }
}

View file

@ -22,10 +22,16 @@
const config = require('../config');
const { ANON_KEY } = require('./device-identity');
const { rollingCounter, bump, read } = require('./rolling-counter');
// key -> { hits: number[], blockedUntil, lastSeen, trips, tripWinStart, quarantinedUntil }
const state = new Map();
// #146 observability — throughput counters (total + rolling lastWindow).
const refusedCtr = rollingCounter(); // every allow:false, any reason
const quarantineStartsCtr = rollingCounter(); // each time a check first sets quarantinedUntil
const refuse = (now, obj) => { bump(refusedCtr, now); return obj; };
function maxFor(key) { return key === ANON_KEY ? config.connectRateAnonMax : config.connectRateMax; }
// Decide whether to allow this connection for `key`. Returns
@ -44,12 +50,12 @@ function check(key, now = Date.now()) {
// is safe in-memory now that Item A ended the prune-induced restart loop; a
// self-healing auto-action must NOT survive as a devices.blocked row.
if (now < s.quarantinedUntil) {
return { allow: false, retryAfterMs: s.quarantinedUntil - now, reason: 'quarantined' };
return refuse(now, { allow: false, retryAfterMs: s.quarantinedUntil - now, reason: 'quarantined' });
}
// Inside an enforced cooldown -> refuse cheaply.
if (now < s.blockedUntil) {
return { allow: false, retryAfterMs: s.blockedUntil - now, reason: 'flap-cooldown' };
return refuse(now, { allow: false, retryAfterMs: s.blockedUntil - now, reason: 'flap-cooldown' });
}
// Sliding window of genuine connects.
@ -64,9 +70,10 @@ function check(key, now = Date.now()) {
// Escalate to a time-limited quarantine after N trips in the window (0 = off).
if (config.connectRateQuarantineTrips > 0 && s.trips >= config.connectRateQuarantineTrips) {
s.quarantinedUntil = now + config.connectRateQuarantineMs;
return { allow: false, retryAfterMs: config.connectRateQuarantineMs, reason: 'flap-rate', tripped: true, trips: s.trips, quarantined: true };
bump(quarantineStartsCtr, now); // a quarantine event is visible even though the gauge decays
return refuse(now, { allow: false, retryAfterMs: config.connectRateQuarantineMs, reason: 'flap-rate', tripped: true, trips: s.trips, quarantined: true });
}
return { allow: false, retryAfterMs: config.connectRateCooldownMs, reason: 'flap-rate', tripped: true, trips: s.trips };
return refuse(now, { allow: false, retryAfterMs: config.connectRateCooldownMs, reason: 'flap-rate', tripped: true, trips: s.trips });
}
return { allow: true };
}
@ -86,12 +93,25 @@ function startSweep() {
return sweepTimer;
}
function reset() { state.clear(); } // tests
function reset() { // tests
state.clear();
Object.assign(refusedCtr, rollingCounter());
Object.assign(quarantineStartsCtr, rollingCounter());
}
function _size() { return state.size; }
// #146 P3.8: soak observability — bucket count + currently-quarantined count.
// #146: soak observability — gauges (bucket/quarantine counts) + THROUGHPUT (refusals and
// quarantine-starts, total + last completed window). The throughput tells the flapper
// story on its own: a real Firestick reads as refusedLastWindow climbing while the gauge
// (quarantined) can stay 0.
function stats(now = Date.now()) {
let quarantined = 0;
for (const [, s] of state) if (now < s.quarantinedUntil) quarantined++;
return { buckets: state.size, quarantined };
const refused = read(refusedCtr, now);
const qstarts = read(quarantineStartsCtr, now);
return {
buckets: state.size, quarantined,
refusedTotal: refused.total, refusedLastWindow: refused.lastWindow,
quarantineStartsTotal: qstarts.total, quarantineStartsLastWindow: qstarts.lastWindow,
};
}
module.exports = { check, sweep, startSweep, reset, _size, stats };

View file

@ -36,6 +36,9 @@ const IDLE_RESET_MS = parseInt(process.env.OTA_BREAKER_IDLE_RESET_MS) || 60 * 60
const state = new Map(); // key -> { hits:number[], blockedUntil, level, lastSeen }
const loggedBad = new Set(); // log unrecognized/superseded versions once
// #146 observability — rate-backoff throughput (total + rolling lastWindow).
const { rollingCounter, bump, read } = require('./rolling-counter');
const rateBackoffCtr = rollingCounter();
// --- minimal semver-ish parse/compare (no dependency) ---
function parseVer(v) {
@ -78,6 +81,7 @@ function decide(clientVersion, latestVersion, deviceId = null, now = Date.now())
b.lastSeen = now;
if (now < b.blockedUntil) {
bump(rateBackoffCtr, now);
return { update_available: false, reason: 'rate-backoff', retry_after_seconds: Math.ceil((b.blockedUntil - now) / 1000) };
}
if (b.blockedUntil !== 0) b.blockedUntil = 0; // cooldown elapsed -> probe window
@ -92,6 +96,7 @@ function decide(clientVersion, latestVersion, deviceId = null, now = Date.now())
// past the point where it stops affecting the cooldown.
b.level = Math.min(b.level + 1, COOLDOWNS_MS.length);
b.hits = []; // require a fresh burst to re-trip after cooldown
bump(rateBackoffCtr, now);
return { update_available: false, reason: 'rate-backoff', retry_after_seconds: Math.ceil(cd / 1000),
log: `[ota] breaker tripped key=${key} (>${THRESHOLD} checks/${Math.round(WINDOW_MS / 1000)}s, looping) -> backoff ${Math.round(cd / 1000)}s [level ${b.level}]` };
}
@ -116,6 +121,12 @@ function startSweep() {
return sweepTimer;
}
function reset() { state.clear(); loggedBad.clear(); }
function reset() { state.clear(); loggedBad.clear(); Object.assign(rateBackoffCtr, rollingCounter()); }
function _size() { return state.size; }
module.exports = { decide, reset, sweep, startSweep, cmp, parseVer, _size, WINDOW_MS, THRESHOLD };
// #146 observability — how many update checks the breaker is rate-backing-off (total +
// last completed window). A device=none 1.8.x flood shows here as rateBackoffLastWindow.
function stats(now = Date.now()) {
const rb = read(rateBackoffCtr, now);
return { rateBackoffTotal: rb.total, rateBackoffLastWindow: rb.lastWindow };
}
module.exports = { decide, reset, sweep, startSweep, cmp, parseVer, _size, stats, WINDOW_MS, THRESHOLD };

View file

@ -6,8 +6,9 @@
const config = require('../config');
// newState() — the single bounded rolling counter the endpoint keeps.
function newState() { return { inFlight: 0, windowStart: 0, windowCount: 0, served: 0, shed: 0 }; }
// newState() — the single bounded rolling counter the endpoint keeps. served/shed are
// per-window (reset each window); servedTotal/shedTotal are running totals (#146 obs).
function newState() { return { inFlight: 0, windowStart: 0, windowCount: 0, served: 0, shed: 0, servedTotal: 0, shedTotal: 0 }; }
// admit(state, band, now) -> { allow, status?, retryAfter?, summary? }
// summary (when a window just rolled) = { served, shed } to log, else null.
@ -27,15 +28,15 @@ function admit(state, band, now = Date.now()) {
}
if (config.otaDownloadGuardEnabled) {
if (band === 'critical') { state.shed++; return { allow: false, status: 503, retryAfter: 30, summary }; }
if (band === 'critical') { state.shed++; state.shedTotal++; return { allow: false, status: 503, retryAfter: 30, summary }; }
if (band === 'elevated') {
const overGlobal = state.inFlight >= config.otaDownloadMaxConcurrent || state.windowCount >= config.otaDownloadMaxPerWindow;
if (overGlobal) { state.shed++; return { allow: false, status: 503, retryAfter: 10, summary }; }
if (overGlobal) { state.shed++; state.shedTotal++; return { allow: false, status: 503, retryAfter: 10, summary }; }
}
// band === 'normal': no cap — serve freely.
}
state.inFlight++; state.windowCount++; state.served++;
state.inFlight++; state.windowCount++; state.served++; state.servedTotal++;
return { allow: true, summary };
}
@ -46,6 +47,6 @@ function release(state) { state.inFlight = Math.max(0, state.inFlight - 1); }
// newState() for isolation.
const _prod = newState();
function prodState() { return _prod; }
function stats() { return { inFlight: _prod.inFlight, servedThisWindow: _prod.served, shedThisWindow: _prod.shed, windowCount: _prod.windowCount }; }
function stats() { return { inFlight: _prod.inFlight, servedThisWindow: _prod.served, shedThisWindow: _prod.shed, servedTotal: _prod.servedTotal, shedTotal: _prod.shedTotal }; }
module.exports = { newState, admit, release, prodState, stats };

View file

@ -0,0 +1,31 @@
'use strict';
// #146 observability — a scalar THROUGHPUT counter with a fixed rolling window. Bounded
// (four ints, no per-key map, no timer): the window rolls lazily on bump AND on read, so
// an idle subsystem's `lastWindow` correctly decays to the last COMPLETED window (or 0 if
// two+ windows passed with no activity) without a background timer. Shared so the roll
// logic is identical everywhere.
const config = require('../config');
function rollingCounter(windowMs = config.debugStatsWindowMs) {
return { total: 0, curWindow: 0, lastWindow: 0, windowStart: 0, windowMs };
}
// Roll if the current window has elapsed. First touch just anchors windowStart.
function roll(c, now) {
if (c.windowStart === 0) { c.windowStart = now; return; }
const elapsed = now - c.windowStart;
if (elapsed >= c.windowMs) {
// exactly one window closed -> lastWindow is what accumulated; 2+ -> last completed was empty
c.lastWindow = elapsed < 2 * c.windowMs ? c.curWindow : 0;
c.curWindow = 0;
c.windowStart = now;
}
}
function bump(c, now = Date.now(), n = 1) { roll(c, now); c.curWindow += n; c.total += n; }
// Plain, cheap read: { total, lastWindow } (rolls first so idle reads are accurate).
function read(c, now = Date.now()) { roll(c, now); return { total: c.total, lastWindow: c.lastWindow }; }
module.exports = { rollingCounter, bump, read };

View file

@ -10,6 +10,7 @@ const { PLATFORM_ROLES } = require('../middleware/auth');
const loopLag = require('../services/loop-lag');
// #146 P3.8: soak observability — internal limiter/maintenance states.
const flapLimiter = require('../lib/flap-limiter');
const otaBreaker = require('../lib/ota-breaker');
const otaDownloadGuard = require('../lib/ota-download-guard');
const logCoalescer = require('../lib/log-coalescer');
const { getMaintenanceStats } = require('../db/database');
@ -36,9 +37,12 @@ router.get('/', (req, res) => {
// #146 P3.8: soak observability — see the limiters biting without grepping logs.
// Aggregate counts only (no device ids / secrets); cheap in-memory reads.
debug: {
flap: flapLimiter.stats(), // { buckets, quarantined }
ota_download: otaDownloadGuard.stats(), // { inFlight, servedThisWindow, shedThisWindow, windowCount }
maintenance: getMaintenanceStats(), // { deleted, ms, at, running } of the last status-log prune
// gauges + THROUGHPUT (total + last completed window) so the server tells the
// flapper/flood story on its own — aggregate only, no ids/secrets.
flap: flapLimiter.stats(), // buckets, quarantined, refused{Total,LastWindow}, quarantineStarts{Total,LastWindow}
ota_breaker: otaBreaker.stats(), // rateBackoff{Total,LastWindow}
ota_download: otaDownloadGuard.stats(), // inFlight, served/shed ThisWindow + Total
maintenance: getMaintenanceStats(), // deleted, ms, at, running, sweepsTotal
log_coalescer_buffer: logCoalescer._size(),
},
});

View file

@ -0,0 +1,73 @@
'use strict';
// #146 observability — throughput counters on /api/status.debug. The shared rolling
// counter + each subsystem's total/lastWindow increment on the right event.
const os = require('node:os');
const path = require('node:path');
const crypto = require('node:crypto');
process.env.DATA_DIR = path.join(os.tmpdir(), 'st-thru-' + crypto.randomBytes(4).toString('hex'));
const { test } = require('node:test');
const assert = require('node:assert/strict');
const { rollingCounter, bump, read } = require('../lib/rolling-counter');
const flap = require('../lib/flap-limiter');
const breaker = require('../lib/ota-breaker');
const guard = require('../lib/ota-download-guard');
const config = require('../config');
test('rolling-counter: total accrues; lastWindow = last CLOSED window; idle decays to 0', () => {
const c = rollingCounter(1000);
bump(c, 0); bump(c, 100); bump(c, 200); // window 1: 3 hits in [0,1000)
let r = read(c, 300);
assert.equal(r.total, 3);
assert.equal(r.lastWindow, 0, 'still inside window 1 — no completed window yet');
bump(c, 1100); // rolls: lastWindow=3, curWindow=1
r = read(c, 1200);
assert.equal(r.total, 4);
assert.equal(r.lastWindow, 3, 'lastWindow reflects window 1');
r = read(c, 6000); // 2+ idle windows
assert.equal(r.lastWindow, 0, 'no activity for 2+ windows -> lastWindow decays to 0');
});
test('flap: allow:false bumps refusedTotal; a quarantine start bumps quarantineStartsTotal', () => {
const save = { max: config.connectRateMax, win: config.connectRateWindowMs, cd: config.connectRateCooldownMs, qt: config.connectRateQuarantineTrips, qm: config.connectRateQuarantineMs };
Object.assign(config, { connectRateMax: 1, connectRateWindowMs: 100000, connectRateCooldownMs: 1, connectRateQuarantineTrips: 2, connectRateQuarantineMs: 100000 });
flap.reset();
try {
flap.check('d:t', 0); flap.check('d:t', 1); // 2nd exceeds max 1 -> trip1 (refused)
let s = flap.stats(2);
assert.ok(s.refusedTotal >= 1, 'a refusal bumped refusedTotal');
assert.equal(s.quarantineStartsTotal, 0, 'no quarantine yet');
flap.check('d:t', 3); flap.check('d:t', 4); // past cooldown -> trip2 -> quarantine
s = flap.stats(5);
assert.equal(s.quarantineStartsTotal, 1, 'quarantine start counted (even though the gauge later decays)');
assert.ok(s.refusedTotal >= 2, 'both refusals counted');
assert.equal(typeof s.refusedLastWindow, 'number');
} finally { Object.assign(config, { connectRateMax: save.max, connectRateWindowMs: save.win, connectRateCooldownMs: save.cd, connectRateQuarantineTrips: save.qt, connectRateQuarantineMs: save.qm }); flap.reset(); }
});
test('ota-breaker: a rate-backoff verdict bumps rateBackoffTotal', () => {
breaker.reset();
const before = breaker.stats(0).rateBackoffTotal;
for (let i = 0; i < 6; i++) breaker.decide('1.8.1', '1.9.2-beta7', null, i); // device=none flood > THRESHOLD
const s = breaker.stats(10);
assert.ok(s.rateBackoffTotal > before, `rate-backoff counted (${s.rateBackoffTotal})`);
assert.equal(typeof s.rateBackoffLastWindow, 'number');
});
test('ota-download: a shed bumps shedTotal; a serve bumps servedTotal', () => {
const s = guard.newState();
guard.admit(s, 'critical'); // shed
assert.equal(s.shedTotal, 1);
guard.admit(s, 'normal'); guard.admit(s, 'normal');
assert.equal(s.servedTotal, 2, 'serves counted');
});
test('maintenance: sweepsTotal increments per completed prune', async () => {
const { pruneStatusLog, getMaintenanceStats } = require('../db/database');
require('../lib/chunked-prune').__setBandForTest(() => 'normal');
const before = getMaintenanceStats().sweepsTotal;
await pruneStatusLog({ bandGate: false });
assert.equal(getMaintenanceStats().sweepsTotal, before + 1, 'a completed sweep bumped sweepsTotal');
});

View file

@ -49,12 +49,21 @@ test('/api/status exposes a current loop_lag snapshot', async () => {
assert.ok(['normal', 'elevated', 'critical'].includes(body.loop_lag.band), 'band is a valid level');
assert.equal(typeof body.loop_lag.p99_ms, 'number', 'p99_ms is numeric');
assert.equal(typeof body.loop_lag.mean_ms, 'number', 'mean_ms is numeric');
// #146 P3.8: soak observability block
// #146 P3.8: soak observability block — gauges + throughput
assert.ok(body.debug, 'debug block present');
assert.equal(typeof body.debug.flap.buckets, 'number', 'flap bucket count exposed');
assert.equal(typeof body.debug.flap.quarantined, 'number', 'flap quarantine count exposed');
assert.equal(typeof body.debug.flap.refusedTotal, 'number', 'flap refusedTotal exposed');
assert.equal(typeof body.debug.flap.refusedLastWindow, 'number', 'flap refusedLastWindow exposed');
assert.equal(typeof body.debug.flap.quarantineStartsTotal, 'number', 'flap quarantineStartsTotal exposed');
assert.equal(typeof body.debug.flap.quarantineStartsLastWindow, 'number', 'flap quarantineStartsLastWindow exposed');
assert.equal(typeof body.debug.ota_breaker.rateBackoffTotal, 'number', 'ota breaker rateBackoffTotal exposed');
assert.equal(typeof body.debug.ota_breaker.rateBackoffLastWindow, 'number', 'ota breaker rateBackoffLastWindow exposed');
assert.equal(typeof body.debug.ota_download.inFlight, 'number', 'download in-flight exposed');
assert.equal(typeof body.debug.ota_download.servedTotal, 'number', 'download servedTotal exposed');
assert.equal(typeof body.debug.ota_download.shedTotal, 'number', 'download shedTotal exposed');
assert.ok('maintenance' in body.debug && typeof body.debug.maintenance.ms === 'number', 'last-prune stats exposed');
assert.equal(typeof body.debug.maintenance.sweepsTotal, 'number', 'maintenance sweepsTotal exposed');
assert.equal(typeof body.debug.log_coalescer_buffer, 'number', 'coalescer buffer size exposed');
});