Skip to content

v0.6.2 — Trace store resilience, WAL hardening, log rotation race fix

Choose a tag to compare

@twinsgeeks twinsgeeks released this 12 Jul 06:42

Reliability hardening for the trace_store SQLite layer and structured logging — both addressing a real production incident on the local fleet that ran undetected for ~4 days. The headline finding: a long-running read transaction held off WAL checkpoints, the WAL grew to 2.5 GB, and the 5-second busy_timeout couldn't absorb the resulting writer contention. ~40,000 background record_trace tasks failed with database is locked over May 10-15 while requests themselves still succeeded — observability was the only visible casualty (dashboard reqs_24h quietly dropped to 0). Adjacent: the daily log rotation handler raced between herd and herd-node writing to the same file, leaving one day's log growing for the entire incident window. Both are fixed; both now have health checks or architectural separation to prevent silent recurrence. Initial fix (busy_timeout + retry + autocheckpoint, committed 2026-05-15) reduced failure amplitude but didn't eliminate it — see the follow-up Part C + A fix below, which addresses the structural cause and was verified clean under live load on 2026-05-16.

Fixed

  • TraceStore and LatencyStore now use a dedicated read connection (Part C in docs/plans/trace-store-read-connection-and-checkpoint.md). Each store opens two aiosqlite connections: _db for writes, _read_db for every dashboard analytics + scoring read path. Two purposes — (1) aiosqlite serializes operations per-connection through one background thread, so a slow read on the shared connection blocks queued writes for the read's duration; with separate connections they run concurrently in separate threads. (2) Read snapshots pin the WAL checkpoint barrier; on a separate connection the writer's view of the WAL can advance independently. Combined effect verified on the local fleet 2026-05-16 — a 30-concurrent-write + 120-dashboard-poll burst held the WAL at 410 KB peak vs 103 MB on the same workload before this change. PRAGMA query_only=1 on the read connection rejects accidental writes immediately rather than silently competing with the writer. 7 new tests cover routing (reads → _read_db, writes → _db), query-only enforcement, and connection lifecycle.

  • Explicit periodic PRAGMA wal_checkpoint(PASSIVE) every 10 seconds on each store's writer connection (Part A in same plan). Defense-in-depth on top of wal_autocheckpoint=100 — autocheckpoint is tied to write volume, so under bursty traffic the WAL can sit at 99 pages for a long time while readers accumulate snapshots; by the time the 100th page write fires autocheckpoint, those snapshots have pinned the checkpoint barrier so far back that very little can advance. Tying checkpoints to wall-clock makes them fire in the gaps between reader snapshots rather than only when a write lands on a threshold. PASSIVE is non-blocking, so this is safe to run on a tight cadence. Logged at DEBUG every tick; promotes to INFO if a tick comes back contested with >100 unwritten pages — surfaces sustained contention without flooding the log under healthy operation. 3 new tests cover the return shape, closed-connection safety, and error-swallow behavior (must never crash the background task).

  • TraceStore and LatencyStore SQLite write resilience. PRAGMA busy_timeout bumped from 5s → 30s in both stores so a transient WAL checkpoint stall can't immediately fail writes. TraceStore.record_trace now retries on database is locked errors with exponential backoff (200ms → 800ms → 2s, 3 attempts) before giving up — so the busy_timeout absorbs short contention and the retry loop covers longer stalls, for ~90s cumulative patience before a trace is declared lost. Added PRAGMA wal_autocheckpoint=100 to both stores to bound WAL growth even when an external reader is slow. Failures after all retries are exhausted are counted in a rolling deque so the new health check (below) can surface them without operators having to grep logs. See the 2026-05-15 observation in docs/observations.md for the full incident timeline.

  • Daily log rotation race between herd and herd-node. Both processes previously called setup_logging with the same default file path (~/.fleet-manager/logs/herd.jsonl) and registered their own TimedRotatingFileHandler. At UTC midnight, one process would rename herd.jsonlherd.jsonl.YYYY-MM-DD and the other would keep writing to the renamed inode via its still-open file descriptor for the rest of the file's life. Observed in the wild: a single day's log grew to 131 MB while peer days were 6 MB; the orphaned file kept receiving writes for five days after its supposed rotation. Fix: setup_logging(log_name=...) is now parameterized; router uses herd (default, back-compat) and node uses herd-node. Each process owns its rotation. Cross-file audits (grep -c '"level": "ERROR"' ~/.fleet-manager/logs/herd*.jsonl*) still work via glob.

Added

  • trace_store_write_failures health check (now 32 distinct checks). Reads TraceStore.get_write_failure_count(window_s=300) and emits a WARNING at 1+ failures in the last 5 minutes, CRITICAL at 50+. Closes the observability black hole that hid the May 10-15 incident — the only visible signal before this was dashboard reqs_24h=0 for a router that was clearly serving traffic, which is easy to dismiss as "nobody's running anything right now." 10 new tests in tests/test_server/test_trace_store_resilience.py cover retry-on-locked-then-succeed, retry-exhaustion-then-record-failure, non-lock-errors-don't-retry, window-pruning semantics, and the severity threshold transitions.

Changed

  • CLAUDE.md "Gotchas" — two new entries to keep future operators (and AI agents reviewing logs) from repeating the failure modes that delayed detection of this incident. (1) JSONL log scans must use '"level": "ERROR"' with a space after the colon — json.dumps writes whitespace by default and the no-space variant silently matches zero lines. A wrong grep pattern was the root cause for ~4 days of "clean fleet" soak reports during the incident. (2) Trace DB write failures are invisible from the dashboard because record_trace is fire-and-forget — explicit pointer to the new health check + the three most common root causes (long-running read, disk-full, stale db-shm/-wal).