From 54bff69f88ab0e38f3a6d25b80e4bee06507fb4e Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Thu, 24 Sep 2026 16:29:54 +0200 Subject: [PATCH] R-672/R-673: 03 + 08 + register + CONTEXT (restore test off, 9201 repaired, agent v0.133.0, hub v0.124.0); R-684 Co-Authored-By: Claude Opus 5.5 (1M context) Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS --- CONTEXT.md | 12 +++++++++ documentation/architecture/03-host-agent.md | 25 +++++++++++++++++++ documentation/architecture/08-alarm-ladder.md | 9 +++++++ .../r672-2026-09-24/C8-hub-0124-rollout.txt | 2 ++ documentation/backlog/OPEN-ITEMS.md | 5 ++-- 5 files changed, 51 insertions(+), 2 deletions(-) create mode 100644 documentation/audits/r672-2026-09-24/C8-hub-0124-rollout.txt diff --git a/CONTEXT.md b/CONTEXT.md index 61d43774..4746c584 100644 --- a/CONTEXT.md +++ b/CONTEXT.md @@ -14,6 +14,18 @@ > language, one screen, no identifiers in the prose. Same subjects, different readers; merging them > would make one of the two audiences stop reading. `STATUS.md` is also a **view of `OPEN-ITEMS.md`** > and holds nothing of its own; this file does hold its own content, namely the standing rulings below. +## 2026-09-24 (evening) — the restore test off on the demo hosts, 9201 repaired, agent v0.133.0 + hub v0.124.0 (R-672, R-673) + +**Operator rulings (recorded in `03` §8).** (1) The scheduled restore-test is OFF on both demo hosts until an +agent with the R-672 fix is delivered there; then it goes back on. Done with +`backup.restore_test_eval_interval_seconds: -1` — **0 would NOT disable it (0 = the 6 h default)**; saved configs +`/etc/felhom-agent/agent.json.pre-r672`. (2) This session could stop, check and start 9201 on demo-hp — done. + +**Shipped.** Agent **v0.133.0** released (tag `9bdb4da`, package verified by download), **not delivered** — the +operator signs `agent_update` per box (R-530). Hub **v0.124.0** live (thin pool critical at 90 %, per pool per 6 h). +Evidence: `audits/r672-2026-09-24/`. R-684 opened (demo-hp's root backup storage too small). Part D (controller +v0.270.0) — see REPORT-r672-2026-09-24.md. + ## 2026-09-24 (night shift, run in daytime) — the second drive brings a file app back whole; the box stops a crash loop; digests on the box; the update leg spiked **Operator rulings recorded (`09` §3 decisions 26–28).** 26 — build one action that brings a file app back WHOLE diff --git a/documentation/architecture/03-host-agent.md b/documentation/architecture/03-host-agent.md index ce942601..f9289cd2 100644 --- a/documentation/architecture/03-host-agent.md +++ b/documentation/architecture/03-host-agent.md @@ -308,6 +308,31 @@ per Part 1: **snapshot** (LVM-thin, transient, whole-guest rollback — not a ba > Unchanged and load-bearing: `onboot=0` on the scratch at restore time, **every NIC link-down before > boot**, journal-before-mutate, guaranteed teardown, and the per-tier restore-task timeout. +> **A restore-test can never fill a box's disk (R-672, agent v0.133.0 + hub v0.124.0).** Measured +> 2026-09-24 on demo-hp: the scheduled restore-test restored 9201's archive into `local-lvm` — the pool +> holding 9201 — with no space check; the pool reached 100 % and 9201's disks remounted read-only. +> Since v0.133.0, before anything is journaled or created: +> - **Space first.** Free data ≥ restored × 1.2 + 5 GiB (`backup.restore_test_space_factor`, +> `…_reserve_gib`) and room in a thin pool's metadata. `restored` is the **uncompressed** size — the +> vzdump log's "Total bytes written" or the PBS snapshot size. **Never the archive file:** 9201's file +> was 6.9 GB and its restore wrote 22.6 GB, so "file × 1.2 + 5 GiB" would have let that test run. +> - **Off the tested guest's pool** when another storage is eligible (active, `rootdir`, and the agent +> holds `Datastore.AllocateSpace` there) and fits. demo-hp has none: `nvme-scratch` carries no grant. +> - **Unknown refuses.** A refusal is the test's result — `pass=false`, `skipped`, "skipped: not enough +> space on …" — so the hub raises `restore_test_failed`; it is never a pass and never dropped. +> - **Leftovers on a timer.** A failed scratch teardown and the stale-lock sweep (R-673) run every 10 +> minutes, not only at agent start; the sweep holds the one-heavy-operation gate; after 3 failed +> teardown tries the operator is told. +> - **A thin pool ≥ 90 % requests an immediate report**; the hub judges a thin pool on the worse of data +> and metadata, critical at 90 %, one alarm per pool per 6 hours (`08` §6.2). +> +> **Operator ruling 2026-09-24 (evening):** the scheduled restore-test is **OFF on both demo hosts** +> (`backup.restore_test_eval_interval_seconds: -1` — **0 does not disable, it means the 6-hour default**) +> until v0.133.0 is delivered there; then it is switched back on. Saved configs: +> `/etc/felhom-agent/agent.json.pre-r672`. On demo-hp, a full restore-test of 9201 does not fit today +> (21.1 GiB restored needs 30.3 GiB; 22.1 GiB free) — the preflight will refuse it, correctly, until the +> pool has room. + - **Quiescing (controller-driven for app-consistency) — implemented (slice 8B):** an LXC has no fsfreeze (`proxmox-platform.md` §4.2), so app-consistency is the controller's job: it learns a backup is due (`GET /backup/due`, §6) → **quiesces** (stops its app stacks) → `POST /backup` → diff --git a/documentation/architecture/08-alarm-ladder.md b/documentation/architecture/08-alarm-ladder.md index 444796c3..69298f75 100644 --- a/documentation/architecture/08-alarm-ladder.md +++ b/documentation/architecture/08-alarm-ladder.md @@ -249,6 +249,15 @@ is immich's first-start import (12 restarts, 2026-09-17 — broken that night; R counting starts again after the boot), +116 s for a crash loop under a backup run, +102 s for a storm with the disk 1 GB above the floor. +**A thin pool is critical at 90 % (R-672, hub v0.124.0 + agent v0.133.0).** `storage_fill_*` judges an +`lvmthin` target on the worse of data and metadata fill, warning 85 %, **critical 90 %** (other storages keep +90/95 %). A full thin pool does not only refuse writes: every guest on it remounts read-only (demo-hp +2026-09-24 — 95 % → 100 % in about a minute, 9201 read-only five minutes later). The agent requests an +immediate host report when a pool crosses 90 %, so the alarm fires in seconds, not at the next 15-minute +report. Grain: **per pool, 6 hours** (`customer:type:host/storage`) — the old `customer:type`, 1 hour let one +pool silence another. The hub HAD alarmed on 2026-09-24 (operator mail at 100 %), but late and at the generic +bands. + **Two event types added 2026-09-17, with who receives them:** | event | severity | who | minted by | why that audience | diff --git a/documentation/audits/r672-2026-09-24/C8-hub-0124-rollout.txt b/documentation/audits/r672-2026-09-24/C8-hub-0124-rollout.txt new file mode 100644 index 00000000..df990643 --- /dev/null +++ b/documentation/audits/r672-2026-09-24/C8-hub-0124-rollout.txt @@ -0,0 +1,2 @@ +2026/09/24 16:28:01 [INFO] felhom-hub 0.124.0 starting +2026/09/24 16:28:26 [INFO] Storage fill checker initialized: warn=90% crit=95%, 6 ok seeded, 0 already-breached left unseeded, 2 root-backed excluded diff --git a/documentation/backlog/OPEN-ITEMS.md b/documentation/backlog/OPEN-ITEMS.md index 1babdcc8..e67c864c 100644 --- a/documentation/backlog/OPEN-ITEMS.md +++ b/documentation/backlog/OPEN-ITEMS.md @@ -809,8 +809,8 @@ class (an image `VOLUME` at an unmounted path) is still live — `immich-server` | **R-669** | **[P2-MEDIUM] After a failed update ends in a restore, the box keeps the FAILED step's health check as the pinned version's — and the NEXT failed update's undo judges the correct old version with it and holds the app.** PROVEN LIVE 2026-09-24 on 9202 (v0.269.0): a failing step (probe port 8999) → hold → the second drive's whole restore cleared the hold, but `applied-meta/.felhom.yml` still carried port 8999 (written by `advancePinTo` at 10:39:21; no restore path rewrites it), and the stack's `.felhom.yml` came back from the unit, which the sync had already filled with the failing step's file. The next failed update's undo put the right version and the right data back and then called it unhealthy on port 8999 → **a false hold** (`not_started`). Data safe; the app stopped for nothing. **Fix direction:** a restore that recreates the definition also sets the applied record to the `.felhom.yml` of the RESTORED pin (the ladder step's `steps/.felhom.yml` for those refs, or the catalog's when the catalog head equals the pin), never the unit's copy. Pre-existing since v0.263.2; not a v0.269.0 regression. `audits/night-2026-09-24/A2/11-applied-meta-wrong-probe.txt` | **READY — P2; owner: CC (controller)** | | **R-670** | **[P3-LOW] Every undo (and every step-file verify) logs `[ERROR] .felhom.yml backup block rejected … docker-compose.yml unreadable`.** `LoadMetadata` validates the backup block against a compose file that the pre-update-meta directory (undo.go:528, since v0.263.0) and the scratch dir of `loadMetadataFile` (v0.269.0) never hold. The health check it feeds is unaffected; an operator reading ERROR lines after an undo is misled. Seen 10:24:41Z and 10:46:24Z on 9202. **Fix:** a probe-only loader that skips the backup-block validation, or copy the compose beside it. `audits/night-2026-09-24/A2/11-applied-meta-wrong-probe.txt` | **READY — P3; owner: CC (controller)** | | **R-671** | **[P3-LOW] The undo copies kept by a hold survive the hold's clearing by a restore.** MEASURED 2026-09-24 on 9202: three `nextcloud_*.pre-update-20260924T103924Z` volumes (~0.9 GiB) were still present after the whole restore cleared that hold at 10:41:52Z, and a second set joined them 6 minutes later. Nothing names them on a page; on a small disk they are the difference between the next update's copy fitting or not. **Fix direction:** the restore that clears an update hold removes that hold's undo copies (they describe the state the restore just replaced), logged. `audits/night-2026-09-24/A2/11-applied-meta-wrong-probe.txt` (volume list) | **READY — P3; owner: CC (controller)** | -| **R-672** | **[P1-HIGH] The agent's SCHEDULED restore-test filled the production thin pool and turned a customer guest's disks read-only.** FOUND 2026-09-24 on demo-hp (agent v0.132.0): at 10:29 CEST the restore-test restored 9201's 22 GiB archive as scratch guest 990000 into `local-lvm` — the SAME pool as 9201 — with no free-space check. The pool reached 100 % at 10:35:24 (`out_of_data_space`, `error_if_no_space`); the scratch failed to start; its teardown failed (`lvremove … contains a filesystem in use`) and was "left for Recover" — **which runs only at agent start**, so the pool stayed full for 2.5 h. The agent logged *„a full pool corrupts every guest on it"* every few seconds and took no action. **Consequence, measured:** 9201's controller got `no space left on device` from 10:38, its log stops at 10:39:57, and at 13:12 both its rootfs and `/var/lib/felhom` were READ-ONLY (errors=remount-ro). **Intervention:** an agent restart ran Recover ("destroyed leaked restore-test scratch guest", pool 100 % → 58.9 %). **Still open:** 9201 needs a stop + fsck + start (operator — the session's permission check refused host-level guest operations). **Fix direction:** the restore-test refuses to start unless the target storage has the archive's size plus a margin free and never targets the pool of the guest it tests; a failed teardown retries on a timer, not only at start; the pool-fill WARN pages the operator. `audits/night-2026-09-24/C-02…C-07` | **OPEN — P1; owner: CC (agent) / operator (9201 repair)** | -| **R-673** | **[P2-MEDIUM] 9201's whole-box backups failed all morning on a stale `snapshot-delete` lock.** demo-hp 2026-09-24: vzdump of 9201 failed at 06:59, 07:17, 07:42 and 08:22 CEST (`CT is locked (snapshot-delete)`), leaving `snap_vm-9201-disk-1_vzdump` (07:42) behind, before R-672's pool fill. The agent's stale-lock scanner ran every 30 s and did not clear it; the lock was gone after the 13:09 agent restart. Cause not read — the session's permission check refused reading the task logs. `audits/night-2026-09-24/C-01-demo-hp-9201-vzdump-errors.txt` | **OPEN — P2; owner: CC (agent)** | +| **R-672** | **[P1-HIGH] The agent's SCHEDULED restore-test filled the production thin pool and turned a customer guest's disks read-only.** FOUND 2026-09-24 on demo-hp (agent v0.132.0): at 10:29 CEST the restore-test restored 9201's 22 GiB archive as scratch guest 990000 into `local-lvm` — the SAME pool as 9201 — with no free-space check. The pool reached 100 % at 10:35:24 (`out_of_data_space`, `error_if_no_space`); the scratch failed to start; its teardown failed (`lvremove … contains a filesystem in use`) and was "left for Recover" — **which runs only at agent start**, so the pool stayed full for 2.5 h. The agent logged *„a full pool corrupts every guest on it"* every few seconds and took no action. **Consequence, measured:** 9201's controller got `no space left on device` from 10:38, its log stops at 10:39:57, and at 13:12 both its rootfs and `/var/lib/felhom` were READ-ONLY (errors=remount-ro). **Intervention:** an agent restart ran Recover ("destroyed leaked restore-test scratch guest", pool 100 % → 58.9 %). **Still open:** 9201 needs a stop + fsck + start (operator — the session's permission check refused host-level guest operations). **Fix direction:** the restore-test refuses to start unless the target storage has the archive's size plus a margin free and never targets the pool of the guest it tests; a failed teardown retries on a timer, not only at start; the pool-fill WARN pages the operator. `audits/night-2026-09-24/C-02…C-07` **— 2026-09-24 (evening): FIXED IN RELEASE, NOT YET DELIVERED.** Agent **v0.133.0** (tag `9bdb4da`, package verified by download): space preflight before anything is created (UNCOMPRESSED size × 1.2 + 5 GiB, thin metadata, off the tested guest's pool when another storage is eligible — demo-hp has none, `nvme-scratch` carries no grant — unknown refuses, reported as a non-pass `skipped`); failed teardown retried every 10 min; thin pool ≥ 90 % requests an immediate report. Hub **v0.124.0** (live): thin pool critical at 90 % of data or metadata, one alarm per pool per 6 h. **The brief's "archive × 1.2 + 5 GiB" would NOT have prevented this incident** (6.9 GB file → 22.6 GB restore). Six red-proofs; live on demo-hp: both margins REFUSE (21.1 GiB restored needs 30.3 GiB, 22.1 GiB free), pool unchanged. The hub HAD alarmed on the day (`storage_fill_critical` at 100 %, operator mail) — late and at the generic bands. **9201 repaired** (stop, `pct fsck` both disks: 17 half-deleted inodes + an orphan block fixed on mp0; second pass clean; start; floor 0.269.1 taken by itself; ONLINE); two Redis AOF tails the pool cut (2,943 B / 6,631 B) truncated with `redis-check-aof --fix` after copies were kept as volumes — the box had meanwhile stopped docmost and romm itself (decision 28, live). **Scheduled restore-test OFF on both demo hosts** (operator ruling) until v0.133.0 is delivered. `audits/r672-2026-09-24/` | **FIXED IN v0.133.0 — awaiting the operator's signed delivery; restore test OFF on demo hosts; owner: operator (sign) / CC** | +| **R-673** | **[P2-MEDIUM] 9201's whole-box backups failed all morning on a stale `snapshot-delete` lock.** demo-hp 2026-09-24: vzdump of 9201 failed at 06:59, 07:17, 07:42 and 08:22 CEST (`CT is locked (snapshot-delete)`), leaving `snap_vm-9201-disk-1_vzdump` (07:42) behind, before R-672's pool fill. The agent's stale-lock scanner ran every 30 s and did not clear it; the lock was gone after the 13:09 agent restart. Cause not read — the session's permission check refused reading the task logs. `audits/night-2026-09-24/C-01-demo-hp-9201-vzdump-errors.txt` **— 2026-09-24 (evening): CAUSE READ, FIX RELEASED.** Not the pool fill (that came at 10:35). The 06:59 and 07:42 backups failed writing the archive to `local` — the host ROOT disk: `zstd: error 70 : … No space left on device` (R-684); the 07:42 failure's cleanup left `snap_vm-9201-disk-1_vzdump` and the `snapshot-delete` lock, and the 08:22 run hit the lock. The agent's own stale-lock recovery cleared it at 13:10, one minute after the agent restart — because it ran ONLY at start. v0.133.0 runs it every 10 min under the one-heavy-operation gate (red-proofed). `audits/r672-2026-09-24/C5-r673-vzdump-logs.txt` | **FIXED IN v0.133.0 — awaiting delivery; root cause R-684; owner: CC** | | **R-674** | **[P3-LOW] The ladder log says an app's pin „matches no update_ladder entry … older than the ladder" when the pin EQUALS the head.** Seen on 9202 2026-09-24 for nextcloud at the head. Misleading to an operator reading why nothing climbed. **Fix:** say "at the head" when the pin equals the newest `to`. | **READY — P3; owner: CC (controller)** | | **R-675** | **[P3-LOW] The unit-only restore's refusal for a file app still points to „Fájlok visszaállítása" instead of the second drive's whole restore.** `missingFileLegsRefusal` predates decision 26 (v0.269.0); when a whole copy exists on the second drive the sentence should name it. | **READY — P3; owner: CC (controller)** | | **R-676** | **[P3-LOW] Watch: immich's first start restarted 12 times — decision 28's crash-loop stop (6 in 10 min) would stop it.** From the 2026-09-17 chaos night (DB connection dropped during the first-start geocoding import on a 6 GB guest; it did not recover that night). No healthy app in any drill evidence restarts on a first start (1831 samples, 40 live containers), so the threshold stands; this row exists so the first immich install under v0.269.x is watched. `audits/night-2026-09-24/A3/40-first-start-restarts.txt` | **OPEN — P3; owner: CC (watch)** | @@ -821,6 +821,7 @@ class (an image `VOLUME` at an unmounted path) is still live — `immich-server` | **R-681** | **[P2-MEDIUM] An install interrupted by a controller restart is lost SILENTLY — no event, no page sentence, and its half-written files stay.** MEASURED 2026-09-24 on 9202 (Part E round 2, v0.269.1): n8n's install pressed at 11:48:42Z ("Deploying stack n8n … checking 1 images"); `systemctl restart docker` 20 s later took the controller down with it. After the restart the box logged NOTHING about n8n, the app read `not_deployed`, and the household's page showed it as never installed — while `app.yaml` (with its generated `N8N_ENCRYPTION_KEY`), `applied-compose.yml` and `applied-meta/` stayed in the stack dir. A fresh install through the product afterwards worked (211 s) and was not blocked by the leftovers. Compare the update path, which journals and RESUMES after the same accident (round 3/4). **Fix direction:** journal the install like the update; on boot either resume it or say on the page (and in an event) that it was interrupted, and clean the half-written files. `audits/night-2026-09-24/E/round-02*` | **READY — P2; owner: CC (controller)** | | **R-682** | **[P3-LOW] A Remove interrupted by a controller kill leaves the app half-removed: containers gone, the app still listed as installed (and held).** MEASURED 2026-09-24 on 9202 (chaos round 9): the kill 2 s after the Remove press answered the household `502 Bad Gateway`; after the restart `chaoscrash` read deployed, stopped, `unhealthy_stop`, with NO container left. Pressing Remove again completed it cleanly (200, only the catalog template left). Recoverable by the household's own second press; nothing tells them to press it. **Fix direction:** the remove journals its intent and finishes (or says it was interrupted) at boot, as the update does. `audits/night-2026-09-24/E/round-09*.json`, `E/round-09b-remove-again.txt` | **READY — P3; owner: CC (controller)** | | **R-683** | **[P3-LOW] Watch: after a power cut during an update's health check, the hold named an HOUR-OLD second-drive copy, not the one the update's own backup should have just made.** 2026-09-24 chaos round 3 (nextcloud, `backup_max_age: 1m`): no `backing-up` phase was seen and the hold named Tier 2 at 13:04 for an update pressed at 14:04; the pre-cut controller log was lost with the container (the runner now saves it at arm time — R-320). Round 11, the same action without a power cut, named a fresh 14:34 copy and logged the Tier-2 copy. The sentence was TRUE (it named the copy it offered); the question is why the update did not back up first. Not reproduced; watch the next power-cut drill. `audits/night-2026-09-24/E/round-03*.json`, `E/round-11-controller-pre.log` | **OPEN — P3; owner: CC (watch)** | +| **R-684** | **[P2-MEDIUM] demo-hp's whole-box backups cannot fit on its backup storage — 9201 has had no new whole-box backup since 2026-09-23.** `local` is the host ROOT disk (40 GB, 84 % used, ~4 GB free); it holds three 9201 archives of 5.8–6.9 GB (retention 3) and a new one needs ~7 GB: the 2026-09-24 runs failed `No space left on device` (06:59, 07:42), leaving the stale lock of R-673. Every night now fails the same way until space is made or the retention/target changes. A Tier-0 box, but the same shape exists on any appliance whose local backup target is its root disk. **Needs a decision** (fewer kept archives, another target, or a larger disk). `audits/r672-2026-09-24/C5-r673-vzdump-logs.txt` | **OPEN — P2; owner: operator (the decision) / CC** |