server-desktop-01/docs/incidents.md

252 lines
13 KiB
Markdown
Raw Permalink Normal View History

# Incident log
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="<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)
**Result: FAILED.** Ran memtest86+ v8.10 from the GRUB boot entry on the
Ryzen 5 5600G / 95.3 GB DDR4-2666 (CAS 20-19-19-43) workstation.
- **Status: Failed!, Errors: 7** at only **0:00:51** elapsed — still in Pass 0,
Test #3 (Moving inversions, 1s & 0s). Errored almost immediately.
- Both captured failures are **single-bit flips** (signature of a failing
module, not a controller-wide / addressing fault):
- `0x000bc0115dd0` (47 GB): expected `f…`, found `bf…`**bit 62 flipped 1→0**
- `0x001005f391e0` (64 GB): expected `0…`, found `…01000000`**bit 24 flipped 0→1**
- Temps 58/65 °C (fine). DDR4-2666 is JEDEC-standard, **not** an aggressive
XMP/EXPO overclock — so this is not merely an unstable memory profile.
**Conclusion**
Confirms the 2026-06-24 hypothesis: scattered multi-file Btrfs csum corruption
with zero drive I/O errors and clean NVMe SMART = **bad RAM** writing garbage to
otherwise-good flash. Root cause: **confirmed**.
**RAM layout (from `dmidecode -t memory`, 2026-06-26)**
96 GB total = **two complete G.Skill Ripjaws V kits**, both DDR4-3200 CL16
running at 2666 (XMP/DOCP off):
| Slot | Size | Part number | Kit |
|------|------|-------------|-----|
| Channel A · DIMM 0 | 32 GB | F4-3200C16-32GVK | 2×32 GB pair → 64 GB |
| Channel B · DIMM 0 | 32 GB | F4-3200C16-32GVK | (matched cross-channel) |
| Channel A · DIMM 1 | 16 GB | F4-3200C16-16GVK | 2×16 GB pair → 32 GB |
| Channel B · DIMM 1 | 16 GB | F4-3200C16-16GVK | (matched cross-channel) |
Two valid matched dual-channel pairs → whichever stick fails, drop to the other
complete pair and keep dual-channel. **Fallbacks need zero purchase:** if a
16 GB stick is bad → run the 2×32 = 64 GB; if a 32 GB stick is bad → run the
2×16 = 32 GB.
**Booting memtest (GRUB hotkeys unreliable on this box)**
memtest86+ 8.10 is installed (`/boot/memtest86+x64.efi`); GRUB uses
`GRUB_DEFAULT=saved`, so one-shot boot needs no keypresses:
```bash
sudo grub2-mkconfig -o /boot/grub2/grub.cfg
sudo grep -o "menuentry '[^']*emtest[^']*'" /boot/grub2/grub.cfg # get exact title
sudo grub2-reboot "<exact title>" # one-shot; reverts after next boot
sudo systemctl poweroff # pull sticks, then power on → boots memtest
```
Exit memtest with **Esc** (reboots back to Fedora).
**Follow-up / next steps**
- **Treat the machine as untrustworthy until the RAM is replaced** — any data
written (including backups) since the corruption began may be silently bad.
Be cautious about pruning known-good restic snapshots.
- **Isolate the bad DIMM** — test **by kit first** (the 2×32, then the 2×16);
a passing pair is immediately a runnable config. Only split a *failing* pair
to find the single bad stick. Errors at 47 GB / 64 GB are interleaved logical
addresses and do NOT map to one physical stick.
- **Don't discard the bad stick** — G.Skill Ripjaws V carry a limited lifetime
warranty; RMA for a free replacement (restores the matched pair at no cost).
Keep its good partner as a spare or for the RMA-restored pair. Avoid buying a
single stick to pair (DDR4 matching is finicky) unless RMA fails.
- After fixing, **re-run memtest to a clean multi-pass**, then **re-scrub
`/home`** and watch for *new* csum errors. None appearing = corruption was
historical and is now resolved. Defer `restic check --read-data` until the RAM
is known-good (a bad-RAM box throws false integrity errors).
## 2026-06-24 — Chrome repeatedly crashing (SIGBUS), corrupt Favicons block on single-copy Btrfs
**Symptom**
Google Chrome crashed within seconds of launch, repeatedly. Three crashes in
three minutes on 2026-06-24 (13:15, 13:16, 13:17), all signal **SIGBUS**.
History of crashes back to April (mixed SIGTRAP / SIGILL / SIGSEGV / SIGBUS),
18 minidumps total.
**Root cause**
A single corrupt data block at offset **942080** of
`~/.config/google-chrome/Profile 2/Favicons` (a SQLite DB, inode 141150,
btrfs root 257). Chrome `mmap()`s the file on startup; the kernel raises SIGBUS
when it cannot fault in the bad page.
Each SIGBUS coredump correlated to the second with a kernel log line:
```
BTRFS warning: csum failed root 257 ino 141150 off 942080 csum 0x0858109c expected 0x0858109e mirror 1
```
Same single-bit flip every time (`9c` vs `9e`). The volume is `Data, single`
(no mirror), so Btrfs detects but **cannot self-heal**. `corruption_errs` was
climbing (41 → 42). Disk `read` / `write` / `flush` `io_errs` were all 0 —
silent at-rest corruption; the NVMe is not reporting hardware faults.
**Ruled out**
- **OOM** — 87 GiB RAM free, and SIGBUS ≠ SIGKILL.
- **Disk full** — 5% used.
- **Chrome version / update** — install dated 2026-06-20 predates the crashes;
`rpm -V` clean.
- **Profile / extension corruption.**
- **Dual-GPU / Wayland stack** — GPU libs in the dump were merely mapped; the
`gpu_channel.cc Buffer Handle is null` line was a downstream symptom logged
~2s after the SIGBUS.
**Fix applied (2026-06-24)**
Confirmed Chrome not running, then deleted the regenerable cache files
`Favicons` and `Favicons-journal` from `Profile 2/`. Chrome regenerates these on
next launch. Verified gone.
**Scrub result (2026-06-24 13:28)**
`sudo btrfs scrub start -B /home` finished in 0:55, scanned 79.57 GiB.
**Error summary: `csum=2`, Corrected 0, Uncorrectable 2.** The corruption is
**not** isolated to the Favicons file — two further uncorrectable blocks, in
two different subvolumes, both regenerable/reinstallable:
| File | Subvol | Action |
|------|--------|--------|
| `~/.cache/google-chrome/Profile 1/Cache/Cache_Data/5f188fe6012a3cdc_0` | home (root 257) | Deleted (regenerates) ✅ |
| `/usr/share/help/fr/gdm/index.docbook` | root (root 259) | Owned by `gdm-49.2-2.fc43`; restore via `sudo dnf reinstall gdm` |
`corruption_errs` 44; `read`/`write`/`flush` `io_errs` 0.
**Remediation + verification (2026-06-24 13:3813:42)**
- Deleted the Chrome cache block (`rm`, regenerates).
- Restored the gdm file: `sudo dnf reinstall gdm`.
- **SSD health is clean** — `sudo nvme smart-log /dev/nvme0n1`:
`critical_warning 0`, `media_errors 0`, `percentage_used 0%`. The drive has
logged **zero** media errors at the hardware level → a *failing SSD* is
unlikely; corruption reached good flash from upstream (RAM/bus).
- **Second scrub (13:41)** still reports `csum=2` uncorrectable — but at the
**exact same two physical blocks** as the first scrub (`logical 1754923008`,
`logical 21439315968`), and this time **with no resolvable path**. The live
files now point at fresh extents; the corrupt extents are **orphaned dead
blocks** (not snapshot-pinned — `snapper`/`timeshift` not installed).
**Assessment**
Same two static blocks across two scrubs 13 min apart = corruption is **static,
not actively spreading** (no new blocks appeared). Combined with the clean SSD
SMART, this most likely stems from a **single past corruption event** rather
than an actively-failing component. The crash-causing live files are fixed;
the residual scrub errors affect no live file.
**Outstanding / follow-up**
- **Re-scrub in a day or two** (`sudo btrfs scrub start -B /home`). If the two
orphaned blocks have cleared (reclaimed) and no *new* errors appear → fully
resolved. **New** blocks appearing = corruption is ongoing → back up now and
run memtest.
- **Run memtest86+** (Fedora GRUB boot entry) for confidence — scattered
multi-file corruption with zero drive I/O errors is the classic bad-RAM
signature, even if currently static.
- The `corruption_errs` counter will not drop on a single-copy volume — expected.