# R-518 read-back — the first night with BOTH tiers due on demo-hp. Read-only, collected from DooPlex 2026-10-09T08:02:41Z.
# demo-hp host journal = CEST (UTC+2). Controller metrics, docker, PVE UPID and ep0 = UTC.

################ CH1 — demo-hp agent journal (felhom-agent), backup lines 2026-10-08 22:15-22:45 local (= 20:15-20:45Z)
Oct 08 22:20:43 demo-hp felhom-agent[666190]: time=2026-10-08T22:20:43.713+02:00 level=INFO msg="backup: space preflight passed" vmid=9201 target=local last_archive_bytes=4885939687 need_bytes=7181166432 avail_bytes=17724211200
Oct 08 22:20:44 demo-hp felhom-agent[666190]: time=2026-10-08T22:20:44.762+02:00 level=INFO msg="local-api: backup reached snapshotted (app may resume)" vmid=9201 target=local job=backup-9201-1791490843121326096
Oct 08 22:25:40 demo-hp felhom-agent[666190]: time=2026-10-08T22:25:40.590+02:00 level=INFO msg="backup: completed" vmid=9201 target=local archive=local:backup/vzdump-lxc-9201-2026_10_08-22_20_43.tar.zst size_bytes=4887664196 uncovered_volumes=2
Oct 08 22:25:40 demo-hp felhom-agent[666190]: time=2026-10-08T22:25:40.590+02:00 level=INFO msg="local-api: backup job complete" vmid=9201 target=local job=backup-9201-1791490843121326096 archive=local:backup/vzdump-lxc-9201-2026_10_08-22_20_43.tar.zst
Oct 08 22:26:14 demo-hp felhom-agent[666190]: time=2026-10-08T22:26:14.221+02:00 level=INFO msg="local-api: backup refused — a heavy operation is already in flight" vmid=9201 requested_target=felhom-pbs busy=backup:local
Oct 08 22:27:10 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:10.591+02:00 level=INFO msg="osupdate: START" run=20261008T202710Z layer=guest vmid=9201 ring=0 trigger=night enabled=true release=ring0-20261008T202710Z
Oct 08 22:27:11 demo-hp felhom-os-apply[1209621]: os-apply: START release=ring0-20261008T202710Z layer=guest:9201 lane=fast mode=apply select=pending-fast packages=0
Oct 08 22:27:16 demo-hp felhom-os-apply[1209908]: os-apply: REPAIR configured=0 journal=0 fixed=0
Oct 08 22:27:26 demo-hp felhom-os-apply[1210615]: os-apply: PLAN upgrade=2 already=0 not-installed=0 from-snapshot=0
Oct 08 22:27:37 demo-hp felhom-os-apply[1211512]: os-apply: DONE rc=0 seconds=4.5 upgraded=2 restart-needed=- reboot-needed=no
Oct 08 22:27:45 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:45.957+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: START release=ring0-20261008T202710Z layer=guest:9201 lane=fast mode=apply select=pending-fast packages=0"
Oct 08 22:27:45 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:45.957+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: REPAIR configured=0 journal=0 fixed=0"
Oct 08 22:27:45 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:45.957+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: PLAN upgrade=2 already=0 not-installed=0 from-snapshot=0"
Oct 08 22:27:45 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:45.957+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: DONE rc=0 seconds=4.5 upgraded=2 restart-needed=- reboot-needed=no"
Oct 08 22:27:45 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:45.958+02:00 level=INFO msg="osupdate: DONE" run=20261008T202710Z layer=guest vmid=9201 ring=0 trigger=night outcome=applied healthy=true reason="" upgraded=2 pending=1 not_covered=1 restart_needed=0 reboot_needed=false wrapper_seconds=35.3
Oct 08 22:27:46 demo-hp felhom-agent[666190]: time=2026-10-08T22:27:46.035+02:00 level=INFO msg="osupdate: START" run=20261008T202710Z layer=host vmid=9201 ring=0 trigger=night enabled=true release=ring0-20261008T202710Z
Oct 08 22:27:47 demo-hp felhom-os-apply[1211951]: os-apply: START release=ring0-20261008T202710Z layer=host lane=fast mode=apply select=pending-fast packages=0
Oct 08 22:27:51 demo-hp felhom-os-apply[1212307]: os-apply: REPAIR configured=0 journal=0 fixed=0
Oct 08 22:27:56 demo-hp felhom-os-apply[1212564]: os-apply: PLAN upgrade=2 already=0 not-installed=0 from-snapshot=0
Oct 08 22:28:02 demo-hp felhom-os-apply[1213497]: os-apply: DONE rc=0 seconds=3.5 upgraded=2 restart-needed=kvm,pmxcfs,pve-firewall,pve-ha-crm,pve-ha-lrm,pvedaemon,pvedaemon worke,pveproxy,pveproxy worker,pvescheduler,pvestatd,rrdcached,spiceproxy,spiceproxy work reboot-needed=no
Oct 08 22:28:11 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:11.095+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: START release=ring0-20261008T202710Z layer=host lane=fast mode=apply select=pending-fast packages=0"
Oct 08 22:28:11 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:11.095+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: REPAIR configured=0 journal=0 fixed=0"
Oct 08 22:28:11 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:11.095+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: PLAN upgrade=2 already=0 not-installed=0 from-snapshot=0"
Oct 08 22:28:11 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:11.095+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: DONE rc=0 seconds=3.5 upgraded=2 restart-needed=kvm,pmxcfs,pve-firewall,pve-ha-crm,pve-ha-lrm,pvedaemon,pvedaemon worke,pveproxy,pveproxy worker,pvescheduler,pvestatd,rrdcached,spiceproxy,spiceproxy work reboot-needed=no"
Oct 08 22:28:12 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:12.164+02:00 level=INFO msg="osupdate: DONE" run=20261008T202710Z layer=host vmid=9201 ring=0 trigger=night outcome=applied healthy=true reason="" upgraded=2 pending=80 not_covered=80 restart_needed=14 reboot_needed=false wrapper_seconds=25
Oct 08 22:28:14 demo-hp felhom-os-apply[1214081]: os-apply: LIVE-RESTORE already on
Oct 08 22:28:14 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:14.220+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: LIVE-RESTORE already on"
Oct 08 22:28:14 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:14.220+02:00 level=INFO msg="osupdate: live-restore" vmid=9201 result="{\"result\": \"already on\"}"
Oct 08 22:28:14 demo-hp felhom-agent[666190]: time=2026-10-08T22:28:14.220+02:00 level=INFO msg="osupdate: START" run=20261008T202710Z layer=docker vmid=9201 ring=0 trigger=night enabled=true release=ring0-20261008T202710Z
Oct 08 22:28:16 demo-hp felhom-os-apply[1214207]: os-apply: START release=ring0-20261008T202710Z layer=docker:9201 lane=slow mode=apply select=pending-docker packages=0 authority=ring0
Oct 08 22:28:21 demo-hp felhom-os-apply[1214648]: os-apply: REPAIR configured=0 journal=0 fixed=0
Oct 08 22:28:27 demo-hp felhom-os-apply[1214956]: os-apply: PLAN upgrade=1 already=0 not-installed=0 from-snapshot=0
Oct 08 22:29:01 demo-hp felhom-os-apply[1217263]: os-apply: SOCKET-USERS restarted=felhom-controller,traefik rc=0 (R-858: they held the old docker socket)
Oct 08 22:29:03 demo-hp felhom-os-apply[1218011]: os-apply: DONE rc=0 seconds=5.1 upgraded=1 restart-needed=- reboot-needed=no
Oct 08 22:29:21 demo-hp felhom-os-apply[1219347]: os-apply: OOM-CHECK result=pass oom_killed=True oom_event=True exit=137 image=gitea.dooplex.hu/admin/felhom-controller:0.303.0 — the engine reported the memory kill: OOMKilled=true and the oom event
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.329+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: START release=ring0-20261008T202710Z layer=docker:9201 lane=slow mode=apply select=pending-docker packages=0 authority=ring0"
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.329+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: REPAIR configured=0 journal=0 fixed=0"
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.329+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: PLAN upgrade=1 already=0 not-installed=0 from-snapshot=0"
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.329+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: SOCKET-USERS restarted=felhom-controller,traefik rc=0 (R-858: they held the old docker socket)"
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.329+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: DONE rc=0 seconds=5.1 upgraded=1 restart-needed=- reboot-needed=no"
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.329+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: OOM-CHECK result=pass oom_killed=True oom_event=True exit=137 image=gitea.dooplex.hu/admin/felhom-controller:0.303.0 — the engine reported the memory kill: OOMKilled=true and the oom event"
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.330+02:00 level=INFO msg="osupdate: DONE" run=20261008T202710Z layer=docker vmid=9201 ring=0 trigger=night outcome=applied healthy=true reason="" upgraded=1 pending=0 not_covered=0 restart_needed=0 reboot_needed=false wrapper_seconds=67
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.342+02:00 level=INFO msg="osupdate: pve step holds the /etc/pve write gate — the agent's own writes wait until it ends" run=20261008T202710Z layer=pve vmid=9201 trigger=night
Oct 08 22:29:21 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:21.342+02:00 level=INFO msg="osupdate: START" run=20261008T202710Z layer=pve vmid=9201 ring=0 trigger=night enabled=true release=ring0-20261008T202710Z
Oct 08 22:29:22 demo-hp felhom-os-apply[1219396]: os-apply: START release=ring0-20261008T202710Z layer=pve:9201 lane=slow mode=apply select=pending-pve packages=0 authority=ring0
Oct 08 22:29:26 demo-hp felhom-os-apply[1219654]: os-apply: REPAIR configured=0 journal=0 fixed=0
Oct 08 22:29:30 demo-hp felhom-os-apply[1219888]: os-apply: PLAN upgrade=70 already=0 not-installed=0 from-snapshot=0
Oct 08 22:29:33 demo-hp felhom-os-apply[1220017]: os-apply: REFUSED: R6 the plan would touch shim-signed-common, which is not in the plan
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.402+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: START release=ring0-20261008T202710Z layer=pve:9201 lane=slow mode=apply select=pending-pve packages=0 authority=ring0"
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.402+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: REPAIR configured=0 journal=0 fixed=0"
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.402+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: PLAN upgrade=70 already=0 not-installed=0 from-snapshot=0"
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.402+02:00 level=INFO msg="osupdate: wrapper" line="os-apply: REFUSED: R6 the plan would touch shim-signed-common, which is not in the plan"
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.403+02:00 level=INFO msg="osupdate: DONE" run=20261008T202710Z layer=pve vmid=9201 ring=0 trigger=night outcome=refused healthy=false reason="" upgraded=0 pending=0 not_covered=0 restart_needed=0 reboot_needed=false wrapper_seconds=0
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.782+02:00 level=INFO msg="osupdate: pve step released the /etc/pve write gate" run=20261008T202710Z layer=pve vmid=9201 trigger=night
Oct 08 22:29:33 demo-hp felhom-agent[666190]: time=2026-10-08T22:29:33.783+02:00 level=WARN msg="osupdate: kernel step skipped — the Proxmox step did not end healthy" run=20261008T202710Z vmid=9201 trigger=night pve_outcome=refused
Oct 08 22:34:28 demo-hp felhom-agent[666190]: time=2026-10-08T22:34:28.003+02:00 level=INFO msg="local-api: backup reached snapshotted (app may resume)" vmid=9201 target=felhom-pbs job=backup-9201-felhom-pbs-1791491666431534232
Oct 08 22:37:38 demo-hp felhom-agent[666190]: time=2026-10-08T22:37:38.865+02:00 level=INFO msg="backup: completed" vmid=9201 target=felhom-pbs archive=felhom-pbs:backup/ct/9201/2026-10-08T20:34:27Z size_bytes=15886927313 uncovered_volumes=2
Oct 08 22:37:38 demo-hp felhom-agent[666190]: time=2026-10-08T22:37:38.865+02:00 level=INFO msg="local-api: backup job complete" vmid=9201 target=felhom-pbs job=backup-9201-felhom-pbs-1791491666431534232 archive=felhom-pbs:backup/ct/9201/2026-10-08T20:34:27Z
== vzdump task log
2026/10/09 05:05:43 main.go:3684: [INFO] local-api: mount mp8 → /mnt/felhom-drives (storage=/mnt/felhom-drives, class=, backup=false)

