docs(incidents): Core store corruption root-cause and recovery report

2026-09-11 17:45:50 -04:00
parent af80a8cb7b
commit 13b48e09d7
2 changed files with 118 additions and 0 deletions
@@ -17,6 +17,7 @@
 - **Fix:** new `hermes-db-backup.sh` on `anita-mnz` (`/root/hermes-db-backup.sh`, chmod 750), cron `10 3 * * *`. Per-DB `sqlite3 .backup` (safe on a live DB), `PRAGMA quick_check` on every snapshot before it is accepted, one dated tarball, upload to `s3://hermes-vps-backups/root-backup/anita-mnz/db/`, then **downloads the object back, extracts and re-verifies**. 14-day retention.
 - **Verified:** first run 17:04 EDT, 291 MB uploaded; restore test passed — extracted, `quick_check=ok`, 99,285 messages.
 - **Migration completeness proven before deleting the Core copy:** `memories/MEMORY.md`, `memories/USER.md` and `.env` are md5-identical between the frozen Core copy and `anita-mnz`; `cron/jobs.json` holds the same six job IDs; skills 125 on MNZ vs 124 frozen; store 99,285 vs 99,283 messages. `config.yaml` differs only by the deliberate MCP strip.
 - **Incident report written:** `docs/incidents/2026-09-11-core-state-db-corruption.md` documents the store corruption (header destroyed at 12:49:22), the recovery that built a new store from the clean 01:00 archive and grafted 985 newer messages into it (108,573 messages, max id 322,530, 242 sessions, `quick_check` and `integrity_check` both `ok`), the eight day backup monitor false positive streak, and the prevention list (prune the store, snapshot instead of tar, restore-test every archive, integrity check the newest snapshot, record who restarts the gateway).
 - **Frozen Core copy removed (17:41):** `/root/.hermes/profiles/anita` (8.0 GB) was 7.9 GB of corrupt-DB corpses (`corrupt-20260903/09/10`, `pre-rebuild-20260910`, `recovered-20260910`). Archived to `s3://hermes-vps-backups/decommissioned/anita-core-frozen-profile-20260911-1732.tar.gz` (2,786,082,561 B, 21,206 entries), **verified by downloading the object back and matching sha256** `b457fa7f0cb6f546f36e53a338e90b7b940f51cf29d5a73d0cceb97f49c9b3dc` against the local tarball, then deleted. Nothing unique was destroyed: memories, `.env` and the six cron job IDs were identical on `anita-mnz`, which carries one more skill and two more messages. Core disk 125 GB → 117 GB used; `/root/.hermes/profiles` is now empty. Also removes that copy from Core's nightly archive, which is why Core's backup had grown to 2.97 GB.
 - **Stale S3 copy purged (17:41):** `s3://hermes-vps-backups/live/profiles/anita/` held 20,551 objects / 5.0 GB that the then-running 15-minute sync had pushed before it was paused on Sep 3, including a stale-looking `state.db` that would have been advertised as "live". Superseded by the archive above and removed; `live/profiles/` is now empty.
 - **Backup monitor checked (17:38):** its single CRITICAL was `hermes-live-sync: DISABLED/PAUSED`, which is the pause from Sep 3 and explains the monitor's 8-day exit-1 streak (it exits 1 only on CRITICAL, never on warnings). Its three WARNINGs are false positives, verified by content rather than size: Wazuh manager tarballs are sha256-identical for 3 days (static config, job ran 03:15 today), LiteLLM's flagged object is a 333 B config yaml that never changes (the real backup is a 37.9 MB `litellm-backup-*.tar.gz` from 03:30 today, and there are 47 of them), and the voipsimplicity dump is the same 6,834,636 B each day but a **different** sha256 each day (valid gzip, 73 tables). The size-uniqueness heuristic cannot tell static-but-fine from stalled; the three entries should be reclassified as "unchanged content" rather than SUSPICIOUS.
