server-desktop-01/docs/incidents.md

252 lines
13 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters

This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.

# 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.