################ CH1 context — tier cadences as armed (agent journal, latest start)
Oct 09 07:16:47 demo-hp felhom-agent[2730121]: time=2026-10-09T07:16:47.622+02:00 level=INFO msg="backup tier armed" target=local cadence=24h0m0s keep_last=1 wait_timeout=30m0s prune_pbs_allowed=false primary=true
Oct 09 07:16:47 demo-hp felhom-agent[2730121]: time=2026-10-09T07:16:47.622+02:00 level=INFO msg="backup tier armed" target=felhom-pbs cadence=168h0m0s keep_last=0 wait_timeout=12h0m0s prune_pbs_allowed=false primary=false

################ CH1b — PVE task index on demo-hp (pvedaemon task log; a different writer from the agent): vzdump tasks 2026-10-07..09
UPID:demo-hp:0031920A:00EA3C89:6AC5AFDF:vzdump:9201:felhom-agent@pve!agent: start=2026-10-07T02:35:11Z end=2026-10-07T02:40:45Z OK
UPID:demo-hp:003C6995:01011C3B:6AC5EA6D:vzdump:9201:felhom-agent@pve!agent: start=2026-10-07T06:45:01Z end=2026-10-07T06:49:49Z OK
UPID:demo-hp:00120671:00AABC2D:6AC7FB1B:vzdump:9201:felhom-agent@pve!agent: start=2026-10-08T20:20:43Z end=2026-10-08T20:25:39Z OK
UPID:demo-hp:0012D84F:00ABFDC1:6AC7FE52:vzdump:9201:felhom-agent@pve!agent: start=2026-10-08T20:34:26Z end=2026-10-08T20:37:35Z OK
-- local vzdump log of the local tier
2026-10-08 22:20:43 INFO: Starting Backup of VM 9201 (lxc)
2026-10-08 22:20:43 INFO: status = running
2026-10-08 22:20:43 INFO: CT Name: demo-hp
2026-10-08 22:20:43 INFO: including mount point rootfs ('/') in backup
2026-10-08 22:20:43 INFO: including mount point mp0 ('/var/lib/felhom') in backup
2026-10-08 22:20:43 INFO: excluding bind mount point mp8 ('/mnt/felhom-drives') from backup (not a volume)
2026-10-08 22:20:43 INFO: excluding bind mount point mp9 ('/etc/felhom-bootstrap') from backup (not a volume)
2026-10-08 22:20:43 INFO: backup mode: snapshot
2026-10-08 22:20:43 INFO: ionice priority: 7
2026-10-08 22:20:43 INFO: suspend vm to make snapshot
2026-10-08 22:20:43 INFO: create storage snapshot 'vzdump'
2026-10-08 22:20:45 INFO: resume vm
2026-10-08 22:20:45 INFO: guest is online again after 2 seconds
2026-10-08 22:20:45 INFO: creating vzdump archive '/var/lib/vz/dump/vzdump-lxc-9201-2026_10_08-22_20_43.tar.zst'
2026-10-08 22:25:33 INFO: Total bytes written: 16625551360 (16GiB, 56MiB/s)
2026-10-08 22:25:33 INFO: archive file size: 4.55GB
2026-10-08 22:25:33 INFO: adding notes to backup
2026-10-08 22:25:33 INFO: prune older backups with retention: keep-last=1
2026-10-08 22:25:33 INFO: removing backup 'local:backup/vzdump-lxc-9201-2026_10_07-08_45_01.tar.zst'
2026-10-08 22:25:33 INFO: pruned 1 backup(s) not covered by keep-retention policy
2026-10-08 22:25:35 INFO: cleanup temporary 'vzdump' snapshot
2026-10-08 22:25:38 INFO: Finished Backup of VM 9201 (00:04:55)

