Files
felhom-controller/REPORT.md
T
2026-08-02 20:38:52 +02:00

248 lines
16 KiB
Markdown
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
# REPORT — v0.190.0: boot recovery finished, and a regression v0.189.0 opened (R-157 A · R-170 · R-171)
**Overwritten** per the standing rule; the prior contents (v0.189.0 / R-166, same day) have their
durable record in `CHANGELOG.md`.
**Session:** 2026-08-02 · **Repos:** `felhom-controller` v0.189.0 → **v0.190.0**, `felhom.eu` (docs
only, no hub bump) · **Live target:** demo box `felhom-pve` guest **9201** · **No STOP point.**
---
## 1. Baselines and the five timing constants — all matched §1 on arrival
| Repo | `main` @ arrival | Expected | Match |
|---|---|---|---|
| `felhom-controller` | `344660942015da292e5bfdf98c457124b6f633a1` | `344660942015` | ✅ |
| `felhom.eu` | `5c97fbc397f2148ea4d5c98d4de06e3dc8b69a91` | `5c97fbc397f2` | ✅ |
| Constant | Value | Confirmed at | Match |
|---|---|---|---|
| `bootReconcileSettle` | `5 * time.Second` | `cmd/controller/main.go:1264` | ✅ |
| `DefaultAttempts` | `2` | `internal/bootrecon/bootrecon.go:46` | ✅ |
| `DefaultRetryDelay` | `30 * time.Second` | `internal/bootrecon/bootrecon.go:49` | ✅ |
| `deadAppBootGrace` | `90 * time.Second` | `cmd/controller/main.go:1238` | ✅ |
| drive-gate tick | `30 * time.Second` | `internal/web/intermediary.go:339` | ✅ |
No drift. Both trees clean before the build.
## 2. Part 0's verdict — **CONFIRMED**, and the first attempt was a false negative
**The sweep DOES start an app whose data drive is absent.** Observed on 9201, both attempts:
```
17:22:07 [gate] drive ABSENT /mnt/felhom-drives/hdd_1 — stopped+blocked 2 app(s): [calibre-web immich]
17:22:34 [bootrecon] Boot reconciliation: 1 boot-orphaned app(s) found: [calibre-web] — up to 2 attempt(s)
17:22:34 [stacks] Starting stack: calibre-web
17:22:35 [bootrecon] attempt 1/2: start "calibre-web" failed after 0.4s: exit code 1
17:23:05 [bootrecon] attempt 2/2: start "calibre-web" failed after 0.4s: exit code 1
17:23:05 [bootrecon] gave up after 2 attempt(s): recovered=[] still down=[calibre-web] (the dead-app alarm now owns these)
```
All four preconditions were verified first: drive mounts **0**, containers **0**,
`desired_state: running`, `deployed: true`.
**RUN 1 WAS A FALSE NEGATIVE AND IS REPORTED BECAUSE IT PRODUCED A MECHANISM.** Unmounting only the
parent bind is **healed by the agent within ~60 s** (`/dev/sdb` is still mounted at `/mnt/hdd_1`), so
the drive gate's startup reconcile re-attached and restarted the apps at `17:18:47` — **one second
before** the sweep looked at `17:18:48` and logged `no boot-orphaned apps`. Reporting that as a
disproof would have been wrong: it is a race that went the safe way. Run 2 held **both** mounts off
for the duration and reproduced the defect immediately.
**The confirmation moved the severity in both directions.**
- The **write** hazard did NOT materialise. Compose failed with
`mkdir /mnt/felhom-drives/hdd_1/userdata: permission denied`; `find` showed only the bare directory
and `df -h /` was unchanged at `25G / 28%` before and after. The mechanism: with the drive unbound
the mountpoint is **host-root-owned** (`uid=0 gid=0 mode=755`) and guest 9201 is an **unprivileged**
LXC, so container root (uid 100000) cannot create the subdirectory. **This protection is accidental**
— no code chose it, no test pinned it, and it depends on the guest staying unprivileged and the
mountpoint staying root-owned (when the drive IS bound, that same path shows `uid=100000`). One
`chown` away from gone, and its removal would be invisible until data landed on the wrong disk.
- The harm that **did** occur was not in the hypothesis and is real on every box: two wasted attempts,
a leftover `Created` container per attempt, and a **false dead-app alarm for an app the drive gate
is deliberately holding** — the noise class R-97/F-A1 exist to prevent.
**A second asymmetry, found while restoring the box:** the API's own start path already refuses this —
`{"ok":false,"error":"A(z) /mnt/felhom-drives/hdd_1 tárhely jelenleg nem elérhető …"}` from
`startGatedByMissingDrive`. The rule existed; the sweep bypassed it by calling `Manager.StartStack`
directly. Full evidence: `felhom.eu/documentation/audits/DIAG-bootrecon-drive-absent-2026-08-02.md`.
**Consequence:** Part 3 applied and was implemented **first**, before the window widened.
## 3. Files modified / created; commits
**Created:** `controller/internal/bootrecon/drivegate_test.go`,
`controller/cmd/controller/bootwindow_test.go`, `controller/internal/web/recreate_intent_test.go`,
`felhom.eu/documentation/audits/DIAG-bootrecon-drive-absent-2026-08-02.md`
**Modified:** `bootrecon/bootrecon.go` (StartGate seam, held filter, `Result.HeldByDrive`),
`cmd/controller/main.go` (settle window, `sampleBootFleet`, `recordLateRecovery`, `bootDriveGate`,
wiring), `stacks/deploy.go` (`Manager.DriveLive`), `backup/appstop_marker.go` (`HeldStacks`),
`web/intermediary.go` (`shouldRecreateOnBoot` + `bootStack.desired` + counters),
`web/intermediary_test.go`, `cmd/controller/appstop_wiring_test.go`, `CHANGELOG.md`, `CONTEXT.md`,
`REUSE.md`, `controller/README.md`; `felhom.eu`: `CONTEXT.md` (S-13), `STATUS.md`,
`architecture/00-capability-map.md`, `architecture/02-controller-module-map.md`,
`backlog/OPEN-ITEMS.md`, `backlog/ROADMAP.md`
| Repo | Commit | Subject |
|---|---|---|
| `felhom-controller` | `582135f` | v0.190.0 — the boot settle window, both gates on intent, and R-171 |
| `felhom-controller` | `dcc3363` | boot window: sample REFRESHES first — a cached fleet made 'settled' meaningless |
| `felhom-controller` | `4bad6e0` | CHANGELOG: the boot window's sample refreshes first |
| `felhom.eu` | `ad28699` | docs: R-157 A / R-170 / R-171 closed — boot recovery finished |
Direct to `main`, no branches, no `Co-Authored-By`. Pre-push hook green; **`--no-verify` NOT used.**
## 4. Tests and red-proofs
**27/27 packages green; +25 test functions across 3 packages.** `go build ./... && go vet ./... &&
go test ./...`**rc=0**. Timing is tested by shrinking the window constants — **never by sleeping**.
Test runs and commits were never combined in one command.
Every red-proof observed **FAIL**, then reverted with a passing control run.
| # | Test | Mutation | Result |
|---|---|---|---|
| **A** | `TestBootWindow_LateSettlerIsSweptOnASettledFleet` | restored the single-sweep shape (deleted the sampling loop) | **FAIL** ✅ — the sweep was handed the `starting` frame |
| **B** | `TestBootWindow_BudgetEndsAForeverChangingFleet` | removed the `time.Since(started) < budget` condition | **FAIL** ✅ — *"did not terminate on a forever-changing fleet"* (a genuine hang; the fixture was changed to CYCLE first, because a fixture whose frames stop changing terminates by settling and would not have reached the hang) |
| **C** | `TestBootWindow_CustomerStoppedAppSurvivesEveryPass` | dropped the `DesiredStateStopped` branch from `isBootOrphan` | **FAIL** ✅ — *"started 2 time(s) by the widened window"* |
| **D** | `TestShouldRecreateOnBoot_IntentTable` + `_AgreesWithBootrecon` + `RecreateDriveBackedApps_Recorded` | restored `&& hasContainers` | **FAIL** ✅ (3 tests, incl. the cross-gate disagreement assertion) |
| **G** | `TestReconcile_DriveAbsentApp_IsNeverStarted` + `_UndeterminableDrive_` + `_HeldByAnyHolder_` | removed the start-gate check from `Run` | **FAIL** ✅ — *"an app whose data drive is ABSENT was started 1 time(s)"* |
| **H** | `TestMainWiresBootDriveGate` | **commented out** `SetDriveGate(...)` | **FAIL** ✅ — while `grep -c` still returned **1**, i.e. a `strings.Contains` test would have passed |
| **I** | `TestBootWindow_EverySampleRefreshesTheStatus` | removed `RefreshStatus()` from `sampleBootFleet` | **FAIL** ✅ — *"refreshed 0 time(s) for 4 samples"* |
**One defect in my own fix, caught by my own test:** `TestBootWindow_CommonCaseFitsInsideTheDeadAppGrace`
rejected the first budget at `5 + 60 + 30 = 95 s > 90 s`. The budget is 50 s **because a test said
so**, and the code comment records that rather than presenting the number as taste.
## 5. The window shape, and its justification against the 90 s grace
| Constant | Value | Why |
|---|---|---|
| `bootReconcileSample` | 5 s | fine enough to see a container settling at T+40 s within one sample; ~12 cheap calls on a quiet boot |
| `bootReconcileStableFor` | 3 identical samples (15 s) | one sample cannot tell "settled" from "sampled between two docker events"; three spans a container exiting and its restart policy re-creating it |
| `bootReconcileBudget` | 50 s | **binding constraint:** `settle 5 + budget 50 + one DefaultRetryDelay 30 = 85 s` < `deadAppBootGrace 90 s`, so a successful recovery stays SILENT |
Terminates on **whichever comes first** — settled, or budget — and the log says which, because
"settled and found nothing" and "ran out of time still churning" are different facts. Sampling is
read-only apart from the status refresh; exactly **one** sweep runs, on a settled fleet, with the
per-app attempt bound untouched. Sweeping per sample was rejected: the sweep's own `StartStack`
changes the fleet, so it would never observe a settled one.
**§8.3 chosen design: allow the window, report a late recovery.** `recordLateRecovery` emits a
`LATE RECOVERY` WARN naming the apps when a recovery lands past the grace. The grace was **not**
widened — that hides a late recovery rather than reporting it.
## 6. §8.2, row by row
| Stopped by | Sweep starts it? | How answered |
|---|---|---|
| the customer (`desired_state: stopped`) | **No** | already handled by `isBootOrphan`; **re-proven** — unit (`TestBootWindow_CustomerStoppedAppSurvivesEveryPass`, red-proofed) and live in **6/6** hard resets |
| a quiesce for a backup | **No** | **exclusion WIRED**`bootDriveGate.MayStart` consults `quiesce.SuppressedStacks()`, the set the quiesce loop already publishes for this exact question |
| the backup app-stop guard | **No** | **exclusion WIRED** — new read-only `AppStopGuard.HeldStacks()`. Its `Recover` completes before this goroutine starts, so a marker seen here belongs to an operation running **now**, not a crashed one |
| the drive-absent gate | **No** | **exclusion WIRED** — Part 3; settings flags (same signal as the API gate) **plus** the live `Manager.DriveLive` mountpoint check, because the flags can lag inside the boot window |
| an interrupted boot | **Yes** | the point of the change |
All three holders answer **one** seam because they differ only in the reason string. `TestReconcile_HeldByAnyHolder_IsNeverStarted` covers all three; none is answered by "it probably won't happen".
## 7. The hard-reset log — every run individually
**Shipped build (v0.190.0 with the refresh fix), the six that count:**
| Run | Window verdict | Apps back (immich · calibre-web · docmost) | `bookstack` (desired=stopped) |
|---|---|---|---|
| F1 | settled after **10 s** | all 3 ✅ | 0 containers ✅ |
| F2 | settled after **40 s** | all 3 ✅ | 0 containers ✅ |
| F3 | settled after **10 s** | all 3 ✅ | 0 containers ✅ |
| F4 | settled after **10 s** | all 3 ✅ | 0 containers ✅ |
| F5 | settled after **15 s** | all 3 ✅ | 0 containers ✅ |
| F6 | settled after **15 s** | all 3 ✅ | 0 containers ✅ |
**6/6 for both the recovery and the customer-stop.** An earlier six on the pre-refresh build were
also 6/6 (settle times 50/30/20/50/25/10 s) but are **not** counted as the deliverable, because the
build changed afterwards.
**The settle times are themselves the evidence for mechanism A:** the window waited 1050 s where the
old code decided at a fixed 5 s. Two pre-fix runs settled at 50 s — the full budget — i.e. the old
sweep would have decided 45 s too early.
**The sharpest evidence is a same-app, same-box before/after**, because 6/6 clean runs only show
nothing regressed:
```
pre-fix 18:08:35 boot window: fleet settled after 25s — sweeping
18:08:35 Boot reconciliation: no boot-orphaned apps (nothing to start) ← calibre-web had ZERO containers
post-fix 18:18:50 boot window: fleet settled after 10s — sweeping
18:18:50 Boot reconciliation: 1 boot-orphaned app(s) found: [calibre-web]
18:18:52 attempt 1/2: started "calibre-web" (took 1.7s)
18:18:52 complete: 1 app(s) recovered in 1 attempt(s): [calibre-web]
```
That miss is what exposed the cache defect in §4 (red-proof I).
## 8. Which gate reads what afterwards — both answer intent
**R-170 proven live in a single reboot**, both halves, on drive-backed apps with **zero containers**:
```
18:20:11 [gate] live bind confirmed — recreating drive-backed app calibre-web (state=stopped) onto /mnt/felhom-drives/hdd_1
18:20:12 [gate] 1 drive-backed app(s) left stopped on purpose (recorded Stop, or a legacy app.yaml at zero containers)
→ calibre-web desired=running containers=1 (recreated — pre-R-170 this was SKIPPED: hasContainers=false)
→ immich desired=stopped containers=0 (left alone)
```
The boot sweep then logged `no boot-orphaned apps` — the two gates agreeing rather than fighting.
Structurally, agreement is pinned from **both sides** against one identical fixture table
(`TestBothBootGatesAgreeOnIntent` in `bootrecon`, `TestShouldRecreateOnBoot_AgreesWithBootrecon` in
`web`), because an import cycle prevents calling the two from one package.
## 9. `OPEN-ITEMS.md` rows
- **R-157 → CLOSED** (both mechanisms), with the repeat count as evidence, not one clean boot.
- **R-170 → CLOSED**, with the live both-halves reboot.
- **R-171 → NEW and CLOSED the same session**, marked a regression from v0.189.0. **ID established
free before minting:** `grep -ro "R-171\b" documentation/ *.md`**0 hits**.
- `ROADMAP.md` collapsed to match; `STATUS.md`'s power-cut line moved from "What's broken" to "What
works right now" with the repeat count, plus one dated bullet.
## 10. Teardown and CI
**Provisioned nothing** — no VM, no guest, no scratch app, no storage. The apps used for validation
already existed and were **all restored**: `bookstack`, `immich`, `calibre-web`, `docmost` all
`desired=running` and running, 15 containers, controller `0.190.0` healthy. The drive is remounted
(`/dev/sdb` at both `/mnt/hdd_1` and `/mnt/felhom-drives/hdd_1`), and the temporary unmount-holder
loops are gone (`ps aux | grep -c '[u]mount …'`**0**). The credential-bearing helper was deleted
from the guest (`/root/act.sh`, `/tmp/act.sh`) and from DooPlex.
**CI — every push checked by run id and run number, matching `head_sha` to the commit:**
| Repo | Task id | Run number | `head_sha` | Status |
|---|---|---|---|---|
| `felhom-controller` | **21** | 6 | `582135f8` | **success** |
| `felhom-controller` | **22** | 7 | `dcc3363d` | **success** |
| `felhom-controller` | **23** | 8 | `4bad6e06` | **success** |
| `felhom-controller` | **24** | 9 | `e6311f9f` | **success** |
| `felhom.eu` | **25** | 12 | `ad286997` | **success** |
Pulled from the run list and polled until each left `running` — not inferred from the absence of a
failure e-mail, which is the check `felhom.eu/CLAUDE.md` now names.
## 11. Observations — noticed, documented, NOT acted on
1. **`Manager.StartStack` has no drive gate of its own**, and now has fourteen callers. The API path
guards it (`startGatedByMissingDrive`), the boot sweep now guards it (R-171), and the remaining
machine callers each decide for themselves. Pushing the check *into* `StartStack` was NOT done —
it would break the legitimate callers that must start an app on a drive the gate is mid-way
through re-attaching (the drive gate's own `Return` branch is one). Recorded because the next
person to add a caller needs to know the gate is per-caller.
2. **The agent heals an unmounted drive within ~60 s** while its block device is present. This is
correct behaviour and it is why the Part 0 diagnosis needed the drive held off, but it also means
**"unmount to simulate an absent drive" does not work on this platform** — worth knowing before
the next drive-absence test.
3. **The accidental permission protection** (§2) is untested and unowned. Not pinned by a test here
because a test asserting it would enshrine an accident; the fix removes the dependency on it
instead. If a privileged guest is ever shipped, this is the note to re-read.
4. **`recreateBootStaleApps` runs before the boot sweep and can fix the same app first**, which is
why several runs logged `no boot-orphaned apps` after the gate had already acted. Not a defect —
the gates agree — but it means the sweep's log alone under-reports how much recovery happened.