Files
felhom.eu/documentation/tests/campaign10-evidence-2026-07-31/r157-bootrecon-start-once-race.md
T
admin 1931dfcb0c Campaign 10: R-157 second mechanism — the zero-container case, which is SILENT
The 4th hard-reset failure had a different signature, verified not assumed: all of
rallly healthy, papra missing entirely with state=stopped deployed=True
containers=0. Zero containers is exactly what bootrecon deliberately never touches,
because the UI's Stop is compose down which removes containers - but a hard reset
landing during a compose operation produces the identical state. The signature the
safety rule depends on cannot distinguish the two.

Worse: in that state the deadapp check reported 0 currently down while a deployed
app was not running. No app_start_failed, no banner. That is the workspace's own
false-invariant #4 (F-CRIT-1, StateStopped assumed deliberate) recurring through a
hard reset rather than quiesce. NOT filed as new - CLAUDE.md already records it -
but confirmed live on 0.188.0 via a new path.

papra returned after ~15 min, later than the harness's 10-min window, so this
instance was slow rather than permanent and the doc says so. What restarted it is
not established.

Mechanism A (Exited, missed by the unsettled snapshot) alarms; mechanism B (zero
containers) is invisible on every channel. A settle-condition fix closes A only.
2026-08-02 05:35:57 +02:00