################ CH2 — controller metrics.db in guest 9201 (one row per RUNNING container per ~60 s sample; a stopped container has no row)
# query: per sample, running count and the containers present at 20:14-20:20:30Z that are missing. Opened ?mode=ro via the controller container's sqlite3.
2026-10-08T20:14:19Z|21|
2026-10-08T20:15:19Z|21|
2026-10-08T20:16:19Z|21|
2026-10-08T20:17:19Z|21|
2026-10-08T20:18:19Z|21|
2026-10-08T20:19:19Z|21|
2026-10-08T20:20:19Z|21|
2026-10-08T20:21:21Z|15|privatebin,paperless-webserver,paperless-postgres,paperless-redis,opengist,kimai
2026-10-08T20:22:19Z|21|
2026-10-08T20:23:19Z|21|
2026-10-08T20:24:19Z|21|
2026-10-08T20:25:19Z|21|
2026-10-08T20:26:19Z|6|privatebin,paperless-webserver,paperless-postgres,paperless-redis,opengist,kimai,kimai-db,docmost,docmost-postgres,docmost-redis,calibre-web,bookstack,bookstack-db,adventurelog,bentopdf
2026-10-08T20:27:19Z|21|
2026-10-08T20:28:19Z|21|
2026-10-08T20:29:04Z|21|
2026-10-08T20:30:04Z|21|
2026-10-08T20:31:04Z|21|
2026-10-08T20:32:04Z|21|
2026-10-08T20:33:04Z|21|
2026-10-08T20:34:04Z|21|
2026-10-08T20:35:04Z|15|privatebin,paperless-webserver,paperless-postgres,paperless-redis,opengist,kimai
2026-10-08T20:36:04Z|21|
2026-10-08T20:37:04Z|21|
2026-10-08T20:38:04Z|21|
2026-10-08T20:39:04Z|21|
2026-10-08T20:40:04Z|21|
2026-10-08T20:41:04Z|21|
total distinct containers 20:14-20:20:30Z: 21

