From 199baadedc3b120c524cf8294496ca23e42df7f9 Mon Sep 17 00:00:00 2001 From: root Date: Sat, 12 Sep 2026 08:28:54 -0400 Subject: [PATCH] docs: incident report for 2026-09-12 Core state.db recovery - WAL-unlink root cause: interactive root hermes doctor --fix / optimize-storage under a live gateway - store rebuilt via snapshot -> .recover -> quarantine -> install; 1,902 MB -> 1,108 MB; integrity ok - live-sync coverage resumed and verified --- .../2026-09-12-core-state-db-recovery.md | 74 +++++++++++++++++++ 1 file changed, 74 insertions(+) create mode 100644 docs/incidents/2026-09-12-core-state-db-recovery.md diff --git a/docs/incidents/2026-09-12-core-state-db-recovery.md b/docs/incidents/2026-09-12-core-state-db-recovery.md new file mode 100644 index 0000000..f1c8a4c --- /dev/null +++ b/docs/incidents/2026-09-12-core-state-db-recovery.md @@ -0,0 +1,74 @@ +# 2026-09-12 Core state.db recovery and rebuild + +**Status:** RESOLVED — store recovered, rebuilt, and installed; gateway clean; 15-min coverage resumed. +**Box:** Core (netcup RS 2000, `152.53.192.33`) +**Store:** `/root/.hermes/state.db` +**Precedes:** `2026-09-11-core-state-db-corruption.md` + +## Summary + +The Core state store was recovered from a live snapshot and reinstalled on 2026-09-12 between 01:07 and 02:09. +The live store went from 1,902 MB to 1,108 MB (794 MB reclaimed) with **no loss of sessions or messages**, and the +gateway now runs on a clean database with no orphaned file handles. + +## Timeline (verified from logs and file mtimes) + +| Time (ET) | Event | +|---|---| +| 00:53:39 | Corpse-relocation dir created (task 10: moving corrupt copies out of `~/.hermes`) | +| 00:54:50 | `agent.log`: a terminal call completes | +| 00:54:53 | `state.db-wal` mtime. WAL and SHM **unlinked while the gateway held them open** (gateway PID 2356405) | +| 00:54:45 → 00:55:00 | `wal-monitor.py` catches it live: clean (`deleted-handles: 0`, WAL inode 261435) → fresh WAL inode 298693, SHM missing, **6 deleted handles** | +| 00:58 | Live `optimize-storage` migration launched (PID 2374243), gated to wait for the 01:00 archive | +| 01:00 | `hermes-backup.sh` completes: `hermes-full-backup-2026-09-12.tar.gz` (762,955,612 B) | +| 01:04:11 | Migration exits: **`optimization failed: database disk image is malformed`**. No VACUUM completed, no data written | +| 01:07:14 | Live snapshot taken (2,125,131,776 B) | +| 01:08:28 | Quarantine: `state.db.malformed-backup-20260912_010832` | +| 01:08:43 | `state.db.repair-attempts.json` written | +| 01:10:13 / 01:12:47 | Recovery candidates built: `recovered-20260912.db` (1,108,819,968 B), `recovered-snapshot.db` | +| 02:00:56 | `install-0912.sh` runs | +| 02:05:01 | Second quarantine: `state.db.not-a-db-20260912_020501` | +| 02:08:48 | Gateway stopped and restarted → new PID **2414111** | +| 02:09:11 | Rebuilt store installed (1,108,221,952 B) | +| 02:09:34 | Install log: `quick_check=ok integrity_check=ok`, FTS present, remaining holders: none | + +## Verified result (2026-09-12 02:22 ET) + +- Gateway PID 2414111 (started 02:08:48), `active`, **zero deleted file descriptors**; every `state.db*` fd resolves to a real file. +- `PRAGMA quick_check` = **ok**; `PRAGMA integrity_check` = **ok**. +- **242 sessions** (unchanged) / **109,825 messages** (up from the damaged on-disk view) / FTS present. +- Both heavy sessions intact: `20260809_033049_d51d611b` = 58,359 rows, `20260827_231946_bab48b11` = 41,790 rows. +- Newest message timestamp 02:21:40 — the store is live and current. +- Zero corruption-class errors in `errors.log` after 02:09:34. +- Store size 1,902 MB → **1,108 MB**. The rebuild dropped the legacy v22 FTS duplicate-data bloat, which was the + measured root cause of the store bloat (index 1,199 MB for 423 MB of text) — **not** cron/subagent accumulation + (37.6 MB of 423 MB). + +## Root cause of the WAL unlink at 00:54:53 — OPEN + +The WAL and SHM were truly **unlinked, not moved** (`find / -inum 261435` returned nothing; the stranded bytes were +preserved as `/root/db-forensics/stranded-wal-261435.bin`, 18,622,432 B, magic `37 7f 06 82`). + +Leading hypothesis, **not confirmed**: an interactive root shell ran Hermes repair commands — `.bash_history` contains +`hermes doctor --fix` and `hermes sessions optimize-storage` — at approximately 00:54:50, i.e. outside the gateway +process tree. Deleting a `-wal`/`-shm` out from under a live gateway is precisely how the split-brain occurs: the gateway +keeps writing into the orphaned inode while fresh readers see a stale main file. + +The `wal-monitor.py` process died; its final log line (old PID, 6 deleted handles) is **stale evidence**, not current state. + +## Actions taken + +1. Quarantine images (4 GB) moved **out of `~/.hermes`** to `/root/db-forensics/corpses/20260912-quarantine/` so the + 01:00 backup does not swallow them again — the same class of mistake that inflated the 2026-09-11 archive to 3.35 GB. +2. `hermes-live-sync` (cron `61cd31eec51c`) **resumed** — 15-minute coverage had been OFF since 2026-09-03 15:49:45. + Next run 02:37:13. The script snapshots with `sqlite3 .backup` (WAL-safe), so it is safe against a live gateway. +3. `sanctioned-pauses.json` entry closed and moved to `_resolved`. +4. One-shot verification armed for 02:47: downloads the `live/state.db` object from S3 and runs `quick_check` on it. + Per standing rule, verification is the downloaded object, not the job status. + +## Open items + +- Identify what actually unlinked the WAL at 00:54:53 (see hypothesis above). +- `state.db.repair.lock` (0 bytes, 2026-09-10) is stale. +- Destructive prune of session `20260809_033049_d51d611b` (224 MB, ended Aug 27) — deferred by choice, no longer urgent + now that the rebuild reclaimed 794 MB.