BIGNIGHT F9: controller killed stays dead 33 min, no alarm delivered — R-523 (P1), stop rule met; F10-F12 not run

2026-09-15 00:08:27 +02:00
parent ce011b823d
commit adc38d1f72
10 changed files with 133 additions and 0 deletions
@@ -627,3 +627,19 @@ itself, through the product's restore endpoint, and reads the data back — reco
 | hub shows DOWN, and when | never DOWN (threshold 1 h). Status „warn · Last report N min ago" climbing 14 → 31 min; **`node_stale` 21:25:43Z** (31 min after the last report, 17 min into the cut) + operator mail; **`node_recovered` 21:26:43Z** + mail |
 | alarms true? | `node_stale` true; `node_recovered` true — a cut shorter than ≈ 13 min after a report would raise nothing, by design |
 | should have fired, did not | a customer-side notice that the box is offline (R-522) |
+
+### F9 — the controller dies in the middle of a deploy (`phase5/F9-controller-killed-mid-deploy.txt`, `phase5/F9/`)
+
+| | |
+|---|---|
+| how | deploy of a throwaway app (homebox) `POST` 21:34:35Z → „Telepítés elindítva" (with a memory warning: „Az alkalmazások csúcsterhelése meghaladhatja a rendelkezésre álló memóriát. Normál használat mellett ez nem okoz problémát.") → **`docker kill felhom-controller` at 21:34:39Z** (4 s in) |
+| what the box did by itself | **nothing brought the controller back**: `Exited (137)`, `restart=unless-stopped` — Docker does not restart a container stopped by `kill`; the in-guest `felhom-controller-bootstrap` unit is a one-shot („active (exited)" since boot) and does not watch it. 5 min later still dead, dashboard **502** on the LAN |
+| the deploy | the app itself came up: container `homebox Up 5 minutes (healthy)`; `app.yaml` and `applied-compose.yml` written at 21:34 |
+| what the customer saw | the dashboard answers 502 — no page at all |
+| 23 min later (21:57:39Z) | still `Exited (137) 22 minutes ago`, LAN health **502**; hub shows only `app_deployed (info) — Homebox` (the controller's last report reached the hub at **21:34:38Z**, 3 s before the kill, so the 30-minute staleness is due ≈ 22:04:38Z). The host agent's journal meanwhile: drive reconcile and stale-lock scans every 20 s, **nothing about the controller** |
+| 33 min later (22:08:04Z) | still `Exited (137) 33 minutes ago`, LAN 502. Hub **22:04:43Z `node_stale` — operator mail suppressed by cooldown** (key `tester-1:node_stale`, set by F8 at 21:25:43Z) |
+
+**STOP RULE MET (22:08Z).** F9 left the box in a state the product did not recover from on its own (33 min) and that a
+customer cannot recover from any screen (there is no dashboard). Filed **R-523 (P1)** before acting. Per the brief:
+**no further faults are injected — F10, F11 and F12 are not run**; the box is recovered by the household's only lever,
+a power-cycle, and the night moves to Phase 6.
@@ -11,3 +11,6 @@
 21:29:23 guest->1.1.1.1=301 guest->hub=302 cloudflared(last120s registered=0 errors=8)
 21:31:14 guest->1.1.1.1=301 guest->hub=302 cloudflared(last120s registered=0 errors=8)
 21:33:05 guest->1.1.1.1=301 guest->hub=302 cloudflared(last120s registered=0 errors=8)
+21:34:57 guest->1.1.1.1=301 guest->hub=302 cloudflared(last120s registered=0 errors=10)
+21:36:49 guest->1.1.1.1=301 guest->hub=302 cloudflared(last120s registered=0 errors=8)
+21:38:40 guest->1.1.1.1=301 guest->hub=302 cloudflared(last120s registered=0 errors=8)
@@ -54,3 +54,15 @@ LAN dashboard banners: ↗ |
 hub: Last report: 7 min ago · Controller 0.242.0 | Auto-refresh | (paused) | Tester 1 | ok | Controller | 0.242.0 |
 LAN dashboard banners: ↗ | 
  tunnel tile: Cloudflare Tunnel | Biztonságos internetkapcsolat — a szerver portnyitás nélkül érhető el kívülről. | Fut | Védett | Doc
+=== 21:34:32
+hub: Last report: 8 min ago · Controller 0.242.0 | Auto-refresh | (paused) | Tester 1 | ok | Controller | 0.242.0 |
+LAN dashboard banners: ↗ | 
+  tunnel tile: Cloudflare Tunnel | Biztonságos internetkapcsolat — a szerver portnyitás nélkül érhető el kívülről. | Fut | Védett | Doc
+=== 21:36:23
+hub: Last report: 2 min ago · Controller 0.242.0 | Auto-refresh | (paused) | Tester 1 | ok | Controller | 0.242.0 |
+LAN dashboard banners: (none)
+  tunnel tile: 
+=== 21:38:13
+hub: Last report: 4 min ago · Controller 0.242.0 | Auto-refresh | (paused) | Tester 1 | ok | Controller | 0.242.0 |
+LAN dashboard banners: (none)
+  tunnel tile: 
@@ -0,0 +1,45 @@
+F9 docker kill felhom-controller at 21:34:39 (deploy started: POST 21:34:35)
+felhom-controller
+felhom-controller Exited (137) 3 seconds ago
+21:34:45 +1s controller=[Exited (137) 4 seconds ago] health=502
+21:35:02 +18s controller=[Exited (137) 20 seconds ago] health=502
+21:35:18 +34s controller=[Exited (137) 37 seconds ago] health=502
+21:35:35 +51s controller=[Exited (137) 53 seconds ago] health=502
+21:35:51 +67s controller=[Exited (137) About a minute ago] health=502
+21:36:08 +84s controller=[Exited (137) About a minute ago] health=502
+21:36:25 +101s controller=[Exited (137) About a minute ago] health=502
+21:36:41 +117s controller=[Exited (137) About a minute ago] health=502
+21:36:57 +133s controller=[Exited (137) 2 minutes ago] health=502
+21:37:14 +150s controller=[Exited (137) 2 minutes ago] health=502
+21:37:30 +166s controller=[Exited (137) 2 minutes ago] health=502
+21:37:47 +183s controller=[Exited (137) 3 minutes ago] health=502
+21:38:03 +199s controller=[Exited (137) 3 minutes ago] health=502
+21:38:20 +216s controller=[Exited (137) 3 minutes ago] health=502
+21:38:36 +232s controller=[Exited (137) 3 minutes ago] health=502
+21:38:53 +249s controller=[Exited (137) 4 minutes ago] health=502
+21:39:10 +266s controller=[Exited (137) 4 minutes ago] health=502
+21:39:26 +282s controller=[Exited (137) 4 minutes ago] health=502
+21:39:43 +299s controller=[Exited (137) 5 minutes ago] health=502
+21:39:59 +315s controller=[Exited (137) 5 minutes ago] health=502
+21:40:16 +332s controller=[Exited (137) 5 minutes ago] health=502
+21:40:32 +348s controller=[Exited (137) 5 minutes ago] health=502
+21:40:49 +365s controller=[Exited (137) 6 minutes ago] health=502
+21:41:05 +381s controller=[Exited (137) 6 minutes ago] health=502
+21:41:22 +398s controller=[Exited (137) 6 minutes ago] health=502
+21:41:38 +414s controller=[Exited (137) 6 minutes ago] health=502
+21:41:55 +431s controller=[Exited (137) 7 minutes ago] health=502
+21:42:11 +447s controller=[Exited (137) 7 minutes ago] health=502
+21:42:28 +464s controller=[Exited (137) 7 minutes ago] health=502
+21:42:44 +480s controller=[Exited (137) 8 minutes ago] health=502
+21:43:01 +497s controller=[Exited (137) 8 minutes ago] health=502
+21:43:17 +513s controller=[Exited (137) 8 minutes ago] health=502
+21:43:34 +530s controller=[Exited (137) 8 minutes ago] health=502
+21:43:50 +546s controller=[Exited (137) 9 minutes ago] health=502
+21:44:07 +563s controller=[Exited (137) 9 minutes ago] health=502
+21:44:23 +579s controller=[Exited (137) 9 minutes ago] health=502
+21:44:40 +596s controller=[Exited (137) 9 minutes ago] health=502
+21:44:57 +613s controller=[Exited (137) 10 minutes ago] health=502
+21:45:13 +629s controller=[Exited (137) 10 minutes ago] health=502
+21:45:30 +646s controller=[Exited (137) 10 minutes ago] health=502
+--- app after restart
+Bad Gateway
@@ -0,0 +1,4 @@
+=== 21:57:39 controller still dead? Exited (137) 22 minutes ago
+LAN health: 502
+=== hub alarms 21:34Z..
+2026/09/14 23:34:35 [INFO] Event from tester-1: app_deployed (info) — Alkalmazás telepítve: Homebox
@@ -0,0 +1,4 @@
+=== 22:08:04 controller: Exited (137) 33 minutes ago · LAN health 502
+2026/09/14 23:34:35 [INFO] Event from tester-1: app_deployed (info) — Alkalmazás telepítve: Homebox
+2026/09/15 00:04:43 [INFO] Staleness: tester-1 ok → stale (node_stale)
+2026/09/15 00:04:43 [INFO] Operator email suppressed for tester-1/node_stale — cooldown (key=tester-1:node_stale)
@@ -0,0 +1,29 @@
+2026/09/14 21:33:05 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:33:15 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:33:25 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:33:35 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:33:45 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:33:45 [INFO] [scheduler] Running job: agent-channel-health
+2026/09/14 21:33:45 [INFO] [scheduler] Job agent-channel-health completed (took 189ms)
+2026/09/14 21:33:55 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:34:05 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:34:15 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:34:25 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:34:34 [INFO] [web] Login from 172.18.0.10:37154
+2026/09/14 21:34:35 [INFO] [api] Deploy requested for stack: homebox
+2026/09/14 21:34:35 [INFO] [stacks] Memory check: total=11828MB, reserved=384MB, usable=11444MB, committed_used=4126MB, new_req=50MB, remaining=7268MB
+2026/09/14 21:34:35 [INFO] [stacks] Deploying stack homebox with 3 env vars: [DOMAIN, HBOX_AUTH_API_KEY_PEPPER, SUBDOMAIN]
+2026/09/14 21:34:35 [INFO] [stacks] SaveAppConfig: saved config for homebox
+2026/09/14 21:34:35 [INFO] Event pushed: app_deployed (info) — Alkalmazás telepítve: Homebox
+2026/09/14 21:34:35 [INFO] [stacks] Status refresh: 28 containers across 57 stacks
+2026/09/14 21:34:37 [INFO] [report] Building system report
+2026/09/14 21:34:37 [INFO] [monitor] Health check: status=ok
+2026/09/14 21:34:38 [INFO] [report] Hub report pushed successfully (13817 bytes)
+2026/09/14 21:34:38 [INFO] [settings] Settings saved
+2026/09/14 21:34:40 [INFO] [stacks] Stack homebox deployed successfully (took 5.7s)
+2026/09/14 21:34:40 [INFO] [stacks] SaveAppConfig: saved config for homebox
+2026/09/14 21:34:41 [INFO] [stacks] installed-images homebox: recorded 1 service(s) (homebox=ghcr.io/sysadminsmedia/homebox:0.26.2 (sha256:b1ad7e3c63f7…))
+2026/09/14 21:34:41 [INFO] [stacks] SaveAppConfig: saved config for homebox
+2026/09/14 21:34:41 [INFO] [stacks] SaveAppConfig: saved config for homebox
+2026/09/14 21:34:41 [INFO] [stacks] pin homebox: homebox=ghcr.io/sysadminsmedia/homebox:0.26.2
+2026/09/14 21:34:41 [INFO] [stacks] Status refresh: 29 containers across 57 stacks
@@ -0,0 +1,17 @@
+● felhom-controller-bootstrap.service - Felhom controller bootstrap (deploy the baked controller from the agent-populated config mount)
+     Loaded: loaded (/etc/systemd/system/felhom-controller-bootstrap.service; enabled; preset: enabled)
+     Active: active (exited) since Mon 2026-09-14 19:54:43 UTC; 1h 45min ago
+ Invocation: acc822de0aa047f7a7e65fb6cef0f587
+TriggeredBy: ● felhom-controller-bootstrap.path
+    Process: 3204 ExecStart=/usr/local/sbin/felhom-controller-bootstrap.sh (code=exited, status=0/SUCCESS)
+   Main PID: 3204 (code=exited, status=0/SUCCESS)
+   Mem peak: 48.6M
+restart=unless-stopped exit=137 oom=false finished=2026-09-14T21:34:41.542160118Z
+homebox Up 5 minutes (healthy)
+total 24
+drwxr-xr-x  2 root root 4096 Sep 14 21:34 .
+drwxr-xr-x 59 root root 4096 Sep 14 18:50 ..
+-rw-r--r--  1 root root 2601 Sep 14 17:58 .felhom.yml
+-rw-------  1 root root  723 Sep 14 21:34 app.yaml
+-rw-r--r--  1 root root 1636 Sep 14 21:34 applied-compose.yml
+-rw-r--r--  1 root root 1636 Sep 14 17:58 docker-compose.yml
@@ -0,0 +1,2 @@
+F9 power-cycle (qm reset) at 22:08:17
+22:08:23 +5s health=000
@@ -726,6 +726,7 @@ class (an image `VOLUME` at an unmounted path) is still live — `immich-server`
 | **R-520** | **[P3-LOW] A power cut during a guarded Update leaves no record that an update was running, so whether the journal resumes or aborts honestly is unmeasured for a real version change.** MEASURED 2026-09-14 (BIGNIGHT F3, VM 333): the only Update the catalog allowed after the Phase 4 revert was a same-version one on nextcloud; power was cut 2 s after `update nextcloud: phase pulling` (safety dump written, pin advanced to the unchanged definition). After boot: no log line resumes, aborts or names the interrupted update; `app.yaml` `pinned_images` = `installed_images`, no hold, no verdict; page „Fut · Naprakész". Nothing wrong was produced — and nothing could have been, with identical images. **What it needs:** the same cut on a real bump (a throwaway app with a one-step catalog move on a scratch branch or the scratch guest), asserting the page's message and the pin after boot. | **READY — rank P3-LOW; owner: CC (drill)** |
 | **R-521** | **[P3-LOW] One unplugged drive sends the operator five e-mails and the household none.** MEASURED 2026-09-14 (BIGNIGHT F4, VM 333): `storage_disconnected (error)` at 21:58:02 CEST plus `app_start_failed (warning)` for each of the four apps the drive carries at 21:58:15, each with its own operator mail (hub log: five `Operator email sent`). The customer's mailbox (`tester1@felhom.eu`, read through the connector) received nothing; the household learns of it only on the dashboard, which is honest and says what to do. The apps' stop is a consequence of the drive event, so the four warnings add no information. **Fix shape:** suppress `app_start_failed` for apps stopped by a `storage_disconnected` (the dead-app check already knows the reason — „Hiányzó tárhely"), and decide whether a household gets a mail for a lost drive. **F6, 40 min later, the opposite failure:** a second, separate drive loss (20:38:33Z) produced `storage_disconnected (error)` and four `app_start_failed`, and the hub logged `Operator email suppressed … cooldown` for all five — **no mail at all for the second unplug**; only `health_degraded (warning)` mailed. A per-key cooldown that outlives the recovery (`storage_reconnected` came between them) silences a new incident. **F7:** the system disk at 95 % produced only `health_degraded (warning)`, whose operator mail was **suppressed by the cooldown** left by F6's `health_degraded` 15 minutes earlier; no disk-specific event reached the hub at all — the operator was not told the disk was nearly full. | **READY — rank P3-LOW; owner: CC (controller) · operator (customer mail policy)** |
 | **R-522** | **[P3-LOW] While the box has no internet, the dashboard's „Cloudflare Tunnel" tile keeps saying „Fut", and no page tells the household the box is offline.** MEASURED 2026-09-14 (BIGNIGHT F8, VM 333): VM 333's traffic off the LAN and to the hub was dropped at demo-hp's bridge 21:08:36 → 21:26:07Z. Throughout, the LAN dashboard (probed every 26 s from demo-hp) answered 200 and, polled every 2 min, showed no banner and the tile „Cloudflare Tunnel — Biztonságos internetkapcsolat — a szerver portnyitás nélkül érhető el kívülről. · **Fut** · Védett"; meanwhile cloudflared logged ≈ 20 errors every 2 minutes, the public name answered 530, and the controller logged `[report] Push failed … context deadline exceeded` and `Job hub-report failed: hub push failed after 3 attempts`. The tile reports the container, not the connection. A household whose remote access is gone sees „Fut". **Fix shape:** the tile reads the tunnel's connection state (cloudflared's registered connections or the report push result) and says „Nincs internetkapcsolat" when either fails. | **READY — rank P3-LOW; owner: CC (controller)** |
+| **R-523** | **[P1-HIGH] If the controller container is killed, nothing restarts it: the household's dashboard is gone and no screen can bring it back — the big night's stop rule.** MEASURED 2026-09-14 (BIGNIGHT F9, VM 333, controller 0.242.0): `docker kill felhom-controller` at 21:34:39Z, 4 s into a deploy. The container stays `Exited (137)` with `restart=unless-stopped` (Docker does not restart a container stopped by kill); the in-guest `felhom-controller-bootstrap` unit is a one-shot (`active (exited)` since boot) and does not watch it; the host agent does not either. The dashboard answered **502** for 33 min until the harness power-cycled the box. The app being deployed came up by itself (`homebox … (healthy)`). The hub raised `node_stale` at 22:04:43Z (30 min after the last report, which reached it 3 s before the kill) and **suppressed the operator mail by cooldown** (F8's `node_stale` 39 min earlier) — so for over half an hour neither the household nor the operator was told. Recovery by power-cycle: see the F9 journal (measured after filing). `docker kill` is the brief's injection; the same state follows any stop that Docker records as deliberate (an operator's `docker stop`, a failed self-update that stops the old container). Memory note „controller DOES auto-recover — test with kill -9/OOM, never docker kill" describes the mechanism, not the consequence: nothing watches for a controller that is simply not running. **Fix shape:** a systemd watchdog (or the agent) that starts `felhom-controller` whenever it is not running and the operator has not parked it; restart policy `always`. | **READY — rank P1-HIGH; owner: CC (controller bootstrap / agent)** |

 <!-- DUE-CHECKS-BEGIN — machine-readable. Parsed by scripts/due_checks_gate.py.
     One row per dated check. The R-number must have a row above. Dates are UTC.