diff --git a/docs/incidents.md b/docs/incidents.md index 180e1d8..0bb19e9 100644 --- a/docs/incidents.md +++ b/docs/incidents.md @@ -4,6 +4,92 @@ Dated entries for diagnosed-and-fixed system incidents on this machine. Newest first. Keep entries factual: symptom, root cause, what was ruled out, fix applied, and any follow-up. +## 2026-07-04 — Backup monitor alert diagnosed: three independent, compounding failures (desktop x2, ovh-prod x1) — not fixed yet + +**Symptom:** Weekly n8n digest (2026-06-26) reported all 3 monitored sources +RED — "no runs reported all week — silent failure": `desktop/synology`, +`desktop/backblaze-b2`, `vps-ovh-prod-01/local`. Prior sessions had tried +several times to fix the automatic trigger without success. + +**Investigation (via direct systemd/journal inspection on desktop, SSH to +ovh-prod, and the n8n REST API against `n8n.swansoncloud.com`):** + +- Confirmed the alerting/reporting pipeline itself (n8n Workflow 1 receiver → + `backup_runs` data table, Workflow 2 weekly reporter) works correctly — + manually POSTing to `https://n8n.swansoncloud.com/webhook/backup-notify` + with production credentials returns `200 {"ok":true}` and creates a real + execution + row. Credentials/URL/token are byte-identical (sha256-verified) + between desktop and ovh-prod. **The monitor is not the bug.** +- Pulled the full historical content of the `backup_runs` data table via the + n8n API: only **5 rows ever existed**, all from the 2026-05-07/05-15 setup + day (a mix of stale-lock failures and one manual "test" row). **Zero rows + from any real automated run on either machine, ever** — the RED status has + been silently true since the system was built, not just "this week." + +**Root cause 1 — desktop, `restic-backup.service` (systemd --user):** `backup.sh` +calls `notify_backup.rb` as a bare command name. The systemd user manager's +PATH (`systemctl --user show-environment`) is +`~/.cargo/bin:~/.nodenv/shims:~/.nodenv/bin:/usr/local/bin:/usr/bin` — it does +**not** include `~/.local/bin`, where `notify_backup.rb` actually lives. +Confirmed by reproducing with `env -i PATH="" which +notify_backup.rb` → not found. The call silently no-ops (swallowed by +`|| true`), so the notifier has never once run from the real timer-triggered +service, even on nights the backup itself succeeded (e.g. 2026-07-02, which +has a real B2 snapshot but produced zero n8n rows). + +**Root cause 2 — desktop, `restic-backup.timer` (separate, affects the backup +itself, not just reporting):** The timer is `Persistent=true` + `WakeSystem=true`, +firing catch-up runs at odd hours (08:36, 09:08, 11:57 seen on 07-01/07-03/07-04) +when the machine missed the 01:58 AM slot. `ExecStart` wraps `backup.sh` in +`systemd-inhibit --why=... `, which requires interactive polkit authentication. +When the timer fires outside an active/unlocked session, `systemd-inhibit` +itself fails with `Access denied ... requires interactive authentication` and +exits 1 **before `backup.sh` ever runs** — no log file, no restic invocation, +nothing. Confirmed in `journalctl --user -u restic-backup.service`. This is why +3 of the last 4 calendar days had zero backup activity at all, not just zero +notifications. (2026-07-02, the one day the timer fired on schedule during an +active session, did back up successfully to B2; Synology failed separately +that day with `Network is unreachable` reaching `192.168.86.31:22`.) + +**Root cause 3 — ovh-prod, `backup.sh` (cron, `0 7 * * *`):** The archive +creation itself has kept succeeding every night (`cron.log` shows a fresh +`backup_YYYYMMDD.tar.gz` created nightly through 2026-07-04). But +`grep -c 'Backup completed successfully' cron.log` shows the **last occurrence +was 2026-05-07** — the setup day. Every run since (2 months, ~55 nights) stops +silently right after the `cleanup_old_backups()` log line ("Cleaning up backups +older than 2 days...") and never reaches the notifier call a few lines later, +despite `set -euo pipefail` normally surfacing a visible error on early exit. +Manually re-running the exact same `find ... -delete` commands and the exact +`notify_backup.rb` invocation right now both succeed cleanly (the manual test +call created a real row: `2026-07-04T16:21:37Z vps-ovh-prod-01 local success`). +No OOM kill in `dmesg`, disk not full (23% used). +**RESOLVED 2026-07-04 (same day, follow-up session):** root cause was NOT a cron +environment difference — it was the `SNAP=$(grep -oE 'snapshot ...' "$LOG_FILE" ...)` +line in `main()`. The ovh box produces tar archives (no restic), so the grep never +matches → exits 1 → `pipefail` + `set -e` kill the script silently right between +cleanup and the notifier. Fails identically over interactive SSH; earlier manual +reproductions only re-ran the `find`/notify commands individually, never that +pipeline under the script's own shell options. Fixed by deleting the dead SNAP +extraction and `--snapshot` flag; verified end-to-end (full run exits 0, real +`backup_runs` row `2026-07-04 17:26:04 vps-ovh-prod-01 local success`). Details in +`ovh-prod/docs/incidents.md`, 2026-07-04 entry. + +**Ruled out:** n8n workflow config/auth/data table wiring (verified working +live); credential/token mismatch between machines (hashes match); OVH archive +creation itself (still succeeds nightly); OVH disk space; OOM kill. + +**Not yet fixed** — this entry is the diagnosis only, at the user's request, +to avoid fixing the wrong problem before a fix is designed. Follow-ups: +1. Desktop: call `notify_backup.rb` by full path (`~/.local/bin/notify_backup.rb`) + in `backup.sh`, matching what ovh-prod's copy already does correctly. +2. Desktop: replace/guard the `systemd-inhibit` interactive-auth dependency + (e.g. drop `--why` interactive prompt requirement, or add + `ConditionACPower`/session-active guards) so catch-up runs outside an + active session don't abort before starting. +3. ~~ovh-prod: instrument `cleanup_old_backups()`/the cron invocation~~ — **done + 2026-07-04**: root cause found without instrumentation (pipefail-killed snapshot + grep) and fixed; see Root cause 3 above. + ## 2026-06-26 — memtest86+ confirms bad RAM (root cause of the 2026-06-24 Btrfs corruption) **Result: FAILED.** Ran memtest86+ v8.10 from the GRUB boot entry on the