Mark ovh-prod leg of 2026-07-04 backup incident resolved (pipefail grep root cause)
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
jared
parent
6a968bf6c7
commit
f9579e925f
|
|
@ -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,
|
Newest first. Keep entries factual: symptom, root cause, what was ruled out,
|
||||||
fix applied, and any follow-up.
|
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="<that exact 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)
|
## 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
|
**Result: FAILED.** Ran memtest86+ v8.10 from the GRUB boot entry on the
|
||||||
|
|
|
||||||
Loading…
Reference in New Issue