diff --git a/documentation/architecture/09-update-architecture.md b/documentation/architecture/09-update-architecture.md index 943a040f..1fb5f8c0 100644 --- a/documentation/architecture/09-update-architecture.md +++ b/documentation/architecture/09-update-architecture.md @@ -1115,7 +1115,7 @@ what the part can do to a household's data if it is wrong, not how likely that i | **4** | **SHIPPED — catalog `6db08a5`, night 2026-09-23** (`audits/DRILL-night-2026-09-23.md`): `update_ladder:` in `.felhom.yml`, one JSON entry per line (spiked on controller v0.266.0 and v0.267.0 first — the controller ignores the key); `check-test-record.py` (static, CI) + `check-test-record-move.py` (history + the registry for moved refs only, decision 23); the only writer `upgrade-test.py --write-ladder`; the 21 moves of 2026-09-22 backfilled from their records (21 proven). Not built: `steps/.yml` (part 5 needs it once an app has two steps); `CompareImageRefs` did NOT move to the gate — the gate asks for a proven test instead, which is decision 13's own test. **The test record + the catalog gate + the memory check.** The harness writes the ladder entry (below) from its verdict record, including the memory watch's peak and marks; the gate refuses an image move with no entry, an entry with a `failed` verdict, or one with no memory watch; `CompareImageRefs`' rule moves here as the push-time safety net. **Backfill:** one entry per current pin — the 21 proven moves from their records, every other pin `needs_person: "never tested"`, which is honest and keeps them manual. A version move re-checks `mem_limit` against the watch's peak (the RomM follow-up: gate, not checklist, because the watch now produces the number). | 13, R-635 follow-up | **2.5** | the memory watch (shipped 2026-09-23) | none on a box — catalog-side only | | **5** | **SHIPPED — controller v0.268.0 (`206b035`) + catalog `5ed599c`, proven live on 9202 2026-09-24** (`audits/ladder-2026-09-24/partD/`): romm 5.3.0/11.4 → 5.3.1/11.4 (its app step, from `steps/90dd9d68258286ef.yml`) → 5.3.1/11.8 (the engine step; `mariadb-upgrade` ran) in two presses, the seeded account read back after each, the page's „Hátralévő frissítési lépések" 2 → 1 → none. Step files: `templates//steps/.yml` (sha256 of `to` as canonical JSON, 16 hex; `stacks.StepKey` = `ladder.step_key`), refused absent or wrong by `check-test-record.py` rule 4, written by `--write-ladder` when a step is superseded, 8 backfilled from the NEWEST commit naming each step's images (romm's from `f4eb94f`, not the OOM-looping `15f9ebf`). The box reads them from its `--depth 1` clone (the whole tree is there — measured). One press = one step; a missing step file refuses before anything moves; an installed version matching no entry jumps, logged by name (measured live: vikunja 2.5.0). Limitation: a step has no `.felhom.yml` of its own (R-664). **The ladder on the box.** Read `update_ladder:` from the clone, find the installed step, apply ONE step with its OWN definition (`steps/.yml`, the last step the current template), repeat next night; a failed step stops the ladder for that app. `CatalogOrder` compares refs with the digest stripped (see part 7). | 14 | **2.5** | 1, 4 | medium — each step is the guarded update + undo; the new risk is rendering the wrong step's definition, pinned by a test per step shape | | **6** | **CATALOG HALF SHIPPED — night 2026-09-23:** every ladder entry carries the digest per `to` ref (`scripts/image_digest.py`, stdlib; equals Docker's `RepoDigests` on a box), and the move gate refuses a digest the registry no longer serves. **The box half (compare, render `name:tag@sha256`) is not built.** **Digests.** The catalog records `sha256` per pin at push time (`check-image-resolvable.py` already resolves it); the box compares it for the badge and renders `name:tag@sha256:…` when present. **Measured 2026-09-23 on 9202:** Docker and Compose both pull and run `redis:7-alpine@sha256:858f…`, and refuse a digest that does not exist (`audits/update-rulings-2026-09-23/70-…`). **Build trap, read from source:** `splitImageRef` returns "unorderable" for ANY ref containing `@` (`updateorder.go:134`), so the digest must be split off before ordering or every digest-pinned app reads Unknown. A digest gone upstream fails the PULL — Scenario E, pin back, nothing ran. | 17, R-446 | **2** | 4 (the entry carries the digest) | low | -| **7** | **The update leg in the chain + the automatic caller + the switch.** A leg that starts when the off-site leg has FINISHED (legs are clock-scheduled today, not chained — a completion signal is new), one app at a time (there is no single-flight, §3b Q4), `app_update.unattended` default ON, `stacks.update_window` removed, reads `UpdateRefusal.Reason`, remembers a failed step so it never re-presses it. **See the one open point below.** | 11, 12 | **3** | 1, 2, 5 | medium — the only part that acts with nobody watching; everything above is what makes it safe | +| **7** | **SPIKED 2026-09-24 (night, Part C) — the measured build brief is §6.4.2 below.** **The update leg in the chain + the automatic caller + the switch.** A leg that starts when the off-site leg has ENDED (on every exit path, skips included), one app at a time, one step per press, `app_update.unattended` default ON (decision 12), `stacks.update_window` removed, reads `UpdateRefusal.Reason`, remembers a failed step so it never re-presses it, and the full-system backup's gate waits for it until W+5h (decision 20). | 11, 12, 14, 15, 20 | **3** | 1, 2, 5 | medium — the only part that acts with nobody watching; everything above is what makes it safe | | **8** | **SHIPPED — controller v0.265.0 + hub v0.121.0, proven live on 9202 2026-09-23** (`audits/cleanup-2026-09-23/`; a kernel `oom_kill` counter, not the sticky flag — `08` §6.2). **R-636** — the same OOM key re-firing escalates instead of staying one `warning` for six hours. | R-636 | **1** | — | none | | **9** | **SHIPPED — controller v0.265.0, proven live on 9202 2026-09-23** (badge „Megállítva — visszaállítás szükséges" / "Stopped — restore needed", no Update button, 409 `held` unchanged). **R-625** — a held app stops offering an Update it will refuse. With the undo, holds become rarer; the lie on the page does not go away by itself. | R-625 | **0.5** | 1 | none | | **10** | **PostgreSQL majors converted by the box.** A guarded-update step: `pg_dumpall` from the old engine, a NEW datadir (the old one kept aside, never deleted, until the check passes), load, check; then each of the eleven apps proven on the bench before its catalog move. | 16, R-463 | **2 + 3** | 1 (the same load discipline), 4 | **HIGH** — it rebuilds the datadir; bounded by keeping the old datadir aside | @@ -1140,6 +1140,66 @@ step takes ~1 min when it works and ~2–6 min when it fails and is undone. **Recommendation: the first.** It keeps the ruling's order and its promise that the full-system backup is never skipped for an update; only the start time inside its existing window moves. +### 6.4.2 Part 7 — the build brief, from measurement (night 2026-09-24, Part C) + +Evidence: `audits/night-2026-09-24/C/` and `C-00…C-07`. Spike only — no product code for the caller was +written. Read with decisions 11, 12, 14, 15 and 20. + +**1. The chain, as it runs today (source + a real night).** The legs are clock-scheduled from one window +start W and NOTHING waits on the leg before it: db-dump at W, Tier 2 at W+60m, off-site at W+105m +(`backupwindow.go:16-21`, `cmd/controller/main.go:1048/1134/1267`); the full-system backup's gate is a +poll loop that opens at W+2h for 4 h (`quiesce.go:656-657`, window check `quiesce.go:238-245`). +**Measured on demo-hp 9201's real night (W = 02:30):** the off-site leg ran 04:15:05 → 04:18:33 CEST +(3 min 28 s, `ok`); the gate opened at 04:30. **So a leg placed after the off-site leg has ~11 minutes +before the gate** — decision 20's wait is required, not optional. + +**2. The signal that the off-site leg has ended.** There is no event. The nearest thing is the +persisted `offbox` status in `settings.json` — `LastStatus` (`running` at start, `ok`/`incomplete`/ +`error` at the end) with `LastRun` beside it, written by `UpdateOffboxStatus` (`offbox.go:1003-1125`). +The status travels with the timestamp (presence-is-not-success holds), **but it is not a reliable +"finished" signal:** five early returns (`offbox.go:863-897` — not configured, escrow pending, orphaned, +migration, another backup running) and the scheduler's own skip (`main.go:1268-1271`) write nothing, and +a box with no off-site target (9202 tonight) never runs the leg at all. **Build: CHAIN, do not poll.** +The `offbox-backup` job function calls the update leg after `RunOffboxBackup` returns, on EVERY path +including every skip — one call site, no new signal to go stale. A box with no off-site target runs +the update leg at W+105m. + +**3. The gate's interlock (decision 20).** Insert after the window check in `quiesce.runOnce`, as an +`Options` func beside `WindowStartFn` (`quiesce.go:75-95`): *update leg active and now < W+5h → defer* +(log and return, exactly like the window deferral; the loop re-polls every 5 min). The leg itself stops +STARTING steps at W+5h; a step already running finishes (≤ health timeout + undo). Manual whole-box runs +(`TriggerNow`) bypass it, as today. + +**4. One simulated night (9202, v0.269.1; the caller = `tools/unattended_caller_ladder.py`, which presses +only the public Update).** Four apps: wishlist 1 step behind, navidrome 2, romm 3, vikunja 1 with a +failing step. Measured per step: navidrome 10.6 s and 8.5 s (no database); wishlist 55.8 s (its first +update: the backup ran); romm 77.4 s, 71.2 s, 93.9 s (database + volume dump each step); vikunja's +failing step **undone in 104 s** with the drill's 90 s health timeout — **with the default 5 min it is +≈ 6–11 min** (verify up to 5 min, the undo's own verify up to 5 min). The whole leg: 7 min 18 s for +four steps and one undo. The household's pages: badges „Naprakész" for the three that climbed, and for +vikunja the undone sentence in both languages („…A doboz automatikusan visszaállította az előző +változatot és az adatokat — semmi nem veszett el." / "…put back the previous version and its data +automatically — nothing was lost."); event `app_update_undone` (dropped on 9202 — no hub, as designed). +During the db-dump leg every press was refused `busy` (transient, retried next pass). + +**5. What the spike found that the build must handle** (rows filed): +- **`ladder_steps_left` and the badge are STALE after a step ends `done`** until the next scan — the first + caller run re-pressed a current app four times (R-678). The leg rescans after every step, and the + update's own finish should refresh them. +- **An Update pressed on an app already at the head runs the whole guarded update** — backup, pull, + restart, `done` — with no refusal (R-679: navidrome restarted four times for nothing). The leg never + presses an app whose pin equals the head; the preflight should refuse with reason `current`. +- **The product does not remember a failed step.** After vikunja's undo the badge still offers the + same step; only the caller's memory kept it from a re-press. Decision 15 needs it on the box: the + failed `to` is recorded per app and the leg skips it until the catalog's ladder changes. + +**6. The build, in order (≈ 3 evenings, unchanged):** (a) the leg as a function called from the +off-site job on every path; one app at a time, one step per press, rescan between steps, stop at W+5h; +(b) the failed-step record + `current` refusal (R-679); (c) the gate's `UpdateLegActiveFn`; (d) the +per-box switch `app_update.unattended`, **default ON (decision 12)**, and `stacks.update_window` +removed; (e) the live proof: this night's four apps, with the window moved forward through the +product's own form (`POST /backups/window` — measured: the three legs reschedule at once). + ### 6.4.1 (record) The update night — the drill brief that preceded the rulings, costed and re-costed **The ruling is decision 6: all 53 apps, through the nightly rotation.** This is an ORDER inside that diff --git a/documentation/audits/night-2026-09-24/C-00-9201-last-night-chain.txt b/documentation/audits/night-2026-09-24/C-00-9201-last-night-chain.txt new file mode 100644 index 00000000..e14d206f --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-00-9201-last-night-chain.txt @@ -0,0 +1,16 @@ +window None +offbox {'enabled': True, 'schedule': 'daily', 'last_run': '2026-09-24T02:18:33Z', 'last_status': 'ok', 'last_success': '2026-09-24T02:18:33Z', 'last_duration': '3m28s', 'last_error': None} +gitea.dooplex.hu/admin/felhom-controller:0.268.0 +2026/09/24 06:47:23 quiesce.go:179: [INFO] [quiesce] loop started (poll 5m0s, max-quiesce 30m0s) +UPID:demo-hp:001C2729:11475EED:6AB4AE30:vzdump:9201:felhom-agent@pve!agent: 6AB4AFAF job errors +UPID:demo-hp:001D29F4:11490EBD:6AB4B281:vzdump:9201:felhom-agent@pve!agent: 6AB4B401 job errors +UPID:demo-hp:001E7D73:114B58E7:6AB4B85E:vzdump:9201:felhom-agent@pve!agent: 6AB4B9DA job errors +UPID:demo-hp:0020B26F:114F02F7:6AB4C1BF:vzdump:9201:felhom-agent@pve!agent: 6AB4C1BF job errors +Sep 24 04:29:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:29:29.641+02:00 level=INFO msg="backup: restore-test evaluated — nothing due" verdicts="felhom-pbs: newest settled archive (landed 2026-09-22T04:12:45Z) is alread +Sep 24 06:59:29 demo-hp felhom-agent[1195783]: time=2026-09-24T06:59:29.177+02:00 level=INFO msg="local-api: backup reached snapshotted (app may resume)" vmid=9201 target=local job=backup-9201-1790225968108254908 +Sep 24 07:05:52 demo-hp felhom-agent[1195783]: time=2026-09-24T07:05:52.441+02:00 level=ERROR msg="local-api: backup job failed" vmid=9201 target=local job=backup-9201-1790225968108254908 err="backup: vzdump task vmid 9201: proxmo +Sep 24 07:17:54 demo-hp felhom-agent[1195783]: time=2026-09-24T07:17:54.612+02:00 level=INFO msg="local-api: backup reached snapshotted (app may resume)" vmid=9201 target=local job=backup-9201-1790227073555655065 +Sep 24 07:24:21 demo-hp felhom-agent[1195783]: time=2026-09-24T07:24:21.352+02:00 level=ERROR msg="local-api: backup job failed" vmid=9201 target=local job=backup-9201-1790227073555655065 err="backup: vzdump task vmid 9201: proxmo +Sep 24 07:42:55 demo-hp felhom-agent[1195783]: time=2026-09-24T07:42:55.193+02:00 level=INFO msg="local-api: backup reached snapshotted (app may resume)" vmid=9201 target=local job=backup-9201-1790228574136769346 +Sep 24 07:49:16 demo-hp felhom-agent[1195783]: time=2026-09-24T07:49:16.829+02:00 level=ERROR msg="local-api: backup job failed" vmid=9201 target=local job=backup-9201-1790228574136769346 err="backup: vzdump task vmid 9201: proxmo +Sep 24 08:22:57 demo-hp felhom-agent[1195783]: time=2026-09-24T08:22:57.653+02:00 level=ERROR msg="local-api: backup job failed" vmid=9201 target=local job=backup-9201-1790230975578595274 err="backup: vzdump task vmid 9201: proxmo diff --git a/documentation/audits/night-2026-09-24/C-01-demo-hp-9201-vzdump-errors.txt b/documentation/audits/night-2026-09-24/C-01-demo-hp-9201-vzdump-errors.txt new file mode 100644 index 00000000..d4071065 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-01-demo-hp-9201-vzdump-errors.txt @@ -0,0 +1,15 @@ + 1 "backup: vzdump task vmid 9201: proxmox: task UPID:demo-hp:001C2729:11475EED:6AB4AE30:vzdump:9201:felhom-agent@pve!agent: failed: exitstatus \"job errors\"" + 1 "backup: vzdump task vmid 9201: proxmox: task UPID:demo-hp:001D29F4:11490EBD:6AB4B281:vzdump:9201:felhom-agent@pve!agent: failed: exitstatus \"job errors\"" + 1 "backup: vzdump task vmid 9201: proxmox: task UPID:demo-hp:001E7D73:114B58E7:6AB4B85E:vzdump:9201:felhom-agent@pve!agent: failed: exitstatus \"job errors\"" + 1 "backup: vzdump task vmid 9201: proxmox: task UPID:demo-hp:0020B26F:114F02F7:6AB4C1BF:vzdump:9201:felhom-agent@pve!agent: failed: exitstatus \"job errors\"" + +2026-09-24 08:22:55 INFO: Starting Backup of VM 9201 (lxc) +2026-09-24 08:22:55 INFO: status = running +2026-09-24 08:22:55 ERROR: Backup of VM 9201 failed - CT is locked (snapshot-delete) + +Name Type Status Total (KiB) Used (KiB) Available (KiB) % +felhom-pbs pbs active 0 0 0 0.00% +local dir active 40453376 34151828 4214432 84.42% +local-lvm lvmthin active 56487936 56487936 0 100.00% +nvme-scratch dir active 983379700 76753176 856599912 7.81% +/dev/mapper/pve-root 39G 33G 4.1G 90% / diff --git a/documentation/audits/night-2026-09-24/C-02-demo-hp-storage.txt b/documentation/audits/night-2026-09-24/C-02-demo-hp-storage.txt new file mode 100644 index 00000000..17489513 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-02-demo-hp-storage.txt @@ -0,0 +1,87 @@ +Thu Sep 24 13:07:01 CEST 2026 + LV VG LSize Data% Meta% Pool Origin CTime + data pve 53.87g 100.00 3.54 2026-08-21 17:40:52 +0200 + root pve <39.50g 2026-08-21 17:40:52 +0200 + snap_vm-9201-disk-1_vzdump pve 70.00g data vm-9201-disk-1 2026-09-24 07:42:54 +0200 + swap pve 8.00g 2026-08-21 17:40:52 +0200 + vm-9201-disk-0 pve 32.00g 5.39 data 2026-08-21 17:59:27 +0200 + vm-9201-disk-1 pve 70.00g 42.87 data 2026-08-21 17:59:30 +0200 + vm-990000-disk-0 pve 32.00g 4.86 data 2026-09-24 10:29:30 +0200 + vm-990000-disk-1 pve 70.00g 28.52 data 2026-09-24 10:29:32 +0200 + vm-990000-disk-2 pve 1.00g 4.80 data 2026-09-24 10:29:39 +0200 + vm-990000-disk-3 pve 1.00g 4.80 data 2026-09-24 10:29:40 +0200 + + LANG = "en_US.UTF-8" +VMID Status Lock Name +9201 running snapshot-delete demo-hp +9202 running demo-hp-scratch +990000 stopped demo-hp + +/etc/pve/lxc/9201.conf:mp0: local-lvm:vm-9201-disk-1,mp=/var/lib/felhom,backup=1,size=70G +/etc/pve/lxc/9201.conf:mp8: /mnt/felhom-drives,mp=/mnt/felhom-drives +/etc/pve/lxc/9201.conf:mp9: /var/lib/felhom-agent/guests/9201/bootstrap,mp=/etc/felhom-bootstrap,ro=1 +/etc/pve/lxc/9201.conf:rootfs: local-lvm:vm-9201-disk-0,size=32G +/etc/pve/lxc/9201.conf:mp0: local-lvm:vm-9201-disk-1,mp=/var/lib/felhom,backup=1,size=70G +/etc/pve/lxc/9201.conf:mp8: /mnt/felhom-drives,mp=/mnt/felhom-drives +/etc/pve/lxc/9201.conf:mp9: /var/lib/felhom-agent/guests/9201/bootstrap,mp=/etc/felhom-bootstrap,ro=1 +/etc/pve/lxc/9202.conf:mp0: nvme-scratch:9202/vm-9202-disk-1.raw,mp=/var/lib/felhom,backup=1,size=70G +/etc/pve/lxc/9202.conf:mp8: /mnt/hdd_1/scratch-drives/scratch_hdd,mp=/mnt/felhom-drives/scratch_hdd +/etc/pve/lxc/9202.conf:mp9: /var/lib/felhom-agent/guests/9202/bootstrap,mp=/etc/felhom-bootstrap,ro=1 +/etc/pve/lxc/9202.conf:rootfs: nvme-scratch:9202/vm-9202-disk-0.raw,size=32G +6:lock: snapshot-delete + +`-> vzdump 2026-09-24 07:42:54 vzdump backup snapshot + `-> current You are here! +Sep 24 04:00:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:00:29.850+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:00:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:00:29.972+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:00:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:00:29.983+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:00:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:00:59.966+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:01:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:01:29.850+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:01:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:01:29.972+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:01:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:01:29.976+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:01:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:01:59.970+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:02:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:02:29.849+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:02:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:02:29.977+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:02:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:02:29.980+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:02:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:02:59.969+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:03:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:03:29.864+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:03:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:03:29.963+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:03:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:03:29.966+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:03:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:03:59.970+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:04:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:04:29.852+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:04:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:04:29.970+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:04:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:04:29.970+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:04:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:04:59.971+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:05:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:05:29.849+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:05:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:05:29.970+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:05:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:05:29.973+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:05:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:05:59.967+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:06:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:06:29.854+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:06:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:06:29.963+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:06:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:06:29.968+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:06:59 demo-hp felhom-agent[1195783]: time=2026-09-24T04:06:59.970+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:07:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:07:29.854+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 +Sep 24 04:07:29 demo-hp felhom-agent[1195783]: time=2026-09-24T04:07:29.977+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1 + +arch: amd64 +cores: 7 +features: nesting=1,keyctl=1 +hookscript: local:snippets/felhom-guest-hook.sh +hostname: demo-hp +memory: 25898 +mp0: local-lvm:vm-990000-disk-1,mp=/var/lib/felhom,backup=1,size=70G +mp8: local-lvm:vm-990000-disk-2,mp=/mnt/felhom-drives,backup=0,size=1G +mp9: local-lvm:vm-990000-disk-3,mp=/etc/felhom-bootstrap,backup=0,size=1G +net0: name=eth0,bridge=vmbr0,hwaddr=BC:24:11:0F:7E:C5,ip=dhcp,link_down=1,type=veth +net1: name=eth1,bridge=vmbr9,hwaddr=BC:24:11:28:B4:F5,ip=169.254.253.2/30,link_down=1,type=veth +onboot: 0 +UPID:demo-hp:00273369:115A998B:6AB4DF6A:vzrestore:990000:felhom-agent@pve!agent: 6AB4E104 OK +UPID:demo-hp:002789C4:115B3A8C:6AB4E106:vzstart:990000:felhom-agent@pve!agent: 6AB4E10B startup for container '990000' failed +UPID:demo-hp:00278B87:115B3CEB:6AB4E10C:vzdestroy:990000:felhom-agent@pve!agent: 6AB4E10C lvremove 'pve/vm-990000-disk-0' error: Logical volume pve/vm-990000-disk-0 contains a filesystem in use. +== dmesg thin +== dmsetup +0 112975872 thin-pool 441 9277/262144 882624/882624 - out_of_data_space discard_passdown error_if_no_space - 1024 +== mounts of 990000 +== 9201 docker + LANG = "en_US.UTF-8" +felhom-controller Up 4 hours (healthy) diff --git a/documentation/audits/night-2026-09-24/C-03-demo-hp-9201-apps-down.txt b/documentation/audits/night-2026-09-24/C-03-demo-hp-9201-apps-down.txt new file mode 100644 index 00000000..582dc626 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-03-demo-hp-9201-apps-down.txt @@ -0,0 +1,63 @@ + LANG = "en_US.UTF-8" +felhom-controller Up 4 hours (healthy) +romm Up 5 hours (healthy) +romm-db Up 5 hours (healthy) +romm-redis Up 5 hours (healthy) +privatebin Up 5 hours (healthy) +opengist Up 5 hours (healthy) +kimai Up 5 hours (healthy) +kimai-db Up 5 hours (healthy) +docmost Up 5 hours (healthy) +docmost-postgres Up 5 hours (healthy) +docmost-redis Up 5 hours (healthy) +calibre-web Up 5 hours (healthy) +bookstack Up 5 hours (unhealthy) +bookstack-db Up 5 hours (healthy) +bentopdf Up 5 hours (healthy) +adventurelog Up 5 hours (unhealthy) +adventurelog-postgres Up 5 hours (healthy) +adventurelog-frontend Up 5 hours (healthy) +filebrowser Up 3 weeks (healthy) +cloudflared Up 3 weeks +traefik Up 3 weeks + +2026/09/24 08:12:24 scheduler.go:346: [INFO] [scheduler] Running job: backup-cache +2026/09/24 08:12:24 backup.go:1117: [INFO] [backup] Found 19 DB dump files across drives +2026/09/24 08:12:24 dbdump.go:208: [INFO] [backup] Discovered 6 databases +2026/09/24 08:12:24 [INFO] [backup] Discovered app data: 10 apps +2026/09/24 08:12:24 backup.go:1187: [INFO] [backup] Backup status cache refreshed +2026/09/24 08:12:24 scheduler.go:363: [INFO] [scheduler] Job backup-cache completed (took 246ms) +2026/09/24 08:17:24 scheduler.go:346: [INFO] [scheduler] Running job: backup-cache +2026/09/24 08:17:24 backup.go:1117: [INFO] [backup] Found 19 DB dump files across drives +2026/09/24 08:17:24 dbdump.go:208: [INFO] [backup] Discovered 6 databases +2026/09/24 08:17:24 [INFO] [backup] Discovered app data: 10 apps +2026/09/24 08:17:24 backup.go:1187: [INFO] [backup] Backup status cache refreshed +2026/09/24 08:17:24 scheduler.go:363: [INFO] [scheduler] Job backup-cache completed (took 341ms) +2026/09/24 08:22:24 scheduler.go:346: [INFO] [scheduler] Running job: backup-cache +2026/09/24 08:22:24 backup.go:1117: [INFO] [backup] Found 19 DB dump files across drives +2026/09/24 08:22:24 dbdump.go:208: [INFO] [backup] Discovered 6 databases +2026/09/24 08:22:24 [INFO] [backup] Discovered app data: 10 apps +2026/09/24 08:22:24 backup.go:1187: [INFO] [backup] Backup status cache refreshed +2026/09/24 08:22:24 scheduler.go:363: [INFO] [scheduler] Job backup-cache completed (took 240ms) +2026/09/24 08:27:24 scheduler.go:346: [INFO] [scheduler] Running job: backup-cache +2026/09/24 08:27:24 backup.go:1117: [INFO] [backup] Found 19 DB dump files across drives +2026/09/24 08:27:24 dbdump.go:208: [INFO] [backup] Discovered 6 databases +2026/09/24 08:27:24 [INFO] [backup] Discovered app data: 10 apps +2026/09/24 08:27:24 backup.go:1187: [INFO] [backup] Backup status cache refreshed +2026/09/24 08:27:24 scheduler.go:363: [INFO] [scheduler] Job backup-cache completed (took 298ms) +2026/09/24 08:32:24 scheduler.go:346: [INFO] [scheduler] Running job: backup-cache +2026/09/24 08:32:24 backup.go:1117: [INFO] [backup] Found 19 DB dump files across drives +2026/09/24 08:32:24 dbdump.go:208: [INFO] [backup] Discovered 6 databases +2026/09/24 08:32:24 [INFO] [backup] Discovered app data: 10 apps +2026/09/24 08:32:24 backup.go:1187: [INFO] [backup] Backup status cache refreshed +2026/09/24 08:32:24 scheduler.go:363: [INFO] [scheduler] Job backup-cache completed (took 292ms) +2026/09/24 08:37:24 scheduler.go:346: [INFO] [scheduler] Running job: backup-cache +2026/09/24 08:37:24 backup.go:1117: [INFO] [backup] Found 19 DB dump files across drives +2026/09/24 08:37:24 dbdump.go:208: [INFO] [backup] Discovered 6 databases +2026/09/24 08:37:24 [INFO] [backup] Discovered app data: 10 apps +2026/09/24 08:37:24 backup.go:1187: [INFO] [backup] Backup status cache refreshed +2026/09/24 08:37:24 scheduler.go:363: [INFO] [scheduler] Job backup-cache completed (took 340ms) +2026/09/24 08:38:24 scheduler.go:360: [ERROR] [scheduler] Job ring-spill failed: sync /opt/docker/felhom-controller/data/debug-ring.log.tmp: no space left on device (took 15ms) +2026/09/24 08:38:54 scheduler.go:360: [ERROR] [scheduler] Job ring-spill failed: sync /opt/docker/felhom-controller/data/debug-ring.log.tmp: no space left on device (took 11ms) +2026/09/24 08:39:24 scheduler.go:360: [ERROR] [scheduler] Job ring-spill failed: sync /opt/docker/felhom-controller/data/debug-ring.log.tmp: no space left on device (took 12ms) +2026/09/24 08:39:54 scheduler.go:360: [ERROR] [scheduler] Job ring-spill failed: sync /opt/docker/felhom-controller/data/debug-ring.log.tmp: no space left on device (took 12ms) diff --git a/documentation/audits/night-2026-09-24/C-04-restore-test-filled-pool.txt b/documentation/audits/night-2026-09-24/C-04-restore-test-filled-pool.txt new file mode 100644 index 00000000..cfe34bc5 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-04-restore-test-filled-pool.txt @@ -0,0 +1,85 @@ +Sep 24 10:29:29 demo-hp felhom-agent[1195783]: time=2026-09-24T10:29:29.327+02:00 level=INFO msg="backup: restore-test tier is DUE (per-archive; oldest-proven first among due tiers)" target=local archive=local:backup/vzdump-lxc-9201-2026_09_23-06_55_25.tar.zst landed=2026-09-23T04:55:25Z reason="newest settled archive (landed 2026-09-23T04:55:25Z) has not been proven (last proven archive was a dif +Sep 24 10:29:29 demo-hp felhom-agent[1195783]: time=2026-09-24T10:29:29.525+02:00 level=INFO msg="restore-test: full-fidelity restore params derived from the archive config" scratch=990000 params=4 +Sep 24 10:29:29 demo-hp felhom-agent[1195783]: time=2026-09-24T10:29:29.971+02:00 level=INFO msg="guest-power: watchdog alive" sweeps_since_boot=10080 guests_evaluated=1 currently_stopped=0 +Sep 24 10:29:31 demo-hp felhom-agent[1195783]: time=2026-09-24T10:29:31.070+02:00 level=INFO msg="controller-supervisor: alive" sweeps_since_boot=20160 guests_evaluated=1 controllers_not_running=0 +Sep 24 10:30:29 demo-hp felhom-agent[1195783]: time=2026-09-24T10:30:29.383+02:00 level=INFO msg="pbs: verify cycle complete" datastore=felhom-offsite snapshots=2 +Sep 24 10:33:10 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:10.974+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.858999999990042 +Sep 24 10:33:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:24.908+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.876699999982906 +Sep 24 10:33:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:26.605+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.878899999996376 +Sep 24 10:33:27 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:27.899+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.879699999993417 +Sep 24 10:33:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:30.409+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.881699999994661 +Sep 24 10:33:50 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:50.628+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.907699999993555 +Sep 24 10:33:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:56.628+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.916999999991563 +Sep 24 10:33:57 demo-hp felhom-agent[1195783]: time=2026-09-24T10:33:57.440+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.917099999997676 +Sep 24 10:34:10 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:10.700+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.932999999984233 +Sep 24 10:34:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:24.654+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.944199999994661 +Sep 24 10:34:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:26.225+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.945099999997815 +Sep 24 10:34:27 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:27.723+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.947399999982823 +Sep 24 10:34:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:30.294+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.950199999998396 +Sep 24 10:34:50 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:50.502+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.980399999994717 +Sep 24 10:34:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:56.464+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.987099999989378 +Sep 24 10:34:57 demo-hp felhom-agent[1195783]: time=2026-09-24T10:34:57.258+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.987199999995491 +Sep 24 10:35:10 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:10.359+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=0.998499999994744 +Sep 24 10:35:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:24.658+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:35:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:26.161+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:35:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:26.913+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:35:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:30.317+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:35:50 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:50.259+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:35:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:56.170+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:35:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:35:56.889+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:10 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:10.275+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:24.693+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:26.184+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:27 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:27.382+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:28 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:28.266+02:00 level=INFO msg="audit: gate decision" class=guest_destroy host=demo-hp-bb76ea guest=990000 source=one_shot_job disposition=benign allowed=true reason=benign key_id="" nonce="" durable_id="" +Sep 24 10:36:28 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:28.266+02:00 level=INFO msg="gate decision" class=guest_destroy guest=990000 source=one_shot_job disposition=benign allowed=true reason=benign +Sep 24 10:36:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:30.302+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:30.330+02:00 level=ERROR msg="restore-test: scratch teardown task failed; left for Recover" vmid=990000 err="proxmox: task UPID:demo-hp:00278B87:115B3CEB:6AB4E10C:vzdestroy:990000:felhom-agent@pve!agent: failed: exitstatus \"lvremove 'pve/vm-990000-disk-0' error: Logical volume pve/vm-990000-disk-0 contains a filesystem in use. +Sep 24 10:36:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:30.331+02:00 level=ERROR msg="backup: scheduled restore-test FAILED" archive=local:backup/vzdump-lxc-9201-2026_09_23-06_55_25.tar.zst err="reconcile: restore-test start task: proxmox: task UPID:demo-hp:002789C4:115B3A8C:6AB4E106:vzstart:990000:felhom-agent@pve!agent: failed: exitstatus \"startup for container '990000' failed\"" +Sep 24 10:36:50 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:50.263+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:56.161+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:36:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:36:56.876+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:10 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:10.318+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:24.498+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:24.682+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:25 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:25.123+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:25 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:25.852+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:26.224+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:26.604+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:27 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:27.036+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:30.315+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:50 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:50.292+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:56.164+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:37:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:37:56.955+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:10 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:10.316+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:24 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:24.666+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:26.198+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:26 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:26.951+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:30 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:30.283+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:50 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:50.302+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 +Sep 24 10:38:56 demo-hp felhom-agent[1195783]: time=2026-09-24T10:38:56.175+02:00 level=WARN msg="storage: lvmthin pool data fill is high (a full pool corrupts every guest on it)" storage=local-lvm data_used_fraction=1 + +== UPID:demo-hp:00273369:115A998B:6AB4DF6A:vzrestore:990000:felhom-agent@pve!agent: +Filesystem UUID: c934b758-ba9f-4713-a1a5-2d1232043953 +Superblock backups stored on blocks: + 32768, 98304, 163840, 229376 +restoring 'local:backup/vzdump-lxc-9201-2026_09_23-06_55_25.tar.zst' now.. +extracting archive '/var/lib/vz/dump/vzdump-lxc-9201-2026_09_23-06_55_25.tar.zst' +Total bytes read: 22607360000 (22GiB, 67MiB/s) +merging backed-up and given configuration.. +TASK OK +== UPID:demo-hp:002789C4:115B3A8C:6AB4E106:vzstart:990000:felhom-agent@pve!agent: +run_buffer: 569 Script exited with status 32 +lxc_init: 1037 Failed to run lxc.hook.pre-start for container "990000" +__lxc_start: 2208 Failed to initialize container "990000" +TASK ERROR: startup for container '990000' failed +== UPID:demo-hp:00278B87:115B3CEB:6AB4E10C:vzdestroy:990000:felhom-agent@pve!agent: +TASK ERROR: lvremove 'pve/vm-990000-disk-0' error: Logical volume pve/vm-990000-disk-0 contains a filesystem in use. +== dmsetup open counts +Name Maj Min Stat Open Targ Event UUID +pve-vm--990000--disk--0 252 8 L--w 0 1 0 LVM-zVqGDaV6jsHB26RyZrd0ftfUB3blL75R3RYWI304wBL9CEdu1E10ZdglPW0HuVJh +pve-vm--990000--disk--1 252 9 L--w 0 1 0 LVM-zVqGDaV6jsHB26RyZrd0ftfUB3blL75RXHMjzdCWlzJJB21MBWeU8M2L9365Wh3i +pve-vm--990000--disk--2 252 10 L--w 0 1 0 LVM-zVqGDaV6jsHB26RyZrd0ftfUB3blL75R4vCRapMR1JPlXcbl9PAQnNETfYQEVTrQ +pve-vm--990000--disk--3 252 11 L--w 0 1 0 LVM-zVqGDaV6jsHB26RyZrd0ftfUB3blL75RjyxMj93W5cBuZZDWPKZVS7RDOHYlk1B9 +== mountinfo holders +== fuser diff --git a/documentation/audits/night-2026-09-24/C-05-intervention1-agent-recover.txt b/documentation/audits/night-2026-09-24/C-05-intervention1-agent-recover.txt new file mode 100644 index 00000000..7e748fb7 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-05-intervention1-agent-recover.txt @@ -0,0 +1,24 @@ +Thu Sep 24 13:09:55 CEST 2026 +== before + LANG = "en_US.UTF-8" +VMID Status Lock Name +9201 running snapshot-delete demo-hp +9202 running demo-hp-scratch +990000 stopped demo-hp +0 112975872 thin-pool 441 9277/262144 882624/882624 - out_of_data_space discard_passdown error_if_no_space - 1024 +== agent journal since restart +Sep 24 13:09:56 demo-hp felhom-agent[3134463]: time=2026-09-24T13:09:56.951+02:00 level=INFO msg="audit: gate decision" class=guest_destroy host=demo-hp-bb76ea guest=990000 source=one_shot_job disposition=benign allowed=true reason=benign key_id="" nonce="" durable_id="" +Sep 24 13:09:56 demo-hp felhom-agent[3134463]: time=2026-09-24T13:09:56.951+02:00 level=INFO msg="gate decision" class=guest_destroy guest=990000 source=one_shot_job disposition=benign allowed=true reason=benign +Sep 24 13:09:59 demo-hp felhom-agent[3134463]: time=2026-09-24T13:09:59.010+02:00 level=WARN msg="recover: destroyed leaked restore-test scratch guest" op_id=scratch-restore-990000-9 vmid=990000 +Sep 24 13:09:59 demo-hp felhom-agent[3134463]: time=2026-09-24T13:09:59.010+02:00 level=INFO msg="recover: in-flight journal reconciled" result="{Examined:1 Resumed:0 Failed:0 RolledBack:0 StillRunning:0 Unresolved:0 ScratchClean:0 ScratchDestroyed:1 BringUpClean:0 BringUpRolledBack:0}" +== after + LANG = "en_US.UTF-8" +VMID Status Lock Name +9201 running demo-hp +9202 running demo-hp-scratch + LV Data% + data 58.91 +0 112975872 thin-pool 446 6935/262144 519948/882624 - rw discard_passdown queue_if_no_space - 1024 + LANG = "en_US.UTF-8" +Thu Sep 24 11:11:41 UTC 2026 +24 diff --git a/documentation/audits/night-2026-09-24/C-07-9201-readonly.txt b/documentation/audits/night-2026-09-24/C-07-9201-readonly.txt new file mode 100644 index 00000000..609ed814 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C-07-9201-readonly.txt @@ -0,0 +1,10 @@ +Thu Sep 24 13:12:05 CEST 2026 + LANG = "en_US.UTF-8" +/etc/felhom-bootstrap ext4 ro,relatime,errors=remount-ro +/run/credentials/systemd-journald.service ramfs ro,nosuid,nodev,noexec,relatime,nosymfollow,mode=700 +/run/credentials/systemd-networkd.service ramfs ro,nosuid,nodev,noexec,relatime,nosymfollow,mode=700 +/run/credentials/container-getty@1.service ramfs ro,nosuid,nodev,noexec,relatime,nosymfollow,mode=700 +/run/credentials/console-getty.service ramfs ro,nosuid,nodev,noexec,relatime,nosymfollow,mode=700 +/run/credentials/container-getty@2.service ramfs ro,nosuid,nodev,noexec,relatime,nosymfollow,mode=700 + +touch: cannot touch '/root/.probe': Read-only file system diff --git a/documentation/audits/night-2026-09-24/C/10-window-moved.txt b/documentation/audits/night-2026-09-24/C/10-window-moved.txt new file mode 100644 index 00000000..e47f401f --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/10-window-moved.txt @@ -0,0 +1,12 @@ +13:12:44 before: +2026/09/24 11:02:48 scheduler.go:132: [INFO] [scheduler] Daily job offsite-proof scheduled for 2026-09-25 05:30 CEST +2026/09/24 11:02:48 scheduler.go:132: [INFO] [scheduler] Daily job metrics-prune scheduled for 2026-09-25 04:00 CEST +2026/09/24 11:02:48 scheduler.go:132: [INFO] [scheduler] Daily job fill-watch scheduled for 2026-09-25 03:30 CEST +13:12:44 POST /backups/window window_start=13:20 -> 303 +13:12:51 after: +2026/09/24 11:12:44 auth.go:142: [DEBUG] [web] auth: valid session for POST /backups/window +2026/09/24 11:12:44 server.go:545: [DEBUG] [web] ServeHTTP: POST /backups/window from 172.18.0.9:39034 +2026/09/24 11:12:44 scheduler.go:172: [INFO] [scheduler] Daily job db-dump rescheduled 02:30 → 13:20 (next run 2026-09-24 13:20 CEST) +2026/09/24 11:12:44 scheduler.go:172: [INFO] [scheduler] Daily job tier2-backup rescheduled 03:30 → 14:20 (next run 2026-09-24 14:20 CEST) +2026/09/24 11:12:44 scheduler.go:172: [INFO] [scheduler] Daily job offbox-backup rescheduled 04:15 → 15:05 (next run 2026-09-24 15:05 CEST) +2026/09/24 11:12:44 backup_handlers.go:64: [INFO] [web] backup window set to 13:20 (legs 13:20/14:20/15:05) diff --git a/documentation/audits/night-2026-09-24/C/11-dbdump-leg.txt b/documentation/audits/night-2026-09-24/C/11-dbdump-leg.txt new file mode 100644 index 00000000..1a3fab6b --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/11-dbdump-leg.txt @@ -0,0 +1,24 @@ + LANG = "en_US.UTF-8" +2026/09/24 11:19:08 healthprobe.go:190: [WARN] Health probe vikunja: API GET :8999/api/v1/info → Get "http://vikunja:8999/api/v1/info": dial tcp 172.18.0.11:8999: connect: connection refused +2026/09/24 11:19:13 update_guard.go:360: [INFO] [backup] update pre-backup for navidrome: starting (DB dump → volume dump → unit capture → Tier 2) +2026/09/24 11:19:13 dbdump.go:208: [INFO] [backup] Discovered 3 databases +2026/09/24 11:19:13 backup.go:920: [INFO] [backup] Stopping navidrome for safe volume dump +2026/09/24 11:19:14 backup.go:821: [INFO] [backup] Volume dump: navidrome/navidrome_navidrome_data → 675.0 KB +2026/09/24 11:19:14 backup.go:930: [INFO] [backup] Restarting navidrome after volume dump +2026/09/24 11:19:15 update_guard.go:410: [INFO] [backup] update pre-backup for navidrome: volume dump OK +2026/09/24 11:19:15 update_guard.go:416: [INFO] [backup] update pre-backup for navidrome: recovery unit captured (0 database dump(s)) +2026/09/24 11:19:15 update.go:1260: [INFO] [stacks] update navidrome: phase safety-dump +2026/09/24 11:19:15 dbdump.go:208: [INFO] [backup] Discovered 3 databases +2026/09/24 11:19:15 update_guard.go:476: [INFO] [backup] update safety dump for navidrome: the app has no database — nothing to copy (no-op) +2026/09/24 11:19:15 update.go:807: [INFO] [stacks] update navidrome: safety dump done (0 file(s)) [] +2026/09/24 11:19:24 update.go:1260: [INFO] [stacks] update navidrome: phase safety-dump +2026/09/24 11:19:24 dbdump.go:208: [INFO] [backup] Discovered 3 databases +2026/09/24 11:19:24 update_guard.go:476: [INFO] [backup] update safety dump for navidrome: the app has no database — nothing to copy (no-op) +2026/09/24 11:19:24 update.go:807: [INFO] [stacks] update navidrome: safety dump done (0 file(s)) [] +2026/09/24 11:19:28 healthprobe.go:190: [WARN] Health probe vikunja: API GET :8999/api/v1/info → Get "http://vikunja:8999/api/v1/info": dial tcp 172.18.0.11:8999: connect: connection refused +2026/09/24 11:19:33 update.go:1260: [INFO] [stacks] update navidrome: phase safety-dump +2026/09/24 11:19:33 dbdump.go:208: [INFO] [backup] Discovered 3 databases +2026/09/24 11:19:33 update_guard.go:476: [INFO] [backup] update safety dump for navidrome: the app has no database — nothing to copy (no-op) +grep: write error: Broken pipe +grep: write error: Broken pipe +grep: write error: Broken pipe diff --git a/documentation/audits/night-2026-09-24/C/20-setup.json b/documentation/audits/night-2026-09-24/C/20-setup.json new file mode 100644 index 00000000..579494d7 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/20-setup.json @@ -0,0 +1,113 @@ +{ + "controller": "gitea.dooplex.hu/admin/felhom-controller:0.269.1", + "apps": { + "wishlist": { + "ladder_len": 1, + "installed_at": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.66.0" + }, + "deploy_ok": true, + "deploy_s": 56, + "pinned": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.66.0" + }, + "steps_left": 1, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 1 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 1 day ago" + } + ] + } + }, + "navidrome": { + "ladder_len": 2, + "installed_at": { + "navidrome": "deluan/navidrome:0.63.2" + }, + "deploy_ok": true, + "deploy_s": 19, + "pinned": { + "navidrome": "deluan/navidrome:0.63.2" + }, + "steps_left": 2, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 1 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 1 day ago" + } + ] + } + }, + "romm": { + "ladder_len": 3, + "installed_at": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "deploy_ok": true, + "deploy_s": 69, + "pinned": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "steps_left": 3, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 1 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 1 day ago" + } + ] + } + }, + "vikunja": { + "ladder_len": 1, + "installed_at": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "deploy_ok": true, + "deploy_s": 5, + "pinned": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "steps_left": 1, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 2 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 2 days ago" + } + ] + } + } + } +} \ No newline at end of file diff --git a/documentation/audits/night-2026-09-24/C/20-setup.log b/documentation/audits/night-2026-09-24/C/20-setup.log new file mode 100644 index 00000000..d9695c4e --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/20-setup.log @@ -0,0 +1,22 @@ +13:14:20 drill: wishlist/navidrome/romm/vikunja at the ladder's first from (+ step .felhom.yml files from live cf7cf84) +13:14:25 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:15:20 [1] deployed, controller state=running, pinned={'wishlist': 'ghcr.io/cmintey/wishlist:v0.66.0'} +13:15:20 wishlist: deployed=True in 56 s pinned={'wishlist': 'ghcr.io/cmintey/wishlist:v0.66.0'} +13:15:24 [1] made the drive paths this app requires: ['/mnt/felhom-drives/scratch_hdd/userdata/navidrome'] +13:15:24 [1] required fields filled beyond DOMAIN/SUBDOMAIN: ['HDD_PATH'] +13:15:24 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:15:39 [1] deployed, controller state=running, pinned={'navidrome': 'deluan/navidrome:0.63.2'} +13:15:39 navidrome: deployed=True in 19 s pinned={'navidrome': 'deluan/navidrome:0.63.2'} +13:15:43 [1] made the drive paths this app requires: ['/mnt/felhom-drives/scratch_hdd/userdata/romm'] +13:15:43 [1] required fields filled beyond DOMAIN/SUBDOMAIN: ['HDD_PATH'] +13:15:43 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:16:48 [1] deployed, controller state=running, pinned={'romm': 'rommapp/romm:5.0.0', 'romm-db': 'mariadb:11.4', 'romm-redis': 'redis:7-alpine'} +13:16:48 romm: deployed=True in 69 s pinned={'romm': 'rommapp/romm:5.0.0', 'romm-db': 'mariadb:11.4', 'romm-redis': 'redis:7-alpine'} +13:16:48 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:16:53 [1] deployed, controller state=running, pinned={'vikunja': 'vikunja/vikunja:2.3.0'} +13:16:54 vikunja: deployed=True in 5 s pinned={'vikunja': 'vikunja/vikunja:2.3.0'} +13:16:55 drill: heads back; vikunja's head step probes port 8999 (the failing step) +13:17:08 wishlist: steps_left=1 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 1 napja'}] +13:17:08 navidrome: steps_left=2 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 1 napja'}] +13:17:09 romm: steps_left=3 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 1 napja'}] +13:17:09 vikunja: steps_left=1 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 2 napja'}] diff --git a/documentation/audits/night-2026-09-24/C/20.stdout b/documentation/audits/night-2026-09-24/C/20.stdout new file mode 100644 index 00000000..d9695c4e --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/20.stdout @@ -0,0 +1,22 @@ +13:14:20 drill: wishlist/navidrome/romm/vikunja at the ladder's first from (+ step .felhom.yml files from live cf7cf84) +13:14:25 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:15:20 [1] deployed, controller state=running, pinned={'wishlist': 'ghcr.io/cmintey/wishlist:v0.66.0'} +13:15:20 wishlist: deployed=True in 56 s pinned={'wishlist': 'ghcr.io/cmintey/wishlist:v0.66.0'} +13:15:24 [1] made the drive paths this app requires: ['/mnt/felhom-drives/scratch_hdd/userdata/navidrome'] +13:15:24 [1] required fields filled beyond DOMAIN/SUBDOMAIN: ['HDD_PATH'] +13:15:24 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:15:39 [1] deployed, controller state=running, pinned={'navidrome': 'deluan/navidrome:0.63.2'} +13:15:39 navidrome: deployed=True in 19 s pinned={'navidrome': 'deluan/navidrome:0.63.2'} +13:15:43 [1] made the drive paths this app requires: ['/mnt/felhom-drives/scratch_hdd/userdata/romm'] +13:15:43 [1] required fields filled beyond DOMAIN/SUBDOMAIN: ['HDD_PATH'] +13:15:43 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:16:48 [1] deployed, controller state=running, pinned={'romm': 'rommapp/romm:5.0.0', 'romm-db': 'mariadb:11.4', 'romm-redis': 'redis:7-alpine'} +13:16:48 romm: deployed=True in 69 s pinned={'romm': 'rommapp/romm:5.0.0', 'romm-db': 'mariadb:11.4', 'romm-redis': 'redis:7-alpine'} +13:16:48 [1] deploy -> 202 {'ok': True, 'message': 'Telepítés elindítva – az állapot a kártyán követhető'} +13:16:53 [1] deployed, controller state=running, pinned={'vikunja': 'vikunja/vikunja:2.3.0'} +13:16:54 vikunja: deployed=True in 5 s pinned={'vikunja': 'vikunja/vikunja:2.3.0'} +13:16:55 drill: heads back; vikunja's head step probes port 8999 (the failing step) +13:17:08 wishlist: steps_left=1 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 1 napja'}] +13:17:08 navidrome: steps_left=2 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 1 napja'}] +13:17:09 romm: steps_left=3 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 1 napja'}] +13:17:09 vikunja: steps_left=1 badge=[{'title': 'Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.', 'text': 'Frissítés elérhető — 2 napja'}] diff --git a/documentation/audits/night-2026-09-24/C/30-night-run1.json b/documentation/audits/night-2026-09-24/C/30-night-run1.json new file mode 100644 index 00000000..77321f74 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/30-night-run1.json @@ -0,0 +1,982 @@ +{ + "total_s": 192.9, + "steps": [ + { + "pass": 1, + "app": "wishlist", + "steps_left_before": 1, + "from": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.66.0" + }, + "wall_s": 55.8, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "backing-up", + "label": "Biztonsági mentés készül a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 38.0, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 40.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 55.5, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 55.5, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "steps_left_after": 1 + }, + { + "pass": 1, + "app": "wishlist", + "steps_left_before": 1, + "from": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "wall_s": 18.8, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 1.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 18.5, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 18.5, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "steps_left_after": 1 + }, + { + "pass": 1, + "app": "wishlist", + "steps_left_before": 1, + "from": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "wall_s": 31.1, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "backing-up", + "label": "Biztonsági mentés készül a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 4.1, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 15.4, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 30.8, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 30.8, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "steps_left_after": null + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.63.2" + }, + "wall_s": 10.6, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "backing-up", + "label": "Biztonsági mentés készül a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 4.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 5.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 10.3, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 10.3, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "navidrome": "deluan/navidrome:0.64.0" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.64.0" + }, + "wall_s": 8.5, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 1.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 8.2, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 8.3, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "wall_s": 8.5, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 1.0, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 8.2, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 8.3, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "wall_s": 8.5, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 1.0, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 8.2, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 8.2, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "wall_s": 8.6, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 1.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 8.2, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 8.3, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "wall_s": 8.6, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 1.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 8.2, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 8.3, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "navidrome", + "steps_left_before": 2, + "from": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 1, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 1, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 2, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 2, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 3, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 3, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 4, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 4, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 5, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 5, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 6, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + }, + { + "pass": 6, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 0.0, + "accepted": false, + "http": "409", + "refusal": { + "ok": false, + "data": { + "reason": "busy" + }, + "error": "A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött." + }, + "phases": [], + "duration_s": 0, + "reason": "busy" + } + ], + "never": {}, + "pages": { + "wishlist": { + "state": "running", + "steps_left": 0, + "badges": { + "hu": [ + { + "title": "Ez az alkalmazás a legfrissebb elérhető változatot futtatja.", + "text": "Naprakész" + } + ], + "en": [ + { + "title": "This app is running the newest version available.", + "text": "Up to date" + } + ] + }, + "hold_reason": null, + "update_phase": "done", + "update_error": null, + "pinned": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "update_error_hu": null, + "update_error_en": null + }, + "navidrome": { + "state": "running", + "steps_left": 0, + "badges": { + "hu": [ + { + "title": "Ez az alkalmazás a legfrissebb elérhető változatot futtatja.", + "text": "Naprakész" + } + ], + "en": [ + { + "title": "This app is running the newest version available.", + "text": "Up to date" + } + ] + }, + "hold_reason": null, + "update_phase": "done", + "update_error": null, + "pinned": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "update_error_hu": null, + "update_error_en": null + }, + "romm": { + "state": "running", + "steps_left": 3, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 1 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 1 day ago" + } + ] + }, + "hold_reason": null, + "update_phase": null, + "update_error": null, + "pinned": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "update_error_hu": null, + "update_error_en": null + }, + "vikunja": { + "state": "unhealthy", + "steps_left": 1, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 2 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 2 days ago" + } + ] + }, + "hold_reason": null, + "update_phase": null, + "update_error": null, + "pinned": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "update_error_hu": null, + "update_error_en": null + } + }, + "events": "" +} \ No newline at end of file diff --git a/documentation/audits/night-2026-09-24/C/30-night-run1.log b/documentation/audits/night-2026-09-24/C/30-night-run1.log new file mode 100644 index 00000000..646aa8d4 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/30-night-run1.log @@ -0,0 +1,110 @@ +13:17:23 == pass 1 +13:17:27 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:17:27 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:17:29 + 2.1s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:17:30 + 3.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:18:05 + 38.0s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:18:07 + 40.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:18:23 + 55.5s phase=done label=Frissítve err=None hold=None +13:18:23 wishlist: step done in 55.8 s, steps_left 1 -> 1 +13:18:23 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:18:23 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:18:24 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:18:25 + 2.1s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:18:26 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:18:42 + 18.5s phase=done label=Frissítve err=None hold=None +13:18:42 wishlist: step done in 18.8 s, steps_left 1 -> 1 +13:18:42 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:18:42 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:18:44 + 2.1s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:18:45 + 3.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:18:46 + 4.1s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:18:57 + 15.4s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:13 + 30.8s phase=done label=Frissítve err=None hold=None +13:19:13 wishlist: step done in 31.1 s, steps_left 1 -> None +13:19:13 wishlist: current (steps_left=0) — nothing to press +13:19:13 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:13 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:19:15 + 2.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:16 + 3.1s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:19:17 + 4.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:18 + 5.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:24 + 10.3s phase=done label=Frissítve err=None hold=None +13:19:24 navidrome: step done in 10.6 s, steps_left 2 -> 2 +13:19:24 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:24 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:25 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:26 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:27 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:32 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:32 navidrome: step done in 8.5 s, steps_left 2 -> 2 +13:19:33 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:33 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:34 + 1.0s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:35 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:36 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:41 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:41 navidrome: step done in 8.5 s, steps_left 2 -> 2 +13:19:41 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:41 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:42 + 1.0s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:43 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:44 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:49 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:50 navidrome: step done in 8.5 s, steps_left 2 -> 2 +13:19:50 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:50 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:51 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:52 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:53 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:58 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:58 navidrome: step done in 8.6 s, steps_left 2 -> 2 +13:19:59 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:59 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:20:00 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:20:01 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:20:02 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:20:07 + 8.2s phase=done label=Frissítve err=None hold=None +13:20:07 navidrome: step done in 8.6 s, steps_left 2 -> 2 +13:20:07 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:07 navidrome: refused (busy) — transient, next pass +13:20:07 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:07 romm: refused (busy) — transient, next pass +13:20:07 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:07 vikunja: refused (busy) — transient, next pass +13:20:07 == pass 2 +13:20:12 wishlist: current (steps_left=0) — nothing to press +13:20:12 navidrome: current (steps_left=0) — nothing to press +13:20:12 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:12 romm: refused (busy) — transient, next pass +13:20:12 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:12 vikunja: refused (busy) — transient, next pass +13:20:12 == pass 3 +13:20:16 wishlist: current (steps_left=0) — nothing to press +13:20:17 navidrome: current (steps_left=0) — nothing to press +13:20:17 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:17 romm: refused (busy) — transient, next pass +13:20:17 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:17 vikunja: refused (busy) — transient, next pass +13:20:17 == pass 4 +13:20:21 wishlist: current (steps_left=0) — nothing to press +13:20:21 navidrome: current (steps_left=0) — nothing to press +13:20:21 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:21 romm: refused (busy) — transient, next pass +13:20:21 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:21 vikunja: refused (busy) — transient, next pass +13:20:22 == pass 5 +13:20:26 wishlist: current (steps_left=0) — nothing to press +13:20:26 navidrome: current (steps_left=0) — nothing to press +13:20:26 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:26 romm: refused (busy) — transient, next pass +13:20:26 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:26 vikunja: refused (busy) — transient, next pass +13:20:26 == pass 6 +13:20:31 wishlist: current (steps_left=0) — nothing to press +13:20:31 navidrome: current (steps_left=0) — nothing to press +13:20:31 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:31 romm: refused (busy) — transient, next pass +13:20:31 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:31 vikunja: refused (busy) — transient, next pass +13:20:36 night total 192.9 s; never={} diff --git a/documentation/audits/night-2026-09-24/C/30-run1.stdout b/documentation/audits/night-2026-09-24/C/30-run1.stdout new file mode 100644 index 00000000..646aa8d4 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/30-run1.stdout @@ -0,0 +1,110 @@ +13:17:23 == pass 1 +13:17:27 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:17:27 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:17:29 + 2.1s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:17:30 + 3.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:18:05 + 38.0s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:18:07 + 40.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:18:23 + 55.5s phase=done label=Frissítve err=None hold=None +13:18:23 wishlist: step done in 55.8 s, steps_left 1 -> 1 +13:18:23 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:18:23 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:18:24 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:18:25 + 2.1s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:18:26 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:18:42 + 18.5s phase=done label=Frissítve err=None hold=None +13:18:42 wishlist: step done in 18.8 s, steps_left 1 -> 1 +13:18:42 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:18:42 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:18:44 + 2.1s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:18:45 + 3.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:18:46 + 4.1s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:18:57 + 15.4s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:13 + 30.8s phase=done label=Frissítve err=None hold=None +13:19:13 wishlist: step done in 31.1 s, steps_left 1 -> None +13:19:13 wishlist: current (steps_left=0) — nothing to press +13:19:13 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:13 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:19:15 + 2.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:16 + 3.1s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:19:17 + 4.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:18 + 5.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:24 + 10.3s phase=done label=Frissítve err=None hold=None +13:19:24 navidrome: step done in 10.6 s, steps_left 2 -> 2 +13:19:24 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:24 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:25 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:26 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:27 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:32 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:32 navidrome: step done in 8.5 s, steps_left 2 -> 2 +13:19:33 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:33 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:34 + 1.0s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:35 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:36 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:41 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:41 navidrome: step done in 8.5 s, steps_left 2 -> 2 +13:19:41 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:41 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:42 + 1.0s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:43 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:44 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:49 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:50 navidrome: step done in 8.5 s, steps_left 2 -> 2 +13:19:50 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:50 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:19:51 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:19:52 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:19:53 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:19:58 + 8.2s phase=done label=Frissítve err=None hold=None +13:19:58 navidrome: step done in 8.6 s, steps_left 2 -> 2 +13:19:59 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:19:59 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:20:00 + 1.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:20:01 + 2.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:20:02 + 3.1s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:20:07 + 8.2s phase=done label=Frissítve err=None hold=None +13:20:07 navidrome: step done in 8.6 s, steps_left 2 -> 2 +13:20:07 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:07 navidrome: refused (busy) — transient, next pass +13:20:07 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:07 romm: refused (busy) — transient, next pass +13:20:07 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:07 vikunja: refused (busy) — transient, next pass +13:20:07 == pass 2 +13:20:12 wishlist: current (steps_left=0) — nothing to press +13:20:12 navidrome: current (steps_left=0) — nothing to press +13:20:12 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:12 romm: refused (busy) — transient, next pass +13:20:12 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:12 vikunja: refused (busy) — transient, next pass +13:20:12 == pass 3 +13:20:16 wishlist: current (steps_left=0) — nothing to press +13:20:17 navidrome: current (steps_left=0) — nothing to press +13:20:17 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:17 romm: refused (busy) — transient, next pass +13:20:17 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:17 vikunja: refused (busy) — transient, next pass +13:20:17 == pass 4 +13:20:21 wishlist: current (steps_left=0) — nothing to press +13:20:21 navidrome: current (steps_left=0) — nothing to press +13:20:21 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:21 romm: refused (busy) — transient, next pass +13:20:21 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:21 vikunja: refused (busy) — transient, next pass +13:20:22 == pass 5 +13:20:26 wishlist: current (steps_left=0) — nothing to press +13:20:26 navidrome: current (steps_left=0) — nothing to press +13:20:26 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:26 romm: refused (busy) — transient, next pass +13:20:26 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:26 vikunja: refused (busy) — transient, next pass +13:20:26 == pass 6 +13:20:31 wishlist: current (steps_left=0) — nothing to press +13:20:31 navidrome: current (steps_left=0) — nothing to press +13:20:31 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:31 romm: refused (busy) — transient, next pass +13:20:31 [6] Update -> 409 {'ok': False, 'data': {'reason': 'busy'}, 'error': 'A frissítés most nem indítható: mentés/visszaállítás folyamatban. Próbáld újra, ha befejeződött.'} +13:20:31 vikunja: refused (busy) — transient, next pass +13:20:36 night total 192.9 s; never={} diff --git a/documentation/audits/night-2026-09-24/C/31-night.json b/documentation/audits/night-2026-09-24/C/31-night.json new file mode 100644 index 00000000..aa0118e2 --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/31-night.json @@ -0,0 +1,441 @@ +{ + "total_s": 438.5, + "steps": [ + { + "pass": 1, + "app": "romm", + "steps_left_before": 3, + "from": { + "romm": "rommapp/romm:5.0.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 77.4, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 16.5, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 24.7, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 36.0, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 77.1, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 77.1, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "romm": "rommapp/romm:5.3.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "steps_left_after": 2 + }, + { + "pass": 1, + "app": "romm", + "steps_left_before": 2, + "from": { + "romm": "rommapp/romm:5.3.0", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 71.2, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 16.4, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 24.6, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 35.9, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 70.8, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 70.8, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "romm": "rommapp/romm:5.3.1", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "steps_left_after": 1 + }, + { + "pass": 1, + "app": "romm", + "steps_left_before": 1, + "from": { + "romm": "rommapp/romm:5.3.1", + "romm-db": "mariadb:11.4", + "romm-redis": "redis:7-alpine" + }, + "wall_s": 93.9, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "backing-up", + "label": "Biztonsági mentés készül a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 20.5, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 22.6, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 27.7, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 41.1, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 57.5, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 93.4, + "phase": "done", + "label": "Frissítve", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 93.4, + "final_phase": "done", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "romm": "rommapp/romm:5.3.1", + "romm-db": "mariadb:11.8", + "romm-redis": "redis:7-alpine" + }, + "steps_left_after": null + }, + { + "pass": 1, + "app": "vikunja", + "steps_left_before": 1, + "from": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "wall_s": 104.0, + "accepted": true, + "http": "202", + "phases": [ + { + "t": 0.0, + "phase": "backing-up", + "label": "Biztonsági mentés készül a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 2.1, + "phase": "safety-dump", + "label": "Adatbázis pillanatkép…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 3.1, + "phase": "pinning", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 4.1, + "phase": "pulling", + "label": "Új verzió letöltése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 8.3, + "phase": "copying", + "label": "Az adatok másolása a frissítés előtt…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 9.3, + "phase": "starting", + "label": "Indítás az új verzióval…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 10.3, + "phase": "verifying", + "label": "Működés ellenőrzése…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 100.5, + "phase": "undoing", + "label": "Visszaállítás az előző változatra…", + "updating": true, + "error": null, + "hold": null + }, + { + "t": 103.6, + "phase": "undone", + "label": "Visszaállítva az előző változatra", + "updating": false, + "error": null, + "hold": null + } + ], + "duration_s": 103.7, + "final_phase": "undone", + "update_error": null, + "hold_reason": null, + "state": "running", + "to": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "steps_left_after": 1 + } + ], + "never": { + "vikunja": "step:undone" + }, + "pages": { + "wishlist": { + "state": "running", + "steps_left": 0, + "badges": { + "hu": [ + { + "title": "Ez az alkalmazás a legfrissebb elérhető változatot futtatja.", + "text": "Naprakész" + } + ], + "en": [ + { + "title": "This app is running the newest version available.", + "text": "Up to date" + } + ] + }, + "hold_reason": null, + "update_phase": "done", + "update_error": null, + "pinned": { + "wishlist": "ghcr.io/cmintey/wishlist:v0.67.1" + }, + "update_error_hu": null, + "update_error_en": null + }, + "navidrome": { + "state": "running", + "steps_left": 0, + "badges": { + "hu": [ + { + "title": "Ez az alkalmazás a legfrissebb elérhető változatot futtatja.", + "text": "Naprakész" + } + ], + "en": [ + { + "title": "This app is running the newest version available.", + "text": "Up to date" + } + ] + }, + "hold_reason": null, + "update_phase": "done", + "update_error": null, + "pinned": { + "navidrome": "deluan/navidrome:0.64.1" + }, + "update_error_hu": null, + "update_error_en": null + }, + "romm": { + "state": "running", + "steps_left": 0, + "badges": { + "hu": [ + { + "title": "Ez az alkalmazás a legfrissebb elérhető változatot futtatja.", + "text": "Naprakész" + } + ], + "en": [ + { + "title": "This app is running the newest version available.", + "text": "Up to date" + } + ] + }, + "hold_reason": null, + "update_phase": "done", + "update_error": null, + "pinned": { + "romm": "rommapp/romm:5.3.1", + "romm-db": "mariadb:11.8", + "romm-redis": "redis:7-alpine" + }, + "update_error_hu": null, + "update_error_en": null + }, + "vikunja": { + "state": "running", + "steps_left": 1, + "badges": { + "hu": [ + { + "title": "Újabb változat érhető el ehhez az alkalmazáshoz. A frissítés indításához nyomd meg a Frissítés gombot.", + "text": "Frissítés elérhető — 2 napja" + } + ], + "en": [ + { + "title": "A newer version of this app is available. Select the Update button to start it.", + "text": "Update available — 2 days ago" + } + ] + }, + "hold_reason": null, + "update_phase": "undone", + "update_error": null, + "pinned": { + "vikunja": "vikunja/vikunja:2.3.0" + }, + "update_error_hu": null, + "update_error_en": null + } + }, + "events": "2026/09/24 11:27:27 undo.go:621: [INFO] [stacks] update vikunja: event app_update_undone\n2026/09/24 11:27:27 notifier.go:1255: [WARN] notifier disabled (no hub configured): DROPPED event app_update_undone (severity warning) — further app_update_undone events are logged at DEBUG only\n" +} \ No newline at end of file diff --git a/documentation/audits/night-2026-09-24/C/31-night.log b/documentation/audits/night-2026-09-24/C/31-night.log new file mode 100644 index 00000000..f00f28ba --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/31-night.log @@ -0,0 +1,47 @@ +13:21:22 == pass 1 +13:21:27 wishlist: current (steps_left=0) — nothing to press +13:21:27 navidrome: current (steps_left=0) — nothing to press +13:21:27 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:21:27 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:21:29 + 2.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:21:44 + 16.5s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:21:52 + 24.7s phase=starting label=Indítás az új verzióval… err=None hold=None +13:22:03 + 36.0s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:22:44 + 77.1s phase=done label=Frissítve err=None hold=None +13:22:49 romm: step done in 77.4 s, steps_left 3 -> 2 +13:22:49 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:22:49 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:22:52 + 2.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:23:06 + 16.4s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:23:14 + 24.6s phase=starting label=Indítás az új verzióval… err=None hold=None +13:23:25 + 35.9s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:24:00 + 70.8s phase=done label=Frissítve err=None hold=None +13:24:05 romm: step done in 71.2 s, steps_left 2 -> 1 +13:24:05 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:24:05 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:24:26 + 20.5s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:24:28 + 22.6s phase=pulling label=Új verzió letöltése… err=None hold=None +13:24:33 + 27.7s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:24:46 + 41.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:25:03 + 57.5s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:25:39 + 93.4s phase=done label=Frissítve err=None hold=None +13:25:43 romm: step done in 93.9 s, steps_left 1 -> None +13:25:43 romm: current (steps_left=0) — nothing to press +13:25:44 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:25:44 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:25:46 + 2.1s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:25:47 + 3.1s phase=pinning label=Új verzió letöltése… err=None hold=None +13:25:48 + 4.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:25:52 + 8.3s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:25:53 + 9.3s phase=starting label=Indítás az új verzióval… err=None hold=None +13:25:54 + 10.3s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:27:24 + 100.5s phase=undoing label=Visszaállítás az előző változatra… err=None hold=None +13:27:27 + 103.6s phase=undone label=Visszaállítva az előző változatra err=None hold=None +13:27:32 vikunja: step undone in 104.0 s, steps_left 1 -> 1 +13:27:32 vikunja: a failed step — never pressed again tonight +13:28:32 == pass 2 +13:28:36 wishlist: current (steps_left=0) — nothing to press +13:28:36 navidrome: current (steps_left=0) — nothing to press +13:28:37 romm: current (steps_left=0) — nothing to press +13:28:37 all apps current or set aside — the leg ends +13:28:41 night total 438.5 s; never={'vikunja': 'step:undone'} diff --git a/documentation/audits/night-2026-09-24/C/31.stdout b/documentation/audits/night-2026-09-24/C/31.stdout new file mode 100644 index 00000000..f00f28ba --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/31.stdout @@ -0,0 +1,47 @@ +13:21:22 == pass 1 +13:21:27 wishlist: current (steps_left=0) — nothing to press +13:21:27 navidrome: current (steps_left=0) — nothing to press +13:21:27 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:21:27 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:21:29 + 2.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:21:44 + 16.5s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:21:52 + 24.7s phase=starting label=Indítás az új verzióval… err=None hold=None +13:22:03 + 36.0s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:22:44 + 77.1s phase=done label=Frissítve err=None hold=None +13:22:49 romm: step done in 77.4 s, steps_left 3 -> 2 +13:22:49 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:22:49 + 0.0s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:22:52 + 2.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:23:06 + 16.4s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:23:14 + 24.6s phase=starting label=Indítás az új verzióval… err=None hold=None +13:23:25 + 35.9s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:24:00 + 70.8s phase=done label=Frissítve err=None hold=None +13:24:05 romm: step done in 71.2 s, steps_left 2 -> 1 +13:24:05 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:24:05 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:24:26 + 20.5s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:24:28 + 22.6s phase=pulling label=Új verzió letöltése… err=None hold=None +13:24:33 + 27.7s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:24:46 + 41.1s phase=starting label=Indítás az új verzióval… err=None hold=None +13:25:03 + 57.5s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:25:39 + 93.4s phase=done label=Frissítve err=None hold=None +13:25:43 romm: step done in 93.9 s, steps_left 1 -> None +13:25:43 romm: current (steps_left=0) — nothing to press +13:25:44 [6] Update -> 202 {'ok': True, 'data': {'accepted': True, 'completed': False}, 'message': 'Frissítés elindult – az állapot a kártyán követhető'} +13:25:44 + 0.0s phase=backing-up label=Biztonsági mentés készül a frissítés előtt… err=None hold=None +13:25:46 + 2.1s phase=safety-dump label=Adatbázis pillanatkép… err=None hold=None +13:25:47 + 3.1s phase=pinning label=Új verzió letöltése… err=None hold=None +13:25:48 + 4.1s phase=pulling label=Új verzió letöltése… err=None hold=None +13:25:52 + 8.3s phase=copying label=Az adatok másolása a frissítés előtt… err=None hold=None +13:25:53 + 9.3s phase=starting label=Indítás az új verzióval… err=None hold=None +13:25:54 + 10.3s phase=verifying label=Működés ellenőrzése… err=None hold=None +13:27:24 + 100.5s phase=undoing label=Visszaállítás az előző változatra… err=None hold=None +13:27:27 + 103.6s phase=undone label=Visszaállítva az előző változatra err=None hold=None +13:27:32 vikunja: step undone in 104.0 s, steps_left 1 -> 1 +13:27:32 vikunja: a failed step — never pressed again tonight +13:28:32 == pass 2 +13:28:36 wishlist: current (steps_left=0) — nothing to press +13:28:36 navidrome: current (steps_left=0) — nothing to press +13:28:37 romm: current (steps_left=0) — nothing to press +13:28:37 all apps current or set aside — the leg ends +13:28:41 night total 438.5 s; never={'vikunja': 'step:undone'} diff --git a/documentation/audits/night-2026-09-24/C/32-vikunja-page.txt b/documentation/audits/night-2026-09-24/C/32-vikunja-page.txt new file mode 100644 index 00000000..eddb2ccc --- /dev/null +++ b/documentation/audits/night-2026-09-24/C/32-vikunja-page.txt @@ -0,0 +1,16 @@ +hu ALERT: Hub kapcsolat kikapcsolva — a központi monitoring nem aktív Rendszermonitor → +hu ALERT: A(z) vikunja frissítése 2026-09-24 13:27-kor nem sikerült. A doboz automatikusan visszaállította az előző változatot és az adatokat — semmi nem veszett el. +hu ALERT: Ez a művelet nem visszavonható! +hu ALERT: Az ügyfélszolgálat foglalkozik ezzel az alkalmazással, ezért az adatai megmaradnak: most csak magát az alkalmazást távolíthatod el. +hu ALERT: ' + 'Ha újratelepíti az alkalmazást, az adatokat újra importálnia kell, mivel az adatbázis törlődik. A megtartott adatok a továbbiakban NEM lesznek automatikusan mentve.' + ' +hu ALERT: ' + 'Az éjszakai restic pillanatképek nem törölhetők egyenként — a megőrzési szabályok szerint automatikusan elavulnak.' + ' +hu ALERT: Ez a művelet nem visszavonható! +hu phase attrs: [] +en ALERT: The hub connection is off — central monitoring is not running System monitor → +en ALERT: The update of vikunja at 2026-09-24 13:27 did not succeed. The box put back the previous version and its data automatically — nothing was lost. +en ALERT: You cannot undo this! +en ALERT: Support is working on this app, so its data stays: for now you can remove only the app itself. +en ALERT: ' + 'If you reinstall the app, you need to import the data again, because the database is deleted. Data you keep is NOT backed up automatically any more.' + ' +en ALERT: ' + 'The nightly restic snapshots cannot be deleted one by one — they expire automatically under the retention rules.' + ' +en ALERT: You cannot undo this! +en phase attrs: [] diff --git a/documentation/audits/night-2026-09-24/PROGRESS.md b/documentation/audits/night-2026-09-24/PROGRESS.md index 85499984..4fd2fe7b 100644 --- a/documentation/audits/night-2026-09-24/PROGRESS.md +++ b/documentation/audits/night-2026-09-24/PROGRESS.md @@ -25,3 +25,6 @@ ROWS TO FILE: R-668 (Tier-2 target on a missing path, fixed); applied-meta after - 12:51 Part B LIVE on 0.269.0: badge Behind for a newer tested digest of a floating tag, Update pulled it, record + badge current (B/10). FINDING: the SYNC wrote the new digest into the running app's compose BEFORE Update → a restart would pull it unguarded. FIXED v0.269.1 (CarryDigests), red-proofed (redproofs/B-sync-carry.txt), pushed 5b1b191, image built, 9202 on 0.269.1 (B/20). - 13:05 Part B LIVE PASS on 0.269.1: sync KEPT the running digest before Update (True), badge Behind hu/en, Update done 44 s, running digest = the tested one, badge current (B/21-floating-tag-0.269.1.*). - DECISION (CC, unattended): a second controller release tonight (0.269.1) instead of shipping the bypass with the floor — first in the morning note. +- 13:07 FOUND (Part C read of the chain): demo-hp's thin pool `local-lvm` 100 % FULL (out_of_data_space, error_if_no_space) since 10:35 CEST. Cause (agent journal, C-04): the SCHEDULED restore-test at 10:29 restored 9201's 22 GiB archive into the SAME pool as scratch guest 990000 with no free-space check; start failed; teardown failed („filesystem in use") → "left for Recover", and Recover runs only at agent start. The agent logged „a full pool corrupts every guest on it" every few seconds and did nothing else. 9201's controller: „no space left on device" from 10:38 CEST, its docker log stops 10:39. 9201 also carried a stale `snapshot-delete` lock; its whole-box backups failed 06:59–08:22 (CT is locked). Before tonight's run; not caused by it (9202 lives on nvme-scratch). +- 13:09 INTERVENTION 1: `systemctl restart felhom-agent` on demo-hp so the agent's own Recover tears the scratch down (a direct `pct destroy` was refused by the session's permission check). Result (C-05): „recover: destroyed leaked restore-test scratch guest" vmid=990000; pool 100 % → 58.91 %, state rw; 9201's lock gone. A further read of the morning vzdump task logs was refused by the permission check — left for the operator. +ROWS TO FILE (agent, P1): restore-test fills the production pool (no space check) and its leaked scratch waits for an agent restart; the pool-fill WARN has no action; 9201 stale snapshot-delete lock blocked whole-box backups all morning. diff --git a/documentation/audits/night-2026-09-24/tools/liveC1.py b/documentation/audits/night-2026-09-24/tools/liveC1.py new file mode 100644 index 00000000..975fa869 --- /dev/null +++ b/documentation/audits/night-2026-09-24/tools/liveC1.py @@ -0,0 +1,19 @@ +#!/usr/bin/env python3 +"""Part C step 1 on 9202: move the backup window forward (the product's own form, POST /backups/window) so the +night chain runs now: db-dump at W, Tier 2 at W+60, off-site at W+105 (9202 has none), gate at W+2h.""" +import sys, time, json +sys.path.insert(0, ".") +import walk as w +W = sys.argv[1] +w.login() +before = w.guest("docker logs --since 20h felhom-controller 2>&1 | grep 'Daily job' | tail -3").strip() +w.say("before:\n" + before) +sess = open(f"{w.SC}/sess{__import__('os').getpid()}.txt").read().strip() +csrf = open(f"{w.SC}/csrf{__import__('os').getpid()}.txt").read().strip() +r = w.sh(["curl", "-sk", "-o", "/dev/null", "-w", "%{http_code}", "-H", w.HOSTHDR, "-H", f"Cookie: {sess}", "-X", "POST", + "--data-urlencode", f"_csrf={csrf}", "--data-urlencode", f"window_start={W}", f"{w.BASE}/backups/window"]) +w.say(f"POST /backups/window window_start={W} -> {r.stdout}") +time.sleep(3) +after = w.guest("docker logs --since 2m felhom-controller 2>&1 | grep -E 'Daily job|window' | tail -6").strip() +w.say("after:\n" + after) +open("../C/10-window-moved.txt", "w").write("\n".join(w.LOG) + "\n") diff --git a/documentation/audits/night-2026-09-24/tools/liveC2setup.py b/documentation/audits/night-2026-09-24/tools/liveC2setup.py new file mode 100644 index 00000000..55064b1e --- /dev/null +++ b/documentation/audits/night-2026-09-24/tools/liveC2setup.py @@ -0,0 +1,88 @@ +#!/usr/bin/env python3 +"""Part C step 2, SETUP on 9202: four apps installed through the product, each at the ladder's first `from`, +then the drill catalog put back at the head — so wishlist is 1 step behind, navidrome 2, romm 3, and vikunja 1 +with a FAILING step (its head .felhom.yml probe points at a closed port AFTER the install, so the install's +applied record keeps the good probe and the undo can judge the old version correctly). +The drill also receives the live catalog's step .felhom.yml files (catalog cf7cf84) the reset predates.""" +import json, os, re, shutil, sys, time +sys.path.insert(0, ".") +import walk as w +sys.path.insert(0, "/mnt/5_hdd/felhom.eu/git/app-catalog-felhom.eu/scripts") +import ladder + +LIVE = "/mnt/5_hdd/felhom.eu/git/app-catalog-felhom.eu/templates" +APPS = {"wishlist": "c-wish", "navidrome": "c-navi", "romm": "c-romm", "vikunja": "c-vik"} +T = lambda a: f"{w.DRILL}/templates/{a}" +out = {"controller": w.guest("cat /etc/felhom-controller-image").strip(), "apps": {}} +w.login() + + +def drill(edit, msg): + import fcntl + with open(f"{w.SC}/drill.lock", "w") as lk: + fcntl.flock(lk, fcntl.LOCK_EX) + w.sh(["git", "-C", w.DRILL, "pull", "-q", "--rebase", "origin", "main"], timeout=120) + edit() + w.sh(["git", "-C", w.DRILL, "add", "-A", "templates"]) + w.sh(["git", "-C", w.DRILL, "commit", "-qm", "NIGHT-C " + msg]) + w.sh(["git", "-C", w.DRILL, "push", "-q", "origin", "main"], timeout=120) + w.say("drill: " + msg) + + +HEAD = {a: open(f"{T(a)}/docker-compose.yml").read() for a in APPS} +FY = {a: open(f"{T(a)}/.felhom.yml").read() for a in APPS} + + +def old_compose(a): + E, _, _ = ladder.parse(FY[a]) + frm, head = E[0]["from"], ladder.images_in(HEAD[a]) + c = HEAD[a] + for svc, ref in head.items(): + if frm.get(svc) and frm[svc] != ref: + c = c.replace(f"image: {ref}", f"image: {frm[svc]}", 1) + assert ladder.images_in(c) == frm, (a, ladder.images_in(c), frm) + return c, len(E) + + +def to_old(): + for a in APPS: + c, n = old_compose(a) + open(f"{T(a)}/docker-compose.yml", "w").write(c) + out["apps"][a] = {"ladder_len": n, "installed_at": ladder.images_in(c)} + for a in ("navidrome", "romm"): + for f in os.listdir(f"{LIVE}/{a}/steps"): + if f.endswith(".felhom.yml"): + shutil.copy(f"{LIVE}/{a}/steps/{f}", f"{T(a)}/steps/{f}") + + +drill(to_old, "wishlist/navidrome/romm/vikunja at the ladder's first from (+ step .felhom.yml files from live cf7cf84)") +w.sync_rescan() +for a, sub in APPS.items(): + t0 = time.time() + ok = w.deploy(a, sub) + st = w.stack(a) + out["apps"][a]["deploy_ok"] = ok + out["apps"][a]["deploy_s"] = round(time.time() - t0) + out["apps"][a]["pinned"] = (st.get("app_config") or {}).get("pinned_images") + w.say(f"{a}: deployed={ok} in {out['apps'][a]['deploy_s']} s pinned={out['apps'][a]['pinned']}") + + +def to_head(): + for a in APPS: + open(f"{T(a)}/docker-compose.yml", "w").write(HEAD[a]) + f = re.sub(r"(healthcheck:\n\s+checks:\n\s+- type: api\n\s+port: )3456\b", r"\g<1>8999", FY["vikunja"], count=1) + assert f != FY["vikunja"] + open(f"{T('vikunja')}/.felhom.yml", "w").write(f) + + +drill(to_head, "heads back; vikunja's head step probes port 8999 (the failing step)") +w.sync_rescan() +time.sleep(5) +w.sync_rescan() +for a in APPS: + st = w.stack(a) + out["apps"][a]["steps_left"] = st.get("ladder_steps_left") + out["apps"][a]["badges"] = w.badges(a) + w.say(f"{a}: steps_left={st.get('ladder_steps_left')} badge={out['apps'][a]['badges']['hu'][:1]}") +json.dump(out, open("../C/20-setup.json", "w"), indent=2, ensure_ascii=False, default=str) +open("../C/20-setup.log", "w").write("\n".join(w.LOG) + "\n") diff --git a/documentation/audits/night-2026-09-24/tools/unattended_caller_ladder.py b/documentation/audits/night-2026-09-24/tools/unattended_caller_ladder.py new file mode 100644 index 00000000..448f2569 --- /dev/null +++ b/documentation/audits/night-2026-09-24/tools/unattended_caller_ladder.py @@ -0,0 +1,111 @@ +#!/usr/bin/env python3 +"""unattended_caller_ladder.py — Part C step 2 (night 2026-09-24): the update leg as it would run, updated for the +LADDER (`09` §3 decisions 11/12/14/15/20). Adapted from audits/update-arc-gaps-2026-09-21/unattended-caller.py. + +EVIDENCE, NOT PRODUCT. It presses exactly the guarded Update a person presses (POST /api/stacks//update) and +nothing else, against scratch guest 9202 only. + +What changed from the 2026-09-21 caller: + - no "within a major" judgement: decision 13 made the LADDER the only authority — the box refuses or climbs; + - ONE APP AT A TIME, ONE STEP PER PRESS: an app is pressed again only after its previous step ended `done`, + until `ladder_steps_left` is 0 and the badge no longer says behind; + - a failed step (`undone`, `failed`, a hold) is NEVER pressed again tonight (decision 15); + - the refusal's REASON decides (R-609): transient → next pass; held/downgrade → never; memory/disk/no_backup → + for a human; unknown (incl. not_found/not_deployed/guards_unwired) → never. +Measures per step: wall-clock, phases, outcome; per app: the page's hold/badge in hu+en and the events logged. + +Usage: python3 unattended_caller_ladder.py --apps wishlist,navidrome,romm,vikunja --passes 8 +""" +import argparse, json, sys, time +sys.path.insert(0, ".") +import walk as w + +TRANSIENT = {"busy", "updating", "deploying", "migrating", "self_updating"} +TERMINAL = {"held", "downgrade"} +FOR_A_HUMAN = {"memory", "disk", "no_backup"} + + +def behind(name): + st = w.stack(name) + left = st.get("ladder_steps_left") or 0 + b = w.badges(name) + txt = (b.get("en") or [{}])[0].get("text", "") if b.get("en") else "" + return st, left, ("Update available" in txt) or left > 0, b + + +def main(): + ap = argparse.ArgumentParser() + ap.add_argument("--apps", required=True) + ap.add_argument("--passes", type=int, default=8) + ap.add_argument("--out", default="../C/30-night") + ap.add_argument("--every", type=int, default=60, help="seconds between passes") + a = ap.parse_args() + apps = a.apps.split(",") + w.login() + never, steps, t_night = {}, [], time.time() + for p in range(1, a.passes + 1): + w.say(f"== pass {p}") + w.sync_rescan() + pressed_any = False + for name in apps: # one app at a time + if name in never: + continue + while True: # one step per press, climb while each step ends done + st, left, is_behind, b = behind(name) + if not is_behind: + w.say(f" {name}: current (steps_left={left}) — nothing to press") + break + t0 = time.time() + r = w.press_update(name) + rec = {"pass": p, "app": name, "steps_left_before": left, "from": (st.get("app_config") or {}).get("pinned_images"), + "wall_s": round(time.time() - t0, 1), **r} + if not r.get("accepted"): + reason = ((r.get("refusal") or {}).get("data") or {}).get("reason", "?") + rec["reason"] = reason + steps.append(rec) + if reason in TRANSIENT: + w.say(f" {name}: refused ({reason}) — transient, next pass") + else: + never[name] = f"refused:{reason}" + w.say(f" {name}: refused ({reason}) — never again tonight") + break + pressed_any = True + # MEASURED 2026-09-24 (first run, C/30-night-run1.*): `ladder_steps_left` and the badge are STALE + # after a step ends `done` until the next scan — the first caller re-pressed a current app + # four times (each a full guarded update: dump, pull, restart). So: rescan before reading. + w.sync_rescan() + st2 = w.stack(name) + rec["to"] = (st2.get("app_config") or {}).get("pinned_images") + rec["steps_left_after"] = st2.get("ladder_steps_left") + steps.append(rec) + w.say(f" {name}: step {rec['final_phase']} in {rec['wall_s']} s, steps_left {left} -> {rec['steps_left_after']}") + if rec["final_phase"] == "done" and rec["to"] == rec["from"]: + never[name] = "noop" + w.say(f" {name}: the press changed nothing (already current) — stop") + break + if rec["final_phase"] != "done" or rec.get("hold_reason"): + never[name] = f"step:{rec['final_phase']}" + w.say(f" {name}: a failed step — never pressed again tonight") + break + if not pressed_any and all(n in never or not behind(n)[2] for n in apps): + w.say("all apps current or set aside — the leg ends") + break + time.sleep(a.every) + pages = {} + for name in apps: + st, left, is_b, b = behind(name) + pages[name] = {"state": st.get("state"), "steps_left": left, "badges": b, "hold_reason": st.get("hold_reason"), + "update_phase": st.get("update_phase"), "update_error": st.get("update_error"), + "pinned": (st.get("app_config") or {}).get("pinned_images")} + for lang in ("hu", "en"): + code, d = w.ctl("GET", f"/api/stacks/{name}?lang={lang}") + pages[name][f"update_error_{lang}"] = ((d or {}).get("data") or {}).get("update_error") + events = w.guest("docker logs --since 3h felhom-controller 2>&1 | grep -E 'event app_update_|DROPPED event app_update|dropped event app_update' | tail -30") + res = {"total_s": round(time.time() - t_night, 1), "steps": steps, "never": never, "pages": pages, "events": events} + w.say(f"night total {res['total_s']} s; never={never}") + json.dump(res, open(a.out + ".json", "w"), indent=2, ensure_ascii=False, default=str) + open(a.out + ".log", "w").write("\n".join(w.LOG) + "\n") + + +if __name__ == "__main__": + main() diff --git a/documentation/backlog/OPEN-ITEMS.md b/documentation/backlog/OPEN-ITEMS.md index c55bd4b2..74b6fe8f 100644 --- a/documentation/backlog/OPEN-ITEMS.md +++ b/documentation/backlog/OPEN-ITEMS.md @@ -812,6 +812,19 @@ class (an image `VOLUME` at an unmounted path) is still live — `immich-server` | **R-665** | **[P3-LOW] An update pressed soon after a restore was judged with the RESTORED `.felhom.yml`.** OBSERVED 2026-09-24 on 9202 (v0.268.0), not diagnosed: vikunja restored from its unit at 06:19; the drill catalog's `.felhom.yml` named probe port 8999 (a deliberately failing edge); the periodic probe used 8999 until 06:20:41, and the update pressed at 06:21:07 probed 3456 (the unit's own file) and ended `done`. The restore apparently writes the unit's `.felhom.yml` into the stack dir, and the next catalog sync has not yet put the catalog's back. Consequence bounded (the OLD probe, ≤ 15 min), but an update's verdict should not depend on how long ago a restore ran. **Needs:** a measurement of what the restore writes and when the sync overwrites it. Evidence: `audits/ladder-2026-09-24/partA/03-why-g-was-done.txt`. | **READY — P3; owner: CC (controller)** | | **R-666** | **[P3-LOW] A held app whose box has no whole copy is told „ne törölje az alkalmazást" — and its card still offers Eltávolítás.** v0.268.0 (R-659) hides the Mentések button beside the no-whole-copy sentence; the Remove button on the stacks card stays (the household may remove its own app — a promise, not CC's to take away). Measured live on 9202: the page and the sentence disagree. **Needs:** an operator word — hide Remove while support is informed, or soften the sentence. Evidence: `audits/ladder-2026-09-24/partB/01-round11-reproduced.json`. | **WAITING-ON-OPERATOR — P3; owner: operator** | | **R-667** | **[P2-MEDIUM] A crash-looping app whose container reads `running` for a moment between restarts never reaches the crash-loop alarm.** MEASURED 2026-09-24 on 9202 (v0.268.0): `gokapi` (R-644) at **385 restarts**, `restarting_since` = 06:46:30Z at 06:47 — the clock resets whenever a scan catches the container up — while the dead-app heartbeat said *„4 deployed app(s) evaluated, 0 currently down"*. `Stack.CrashLooping` needs `crashLoopAfter` (5 min) of CONTINUOUS `restarting`. Likely also the unattributed second `app_start_failed` at 06:31:41Z (a scan that caught gokapi `exited`): the dropped-event line names no app, so this is inference. **Needs:** crash-loop judged on the container's RestartCount growth over a window, not on an uninterrupted state; a test with a flapping fixture. Evidence: `audits/ladder-2026-09-24/partB/04-states-and-banner.txt`, `02-r660-positive-observables.txt`. | **READY — P2; owner: CC (controller)** | +| **R-668** | **[P2-MEDIUM] The Tier-2 copy chose a registered storage path that no longer existed — on the SAME disk as the app.** MEASURED 2026-09-24 on 9202 (v0.268.0): `sameDevice` failed OPEN when it could not `stat` a path, so a removed folder read as "another disk" and a file app's "second drive" copy landed beside its own data. **FIXED v0.269.0:** the check fails CLOSED (an unreadable path is the same disk) — `r668_missing_path_test.go`, red-proofed; LIVE on 9202 the next copy went to the SSD (dev 1793 vs 66304). Residual, recorded not fixed: a Tier-2 record written on the same disk BEFORE the fix still counts as a copy until the next Tier-2 run replaces it. `audits/night-2026-09-24/A1/01-find-mirror.txt`, `redproofs/A1-r668.txt` | **CLOSED 2026-09-24 — v0.269.0, proven live** | +| **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-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)** | +| **R-677** | **[P3-LOW] For a floating tag re-tested at a new digest, the Behind badge's age reads the TAG's catalog date („1 napja"), not when the new digest was tested (minutes).** Seen 2026-09-24 on 9202 (Part B). Harmless but confusing. **Fix:** for a digest-only move, age from the ladder entry's `tested_at`. `audits/night-2026-09-24/B/10-floating-tag.json` | **READY — P3; owner: CC (controller)** | +| **R-678** | **[P3-LOW] After an update step ends `done`, the app's „steps left" and its badge stay STALE until the next scan.** MEASURED 2026-09-24 on 9202 (Part C, first caller run): wishlist read `ladder_steps_left` 1 after its only step, navidrome 2 after both of its steps — for ~50 s, through six presses. A person sees „Frissítés elérhető" for an app that just updated; an automatic caller re-presses. **Fix:** the update's finish refreshes the app's catalog/ladder fields (the same read the scan does). `audits/night-2026-09-24/C/30-night-run1.json` | **READY — P3; owner: CC (controller)** | +| **R-679** | **[P2-MEDIUM] An Update pressed on an app that is already current runs the whole guarded update — backup, pull, restart — and reports `done`.** MEASURED 2026-09-24 on 9202: navidrome at the head was pressed four times by the stale-read caller (R-678); each press made a safety dump and restarted the app (8.5 s of downtime each) and changed nothing. There is no `current` refusal (`UpdatePreflight`, `update.go:366`; `UpdateOrderCurrent` falls through). Harmless by hand, costly for the automatic leg (`09` §6.4.2). **Fix:** the preflight refuses with reason `current` when the pin equals the catalog head and no newer tested digest exists. `audits/night-2026-09-24/C/30-night-run1.json` | **READY — P2; owner: CC (controller)** | +| **R-680** | **[P2-MEDIUM] The box does not remember a failed update step — after an undo it offers the same step again.** MEASURED 2026-09-24 on 9202: vikunja's failing step was undone (104 s) and its badge went straight back to „Frissítés elérhető"; only the test caller's own memory stopped a re-press. Decision 15 („a failed step is never pressed again") therefore holds for a person only by their judgement and not at all for the automatic leg. **Fix (part 7 (b), `09` §6.4.2):** record the failed `to` per app; the leg skips it until the catalog's ladder for that app changes; the page says the step was tried and put back. `audits/night-2026-09-24/C/31-night.json` | **READY — P2; owner: CC (controller, with part 7)** |