burn-down night watches: R-872 05:00 run worked as designed but silently (Tester 2 34.8 h old) — early returns now log why, check re-dated 2026-10-07; R-887: 2 lost jobs, both re-run green; session report
gates / gates (push) Successful in 2m17s

Co-Authored-By: Claude Opus 5.5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_0159rPz1ZhFKsS53msqPYxtS
This commit is contained in:
2026-10-06 05:05:42 +02:00
parent c8774593f8
commit 307ecdf005
9 changed files with 144 additions and 3 deletions
+89
View File
@@ -0,0 +1,89 @@
# REPORT — the burn-down night: fix as many open items as possible, unattended, safely — 2026-10-05 21:00 → 2026-10-06 06:30
Brief: `drills/NIGHT-burndown-2026-10-05.md` (workspace root). Rules: `.claude/rules/unprompted-work.md`. Night log (one
line per row): `documentation/audits/night-burndown-2026-10-05/NIGHT-LOG.md`. Morning note: same folder, `MORNING-NOTE.md`.
| Rows before | Rows after | Opened | Closed |
|---|---|---|---|
| **199** | **164** | **1** (R-889) | **36** |
Counted by `register_shape_gate.py`'s method. After: P2 19, P3 76, P4 69.
## Baselines (read from live source at 21:03)
felhom.eu `30650cad6e` · controller `6f1ba1fe43` (v0.297.0) · agent `208fac8027` (v0.147.0) · catalog `4828dc754d` ·
hub v0.137.0 · golden 0.297.0 · register 199 (19 P2, 95 P3, 85 P4). All matched the brief's facts.
## How it was worked
The lead read the register and split group E (97 rows) into lanes, one helper session per lane, each in its own git
worktree cut from `origin/main`: controller ×4 (a, b, c, d), hub, installer, agent, catalog, gates, decoys; plus a
read-only helper for three group-D design proposals and one live-proof helper (stopped — below). Helpers committed
locally and never pushed; the lead reviewed, cherry-picked onto `main`, wrote every CHANGELOG, ran each repo's full
suite and gates on `main` before each push, closed rows and watched CI (one filtered call a minute).
## §1 — the three rulings (recorded first: `09` §3 decisions 128–130)
- **R-126** built (refuse an export without a password to a network drive) — delivered in controller v0.298.0.
- **R-856** — **the ruling as worded already held in the code**: the 90 s boot grace runs after every controller start,
crash boots included (`cmd/controller/main.go:286`, `:928`, `:2174`); the 2026-10-04 mails came 3.5 and 9 minutes
after the boot, after the grace. Building „the same grace" changes nothing, so nothing was built; back to the operator.
- **R-888, R-337, R-375** closed by the ruling.
## Releases (window 1, 00:30–00:58; evidence `audits/night-burndown-2026-10-05/delivery/`)
| | |
|---|---|
| hub **v0.138.0** | healthz 200 31 s after the sync; System page 200; 16 secrets sealed; a raw DB copy (with -wal) held 0 plaintext in the four columns; three box reports after the deploy, 0 auth failures; cookie `__Host-hub_session` |
| agent **v0.148.0** | released + verified by download; vouched; signed `agent_update` and `agent_config_update` to demo-hp, demo-felhom, Tester 1; host pages „matches vouched" |
| controller **v0.298.0** | image; golden 0.298.0 (**first bake unpinned — never vouched, re-baked pinned**); vouched with agent 0.148.0 / min_agent 0.131.0; floors for the three boxes only; all three run it |
| catalog | `c265b37` pushed 00:30 |
**Never touched:** the global floor, Tester 2 (off; nothing sent), ep0, DooPlex beyond the release acts and reads.
**No delivery 02:00–05:30.** Window 2 not used (nothing was proven on 9202).
## Rows, by result (the full table is the night log)
- **Closed (36):** 3 by ruling; R-531 stale; R-315, R-422, R-578, R-576, R-488, R-325, R-426 (tooling, live on
push); 25 fixed and delivered in window 1 (R-879, R-136, R-283, R-349, R-25, R-126, R-270, R-498, R-682, R-757, R-522,
R-575, R-718, R-729, R-545, R-839, R-271, R-607, R-615, R-569, R-492, R-574, R-758, R-798, R-731).
- **Fixed on `main`, waiting for a release:** installer 1.32.0 — R-275, R-276 (+ hub half live), R-881, R-306, R-130
(decision 131), R-180, R-179, R-310, R-274 — they ship with the tag `installer-v1.32.0`, which is not in the night's
release list; controller unreleased — R-585 (the rest), R-621 (hold panel), R-516 items 7–10 and 12.
- **Partial:** R-616 (the operator's Gitea token rotation left), R-521 (hub half + operator), R-127 (leg b → design).
- **Moved to „needs the operator" (A):** R-444, R-99, R-618, R-645, R-856, R-747, R-734, R-624, R-502, R-774 (part).
- **Moved to „needs a design" (D):** R-540, R-435, R-314, R-279, R-177, R-35, R-844, R-138, R-79, R-298, R-717, R-76,
R-805, R-693, R-652, R-794, R-127 (b).
- **Need a live proof or reading:** R-776, R-613 (written, held off the live catalog), R-763/R-764 (pushed; wger is
hidden), R-762, R-612, R-759, R-807, R-739, R-644, R-878, R-756, R-786 (part).
- **Group D proposals (no code):** R-518, R-638, R-528 — `audits/night-burndown-2026-10-05/design-R-*.md`.
## Decisions taken by CC unattended (operator may reverse) — `09` §3 131–136
131 R-130 the 120 GiB check is a recommendation · 132 R-879 no key → a new box secret is refused · 133 R-729/R-545 the
repository password is kept whenever anything could depend on it · 134 R-682 a cut-off Remove finishes keeping data ·
135 R-426 one-register's exemption removed · 136 R-621 the hold panel links to the kept log.
## Said plainly
- **The live-proof helper produced nothing** in 90 minutes and was stopped at 23:30. It had pointed 9202's catalog at
the drill repo; the controller was never restarted, so it never took effect; the line was put back byte-identical
(`cmp` with the saved copy). No proof ran; R-776/R-613 stay held.
- **The first golden bake was unpinned** — the runbook's runner script did not name `GOLDEN_DOCKER_PKGS`. Caught from
the bake's own WARNING line, never vouched, re-baked pinned; the runbook now names it.
- **The agent's `go test` was red on DooPlex 21:25–01:55** (a bundle test read the installer's new KEPT names as written
files); agent v0.148.0 was released inside that window (code unaffected). Fixed.
- **A golden-gate test was a time bomb** between 00:00 and 02:00 CEST (local date vs the gate's UTC). Fixed.
- Two helpers each once chained a test run and a commit in one command (standing rule 1); in both the suite had been read
green first. One helper amended a commit before its result line (allowed by the brief).
- The hub deploy re-sent one true operator mail: „Tester 2 down" (the restart re-checks a down box).
## Night watches (§5) — FILLED IN AFTER 05:00
(see below)
## Teardown
Drill VM: build guest destroyed, token/script/logs shredded, powered off, disk on `virgin`. 9202: catalog pointer
restored, nothing installed. Boxes: only the deliveries above. Hub: the deploy, the vouches, three floors. Worktrees
removed. Scratch secrets shredded at the end.
@@ -112,3 +112,13 @@ cherry-picks onto `main`, writes CHANGELOG, closes rows, pushes and watches CI.
| (agent, no row) | `go test ./internal/osupdate` red on DooPlex 21:25–01:55 (bundle test read the installer's new KEPT names as written files) — fixed | 10 | agent `b2b82ae` |
| (register) | section headings recounted (they still carried the 199-row counts) | 5 | this batch |
| R-516 | the bundle's last 49 formal forms → te-form; gate widened (61 → 0); narrowed to Go/template literals | 25 | controller `4c3c203` |
## The two night watches (§5)
| Watch | Result |
|---|---|
| R-872 at 05:00 | `Deadline check: 4 customers, 0 backup missed … 1 skipped (down)`. From a hub.db copy (+ -wal): Tester 2 first reported 2026-10-04 16:13:44Z → 34.8 h old at 05:00, under the 48 h line → not judged, by design, but SILENTLY. No alarm owed, none fired. Fixed without a row: the early returns now log why (hub, unreleased; red-proved). Dated check moved to 2026-10-07. `r872-watch.txt` |
| R-887 lost CI jobs | **2** of ~30 runs: felhom.eu 1384 (21:23Z) and felhom-controller 1401 (00:45Z) — no log, failed after 10–13.5 min; each re-run once → success. `r887-lost-jobs.txt` |
Seen, not filed (a documented design choice, F2 in `hub/internal/monitor/host_staleness.go`): a box already down when the
hub restarts is announced again once — Tester 2 got a `host_down` operator mail at each of yesterday's six hub restarts.
@@ -0,0 +1,4 @@
=== RUN TestR872_DownButTooYoungIsLogged
r872_down_box_test.go:97: no 'not judged yet' line for a down box 34 h old; log:
--- FAIL: TestR872_DownButTooYoungIsLogged (0.04s)
FAIL
@@ -0,0 +1,7 @@
== R-872 night watch, read 2026-10-06T03:02:06Z from a hub.db copy (+ -wal, -shm) — a different channel from the hub log
host_reports True
customer_configs True
events True
host_reports cols: ['id', 'host_id', 'customer_id', 'received_at', 'report_json', 'agent_version', 'cpu_percent', 'memory_percent']
Tester-2: config status=('active',) host_reports=8 first host report=('2026-10-04 16:13:44',) last=('2026-10-04 18:05:48',)
recent events: [('host_down', '2026-10-05 22:50:08'), ('host_down', '2026-10-05 18:12:36'), ('host_down', '2026-10-05 13:26:03'), ('host_down', '2026-10-05 13:03:42'), ('host_down', '2026-10-05 12:31:37'), ('host_down', '2026-10-05 09:16:10')]
@@ -0,0 +1,4 @@
1384 felhom.eu 4aa4d837 lost (no log, 21:23:23Z->21:33:38Z, 10m15s); rerun requested 21:34:51Z
1384 rerun -> success (21:34:53Z->21:36:58Z, 2m05s)
1401 felhom-controller c67b26be lost (no log, 00:45:01Z->00:58:38Z, 13m37s); rerun requested 00:59:06Z
1401 rerun -> success (00:59:09Z->01:00:06Z, 57s)
+3 -3
View File
@@ -270,7 +270,7 @@ stopping line that lies.
| **R-266** | Monitoring & notifications | P4 | **A failed root `statfs` still reaches the hub as a 0-of-0 disk, and the hub cannot tell that from an empty one.** Split out of R-259 on 2026-08-08 so that fixing the CUSTOMER-facing half could not be mistaken for fixing the wire. `report/builder.go:93-95` copies `sysInfo.DiskTotalGB` / `DiskUsedGB` / `DiskPercent` into `r.Storage[0]` (`Mount: "/"`), and those are exactly the zeros a failed `statfs` leaves behind — the controller now KNOWS the measurement failed (`SystemInfo.DiskKnown`, controller v0.210.0) and the report still does not carry it. **Deliberately not fixed here, for a reason that is now structural rather than a preference:** adding a field to that report is a change to a declared wire, which since G-1 means the receiving side must model it in the same session (`scripts/wire_contract_gate.py` refuses otherwise) — a two-repo change with a hub bump, and this session deliberately touched no hub code. **RANKED LOW, and the reason is that the consequence is bounded:** the hub bands host storage on `disk_percent`, so a failed read presents as 0% used — the *quiet* direction. It cannot raise a false "nearly full" alarm; it can only fail to raise a true one, and only while the root filesystem is unreadable, which is a state with louder symptoms of its own. **Fix shape when it is taken:** carry `disk_known` on the storage entry and have the hub's fill checker skip an unknown reading rather than band it — never treat absent as 0 | **READY** — owner Viktor | — | — | operator |
| **R-285** | Monitoring & notifications | P4 | **A planned, supervised reinstall pages the operator as if the machine had died — there is no notion of expected downtime anywhere.** During the 2026-08-09 rehearsal the hub sent, all `status: sent` to the operator channel: `host_stale` 08:58 UTC, `node_stale` 09:00, **`host_down` 09:28 (error)**, **`node_down` 09:30 (error)**, `host_leaf_changed` 09:31, `host_recovered` 09:31, `node_recovered` 09:34, `offsite_delivery_stuck` 09:34 — eight operator mails for work that was deliberate, attended and announced. **This is the OPPOSITE gap from the one R-281 filed:** the alarms are not missing, they are indiscriminate. `host_stale` at 30 min and `host_down` at 60 min (`monitor/host_staleness.go:22-23`, `downAfter = 2 * threshold`) cannot distinguish a wiped-on-purpose box from a dead one, and `host_leaf_changed` firing on a reinstall is correct-but-expected. **Note the interaction with the mute used on 2026-08-09 evening:** blocking a customer silences everything, so today the only two settings are *page me for planned work* and *tell me nothing at all*. **What is owed is a middle:** a maintenance window, or an operator-set expected-downtime flag, that suppresses staleness and leaf-change while leaving genuine faults audible | **READY (M) — NEW 2026-08-09** | — | The evidence is the operator's mailbox plus `events`/`notification_log` for 2026-08-09 | CC |
| **R-856** | Monitoring & notifications | P4 | **A crash restart reaches the household twice: the hub's "restarted after an unexpected stop" line AND the controller's app mails.** 2026-10-04 crash-guard test on demo-hp: after the third crash and the power-on, the controller sent `app_start_failed` (operator) and `app_stopped_unhealthy` (operator AND the household's address) for apps that were still coming up. Each is true on its own; the app ladder has no "the host just crashed" suppression like its boot grace for an ordinary restart (`08` §5). A design question for the operator, not a defect yet. `audits/os-docker-crash-2026-10-04/partC/c4-hub-events.txt` | **READY — RULED 2026-10-05 ~21:00 (`09` §3 decision 129): after a crash boot, the controller's app mails wait the same grace period as after a normal start. Being built (burn-down night).** **2026-10-05 (burn-down night): the ruling as worded ALREADY HOLDS — NEEDS THE OPERATOR again.** The 90 s boot grace runs after every controller start, crash boots included (`cmd/controller/main.go:286`, `:928`, `:2174`); the 2026-10-04 mails came 3.5 and 9 minutes after the boot, after the grace, so decision 129 would not have stopped them. Next: either a LONGER grace after a crash boot (how long — the incident needed > 9 min), or suppress only the household leg, or close the row. A longer grace needs the crash-boot fact over the local API. | — | Build decision 129 | CC |
| **R-872** | Monitoring & notifications | P2 | **A box that is off every night never raises a missed-backup alarm: the 05:00 deadline check skips every customer whose node is `down`, so missing database dumps, second copies and off-site copies stay silent indefinitely; the only nightly signal is `node_down`.** MEASURED 2026-10-05 05:00 Budapest, hub log: `Deadline check: … 0 backup missed … 1 skipped (down)` — the skipped one is Tester 2, off since 18:06 UTC (`hub/internal/monitor/deadline.go` ~360: `if st == "down" \|\| st == StateDisabled { skipped++; continue }`). R-195 / R-321's shape again — a skip keyed off the wrong fact: "down now" was meant to avoid a double alarm, but a box down at every deadline is never checked at all. Fix direction (after R-871): count the days since the last success regardless of the node state, and alarm on N missed nights. `audits/night-fixes-2026-10-05/partF/FINDINGS.md` | **NARROWED 2026-10-05 — FIXED hub v0.134.0, proven by tests (3 red-proofs, `audits/catchup-2026-10-05/partC/`): a down box is judged on 48 h (dump) / 72 h (whole-guest) lines (`08` §6.4, decision 115). LEFT: the first live 05:00 run — DATED CHECK 2026-10-06 (DUE-CHECKS): the hub log line `Deadline check: Tester-2 is DOWN — judged on the longer lines … dump missed=1 backup missed=1` (if Tester 2 is still off at 05:00), and the two events in `events`. Holds → close; does not → a new row.** | R-871 | — | CC |
| **R-872** | Monitoring & notifications | P2 | **A box that is off every night never raises a missed-backup alarm: the 05:00 deadline check skips every customer whose node is `down`, so missing database dumps, second copies and off-site copies stay silent indefinitely; the only nightly signal is `node_down`.** MEASURED 2026-10-05 05:00 Budapest, hub log: `Deadline check: … 0 backup missed … 1 skipped (down)` — the skipped one is Tester 2, off since 18:06 UTC (`hub/internal/monitor/deadline.go` ~360: `if st == "down" \|\| st == StateDisabled { skipped++; continue }`). R-195 / R-321's shape again — a skip keyed off the wrong fact: "down now" was meant to avoid a double alarm, but a box down at every deadline is never checked at all. Fix direction (after R-871): count the days since the last success regardless of the node state, and alarm on N missed nights. `audits/night-fixes-2026-10-05/partF/FINDINGS.md` | **NARROWED 2026-10-05 — FIXED hub v0.134.0, proven by tests (3 red-proofs, `audits/catchup-2026-10-05/partC/`): a down box is judged on 48 h (dump) / 72 h (whole-guest) lines (`08` §6.4, decision 115). LEFT: the first live 05:00 run — DATED CHECK 2026-10-06 (DUE-CHECKS): the hub log line `Deadline check: Tester-2 is DOWN — judged on the longer lines … dump missed=1 backup missed=1` (if Tester 2 is still off at 05:00), and the two events in `events`. Holds → close; does not → a new row.** **NIGHT WATCH 2026-10-06 05:00 (burn-down night): the run WORKED AS DESIGNED but could not be seen to.** Hub log: `Deadline check: 4 customers, 0 backup missed … 1 skipped (down)` and NO per-box line. Read from a hub.db copy with -wal (a different channel): Tester 2's first host report was 2026-10-04 16:13:44Z, its last 2026-10-04 18:05:48Z — at 05:00 it was 34.8 h old, under the 48 h line, so `judgeDownCustomer` returned early („nothing expected yet") — silently. No alarm was owed, none fired. **Fixed without a row (hub, on `main`, ships with the next hub release):** each early return now logs why (`… is DOWN — not judged yet: first host report … ago`); `TestR872_DownButTooYoungIsLogged`, red-proved. **RE-DATED 2026-10-06 → 2026-10-07:** from 16:14Z today Tester 2 is old enough; if it is still off at 05:00 tomorrow the existing `… is DOWN — judged on the longer lines …` line and its events are the proof. `audits/night-burndown-2026-10-05/r872-watch.txt`. | R-871 | — | CC |
| **R-886** | Monitoring & notifications | P3 | **DooPlex's Alertmanager cannot write its own state since the Longhorn restart of 2026-10-05 13:20Z** — every 15 min `Running maintenance failed … open /alertmanager/nflog.…: permission denied` (and the same for `silences`), 8 times by 14:21Z; the pod was recreated 13:20:48Z by that restart. Mail still goes out (`alertmanager_notifications_total{integration="email"}` 5 → 6, `failed_total` 0, 14:23Z), but a silence set now and the record of what was already sent do not survive the next pod restart — so a restart can re-send every active alarm or drop a silence. Likely collateral of the restart (volume ownership on re-attach), not measured. **Checked from source 2026-10-05 (burn-down round 2):** homelab-manifests@87dfc29 mon-system/alertmanager.yaml:137-247: the Deployment has NO securityContext / fsGroup / runAsUser at all (grep), runs prom/alertmanager:v0.34.1 (:199, non-root `nobody` image) with --storage.path=/alertmanager on the Longhorn PVC alertmanager-data (:202, :212-213, :245-247). The comment :239-244 asserts silences now survive a restart -- an invariant with no test, which is exactly what this row says broke. Last structural change 58d1cd2 (2026-08-14, 'give alertmanager re | **OPEN** | — | Compare the volume's file owner with the pod's `securityContext` (`fsGroup`/`runAsUser`); fix in homelab-manifests; prove with a silence that survives a pod restart | operator |
| **R-884** | Monitoring & notifications | P4 | **ArgoCD app `monitoring` shows `Deployment/prometheus` OutOfSync** (seen 2026-10-05 while syncing the R-173 alarm rules; only the rules ConfigMap was synced, so the Deployment drift is untouched and its cause unknown). A full sync would change the running Prometheus in an unknown way. **Checked from source 2026-10-05 (burn-down round 2):** Strong lead from source: homelab-manifests@87dfc29 commit 53c6e99 (Renovate, 2026-10-03) changed ONLY mon-system/monitoring.yaml `prom/prometheus:v3.14.0` -> `v3.15.0` (monitoring.yaml:419), and the `monitoring` Application has no `automated` syncPolicy in git (argocd-apps/homelab.yaml:602-605). So the drift is most likely an unsynced Renovate bump, i.e. a full sync = Prometheus 3.14 -> 3.15 upgrade (plus pod restart; R-211: no reloader). Not confirmed live. | **OPEN** | — | `argocd app diff monitoring` (or the CR's resource diff) to see what differs, then decide git or live | operator |
@@ -307,7 +307,7 @@ stopping line that lies.
| ID | Category | Sev | What | State | Blocked on | Next action | Owner |
|---|---|---|---|---|---|---|---|
| **R-733** | Process & tooling | P3 | **[P3-LOW] The test bench has NO swap and the boxes have 512 MiB — so a box proof can pass on swap where the bench fails, and nobody records whether a customer guest has swap.** MEASURED 2026-09-30 (R-732): immich's first start was OOM-killed 61–104 times on the bench (swap 0) and passed on 9202 by swapping ~108 MB; the bench given 512 MiB swap passed too. demo-hp 9201, 9202 and demo-felhom 9201 all read `swap: 512`; the golden's guest config is not recorded in its bake evidence, so a customer guest's swap is NOT measured. The harness's memory watch judges `anon` against the limit and never reads `memory.swap.current`. **Needs:** the golden's `swap` read and recorded; the box walk and the harness report `memory.swap.peak` beside `anon`; a decision whether proofs run with swap off (the stricter venue, as R-732's fix was proven). | **READY — rank P3-LOW; owner: CC (harness + golden evidence)** | — | — | CC |
| **R-887** | Process & tooling | P3 | **Some CI jobs are never run, and Gitea fails them ~10–13 minutes later with no log.** Seen 2026-10-05: felhom.eu job 1361 (commit `1122b5c`) and felhom-controller job 1357 (`114ff27`): every step reads `failure`, including the first fetch, the log API answers `file does not exist`, and the runner pod's log has no `task` line for them (its task ids are job id + 1). A re-run through the API ran the controller job normally (success in 32 s) but the felhom.eu job was again never picked up and failed after ~12 min. The runner pod (`gitea-system/act-runner`, image `felhom-act-runner:0.1.0`) had restarted 5 times ~142 min earlier, around the Longhorn instance-manager restart (R-882). Suspected, NOT measured: a stale runner registration claims jobs it never runs — the session's Gitea token cannot list runners (`read:admin` scope). Consequence: a red CI verdict that is not about the code, and **no failure mail** (the alarm step never runs either), so only the pull check sees it. **CORRECTED 2026-10-05 18:21 (operator's screenshot of Gitea → Site Administration → Runners): ONE runner only — ID 2, `felhom-gates-runner`, v0.6.1, label `felhom-gates`, Idle, last online „now". There is no old registration; the stale-registration guess (this row's first text and the reviewer's) was WRONG.** **RE-DIAGNOSED 2026-10-05 (round 2), from the logs that survive:** (1) **„lost in a runner restart" does NOT fit** — the runner pod last restarted 13:24:42Z (`restartCount 5`, all around the 13:20Z Longhorn restart), the lost attempts started 1.5–2.5 h later. (2) **FOUR attempts were lost, not two:** controller job 1357 (start 15:05:41Z → failed 15:18:38Z), felhom.eu job 1359 (15:15:37 → 15:28:38 — the previous session blamed that one on the BusyBox fault; the runner never ran it), job 1361 (15:33:21 → 15:43:38) and its API re-run (15:46:48 → 15:58:38). None has a `task` line in the runner log; every one was failed at a :38-second mark on a 5-minute step, 10–13 min after it was handed out — **the shape of Gitea's periodic „zombie task" stop** (a task assigned to a runner that never reports is failed after ~10 min; no log exists because none was written). (3) The runner's task ids are NOT job id + 1 (the controller re-run was task 1363). (4) **Gitea's own log for the window is gone** — the pod log starts 16:16:32Z (rotated), so the assignment side cannot be read. **Likely mechanism, NOT proven:** the runner's fetch-task request timed out on its side after Gitea had already assigned the task, so the task was orphaned. In that same hour this session polled Gitea's jobs API hard (15 pages every 15 s per wait loop) and Gitea logged „slow" requests — a plausible load cause, and the session's own. Mitigation taken: the session's CI waiter now polls once a minute. **Nothing changed on DooPlex.** **MECHANISM SEEN 2026-10-05 17:15–17:28Z, with Gitea's own log (round 2):** catalog run 1368 (`4828dc7`) — 17:15:14 the job is marked started; 17:15:16 `router: slow POST /api/actions/runner.v1.RunnerService/FetchTask for 10.42.0.42 (the runner), elapsed 3192ms`, then `UpdateRepoRunsNumbers … context canceled` and `GetActionWorkflow: EOF` — **the runner abandoned its fetch after Gitea had assigned the task**; the runner log has no line for task 1371; 17:28:39 `actions/clear_tasks.go:174 stopTasks() [W] Cannot transfer logs of task 1371` — Gitea's zombie-task stop. **The load at that minute:** an outside crawler (216.73.216.78) walking commit pages and `archive/*.tar.gz`, and THIS session's CI waiter, whose 15-page job listings took 13–31 s each. An API re-run passed in 7 s. **Done in-session:** the waiter now asks `GET …/actions/runs?head_sha=<sha>` once a minute (1 s). **Not done (DooPlex, the operator's):** the runner's fetch timeout and Gitea's exposure to the crawler. | **OPEN** **DATED CHECK 2026-10-12 (DUE-CHECKS):** if no job was lost since 2026-10-05 16:00Z (no completed job whose runner log has no `task` line / whose log API answers `file does not exist`), close. | — | Operator: decide whether to raise the act-runner fetch timeout and/or rate-limit the public Gitea pages the crawler walks; meanwhile re-run a lost job via `POST /repos/admin/<repo>/actions/runs/<id>/rerun`. Keep the 2026-10-12 check | operator |
| **R-887** | Process & tooling | P3 | **Some CI jobs are never run, and Gitea fails them ~10–13 minutes later with no log.** Seen 2026-10-05: felhom.eu job 1361 (commit `1122b5c`) and felhom-controller job 1357 (`114ff27`): every step reads `failure`, including the first fetch, the log API answers `file does not exist`, and the runner pod's log has no `task` line for them (its task ids are job id + 1). A re-run through the API ran the controller job normally (success in 32 s) but the felhom.eu job was again never picked up and failed after ~12 min. The runner pod (`gitea-system/act-runner`, image `felhom-act-runner:0.1.0`) had restarted 5 times ~142 min earlier, around the Longhorn instance-manager restart (R-882). Suspected, NOT measured: a stale runner registration claims jobs it never runs — the session's Gitea token cannot list runners (`read:admin` scope). Consequence: a red CI verdict that is not about the code, and **no failure mail** (the alarm step never runs either), so only the pull check sees it. **CORRECTED 2026-10-05 18:21 (operator's screenshot of Gitea → Site Administration → Runners): ONE runner only — ID 2, `felhom-gates-runner`, v0.6.1, label `felhom-gates`, Idle, last online „now". There is no old registration; the stale-registration guess (this row's first text and the reviewer's) was WRONG.** **RE-DIAGNOSED 2026-10-05 (round 2), from the logs that survive:** (1) **„lost in a runner restart" does NOT fit** — the runner pod last restarted 13:24:42Z (`restartCount 5`, all around the 13:20Z Longhorn restart), the lost attempts started 1.5–2.5 h later. (2) **FOUR attempts were lost, not two:** controller job 1357 (start 15:05:41Z → failed 15:18:38Z), felhom.eu job 1359 (15:15:37 → 15:28:38 — the previous session blamed that one on the BusyBox fault; the runner never ran it), job 1361 (15:33:21 → 15:43:38) and its API re-run (15:46:48 → 15:58:38). None has a `task` line in the runner log; every one was failed at a :38-second mark on a 5-minute step, 10–13 min after it was handed out — **the shape of Gitea's periodic „zombie task" stop** (a task assigned to a runner that never reports is failed after ~10 min; no log exists because none was written). (3) The runner's task ids are NOT job id + 1 (the controller re-run was task 1363). (4) **Gitea's own log for the window is gone** — the pod log starts 16:16:32Z (rotated), so the assignment side cannot be read. **Likely mechanism, NOT proven:** the runner's fetch-task request timed out on its side after Gitea had already assigned the task, so the task was orphaned. In that same hour this session polled Gitea's jobs API hard (15 pages every 15 s per wait loop) and Gitea logged „slow" requests — a plausible load cause, and the session's own. Mitigation taken: the session's CI waiter now polls once a minute. **Nothing changed on DooPlex.** **MECHANISM SEEN 2026-10-05 17:15–17:28Z, with Gitea's own log (round 2):** catalog run 1368 (`4828dc7`) — 17:15:14 the job is marked started; 17:15:16 `router: slow POST /api/actions/runner.v1.RunnerService/FetchTask for 10.42.0.42 (the runner), elapsed 3192ms`, then `UpdateRepoRunsNumbers … context canceled` and `GetActionWorkflow: EOF` — **the runner abandoned its fetch after Gitea had assigned the task**; the runner log has no line for task 1371; 17:28:39 `actions/clear_tasks.go:174 stopTasks() [W] Cannot transfer logs of task 1371` — Gitea's zombie-task stop. **The load at that minute:** an outside crawler (216.73.216.78) walking commit pages and `archive/*.tar.gz`, and THIS session's CI waiter, whose 15-page job listings took 13–31 s each. An API re-run passed in 7 s. **Done in-session:** the waiter now asks `GET …/actions/runs?head_sha=<sha>` once a minute (1 s). **Not done (DooPlex, the operator's):** the runner's fetch timeout and Gitea's exposure to the crawler. | **OPEN** **DATED CHECK 2026-10-12 (DUE-CHECKS):** if no job was lost since 2026-10-05 16:00Z (no completed job whose runner log has no `task` line / whose log API answers `file does not exist`), close. **NIGHT WATCH 2026-10-05/06 (burn-down night): 2 jobs lost of ~30 runs** — felhom.eu run 1384 (`4aa4d837`, 21:23→21:33Z, no log) and felhom-controller run 1401 (`c67b26be`, 00:45→00:58Z, no log); each re-run once through the API and each passed (2 m 05 s, 57 s). The night's waiter made one filtered call a minute. So the 2026-10-12 close condition („no job lost since 2026-10-05 16:00Z") is already NOT met. `audits/night-burndown-2026-10-05/r887-lost-jobs.txt`. | — | Operator: decide whether to raise the act-runner fetch timeout and/or rate-limit the public Gitea pages the crawler walks; meanwhile re-run a lost job via `POST /repos/admin/<repo>/actions/runs/<id>/rerun`. Keep the 2026-10-12 check | operator |
| **R-206** | Process & tooling | P4 | **The build-cache cap and the weekly prune exist only as a hand-edited `/etc/docker/daemon.json` on DooPlex — not in Ansible, so a rebuild loses them.** The `node_housekeeping` role must also carry the prune, which today it is forbidden to run | **READY (M) — NEW 2026-08-05** | — | **The spike validated the recipe; this row builds it.** Three parts. **(a) Template `/etc/docker/daemon.json`** with the **`policy` array** form — **the flat form (`{"gc":{"reservedSpace":…}}`) is SILENTLY IGNORED**, measured: the daemon starts, logs nothing, and `docker buildx inspect` still reports the built-in defaults. **The oracle is `docker buildx inspect`, never `dockerd --validate`** — the validator returned `configuration OK` for a bogus key AND for the config that then **crashed the daemon** (`filter` takes one value per policy entry, not an array; `error initializing buildkit: filters expect only one value`). **(b) Narrow the role's Docker ban** (`node-housekeeping.sh.j2:10-14`) to permit exactly `docker builder prune -af` and nothing else — the ban's stated premise ("Docker here runs only unrelated jarr-* dev containers") is obsolete: the growth is Felhom Go build cache. **The measured prune is SYNCHRONOUS** (150.35 GB back at t+0, two consecutive polls <1 MB apart within 60 s) — **unlike containerd's image GC, so it needs no `settle_imagefs` equivalent**, but it MUST measure the filesystem rather than trust the command: `prune` claimed **156.9 GB** and the filesystem returned **150.35 GB**, the 6.5 GB gap being layers still shared with images. **(c) A restart-safety note in the role:** a bad `daemon.json` takes the daemon down AND leaves the `unless-stopped` dev containers stopped — they needed a manual `docker start` — so the role must restart-and-verify, not validate-and-assume. Recipe + every measurement: `audits/SPIKE-dooplex-buildcache-2026-08-05.md` | CC |
| **R-209a** | Process & tooling | P4 | **The SSD2 move has NOT survived a reboot, so by this project's own standard it is not fully validated** | **WATCHING — NEW 2026-08-05** | the next DooPlex reboot | **Operator ruled explicitly: do NOT reboot DooPlex.** Uptime verified unbroken (7 weeks 6 days, since 2026-06-10). **The distinction is stated rather than glossed: the MECHANISM is proven** — the guard is wired into both units and containerd refuses to start when a required mount's device is absent — **but the CONSEQUENCE is not**: that a real boot mounts `/mnt/ssd_2` before containerd starts, in this host's actual ordering. Mount-ordering reasoning is precisely the class this project has been burned by (`RequiresMountsFor` RE-MOUNTS rather than refusing — the ep0 lesson), and `CLAUDE.md` prefers a consequence assertion over a mechanism one. **Two deliberate consequences: (1)** the rollback copy `/var/lib/containerd.pre-move-2026-08-05` (**34.3 GB on `/`**) **STAYS** until a reboot validates — which is why `/` sits at 54% and not lower; deleting it now would trade a cheap 34 GB for the only cheap way back. **(2)** validation is **automatic and needs no one to remember it**: `felhom-store-postboot-check.service` (oneshot, enabled, dry-run PASS at install) runs at **every** boot and writes `RESULT: PASS`/`FAIL` to `/var/log/felhom-store-postboot-check.log`, asserting positively that `/mnt/ssd_2` is mounted, that containerd's root is on it, that **`/var/lib/containerd` does NOT exist** (the empty-store trap), that ≥100 images are visible and that both dev containers run. **Next action: after the next reboot — planned or not — read that file; on PASS, `rm -rf /var/lib/containerd.pre-move-2026-08-05` returns ~34 GB to `/`** **P3's prune already removed the urgency: `/` went 86% → 53% used and SSD1's Longhorn disk went `Schedulable=False (DiskPressure)` → `Schedulable=True` (18.85% → 50.32% available).** The move was ruled "cap then move"; the cap is in and the pressure is gone, so this is now a deliberate choice rather than a rescue. **The numbers, measured (`Crucial-SSD-240G`, `/mnt/ssd_2/data/longhorn`, `storageMaximum` 235,148,750,848):** available today **214,958,080,000 (91.41%)**; 25% floor **58,787,187,712**. Moving the whole containerd tree at steady state (~31.5 GB images + ≤30 GB cache ≈ 65 GB) leaves **63.77%, i.e. +38.8 pp above the floor — comfortably safe as measured.** **But `storageScheduled` on SSD2 is 139,586,437,120 while `df` says only 20,094,939,136 is actually used** — Longhorn has overcommitted 6.9× — and if those volumes ever inflate to their scheduled size, the same disk lands at **13.00%, i.e. 12 pp BELOW the floor → `Schedulable=False`**, which is exactly the failure that just took SSD1 out. **Recommendation: do the move only together with setting `storageReserved` on SSD2 to cover the containerd tree (~80 GB); SSD2 reserving zero while HDD2 and HDD4 each reserve 500 GB is an anomaly in its own right.** Mechanism, if it goes ahead: **containerd's `root` in `/etc/containerd/config.toml`** (the key is present but commented out) — **not** Docker's `data-root`, which would move only 0.62 GB. Guard: `RequiresMountsFor=/mnt/ssd_2` on `containerd.service` **and** `docker.service`, remembering that **`RequiresMountsFor` RE-MOUNTS rather than refusing** ([[ep0-datastore-volume-move-2026-07-27]]) — so it must be tested with a genuinely absent device, and the move is not validated until it has survived a **reboot**. Full pre-analysis: `audits/SPIKE-dooplex-buildcache-2026-08-05.md` §P6 | operator + CC |
| **R-230** | Process & tooling | P4 | **Three instruction/memory follow-ups deliberately left by the part-2 session (2026-08-06), each needing a decision rather than an implementation.** (a) **A ruling is owed on auto-written staleness.** The hand-written `CLAUDE.md` files are now clean of version literals and expired blocks — the gate enforces it — but `MEMORY.md`, which Claude writes and which is the LARGER half of what loads (8.4k tokens vs the root file's 6.6k), carries **21 lines with component version literals**, **5 with bare host addresses**, and an entry still reading *"demo boxes REMOTE till ~08-02"* — the same expired-TEMPORARY class the gate was built to kill, now surviving in the one file the gate's content rules do not cover. **Partly actioned 2026-08-06 (close-out), and the ruling is STILL OWED:** the **three statements that were actively false** were corrected — `R-193 decision open` (closed 2026-08-05), `demo boxes REMOTE till ~08-02` (the box answers on the home LAN), `OPEN R-25b` (shipped 2026-07-21) — and gate check 6 now **WARNs** on version literals, host addresses, expired statements and stale-open citations in the index. WARN, never FAIL: Claude writes that file between sessions, so a hard failure would refuse a human's push over a line no human typed, and the warning is read by the model that will next edit it. **The remaining 32 version literals and 4 host addresses were deliberately left** for that loop. What is still owed is the bulk-correction ruling. **Correcting the premise:** the earlier report's "three expired statements" were all FALSE POSITIVES — each matched an ISO date inside a markdown link target, i.e. a filename — while the one real expired claim carried no ISO date at all. (b) **CLOSED 2026-08-06 (close-out)** — the workspace-root `CLAUDE.md` **is now a relative symlink** to the versioned copy, so the divergence class is gone rather than policed. Check 5 learned two shapes: for a link it asserts the target resolves to a real file (**a dangling link is worse than a diverged copy — the instructions load NOTHING and there is no content left to notice is wrong**), for two files byte-identity as before, so a clone elsewhere is unaffected. **Proven, not assumed:** three fresh sessions logged `session_start` for the link path, and a fourth **with no tools at all** quoted standing rule 1 verbatim — the content reaches the model, not just the path. (c) **The spec-as-failing-test pilot**, approved in principle and not started (was R-229(d)). | **READY** — owner Viktor | — | — | operator |
@@ -340,5 +340,5 @@ stopping line that lies.
| item | due (UTC) | what to measure |
|---|---|---|
| R-887 | 2026-10-12 | no CI job lost since 2026-10-05 16:00Z (every completed job has a runner `task` line and a log); detail in the R-887 row |
| R-872 | 2026-10-06 | the first live 05:00 deadline run judges a down box on the longer lines (Tester 2, if still off): hub log + the two events (detail in the R-872 row) |
| R-872 | 2026-10-07 | the 05:00 deadline run judges a down box on the longer lines (Tester 2, if still off; it is old enough from 2026-10-06 16:14Z): hub log `… is DOWN — judged on the longer lines …` + the events (detail in the R-872 row) |
<!-- DUE-CHECKS-END -->
+4
View File
@@ -1,3 +1,7 @@
## unreleased
- **Fixed without a row (R-872 night watch):** the 05:00 deadline check's down-box judgement returned early in silence for a box never bound or first seen under 48 h ago, so the log read only „1 skipped (down)" and a night watch could not tell „too young to judge" from „judged, nothing missed". Each early return now logs why. `TestR872_DownButTooYoungIsLogged`; red-proved (without the line: the test fails).
## v0.138.0 — secrets sealed at rest, a cookie no sibling can plant, the box's own claim state, agent-binary drift (burn-down night: R-879, R-136, R-283, R-349, R-276) (2026-10-05)
**Operator action on deploy: log in again once** (the session cookie is renamed). **Roll-back needs one extra step
+10
View File
@@ -346,11 +346,21 @@ const (
// expected_dbdump_missed and one expected_backup_missed, each only past its longer line, and never for a box that
// was bound or first reported less than downDumpMissedAfter ago (nothing has been expected yet).
func judgeDownCustomer(s *store.Store, id string, now time.Time, onEvent EventNotifyFunc, logger *log.Logger) (backupMissed, dbdumpMissed int) {
// Each early return says so in the log: the 2026-10-06 05:00 night watch saw only "1 skipped (down)" and could not
// tell "judged, nothing missed" from "too young to judge" (Tester 2, first report 34.8 h before). Pinned by
// TestR872_DownButTooYoungIsLogged.
if bound, err := s.HasEverBoundHost(id); err == nil && !bound {
logger.Printf("[INFO] Deadline check: %s is DOWN — not judged: no host was ever bound", id)
return 0, 0
}
first, ferr := s.GetFirstHostReportAt(id)
if ferr != nil || first.IsZero() || now.Sub(first) < downDumpMissedAfter {
age := "unknown"
if ferr == nil && !first.IsZero() {
age = now.Sub(first).Round(time.Minute).String()
}
logger.Printf("[INFO] Deadline check: %s is DOWN — not judged yet: first host report %s ago (under %s, nothing expected yet)",
id, age, downDumpMissedAfter)
return 0, 0
}
raise := func(typ, msg string) {
@@ -4,6 +4,7 @@ import (
"database/sql"
"io"
"log"
"strings"
"testing"
"time"
@@ -84,3 +85,15 @@ func TestR872_NewDownBoxIsQuiet(t *testing.T) {
t.Fatalf("events %v for a box bound a day ago", got)
}
}
// The 2026-10-06 05:00 night watch saw only "1 skipped (down)" for Tester 2 (first report 34.8 h before) and could not
// tell "too young to judge" from "judged, nothing missed": the early return wrote no line. Now it says which.
// Red-proof: drop the Printf in judgeDownCustomer's age return → the line is missing.
func TestR872_DownButTooYoungIsLogged(t *testing.T) {
st, _, sc := downBox(t, 34*time.Hour)
var buf strings.Builder
CheckBackupDeadlines(st, sc, func(cid, et, sev, msg, det, src string) {}, log.New(&buf, "", 0))
if !strings.Contains(buf.String(), "c1 is DOWN — not judged yet: first host report") {
t.Fatalf("no 'not judged yet' line for a down box 34 h old; log:\n%s", buf.String())
}
}