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
This commit is contained in:
root
2026-09-12 08:28:54 -04:00
parent 3a51b79b51
commit 199baadedc
@@ -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.