################ CH2b — guest docker: container start/create times (bentopdf recreated 15 s after the off-site snapshot)
/bentopdf started=2026-10-08T20:34:43.277725548Z created=2026-10-08T20:34:43.157907984Z
/traefik started=2026-10-08T20:29:01.412754011Z created=2026-10-04T09:01:48.259555986Z
/bookstack started=2026-10-09T02:15:27.95387884Z created=2026-10-09T02:15:22.165968876Z
/felhom-controller started=2026-10-09T05:05:42.178985741Z created=2026-10-09T05:05:42.122744205Z
# all other app containers were recreated 2026-10-09T02:15-02:16Z (after the window), so their StartedAt cannot show the 20:2x stops.

################ CH3 — ep0 PBS datastore, namespace demo-hp, ct/9201 (ls, read-only)
felhom-hetzner
2026-10-09T08:02:47Z
total 20
drwxr-xr-x 4 backup backup 4096 2026-10-09 03:29:59.997681474 +0000 .
drwxr-xr-x 3 backup backup 4096 2026-07-26 15:42:44.833483940 +0000 ..
drwxr-xr-x 2 backup backup 4096 2026-10-09 05:17:18.883235046 +0000 2026-10-01T20:15:29Z
drwxr-xr-x 2 backup backup 4096 2026-10-09 05:17:15.547227803 +0000 2026-10-08T20:34:27Z
-rw-r--r-- 1 backup backup   19 2026-07-26 15:42:44.833483940 +0000 owner

################ What could NOT be read (tried)
# controller docker log for the night: 'docker logs felhom-controller' starts 2026-10-09 05:05:43 — the 0.304.0 swap replaced the container.
# controller persisted debug ring (data/debug-ring.log): 5000 lines, oldest 2026-10-09T07:30:53Z — does not reach the night.
# guest docker events: 'docker events --since 2026-10-08T20:15Z --until 20:45Z' returned nothing; the event buffer's oldest entry is 2026-10-09T07:58Z (healthcheck execs fill it).
