Power-cut fixes E done: a real cut mid-backup on demo-hp, the box cleared up by itself; agent 0.156.1 on all three boxes; R-1006 + R-1008 closed, R-1013 filed
gates / gates (push) Successful in 6m45s
gates / gates (push) Successful in 6m45s
demo-hp 12:06:52 UTC, 1.53 GB written: at boot the dead task was judged dead, the partial and its .tmp removed by the root helper, the next backup finished (5.65 GB), host root back below its pre-cut use. Orphan thin device 4 repaired first (operator B2 - A); R-1012 P2 -> P3, detection stays open. Delivered by signed jobs to Tester 1 and the N100 (probe 71/71, real sudo checked). Controller 0.310.0 everywhere after the operator cleared the per-customer floors. Register 134 -> 134 (opened 4, closed 4). Report: REPORT-power-cut-fixes-2026-10-14.md. Both plugs ON. Claude-Session: https://claude.ai/code/session_012qRErfCoiTkvDK9N5XHbzb
This commit is contained in:
@@ -0,0 +1,23 @@
|
||||
Wed Oct 14 12:07:58 UTC 2026
|
||||
Oct 14 14:07:42 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:42.197+02:00 level=INFO msg="felhom-agent daemon starting" version=0.156.1 host_id=demo-hp-bb76ea hub_url=https://hub.felhom.eu interval_s=900
|
||||
Oct 14 14:07:43 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:43.150+02:00 level=INFO msg="storage: watchdog starting" interval=5s debounce=15s
|
||||
Oct 14 14:07:43 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:43.150+02:00 level=INFO msg="backup: restore-test scheduler starting (per-archive due-check)" eval_interval=6h0m0s settle=24h0m0s
|
||||
Oct 14 14:07:43 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:43.150+02:00 level=INFO msg="pbs: verify loop starting" cadence=6h0m0s
|
||||
Oct 14 14:07:43 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:43.975+02:00 level=INFO msg="selfheal: node watchdog starting" mode=appliance interval_s=60
|
||||
Oct 14 14:07:43 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:43.975+02:00 level=INFO msg="guestnet: watchdog starting" interval=1m0s min_heal_interval=10m0s max_heals_per_hour=3 settle=3m0s
|
||||
Oct 14 14:07:43 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:43.998+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1
|
||||
Oct 14 14:07:44 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:44.008+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1
|
||||
Oct 14 14:07:44 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:44.017+02:00 level=WARN msg="backup-in-flight: a vzdump task is listed as active but its worker process is gone — it is dead, not running" vmid=9201 upid=UPID:demo-hp:000939B2:00125EED:6ACF7001:vzdump:9201:felhom-agent@pve!agent:
|
||||
Oct 14 14:07:44 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:44.017+02:00 level=WARN msg="stale-lock: clearing a stale backup lock left by an interrupted backup" vmid=9201 lock=backup onboot=true status=stopped
|
||||
Oct 14 14:07:44 demo-hp sudo[1522]: felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/sbin/pct unlock 9201
|
||||
Oct 14 14:07:45 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:45.003+02:00 level=ERROR msg="stale-lock: pct unlock failed" vmid=9201 err="pct unlock: exit status 255: no lock found trying to remove any lock\n"
|
||||
Oct 14 14:07:45 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:45.025+02:00 level=INFO msg="stale-lock: scanning pool guests" pool=felhom listed=1 scanned=1
|
||||
Oct 14 14:07:45 demo-hp sudo[1704]: felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/local/sbin/felhom-vzdump-partial-clean local 9201 vzdump-lxc-9201-2026_10_14-14_05_21.tar.dat
|
||||
Oct 14 14:07:48 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:48.565+02:00 level=WARN msg="vzdump-partial: removed a dead half-written backup" storage=local vmid=9201 name=vzdump-lxc-9201-2026_10_14-14_05_21.tar.dat bytes=964239360 why="written before this boot" helper="removed vzdump-lxc-9201-2026_10_14-14_05_21.tar.dat 964239360 B (written before this boot)"
|
||||
Oct 14 14:07:48 demo-hp sudo[5221]: felhom-agent : PWD=/ ; USER=root ; COMMAND=/usr/local/sbin/felhom-vzdump-partial-clean local 9201 vzdump-lxc-9201-2026_10_14-14_05_21.tmp
|
||||
Oct 14 14:07:52 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:52.457+02:00 level=WARN msg="vzdump-partial: removed a dead half-written backup" storage=local vmid=9201 name=vzdump-lxc-9201-2026_10_14-14_05_21.tmp bytes=4096 why="written before this boot" helper="removed vzdump-lxc-9201-2026_10_14-14_05_21.tmp 571 B (written before this boot)"
|
||||
Oct 14 14:07:52 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:52.464+02:00 level=INFO msg="janitor: starting (restore-test scratch retry + stale-lock sweep)" interval=10m0s
|
||||
Oct 14 14:07:52 demo-hp felhom-agent[1273]: time=2026-10-14T14:07:52.465+02:00 level=INFO msg="fstrim: weekly guest disk trim starting" schedule="weekly, due Wednesday from 10:00 host-local time; starts only 10:00-20:59; never beside a backup or restore-test"
|
||||
---
|
||||
/dev/mapper/pve-root 41424257024 24689217536 14597832704 63% /
|
||||
status: running
|
||||
@@ -0,0 +1,7 @@
|
||||
GO
|
||||
12:06:51
|
||||
-rw-r--r-- 1 root root 1528340480 Oct 14 14:06 vzdump-lxc-9201-2026_10_14-14_05_21.tar.dat
|
||||
drwxr-xr-x 3 root root 4096 Oct 14 14:05 vzdump-lxc-9201-2026_10_14-14_05_21.tmp
|
||||
lock: backup
|
||||
btime 1791967481
|
||||
/dev/mapper/pve-root 41424257024 26249101312 13037948928 67% /
|
||||
|
||||
@@ -0,0 +1,16 @@
|
||||
/dev/mapper/pve-root 41424257024 24720375808 14566674432 63% /
|
||||
btime 1791967481
|
||||
felhom-golden-0.236.0.tar.zst
|
||||
vzdump-lxc-9100-2026_08_21-17_59_15.tar.zst
|
||||
vzdump-lxc-9201-2026_09_24-06_59_28.log
|
||||
vzdump-lxc-9201-2026_09_24-07_17_53.log
|
||||
vzdump-lxc-9201-2026_09_24-07_42_54.log
|
||||
vzdump-lxc-9201-2026_09_24-08_22_55.log
|
||||
vzdump-lxc-9201-2026_09_24-22_40_21.log
|
||||
vzdump-lxc-9201-2026_10_14-07_17_45.log
|
||||
vzdump-lxc-9201-2026_10_14-09_28_50.log
|
||||
vzdump-lxc-9201-2026_10_14-09_28_50.tar.zst
|
||||
vzdump-lxc-9201-2026_10_14-09_28_50.tar.zst.notes
|
||||
vzdump-lxc-9201-2026_10_14-11_02_50.log
|
||||
vzdump-lxc-9201-2026_10_14-13_42_48.log
|
||||
vzdump-lxc-9202-2026_10_14-11_01_36.log
|
||||
@@ -0,0 +1,37 @@
|
||||
# delivery of agent 0.156.1 to Tester 1 and the N100 (signed jobs: agent_update 12:21:24, step1 12:35:37, bundle 12:50:14 UTC)
|
||||
12:49:51
|
||||
== root@192.168.0.154
|
||||
"agent_version": "0.156.1-step1"
|
||||
Oct 14 14:38:31 felhom felhom-agent[23122]: time=2026-10-14T14:38:31.859+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE WROTE /usr/local/sbin/felhom-os-apply (replaced)"
|
||||
Oct 14 14:38:31 felhom felhom-agent[23122]: time=2026-10-14T14:38:31.859+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE DONE agent=0.156.1-step1 written=1 same=26 self-check=ok signers-created=False"
|
||||
Oct 14 14:38:32 felhom felhom-agent[23122]: time=2026-10-14T14:38:32.676+02:00 level=WARN msg="osupdate: capability probe after the config bundle" ok=70 total=71 degraded=vzdump-partial-clean
|
||||
== felhom-pve
|
||||
"agent_version": "0.156.1-step1"
|
||||
Oct 14 14:49:35 demo-felhom felhom-agent[798256]: time=2026-10-14T14:49:35.387+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE WROTE /usr/local/sbin/felhom-os-apply (replaced)"
|
||||
Oct 14 14:49:35 demo-felhom felhom-agent[798256]: time=2026-10-14T14:49:35.387+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE DONE agent=0.156.1-step1 written=1 same=26 self-check=ok signers-created=Fals
|
||||
Oct 14 14:49:35 demo-felhom felhom-agent[798256]: time=2026-10-14T14:49:35.987+02:00 level=WARN msg="osupdate: capability probe after the config bundle" ok=70 total=71 degraded=vzdump-partial-clean
|
||||
|
||||
13:04:50
|
||||
== root@192.168.0.154
|
||||
felhom-agent 0.156.1
|
||||
"agent_version": "0.156.1"
|
||||
Oct 14 14:53:31 felhom felhom-agent[23122]: time=2026-10-14T14:53:31.956+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE WROTE /etc/sudoers.d/felhom-agent (replaced)"
|
||||
Oct 14 14:53:31 felhom felhom-agent[23122]: time=2026-10-14T14:53:31.956+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE DONE agent=0.156.1 written=2 same=26 self-check=ok signers-created=False"
|
||||
Oct 14 14:53:32 felhom felhom-agent[23122]: time=2026-10-14T14:53:32.777+02:00 level=WARN msg="osupdate: capability probe after the config bundle" ok=71 total=71 degraded=""
|
||||
-rwxr-xr-x 1 root root 5537 Oct 14 14:53 /usr/local/sbin/felhom-vzdump-partial-clean
|
||||
2
|
||||
sudo: shape allowed
|
||||
sudo: finished archive refused
|
||||
gitea.dooplex.hu/admin/felhom-controller:0.310.0
|
||||
== felhom-pve
|
||||
felhom-agent 0.156.1
|
||||
"agent_version": "0.156.1"
|
||||
Oct 14 15:04:35 demo-felhom felhom-agent[798256]: time=2026-10-14T15:04:35.302+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE WROTE /etc/sudoers.d/felhom-agent (replaced)"
|
||||
Oct 14 15:04:35 demo-felhom felhom-agent[798256]: time=2026-10-14T15:04:35.302+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: BUNDLE DONE agent=0.156.1 written=2 same=26 self-check=ok signers-created=False"
|
||||
Oct 14 15:04:35 demo-felhom felhom-agent[798256]: time=2026-10-14T15:04:35.903+02:00 level=WARN msg="osupdate: capability probe after the config bundle" ok=71 total=71 degraded=""
|
||||
-rwxr-xr-x 1 root root 5537 Oct 14 15:04 /usr/local/sbin/felhom-vzdump-partial-clean
|
||||
2
|
||||
sudo: shape allowed
|
||||
sudo: finished archive refused
|
||||
gitea.dooplex.hu/admin/felhom-controller:0.310.0
|
||||
|
||||
File diff suppressed because it is too large
Load Diff
@@ -0,0 +1,53 @@
|
||||
Oct 14 14:10:50 demo-hp felhom-agent[1273]: time=2026-10-14T14:10:50.867+02:00 level=INFO msg="backup: space preflight passed" vmid=9201 target=local last_archive_bytes=5648463064 need_bytes=8134320654 avail_bytes=14597816320
|
||||
Oct 14 14:10:51 demo-hp felhom-agent[1273]: time=2026-10-14T14:10:51.923+02:00 level=INFO msg="local-api: backup reached snapshotted (app may resume)" vmid=9201 target=local job=backup-9201-1791979850313118192
|
||||
Oct 14 14:17:08 demo-hp felhom-agent[1273]: time=2026-10-14T14:17:08.424+02:00 level=INFO msg="backup: completed" vmid=9201 target=local archive=local:backup/vzdump-lxc-9201-2026_10_14-14_10_50.tar.zst size_bytes=5650197172 uncovered_volumes=2
|
||||
Oct 14 14:17:08 demo-hp felhom-agent[1273]: time=2026-10-14T14:17:08.424+02:00 level=INFO msg="local-api: backup job complete" vmid=9201 target=local job=backup-9201-1791979850313118192 archive=local:backup/vzdump-lxc-9201-2026_10_14-14_10_50.tar.zst
|
||||
Oct 14 14:17:08 demo-hp felhom-agent[1273]: time=2026-10-14T14:17:08.463+02:00 level=INFO msg="local-api: no OS leg after a manual backup — it follows the night's own backup (R-899)" vmid=9201 job=backup-9201-1791979850313118192
|
||||
2026-10-14 14:10:50 INFO: Starting Backup of VM 9201 (lxc)
|
||||
2026-10-14 14:10:50 INFO: status = running
|
||||
2026-10-14 14:10:50 INFO: CT Name: demo-hp
|
||||
2026-10-14 14:10:50 INFO: including mount point rootfs ('/') in backup
|
||||
2026-10-14 14:10:50 INFO: including mount point mp0 ('/var/lib/felhom') in backup
|
||||
2026-10-14 14:10:50 INFO: excluding bind mount point mp8 ('/mnt/felhom-drives') from backup (not a volume)
|
||||
2026-10-14 14:10:50 INFO: excluding bind mount point mp9 ('/etc/felhom-bootstrap') from backup (not a volume)
|
||||
2026-10-14 14:10:50 INFO: found old vzdump snapshot (force removal)
|
||||
2026-10-14 14:10:51 INFO: backup mode: snapshot
|
||||
2026-10-14 14:10:51 INFO: ionice priority: 7
|
||||
2026-10-14 14:10:51 INFO: suspend vm to make snapshot
|
||||
2026-10-14 14:10:51 INFO: create storage snapshot 'vzdump'
|
||||
2026-10-14 14:10:52 INFO: resume vm
|
||||
2026-10-14 14:10:52 INFO: guest is online again after 1 seconds
|
||||
2026-10-14 14:10:53 INFO: creating vzdump archive '/var/lib/vz/dump/vzdump-lxc-9201-2026_10_14-14_10_50.tar.zst'
|
||||
2026-10-14 14:17:01 INFO: Total bytes written: 19269263360 (18GiB, 50MiB/s)
|
||||
2026-10-14 14:17:01 INFO: archive file size: 5.26GB
|
||||
2026-10-14 14:17:01 INFO: adding notes to backup
|
||||
2026-10-14 14:17:01 INFO: prune older backups with retention: keep-last=1
|
||||
2026-10-14 14:17:01 INFO: removing backup 'local:backup/vzdump-lxc-9201-2026_10_14-09_28_50.tar.zst'
|
||||
2026-10-14 14:17:01 INFO: pruned 1 backup(s) not covered by keep-retention policy
|
||||
2026-10-14 14:17:04 INFO: cleanup temporary 'vzdump' snapshot
|
||||
2026-10-14 14:17:04 INFO: Finished Backup of VM 9201 (00:06:14)
|
||||
total 6798200
|
||||
drwxr-xr-x 2 root root 4096 Oct 14 14:17 .
|
||||
drwxr-xr-x 7 root root 4096 Aug 21 18:00 ..
|
||||
-rw-r--r-- 1 root root 654115664 Sep 13 22:16 felhom-golden-0.236.0.tar.zst
|
||||
-rw-r--r-- 1 root root 656970239 Aug 21 17:59 vzdump-lxc-9100-2026_08_21-17_59_15.tar.zst
|
||||
-rw-r--r-- 1 root root 1874 Sep 24 07:05 vzdump-lxc-9201-2026_09_24-06_59_28.log
|
||||
-rw-r--r-- 1 root root 1874 Sep 24 07:24 vzdump-lxc-9201-2026_09_24-07_17_53.log
|
||||
-rw-r--r-- 1 root root 1874 Sep 24 07:49 vzdump-lxc-9201-2026_09_24-07_42_54.log
|
||||
-rw-r--r-- 1 root root 187 Sep 24 08:22 vzdump-lxc-9201-2026_09_24-08_22_55.log
|
||||
-rw-r--r-- 1 root root 1780 Sep 24 22:45 vzdump-lxc-9201-2026_09_24-22_40_21.log
|
||||
-rw-r--r-- 1 root root 1563 Oct 14 07:28 vzdump-lxc-9201-2026_10_14-07_17_45.log
|
||||
-rw-r--r-- 1 root root 1942 Oct 14 11:06 vzdump-lxc-9201-2026_10_14-11_02_50.log
|
||||
-rw-r--r-- 1 root root 994 Oct 14 13:42 vzdump-lxc-9201-2026_10_14-13_42_48.log
|
||||
-rw-r--r-- 1 root root 1562 Oct 14 14:17 vzdump-lxc-9201-2026_10_14-14_10_50.log
|
||||
-rw-r--r-- 1 root root 5650197172 Oct 14 14:17 vzdump-lxc-9201-2026_10_14-14_10_50.tar.zst
|
||||
-rw-r--r-- 1 root root 16 Oct 14 14:17 vzdump-lxc-9201-2026_10_14-14_10_50.tar.zst.notes
|
||||
-rw-r--r-- 1 root root 2234 Oct 14 11:02 vzdump-lxc-9202-2026_10_14-11_01_36.log
|
||||
/dev/mapper/pve-root 41424257024 24691134464 14595915776 63% /
|
||||
0 112975872 thin-pool 567 6157/262144 342710/882624 - rw discard_passdown queue_if_no_space - 1024
|
||||
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
|
||||
data pve twi-aotz-- 53.87g 38.83 2.35
|
||||
root pve -wi-ao---- <39.50g
|
||||
swap pve -wi-ao---- 8.00g
|
||||
vm-9201-disk-0 pve Vwi-aotz-- 32.00g data 6.00
|
||||
vm-9201-disk-1 pve Vwi-aotz-- 70.00g data 27.14
|
||||
@@ -0,0 +1,5 @@
|
||||
2026-10-14T12:06:52.175Z hp watchdog armed (pid 3678823, relay on after 25 s at the latest)
|
||||
2026-10-14T12:06:52.325Z hp CUT: relay off + countdown 10 s sent in one command
|
||||
2026-10-14T12:06:52.371Z hp read back: relay=off countdown=10
|
||||
2026-10-14T12:07:02.409Z hp BACK: relay on by the plug countdown, +10.0 s after the cut
|
||||
2026-10-14T12:07:17.391Z hp watchdog: relay already on — nothing to do
|
||||
@@ -0,0 +1,15 @@
|
||||
516942 bash -c until f=$(ls -t /var/lib/vz/dump/*.tar.dat 2>/dev/null | head -1); [ -n "$f" ] && [ "$(basename $f)" != "vzdump-lxc-9201-2026_10_14-10_42_25.tar.dat" ] && [ $(stat -c %s "$f") -gt 1500000000 ]; do sleep 2; done; date -u +%T; ls -la /var/lib/vz/dump | grep -E "tar.dat|\.tmp"; grep ^lock /etc/pve/lxc/9201.conf; grep btime /proc/stat
|
||||
vm-9201-disk-0 1
|
||||
vm-9201-disk-1 2
|
||||
DEV MAPPED CREATE_TIME SNAP_TIME
|
||||
1 1964MiB 0 139
|
||||
2 19GiB 0 138
|
||||
4 19GiB 138 138
|
||||
--- delete 4 at 12:02:02
|
||||
deleted
|
||||
DEV MAPPED CREATE_TIME SNAP_TIME
|
||||
1 1964MiB 0 139
|
||||
2 19GiB 0 138
|
||||
0 112975872 thin-pool 559 6154/262144 341320/882624 - rw discard_passdown queue_if_no_space - 1024
|
||||
LV Data% TransId
|
||||
data 38.67 559
|
||||
@@ -0,0 +1,2 @@
|
||||
12:09:53 uptime 147 s, power-off request: ('409', {'data': {'code': 'too_soon_after_boot'}, 'error': 'The machine has just started. You can turn it off in 10 minutes.', 'ok': False})
|
||||
Oct 14 14:09:54 demo-hp felhom-agent[1273]: time=2026-10-14T14:09:54.808+02:00 level=INFO msg="local-api: host power-off refused" vmid=9201 reason=too_soon_after_boot detail="host up 2m30s, minimum 10m0s"
|
||||
@@ -140,4 +140,31 @@ and succeeds; host root returns below its use before this cut.
|
||||
| why | the thin pool holds an **orphan thin device 4** — a 19 GiB snapshot of 9201's data disk (device 2) created at pool time 138 — which LVM does not know (LVM: devices 1, 2; transaction 559 on both sides). It is what C4's full root disk left: the snapshot cleanup could not write LVM's metadata. Read with a metadata snapshot (`thin_ls --metadata-snap`, reserved and released; `E/thin-ls.txt`) |
|
||||
| consequence | **no whole-guest backup of 9201 on demo-hp can run until device 4 is deleted** (every snapshot create picks id 4). Caused by this session's C4 test |
|
||||
|
||||
The power-cut leg of E waits on the repair (one pool message, `dmsetup message pve-data-tpool 0 "delete 4"`) — an operator decision.
|
||||
**Repair (operator „B2 - A", 12:02 UTC):** `dmsetup message pve-data-tpool 0 "delete 4"` → thin_ls shows devices 1 and 2
|
||||
only, pool transaction 559 unchanged, LVM agrees (`E/repair.txt`). Identity, not size: device 4 was the one id LVM does not
|
||||
know, a snapshot (CREATE_TIME 138) of device 2.
|
||||
|
||||
**The cut (`E/`):** fences clear 12:04:48; backup pressed through the product 12:04:48 (`POST /api/guest-backup/trigger`,
|
||||
200); the apps were stopped for the snapshot and started again at 12:05:30 (snapshot create worked — the repair held);
|
||||
at 1.53 GB written, `plugcut.py --plug hp --off-seconds 10`: **12:06:52.325 off → 12:07:02.409 on** (plug countdown;
|
||||
watchdog not needed). Root use at the cut 26,249,101,312 B; before the press 24,720,375,808 B. SSH back 12:07:45.
|
||||
|
||||
| Prediction | Measured |
|
||||
|---|---|
|
||||
| dead task logged once as „worker process is gone" | **yes** — 12:07:44 „backup-in-flight: a vzdump task is listed as active but its worker process is gone — it is dead, not running" (the agent started 12:07:42, inside the 30–60 s window in which Proxmox still lists the dead task — the R-1008 case, now judged right) |
|
||||
| the start-up stale-lock pass clears the lock, or finds Proxmox did | **both, in the same second:** the agent decided „clearing a stale backup lock" and ran `pct unlock 9201`; Proxmox's start-all had just removed it („removed left over backup lock from '9201'!", 12:07:44) → the agent logged **ERROR „pct unlock failed … no lock found"**. Harmless (the guest started 12:07:47), but an ERROR for an outcome that is the goal — R-1013 |
|
||||
| the start-up sweep removes the partial | **yes** — 12:07:48 „removed a dead half-written backup … vzdump-lxc-9201-2026_10_14-14_05_21.tar.dat 964,239,360 B (written before this boot)" and 12:07:52 its `.tmp` — through the root helper. 1.53 GB were written before the cut, 0.96 GB survived (the unwritten tail lost, as in C1) |
|
||||
| guards do not refuse because of the dead task | the start-up sweep IS a `BackupRunning` caller: it went ahead only because the dead task was judged not running. The household power-off request at 12:09:53 (uptime 147 s) was refused **`too_soon_after_boot`** only (`E/requests.txt`). The guest restart is not guarded by `BackupRunning` at all (C3) |
|
||||
| the next backup succeeds | **yes** — pressed 12:10:06, „found old vzdump snapshot (force removal)" (vzdump removed the cut's LVM snapshot itself), archive `vzdump-lxc-9201-2026_10_14-14_10_50.tar.zst` 5,650,197,172 B at 12:17:08; the older archive pruned (keep-last 1) (`E/next-backup.txt`) |
|
||||
| host root back below its use before this cut | **yes** — 24,689,217,536 B after the boot sweep; 24,691,134,464 B after the new backup (before the press: 24,720,375,808 B) |
|
||||
| no orphan thin device this time | **yes** — pool transaction 567, LVM lists only vm-9201-disk-0/1 |
|
||||
|
||||
`E/demo-hp-journal-boot.txt` is the whole boot journal (scanned: no key, token or password). R-1006 and R-1008 are proven
|
||||
live on demo-hp.
|
||||
|
||||
**Delivery to the other two boxes (`E/delivery-tester1-n100.txt`):** signed jobs `agent_update 0.156.1` (12:21:24 UTC) →
|
||||
`agent_config_update 0.156.1-step1` (12:35:37) → `agent_config_update 0.156.1` (12:50:14). Tester 1: agent 0.156.1 committed
|
||||
12:24, bundle done 12:53 (probe 71/71); N100: agent 12:34 (it reports every 15 min), bundle done 13:04 (probe 71/71). On
|
||||
both, real `sudo -l -U felhom-agent` allows the cleanup shape and refuses a finished archive (`.tar.zst`). The operator
|
||||
cleared the per-customer floors (demo-hp and demo-felhom 12:00, Tester 1 12:44 UTC): every guest runs controller 0.310.0.
|
||||
Both plugs ON: the HP relay back on by its countdown (12:07:02, `E/plugcut.log`), the N100's never cut; both hosts answer.
|
||||
|
||||
@@ -26,6 +26,13 @@
|
||||
|
||||
---
|
||||
|
||||
## 2026-10-14 — a box clears up after a power cut mid-backup
|
||||
|
||||
| Row | What | Closed | Evidence |
|
||||
|---|---|---|---|
|
||||
| **R-1006** | **A power cut during the night's whole-guest backup leaves the half-written archive on the host, and from then on every local whole-guest backup of that box is skipped „not enough space" — nothing removes it** (P2) | CLOSED 2026-10-14 — agent v0.156.1 + config bundle (new root helper `felhom-vzdump-partial-clean`, sudoers `FELHOM_VZPARTIAL`): at start-up and before every backup the agent removes a dead `.tar.dat`/`.vma.dat`/`.tmp` of that guest on a dir storage; the helper re-checks name, storage, any vzdump on the host, open files, and death (before this boot, or quiet 120 s). Proven live on demo-hp with a real power cut mid-backup (12:06:52 UTC): the 0.96 GB partial removed at boot, the next backup finished (5.65 GB), host root back below its pre-cut use. Delivered by signed jobs to demo-hp, Tester 1 and the N100 (probe 71/71 each, real sudo checked). Part 2 (preflight sizing) settled by C4: vzdump removes its own ENOSPC partial; `spaceFits` stays | felhom-agent `v0.156.1` (`7ae3081`); `audits/power-cut-fixes-2026-10-14/` C1–C4, E |
|
||||
| **R-1008** | **After a power cut the agent's stale-lock check calls the dead backup „genuinely in-flight" and leaves `lock: backup` on the guest** (P4) | CLOSED 2026-10-14 — agent v0.156.1: a vzdump task is in flight only while its worker process lives (Proxmox's own pid + pstart rule; a zombie or a reused pid is dead; unreadable `/proc` fails safe). Proven live on demo-hp 12:07:44 UTC: „a vzdump task is listed as active but its worker process is gone — it is dead, not running". 0.156.0's wall-clock rule was fail-open under a clock step (security review) — superseded, never vouched. The ERROR the unlock then logged when Proxmox had cleared the lock first is R-1013 | felhom-agent `v0.156.1`; `audits/power-cut-fixes-2026-10-14/E/after-boot.txt` |
|
||||
|
||||
## 2026-10-14 — the FAQ says who sets the BIOS, and how to turn the machine off
|
||||
|
||||
| Row | What | Closed | Evidence |
|
||||
|
||||
@@ -149,12 +149,11 @@ stopping line that lies.
|
||||
| **R-683** | App updates | P3 | **[P3-LOW] Watch: after a power cut during an update's health check, the hold named an HOUR-OLD second-drive copy, not the one the update's own backup should have just made.** 2026-09-24 chaos round 3 (nextcloud, `backup_max_age: 1m`): no `backing-up` phase was seen and the hold named Tier 2 at 13:04 for an update pressed at 14:04; the pre-cut controller log was lost with the container (the runner now saves it at arm time — R-320). Round 11, the same action without a power cut, named a fresh 14:34 copy and logged the Tier-2 copy. The sentence was TRUE (it named the copy it offered); the question is why the update did not back up first. Not reproduced; watch the next power-cut drill. `audits/night-2026-09-24/E/round-03*.json`, `E/round-11-controller-pre.log` | **OPEN — P3; owner: CC (watch)** | — | — | CC |
|
||||
| **R-785** | App updates | P3 | **[P3-LOW] SparkyFitness is pinned 11 releases and a major behind upstream (v0.17.3; upstream v1.7.3, v1.6.0 dated 2026-07-24).** READ 2026-10-01 (`audits/visitors-2026-10-01/C/bench/C1-previous-tag.txt`). **Needs:** an update walk 0.17 → 1.x through the ladder (bench + box), after R-784 is decided. | **OPEN — rank P3-LOW; owner: CC (after R-784)** | — | — | CC |
|
||||
|
||||
## Backup & restore — 30 rows (P2 5, P3 15, P4 10)
|
||||
## Backup & restore — 29 rows (P2 3, P3 16, P4 10)
|
||||
|
||||
| ID | Category | Sev | What | State | Blocked on | Next action | Owner |
|
||||
|---|---|---|---|---|---|---|---|
|
||||
| **R-1012** | Backup & restore | P2 | **A full host root can leave an orphan thin snapshot in the LVM pool that LVM no longer knows; from then on every whole-guest backup of that guest fails at the snapshot step („Creation of new snapshot 4 of device 2 failed"), and nothing in the product finds or names the cause.** Made on demo-hp 2026-10-14 by this session's C4 test (the root filled while vzdump snapshotted; LVM could not write its metadata): `thin_ls --metadata-snap` shows device 4 (19 GiB, a snapshot of 9201's data disk), LVM only 1 and 2 (`audits/power-cut-fixes-2026-10-14/E/thin-ls.txt`). R-1006's cleanup keeps the root from filling; this row is the repair and the detection. | **WAITING-ON-OPERATOR** — filed 2026-10-14 | operator: the repair on demo-hp | Operator: yes/no to `dmsetup message pve-data-tpool 0 "delete 4"` on demo-hp; then CC: a check that compares the pool's thin ids with LVM's and names an orphan in the backup failure | CC |
|
||||
| **R-1006** | Backup & restore | P2 | **A power cut during the night's whole-guest backup leaves the half-written archive on the host, and from then on every local whole-guest backup of that box is skipped „not enough space" — nothing removes it.** Measured 2026-10-14 on demo-hp (`audits/night-power-2026-10-13/` R3): the cut at 02:52 left `vzdump-lxc-9201-2026_10_14-04_42_18.tar.dat` (12.2 GB) + `.tmp`; host root at 92 %; agent retry 03:08 „skipped: not enough space: local has 2.9 GiB free; the last archive … was 4.6 GiB". The operator got `whole_guest_backup_failed` (true). Second part: the space preflight sizes the new archive from the LAST one (7.2 GB planned) while the guest had grown (12.4 GB written when cut) — a backup that outgrows the plan can fill the host root. Third part, the same rule the other way: after one big archive (14.4 GB at 05:17, while bench data sat on the guest disk) the next preflight would need ~21 GB of 5.5 GB free — the box skips every later backup though the guest is small again; cleared by hand at 07:28 UTC (`night-power-2026-10-13/README.md`). | **WAITING-ON-OPERATOR** — 2026-10-14: built and released in agent v0.156.1 (0.156.0 superseded); `audits/power-cut-fixes-2026-10-14/` (spike C1–C4, 19 red-proofs); part 2 (the preflight sizing) settled by C4 — vzdump cleans its own ENOSPC partial, `spaceFits` stays | operator: vouch agent 0.156.1 + bundle | CC: after the vouch — deliver (agent → step bundle → bundle) to demo-hp; one real cut mid-backup; prove the partial is gone, the next backup succeeds; then Tester 1 and the N100 | CC |
|
||||
| **R-1012** | Backup & restore | P3 | **A full host root can leave an orphan thin snapshot in the LVM pool that LVM no longer knows; from then on every whole-guest backup of that guest fails at the snapshot step („Creation of new snapshot 4 of device 2 failed"), and nothing in the product finds or names the cause.** Made on demo-hp 2026-10-14 by this session's C4 test (the root filled while vzdump snapshotted; LVM could not write its metadata): `thin_ls --metadata-snap` shows device 4 (19 GiB, a snapshot of 9201's data disk), LVM only 1 and 2 (`audits/power-cut-fixes-2026-10-14/E/thin-ls.txt`). R-1006's cleanup keeps the root from filling; this row is the repair and the detection. | **OPEN** — filed 2026-10-14; **repaired on demo-hp 2026-10-14 12:02 UTC** (operator „B2 - A"): `dmsetup message pve-data-tpool 0 "delete 4"`, then thin_ls and LVM agree on devices 1 and 2, and the next backup (12:10, after a real power cut) made its snapshot and finished (`audits/power-cut-fixes-2026-10-14/E/repair.txt`, `E/next-backup.txt`). What is left is the detection. 2026-10-14: P2 → P3 — the cause (a full host root) is what agent v0.156.1's leftover cleanup now prevents | — | CC: a check that compares the pool's thin ids with LVM's and names an orphan in the backup failure | CC |
|
||||
| **R-978** | Backup & restore | P3 | **Starting the escrow ceremony again can make the customer's written-down recovery code useless: the new package replaces the old one before the new code is confirmed.** It can happen to an ordinary customer who starts and walks away. Fix: keep the previous package until the new code is confirmed. Security review 2026-10-12 (`audits/security-review-2026-10-12/`); detail held off-git for the operator (`/mnt/5_hdd/felhom.eu/evidence/security-review-2026-10-12-PRIVATE/`). | OPEN | — | Fix in the agent with a test | CC |
|
||||
| **R-973** | Backup & restore | P3 | **A compromised controller can make the whole-guest backup run again and again, and each run prunes older restore points: the local tier directly, and the off-site tier through the store's own nightly keep-last-2.** So `07` §8 row 10 (ransomware) is weaker than it reads. The second reader confirmed the local half; the off-site half is inferred. Fix: a cadence or daily cap on the local-API backup route, and off-site snapshots that a nightly prune cannot remove. Security review 2026-10-12 (`audits/security-review-2026-10-12/`); detail held off-git for the operator (`/mnt/5_hdd/felhom.eu/evidence/security-review-2026-10-12-PRIVATE/`). | OPEN | — | Add the cap with a test; decide the off-site retention shape | CC |
|
||||
| **R-926** | Backup & restore | P3 | **After a household removes an `after_install` app keeping its backups and then restores it, nobody has checked whether the app page still shows a password that works.** A `type: password` deploy field is NOT in `stacks.PortableSecretEnvVars` (that list is `type: secret` only, `deploy.go:1199`), so it does not travel in the backup unit — the same shape as R-765, where Radicale's restored login was replaced by a value no page showed and every phone lost its calendar. MEASURED on 9202 2026-10-10 for grocy: remove keeping the backups, restore, and **the household's own password still signs in and the seeded data reads back** — so the DATABASE half is right. What was NOT settled is the PAGE half: `app.yaml` holds the value encrypted at rest, so reading it proves nothing (a 76-character string that of course did not sign in), and `POST /apps/grocy/initial-credentials/reveal` answered 404 for this app. Seven apps are in the same class: bookstack, calibre-web, claper, dawarich, grocy, mealie, wger. | **OPEN — the question is unanswered, not the answer bad** | — | Ask the controller what the app page renders for a generated `type: password` after a restore (one endpoint read, one app), and if it differs from the one that works, decide: carry the value in the unit, or re-run `after_install` after a restore | CC |
|
||||
@@ -226,7 +225,7 @@ stopping line that lies.
|
||||
| **R-78** | Box system & updates | P3 | **`local_api` authority ruling — auto-reconcile vs detect-only** **MIGRATED FROM `ROADMAP.md` 2026-08-22 (R-369) — originally filed 2026-07-25, size M, roadmap state `idea (deferred OUT of R-77 on purpose)`.** Moved verbatim; nothing added or reinterpreted. The roadmap keeps its copy as history, marked moved. **An OWED OPERATOR DECISION, not a defect — moved because an owed ruling hidden among feature ideas is the shape this session exists to remove.** | **OPEN — migrated from ROADMAP 2026-08-22, rank unchanged** | — | R-77 ships detection because the fix is genuinely undecided, and **both directions can lose customer-visible function**. **Direction 1 (today):** `controller.yaml` wins and drift is silent → the 2026-07-25 island migration blinded the whole fleet's control plane for 17.5 h (drive gate, guest-reboot recovery, quiesce/backup all degrade). R-77 makes that loud but does not stop it recurring. **Direction 2 (`bootstrap.json` wins, auto-reconcile on boot):** a guest whose `controller.yaml` is CORRECT and whose `bootstrap.json` is stale — a half-completed re-provision, a hand-repaired guest, a setup-wizard box — gets a **working channel clobbered on the next restart**, fleet-wide and silently, during a routine deploy. That is not obviously better than the bug. Needs a spike: which writer is authoritative per field (endpoint vs fingerprint vs token — `mergeLocalAPI` replaces the whole block, so they cannot be reconciled independently today), whether the agent side should stamp a generation/mtime so 'newer wins' is even expressible, and whether reconcile should require an operator ack. Until then the drift alert plus a manual edit is the supported path. | CC |
|
||||
| **R-468** | Box system & updates | P3 | **[P3-LOW] THE GOLDEN WAIVER — goldens on a cadence, not per release (operator ruling 2026-09-13).** 25 goldens in 26 days in August, almost one per release, because `golden_currency_gate.py` trips on every release by design and the only honest ways past it were a bake or a declared `--no-verify` (thirteen by 2026-09-01, R-404/R-417). **The ruling: bake WEEKLY, and always before any drill or fresh install.** Every release still raises the FLOOR, so both demo boxes keep getting each release in ~20 s; only the golden — which protects a fresh install and nothing else — moves to a cadence. **The mechanism (built 2026-09-13):** `documentation/tests/golden-waiver. **⚠ CORRECTED THE SAME DAY (R-472): between bakes the floor does NOT carry a release — the hub holds any floor above the vouched golden (publish-train rule 1), so releases between bakes reach the demo boxes only by hand-deploy.**yml`, four lines (`issued`, `expires`, `reason`, `register_row: R-468`), read by the gate. While valid, a golden BEHIND the record makes the gate print a loud ADVISORY and exit 0; when it expires the gate is red again until someone bakes or renews. **The 14-day cap is enforced by the gate, not the runbook** — a longer, undated, unparseable, reason-less or row-less waiver is INCONCLUSIVE (exit 2), never 0 and never silently ignored. **It never covers a golden that is UNRECORDED (R-385)** — that is not a cadence choice. **A dated waiver cannot be forgotten; it just expires** — the difference from R-242's original rule, which recurred the day after it was written. Tests: `scripts/test_golden_currency_gate.py` cases 5–15 (E/F/G/H, a 15-day, absent, unparseable, bad-row and empty-reason waiver each 2; the R-421 decoy — a file saying only `expires` — 2). **This is a PRE-CUSTOMER arrangement: the first external install retires it** (delete the file in that commit). Cadence written into `RUNBOOK-manual-build.md` §4.2 and the `felhom.eu` end-of-session checklist. **Does NOT touch R-242's open half (nothing gates the VOUCH).** | **WATCHING — rank P3-LOW; owner: CC (renew ≤ 14 days or bake); retire at the first external install** | — | — | CC |
|
||||
| **R-1004** | Box system & updates | P4 | **After an unclean stop every guest ext4 volume waits ~43 s in multi-mount protection before it mounts, so each restart after a power cut takes ~1.5 min longer.** Kernel: „EXT4-fs warning (device dm-6): ext4_multi_mount_protect: MMP interval 42 higher than expected, please wait" on dm-6/dm-7 and loop0/loop1, demo-hp and Tester 1, every round of `audits/night-power-2026-10-13/` (R1 `repairs.txt`). | **READY** — filed 2026-10-14 | — | CC: find where MMP is switched on for the guest volumes (Proxmox `pct` create, or our own mkfs), whether it protects anything on a one-host disk, and measure the restart without it on a scratch guest | CC |
|
||||
| **R-1008** | Box system & updates | P4 | **After a power cut the agent's stale-lock check calls the dead backup „genuinely in-flight" and leaves `lock: backup` on the guest.** Harmless today only because Proxmox's own start-all removes it in the same second („removed left over backup lock from '9201'!", demo-hp 2026-10-14 02:52:56, `audits/night-power-2026-10-13/R3/lock-lines.txt`). Nothing can be in flight on a fresh boot. | **WAITING-ON-OPERATOR** — 2026-10-14: built in agent v0.156.1 — in flight = the worker process lives (Proxmox's pid + pstart rule), not a wall-clock start (0.156.0's btime rule was fail-open under a clock step — security review); measured: the dead task stays listed only ~30–60 s after a boot (C3), so the live harm is that first minute | operator: vouch agent 0.156.1 | CC: the live proof with R-1006 (the agent's start-up line after the cut) | CC |
|
||||
| **R-1013** | Box system & updates | P4 | **After a power cut the agent's start-up stale-lock pass logs an ERROR „pct unlock failed … no lock found" when Proxmox's own start-all removed the lock in the same second.** The outcome is the goal (no lock), so the line is a false alarm in the log. Seen on demo-hp 2026-10-14 12:07:44–45 UTC (`audits/power-cut-fixes-2026-10-14/E/after-boot.txt`; Proxmox: „removed left over backup lock from '9201'!"). Small, but the agent's release for this session is spent (v0.156.1). | **OPEN** — filed 2026-10-14 | — | CC: treat „no lock found" from `pct unlock` as already clear (INFO), with a test; ride the next agent release | CC |
|
||||
| **R-1010** | Box system & updates | P3 | **The agent's stale-lock janitor cannot remove a half-removed `vzdump` snapshot: Proxmox's delete fails on the first missing volume („Failed to find logical volume pve/snap_vm-9201-disk-0_vzdump") and the janitor retries the same call every 10 min forever, leaving the other volume's snapshot and the snapshot entry.** Seen 2026-10-14 after a backup ran out of space on a full host root (LVM could not write its metadata; `audits/power-cut-fixes-2026-10-14/README.md` C4). Fixed by hand with `pct delsnapshot 9201 vzdump --force`. | **READY** — filed 2026-10-14 | — | CC: on that error, retry once with `--force` (a sudoers line or the API's `force=1`), with a test that replays the error text; next agent release | CC |
|
||||
|
||||
|
||||
|
||||
Reference in New Issue
Block a user