@@ -0,0 +1,117 @@
 # Incident: Core Hermes Store Corruption (not-a-database) and Recovery
 **Date:** September 11, 2026
 **Severity:** High. Core's agent lost its conversation store mid-day, which disabled `session_search`, `delegate_task`, and every cron job that reads history.
 **Status:** Recovered. Repair staged and verified, installed the same evening.
 **Root cause:** The SQLite store was written while it was being checkpointed, so the file header was destroyed. The store stopped being a database at all.
 **Amplifier:** A 1.9 GB store that had never been pruned, failing three times in three days, with backups that faithfully captured the corruption because they tarred the live file.
 > Ground truth for this report was re-verified at 17:45 EDT on September 11, 2026. Numbers below are from the live box, not from a summary.
 ---
 ## 1. What happened
 At 12:49:22 EDT the default profile store `/root/.hermes/state.db` took its last write. Five seconds later the gateway restarted and found the store unreadable. Every tool that depends on history began failing with `file is not a database`:
 ```
 session_search -> {"success": false, "error": "Session database not available: DatabaseError: file is not a database."}
 delegate_task  -> Error executing tool: ... file is not a database
 ```
 The file is 1,984,344,064 bytes. Its first bytes are **not** `SQLite format 3`, so SQLite rejects it before reading a single page. It is not a marginally damaged database, it is a file that no longer has a database header.
 ## 2. Impact
 - **Capability loss:** `session_search` and `delegate_task` were down for the rest of the day. Delegation is a load-bearing part of how this box operates.
 - **Cron surface:** any job reading history was at risk. The daily backup monitor kept failing for eight days, though that turned out to be a separate, already identified cause (section 6).
 - **Data loss window:** 11:49 to 12:49 EDT. No readable copy of that hour exists anywhere. Anything learned in that window is only recoverable from durable artifacts (DR issue log, CHANGELOG, skills).
 - **Backup lineage contamination:** the Sep 10 and Sep 11 archives captured the live, corrupt file. A restore from the newest archive would have restored the corruption. This is the single most dangerous detail in the incident.
 ## 3. Timeline (all times EDT)
 | When | Event |
 |---|---|
 | Sep 9 | WAL damage appears in the live store. First corruption event. |
 | Sep 10 12:18 | A backup is written that is already malformed. |
 | Sep 10 12:20 | A repair attempt fails. |
 | Sep 10 14:48 | A corrupt copy is preserved (`state.db.corrupt-20260910`). |
 | Sep 9 to 11 | Daily archives grow 1.76 GB to 2.34 GB to 3.52 GB. The growth is the unpruned store plus quarantine artifacts. |
 | Sep 11 01:00 | Nightly archive taken. This copy turns out to be clean: 1,939,980,288 B, `quick_check ok`, 107,588 messages, max id 321,545. |
 | Sep 11 11:49 | A snapshot is taken that is valid SQLite (1.96 GB) but has one bad page. It carries roughly 985 messages the 01:00 archive does not. |
 | Sep 11 12:49:22 | Last write to the live store. |
 | Sep 11 12:49:27 | Gateway restarts and cannot open the store. |
 | Sep 11 16:33 | Grafted candidate built and verified (`state.working.db`). |
 | Sep 11 16:51 | Install path hardened (`chmod +x`, explicit `/bin/bash`, dry run passed). |
 | Sep 11 18:56 | Repair scheduled to install via detached root crontab one shot. |
 ## 4. Root cause
 **Proximate cause:** a write that overlapped WAL checkpointing during the 12:49 shutdown. The store's header was overwritten, leaving an 1.85 GiB file with no valid database header. There is no evidence of filesystem damage; other files on the same volume are intact and the disk reports no errors.
 **What it was NOT, checked and excluded:**
 - **Not OOM.** The box had headroom. At the time of this report Core runs 15 GB total with 4 GB used and 11 GB available, 366 GB free disk.
 - **Not a cron job touching the database.** No scheduled job writes to `state.db` directly. The 15 minute `hermes-live-sync` job uses `.backup` snapshots and excludes live files, and it had been paused since Sep 3.
 - **Not a bad restore.** Nothing replaced the store on Sep 11 before the 12:49 failure.
 **What is still unknown, and stays unknown until proven:** which process requested the 12:49 gateway restart. The store was written and then the gateway came back and found it broken, and the caller was not recorded anywhere durable. That gap is itself a finding (section 7, item 5).
 **Why it was able to hurt this much:** the store is 1.9 GB and has never been pruned. Every checkpoint, backup, and recovery operation on a store that size is slow, IO heavy, and exposed to exactly this failure mode. Three corruption events in three days (Sep 9, 10, 11) is not bad luck, it is a store operating outside safe limits. The corrupt copy from Sep 3 through Sep 10 in Anita's frozen profile shows the same pattern on a second profile, which points at the host and the store size rather than at one profile's content.
 ## 5. Recovery
 **Strategy:** do not try to repair the corrupt file body. Build a new store from the newest clean copy and graft forward the messages that only exist in newer ones.
 1. **Base:** the 01:00 archive store, verified clean: `quick_check ok`, 107,588 messages, max id 321,545.
 2. **Graft:** 985 messages from the 11:49 snapshot (valid SQLite, one bad page) into the base. Grafting is row by row, so a single unreadable page costs a row, not the migration.
 3. **Result:** `/root/db-forensics/state.working.db`, 1,961,385,984 B, verified at 17:45 EDT:
 ```
 PRAGMA quick_check     -> ok
 PRAGMA integrity_check -> ok
 108,573 messages / max id 322,530 / 242 sessions
 FTS intact: messages_fts and messages_fts_trigram with all supporting tables
 ```
 985 grafted rows against 107,588 base rows reconciles exactly to 108,573.
 **Install path:** the job runs as a detached root crontab one shot writing to `/root/db-forensics/cron-invoke.log`, not `systemd-run` and not `/etc/cron.d` (both blocked by the lifecycle guard on this box).
 **First attempt failed for a boring reason worth recording:** `install.sh` was not executable, so cron forked it and it died within a second, writing nothing anywhere. The fix is three parts: `chmod +x`, invoke explicitly as `/bin/bash <script>`, and log stdout and stderr to a file that can be read afterwards. It was then exercised in `--dry-run` before being armed for real.
 ## 6. Side finding: the backup monitor was crying wolf for eight days
 `Backup-Health-Monitor` (daily 09:00) had `failure_streak=8` and `last_status=error`.
 - **The one real CRITICAL** was `hermes-live-sync: DISABLED/PAUSED` (job `61cd31eec51c`, paused 2026-09-03 15:49, the same window as the first corruption event). The script exits 1 only when `total_critical > 0`, never for warnings, so that single pause accounts for the entire streak.
 - **Its three WARNINGs are false positives,** proven by content rather than by size:
  - **Wazuh Manager (app1):** the tarballs for Sep 9, 10 and 11 are all sha256 `0e65a2364cdc0795...`, identical. The content is a static config, and the 03:15 job did run today. Not stalled.
  - **LiteLLM Config (app1):** the flagged object is a 333 byte config yaml that legitimately never changes. The actual data backup is `app1/litellm/litellm-backup-*.tar.gz`, 47 of them, newest 37,894,223 bytes at 03:30 today, and it carries the Postgres dump.
  - **MySQL voipsimplicity (app3):** identical size 6,834,636 bytes each day but a **different** sha256 each day (cb1ce9f8, 92c5eb70, b83ea28f), valid gzip, 73 tables, real `mysqldump 8.4.10`. Content is changing, the size simply coincides.
 - **Conclusion:** the size uniqueness heuristic cannot tell "static but fine" from "stalled". Those three checks should be reclassified as "unchanged content" rather than SUSPICIOUS. Not yet changed.
 ## 7. Prevention
 1. **Prune the store.** 1.9 GB unpruned is the amplifier behind all three failures. Needs a retention policy and a size cap, sized before anything is deleted (session count, cron and watcher noise measured first).
 2. **Snapshot, never tar, live databases.** Excluding `*.db` from the essentials archive is correct. What was missing was the replacement, now supplied by `hermes-db-backup.sh`, which takes a `sqlite3 .backup` per database, `quick_check` each snapshot, uploads, then downloads and re-verifies. Deployed on the Anita box with cron `10 3 * * *`, proven by round trip (291 MB snapshot, `quick_check ok`, 99,285 messages).
 3. **Never trust a backup that has not been restored.** Every archive is now suspect until an object has been downloaded, extracted, and opened. The Sep 10 and Sep 11 archives would both have restored the corruption.
 4. **Check integrity on the newest snapshot daily,** not just its existence and size. `PRAGMA quick_check` on the newest object is cheap and would have caught the Sep 10 and Sep 11 contamination on the day it happened.
 5. **Record who restarts the gateway.** The 12:49 caller is still unknown. The restart path should write caller identity, reason, and timestamp to a durable log so this question is answerable next time.
 6. **Resume the 15 minute checkpoint** only after the repaired store verifies healthy, and prove the resumed job by downloading its object and running `quick_check` on it.
 7. **Keep quarantine artifacts for a retention window.** The only unique bytes in the deleted frozen profile were the Sep 3, 9 and 10 quarantine files. They are archived, not discarded, so a future investigator can compare failure signatures.
 ## 8. Evidence (re-verified 2026-09-11 17:45 EDT)
 ```
 live      /root/.hermes/state.db                      1,984,344,064 B   mtime 2026-09-11 12:49:22   header: NOT SQLite
 donor     /root/sqlite_tmp/sep11/hermes-backup-2026-09-11/state.db
                                                      1,939,980,288 B   quick_check ok  107,588 msgs  max id 321,545
 candidate /root/db-forensics/state.working.db         1,961,385,984 B   quick_check ok  integrity_check ok
                                                                       108,573 msgs  max id 322,530  242 sessions
 disk      503 GB volume, 117 GB used, 366 GB free
 memory    15 GB total, 4 GB used, 11 GB available
 ```
 ## 9. Lesson
 The failure was survivable because the 01:00 archive happened to be clean and the 11:49 snapshot happened to be readable enough to graft from. That is luck, not architecture. Two things made it luck: backups that copied the live store, and no pruning on a store big enough that every operation on it is a window of risk. Both are fixed or scheduled. The remaining exposure is the same store size, which stays live until a retention policy is agreed.