158 lines
9.0 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.
# R-157 — bootrecon's start-ONCE sweep acts on an unsettled snapshot, so the boot orphan it exists to recover survives
**INTERMITTENT — 3 failures in 6 hard resets (~50%), across two independent runs.** Controller
**0.188.0**, agent 0.119.0.
> **Correction to this document's first version.** It said the failure reproduced "at the same cycle
> in both runs — deterministic, not a coincidence". That was wrong, and the correction matters because
> it changes what kind of bug this is. The cycle numbers matched only because the runner's RNG is
> seeded, so both runs drew the same permutation; the *failure* is a coin flip. Run 2b's four hard
> resets went **PASS (c2) → FAIL (c10) → PASS (c18) → FAIL (c26)**, and run 2a went PASS (c2) →
> FAIL (c10). **Intermittency is what a race predicts** — a wrong predicate would fail every time —
> so this strengthens the root cause below rather than weakening it.
R-52 built `internal/bootrecon` for exactly this failure (audit F5: `immich-server` and `calibre-web`
left `Exited` after an interrupted boot, ten siblings back, those two **still down ~18 h later**
*"the controller REPORTED them (the 30 s deadapp-check) but never started them"*). This is that
failure recurring through a timing hole in the fix.
## What happened
Cycle 10's permutation ran `hard_reset_mid_write` — a `qm reset` of the VM during a backup.
Everything came back **except the app half of the DB-backed stack**:
| | |
|---|---|
| `rallly` | **`Exited (255)`**, `oom=false`, no error string, **`restarts=0`** |
| `rallly-postgres` | `Up (healthy)` |
| every other app | back and healthy, both drives bound |
| rallly's own last log line | `▲ Next.js 16.2.6 … ✓ Ready in 0ms` — it died **healthy** |
The controller start-up sequence, verbatim:
20:28:13 [stacks] ScanStacks complete: 55 stacks found (5 deployed, 50 available)
20:28:13 [stacks] Status refresh: 8 containers across 55 stacks
20:28:18 [bootrecon] Boot reconciliation: no boot-orphaned apps (nothing to start)
20:28:24 [stacks] Status refresh: 8 containers across 55 stacks
20:28:25 [stacks] Status refresh: 7 containers across 55 stacks <-- still churning
20:28:25 [stacks] Status refresh: 8 containers across 55 stacks
20:29:44 Event pushed: app_start_failed (warn) — Telepített alkalmazás nem fut: Rallly
20:39:14 [deadapp] check alive: 20 scans since boot, 5 deployed app(s) evaluated, 1 currently down
**`docker ps -a` reports 9 containers; every `Status refresh` reports 8.** The controller's boot-time
snapshot is one short, and the missing one is the exited `rallly`.
## Why this is a defect and not the documented safety boundary
bootrecon deliberately never touches a stack the customer stopped, and the predicate for that is
sound (`bootrecon.go:100`):
len(s.Containers) > 0 && stacks.IsDownState(s.State)
Both terms hold for this stack **once the system settles** — the controller's own API now reports:
rallly state=degraded deployed=true containers=2
rallly exited Exited (255)
rallly-postgres running Up (healthy)
`IsDownState` includes `StateDegraded` (`manager.go:55`), and `len(Containers)` is 2. So the predicate
was never the problem. **The snapshot was.** bootrecon fires as `go runBootReconcile(...)` at
`cmd/controller/main.go:236`, ~5 s after start, while docker is still bringing containers back — and
it is **start-once by design**, so it never re-evaluates.
Two mechanisms are consistent with the evidence and this report does not claim to distinguish them:
1. the exited container was not yet enumerated, so the stack looked `running` (1/1) rather than
`degraded` (1/2) — supported by the 8-of-9 count; or
2. the stack's state had not yet aggregated to `degraded` at that instant.
Either way the root is the same: **a single observation taken before the system settles, with no
re-check.**
## Consequence
The app stays down **indefinitely**. Detection works perfectly and recovery never happens — the
deadapp check correctly counted `1 currently down` across 20 scans / 10 minutes, and
`app_start_failed` reached the customer. In run 2a the app only returned because a *later* campaign
atom happened to redeploy the stack; nothing in the product recovered it.
This is the R-52 failure shape exactly: *an alarm with no recovery*.
## Why it is not a harness artifact
The preceding two violations in this campaign **were** harness defects and are documented as such
(`run2a-violations-were-harness.md`). This one is not:
- both drives were bound (`adatok: True`, `mentes: True`), so no drive gate stopped anything;
- every other app returned, including `calibre-web`, whose data is on an enrolled drive;
- only the app half of a two-container stack is missing, while its database is healthy;
- the fixed harness reported it through the check written for precisely this
(*"apps did not return within 10 min — that IS the failure"*), not through a seed or canary path;
- it recurred **3 times out of 6 hard resets** with an identical signature every time: `rallly`
`Exited (255)` with `rallly-postgres` healthy, `bootrecon` reporting "no boot-orphaned apps" ~5 s
after start, and the container count still churning **after** the sweep. Third occurrence
(2026-08-02 01:05): `Status refresh` 8 → bootrecon at 01:05:13 → refresh 8 → **7** → 8 at
01:05:19-20.
## Shape of a fix — not applied (the fences forbid it, and a fix mid-run proves a version that did not exist)
The bounded start-once property is the safety argument and should be kept. What is missing is a
**settle condition** before the one observation: wait for the container set to stop changing (or for
docker to report ready) before the sweep, or re-evaluate once at the end of `deadAppBootGrace` and
recover then, still bounded to the same total attempts. A test would pin the consequence — *an app
left Exited by an interrupted boot is running again before the grace expires* — rather than the
mechanism, per the workspace rule about invariants needing a test that fails when the dependency moves.
## Register
`R-52` is the feature; grep found **no existing item covering its timing**. `R-156` is this campaign's
papra finding. **R-157 is free and is claimed here.**
---
## Second mechanism, observed 2026-08-02 ~05:25 (run 2b cycle 34) — the zero-container case
The 4th hard-reset failure had a **different signature**, and it matters because it is not a race at
all. Verified rather than assumed (the two preceding non-R-157 violations in this campaign turned out
to be harness artifacts, so each occurrence is now checked):
all of rallly healthy this time; papra MISSING ENTIRELY
papra: state=stopped deployed=True containers=0
bootrecon 03:14:34: "no boot-orphaned apps" (refresh 7 → 6 → 7 after it, same churn)
`containers=0` is precisely the state bootrecon **deliberately never touches** — its documented safety
rule is *"a stack with ZERO containers is deliberately never touched"*, because the UI's Stop is
`docker compose down`, which removes containers. But a hard reset landing **during** a compose
operation produces the identical zero-container state. **The signature the safety rule relies on
cannot distinguish "the customer stopped this" from "an interruption caught it between containers".**
### And in this state the app is SILENT, not merely unrecovered
[deadapp] check alive: 20 scans since boot, 5 deployed app(s) evaluated, 0 currently down
`papra` was `deployed=True` and not running, and the deadapp check counted **0 down**. No
`app_start_failed`, no banner. This is the workspace's own false-invariant #4 recurring —
*"`StateStopped` means deliberately stopped by the user"* (F-CRIT-1), reached here through a hard
reset rather than through quiesce. **Not filed as new**: `CLAUDE.md` already records it. Confirmed
live, on controller 0.188.0, via a new path.
That makes the zero-container case **worse than the Exited case** this document opens with: the Exited
one at least alarmed (`app_start_failed`, `1 currently down`); this one is invisible on every channel.
### Recovery in this instance
`papra` did come back roughly 15 minutes after the reset — later than the harness's 10-minute window,
which is why the violation fired. **So this instance was slow, not permanent**, and the document does
not claim otherwise. What is not established is *what* restarted it: the campaign's own later atoms
are a candidate, and nothing in the logs attributes the recovery to a product mechanism.
## Summary — two mechanisms, one root
| | signature | bootrecon's view | alarmed? | observed |
|---|---|---|---|---|
| **A** | container `Exited (255)`, `state=degraded` | missed — snapshot taken before settle | yes (`app_start_failed`, `1 down`) | 3× |
| **B** | **zero containers**, `state=stopped` | deliberately skipped — matches a user Stop | **no — `0 currently down`** | 1× |
Both leave a `deployed: true` app not running after an interrupted boot, which is the exact condition
R-52 exists to eliminate. A fix that only adds a settle condition closes **A** and leaves **B** open.