Bold reported loop lag that grew with uptime and reset on restart. The
signature they saw — mean = p50 = p99 = max, identical to two decimals —
is not a fixed cost paid on every cycle. It is what an IntervalHistogram
window reports when it recorded exactly ONE delay: the mean is the raw
value, and every percentile returns the bucket ceiling above it.
Reproduced against their exact numbers (1329.07 / 1329.59). So the loop
took one long turn that swallowed the sampling second, episodically —
which is what they later confirmed independently.
The turn is ours, and it is now measured rather than theorised. Probing
the real worker against a real WAL with one reader mid-transaction: a
single main-thread write blocked for 4,936ms behind the worker's
wal_checkpoint(TRUNCATE), which then reported WAL 8.8MB -> 8.8MB. TRUNCATE
is the blocking form and its locks are held ACROSS connections, so moving
it to a worker kept the fsync off the loop but not the lock; and it does
not throw when it cannot get those locks, it returns busy=1 having sat on
SQLite's 5s busy timeout and reclaimed nothing. Five seconds of stalled
loop for zero benefit, and silent.
It was reached far too easily. The rule was "escalate if the WAL grew
across three consecutive 15s runs" — which any sustained 45-second write
burst satisfies. A customer's fleet powering on in the morning does it
daily.
Two gates, because either alone leaves the hole open. A size FLOOR, so a
WAL in the lower half of its budget can't buy a blocking checkpoint it has
nothing to reclaim from. And a COOLDOWN, because the floor alone fixes
nothing for Bold — their WAL already sits at 6.2MB against a 16MB
high-water, above any sane floor, so every burst would still escalate.
However long the pressure lasts, our own maintenance may now stall the
loop at most once per window. The high-water rule bypasses both and is
untouched: a runaway WAL is the one case worth blocking for, so the
"WAL cannot grow forever" invariant is exactly as strong as before.
A busy TRUNCATE now says so in the log instead of reading like a success.
Also softened the adjacent path: when the worker is declared
unrecoverable, engageFallback() re-arms inline autocheckpoint on the main
connection — a state that is STICKY for the life of the process, i.e.
exactly the shape of "degrades with uptime, a restart fixes it". It used
to also run an unconditional main-thread TRUNCATE on the way in; that now
happens only when the WAL is genuinely over high-water, and the fallback
state is served on /api/status rather than being inferable only from a log
line that may have rolled.
Telemetry, so the next report is self-explanatory: loop_lag carries
`samples` (~50 when healthy, 1 when a single turn swallowed the second),
`tick_gap_ms` measured on the WALL CLOCK independently of the histogram,
and `worst_tick_gap_ms`/`worst_tick_at` — monotone, so five-minute polling
can no longer miss an episode.
Band semantics are deliberately unchanged. A one-sample window during a
real stall is the correct trigger for the shed valve; suppressing it would
blind the protection at exactly the moment it is needed.
Separately, device_telemetry gets the age sweep it never had. The
per-heartbeat row cap only ever trims the device whose heartbeat is being
handled, so a device that STOPS reporting leaves its rows behind forever.
The new sweep is per-device (rides idx_telemetry_device rather than
scanning), chunked and yielding like the device_status_log one, and
defaults to 30 days to match the uptime report's own default window — so
it cannot remove rows that report would have shown.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_014skWYXJUWhF73EvNPgB2AS
A sampling window that recorded nothing leaves the histogram empty, and an
empty IntervalHistogram reports its mean as NaN. Its percentiles return a floor
instead, which is why only the mean was affected and why this went unnoticed.
NaN then survives every arithmetic step in the sampler without complaint and
becomes visible only at the edge, where JSON.stringify renders it as null. So
/api/status served "mean_ms": null while nothing raised an error anywhere, and
any consumer of that gauge read null instead of a number.
Non-finite readings now report 0, which is the honest value: no samples means
no measured delay. Applied to every field so a later change to the histogram
source cannot reintroduce this one field at a time.
Found by CI rather than locally, because an idle window is far likelier on a
loaded runner with several test servers in flight. The failure was real; the
new tests establish the NaN premise and the null serialisation directly rather
than relying on that timing to reproduce.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Uaeo9MvzKoyXuN6ZsbhtkL
The coalesced loop-lag summary carried an arbitrary sample's p99. Now record() tracks
the MAX (peak) over the window and the summary emits it — the peak is the number that
matters during an incident: '[loop-lag] band=critical (x47 in 30s, peak 1502ms)'. Band
CHANGES still log immediately, unchanged.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Don't let telemetry/logging cook the loop under a storm.
- lib/log-coalescer.js: dedup+count high-frequency lines, flush ONE summarized line per
key per window ("[loop-lag] band=critical (x47 in 30s)"). Bounded buffer (auto-flush
at MAX_KEYS). Applied to the loop-lag "still loaded" line (band CHANGES stay immediate),
the per-request OTA check line, and "Device reconnected".
- loop-lag: event_loop_lag rows are BUFFERED and batch-inserted on a flush interval
(was a synchronous INSERT per sample); the buffer is bounded (drop-oldest). Its
retention prune now rides the Item-A chunkedDelete so this table can never repeat the
status_log bloat-then-freeze. /api/status still reads in-memory current (real-time
band unaffected).
- Bounded the previously un-evicted per-device Maps: content-ack limiter gets an idle
sweep (started in server.js); status-log-writer.lastWritten is capped (drop-oldest;
it only suppresses a redundant consecutive row, so eviction is safe).
Tests: N identical lines -> one counted line; single line verbatim; coalescer buffer
bounded under a distinct-key flood; content-ack Map swept of idle buckets.
loop-lag-integration updated for the batched-insert cadence. Suite 266/266.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
#142's content-ack dedup is insufficient: a device cycling 2-4 content IDs makes
every ack look unique so dedup never fires, while aggregate volume from ~30 devices
saturates the event loop (the #142 reconnect throttle kept the server responsive,
which is how this was even observable).
Folded ONE control on the content-ack path (no competing limiters; reconnect-
throttle.js untouched) in lib/content-ack-limiter.js:
- Step 1 — per-device RATE budget: caps TOTAL non-duplicate acks per device per
window regardless of differing content_id (the case dedup misses). Over budget =
DROP silently (the per-ack log+emit is the cost); log ONCE per device per window
when shedding starts. Keeps the #142 dedup (dedup'd repeats don't consume budget).
Per-device, in-memory, resets on restart (modeled on lastPlayLogAt; does NOT reuse
reconnect-throttle's ban-semantics bucket).
Env (TUNING GUESSES, validate vs Bold's fleet): CONTENT_ACK_MAX_PER_WINDOW=20,
CONTENT_ACK_RATE_WINDOW_MS=10000 (=2/s, above legit ~<=1/s, below the flood).
- Step 2 — global pressure valve: reuses the #142 loop-lag band (+ its hysteresis,
no second control loop). Under CRITICAL band, shed content-acks even for an
in-budget device; reconnects + dashboard/HTTP are ALWAYS processed; a healthy
device in a non-critical band is never touched by the valve. Valve open/close
logged once at the band edge in services/loop-lag.js (not per shed message).
Tests (unique ports 3985/3986, not the 3982/3983/3984 set):
- unit: the #143 regression (cycling ids evading dedup IS rate-limited), under/over
budget, dedup still works + doesn't consume budget, valve sheds in-budget under
critical while normal is untouched, rate precedence, window reset, per-device
isolation.
- integration: socket flood is capped to budget with a single shed-start log;
under-budget passes every ack; valve OPEN sheds content-acks while a reconnect +
/api/status still succeed.
Full suite green serial AND parallel (208 tests).
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Continuously samples event-loop delay via perf_hooks.monitorEventLoopDelay()
(C++-backed histogram; cheap). Each window persists mean/p50/p99/max to a new
event_loop_lag table and recomputes a coarse load band (normal/elevated/critical)
from the window p99. Standalone value: current lag is exposed on /api/status and
band changes are logged, so site lag is diagnosable independent of throttling.
The band feeds the #142 reconnect throttle (next commit) but ships first as its
own subsystem.
- event_loop_lag is bounded from day one: indexed on sampled_at + scheduled prune
(LAG_TELEMETRY_RETENTION_DAYS, small default) modeled on the play_logs prune.
Deliberately NOT another unbounded-growth table.
- Band transitions are asymmetric: jump up immediately (tighten fast), release one
level at a time after N calm samples below a deadband (release slow, no flap).
Pure nextBand() function, unit-tested deterministically.
- config: LAG_SAMPLE_INTERVAL_MS, LAG_RESOLUTION_MS, LAG_TELEMETRY_RETENTION_DAYS,
LAG_PRUNE_INTERVAL_MS, LAG_ELEVATED_MS, LAG_CRITICAL_MS, LAG_RELEASE_SAMPLES.
- tests: band-transition unit tests; integration proves sampling persists, stays
bounded under the prune, and surfaces on /api/status.
Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
