diff --git a/CHANGELOG.md b/CHANGELOG.md index 6d88cd1..2bf2812 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -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. diff --git a/docs/incidents/2026-09-11-core-state-db-corruption.md b/docs/incidents/2026-09-11-core-state-db-corruption.md new file mode 100644 index 0000000..61fcaa6 --- /dev/null +++ b/docs/incidents/2026-09-11-core-state-db-corruption.md @@ -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