admin/felhom-controller
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity
Files
b30e2e5a2827f3e8474c49c8b6786c453089cc25
felhom-controller/REPORT.md
T
admin b30e2e5a28 docs: C6 destructive drill PASSED + R-23(a) evidence banked 
C6: operator deleted the photos, EMPTIED THE TRASH, then restored through
the customer UI. 40 files placed (vs 6 in the non-destructive run) — the
files were really gone and really came back. 11 assets active, no schema
drift, timeline confirmed. Full UI path, no endpoint shortcuts.

R-23(a): the STOP-2 floor save turned out to be exactly the trigger. Hub set
the floor at 18:56:27 CEST; the controller logged 'wait woke: generation=1'
at 16:56:27 UTC — the same second — with the out-of-cycle report 2s later.
The wake is logged at DEBUG only, so it is invisible in docker logs and
lives only in the debug ring.

R-23(a) is NOT complete: the floor was set to a version the box already ran,
so nothing restarted and the restart-single-fire assertion is unexercised.
2026-07-20 19:22:11 +02:00

315 lines
20 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 — R-47: the DB replay must not race the app (both restore paths) · felhom-controller v0.153.0
**Date:** 2026-07-20 · **Repo:** `felhom-controller` (v0.152.0 → **v0.153.0**) · Trunk, pushed to
`main`. · **Baseline:** `main` @ `fd40b29` (clean, equal to `origin/main` at session start)
---
## 1. What was wrong
`felhom.eu/documentation/audits/DIAG-immich-restore-round2-2026-07-19.md`, finding **H4**. The
offsite reconstitution ran its designed sequence — safety dump → stop → start → replay — and the
replay aborted:
```
10:58:25 controller: replaying DB dump into immich-postgres
10:58:33 immich-server: "Reindexing clip_index" -> "Reindexed clip_index"
10:58:35 controller: ERROR relation "clip_index" already exists - exit status 3
```
`ImportDump` needs a running database container, so the code started the WHOLE stack first. That gave
the application an eight-second window to rebuild the very schema objects the dump was about to
create; under `ON_ERROR_STOP=1` the collision aborted the script. The data survived only because
`pg_dump` emits COPY before CREATE INDEX — a collision earlier in the script would have left a
genuinely half-restored database and reported it identically.
**Class defect.** The local `RestoreFromRecoveryUnit` had the same start-then-replay shape, hidden
inside `RecreateStackFromUnit` (which ended in a full `compose up -d`). Both are fixed here.
## 2. What was built
**Part 1 — the seams**
| Change | File |
|---|---|
| `dbTypeForImage` extracted from `DiscoverDatabases` (behaviour byte-equivalent) and shared | `internal/appbackup/dbdump.go`, `internal/appbackup/dbservices.go` (new) |
| `DBServiceNames(composePath)` — sorted compose SERVICE names holding a DB; yaml.v3 `services:` map parse | `internal/appbackup/dbservices.go` (new) |
| `Manager.StartStackServices(name, services)` — scoped `up -d`, **refuses an empty list** | `internal/stacks/manager.go` |
| `RedeployFromEnv` split; persist half is `PersistUnitRedeployConfig` (starts nothing) | `internal/stacks/deploy.go` |
| `StackDataProvider`: `RecreateStackFromUnit` → `RecreateStackDefinitionFromUnit` (+ `StartStackServices`) | `internal/appbackup/appdata.go` |
| Adapter: definition-only recreate + delegation | `cmd/controller/main.go` |
| `DBServiceNames` forwarder | `internal/backup/appbackup_bridge.go` |
**Part 2 — offsite** (`internal/backup/offbox_reconstitute.go`): DB services resolved from the LIVE
compose before any mutation; fail-closed refusal when a DB exists but no service is identifiable;
sequence is now **stop → files → `StartStackServices(dbServices)` → replay → `StartStack` (full) →
health wait**; both failure exits from the window do a best-effort full start.
**Part 3 — local** (`internal/backup/restore_unit.go`): DB services resolved from the UNIT's compose
(it is about to become the live one) plus `hasReplayableDump` (excludes `pre-restore-` safety dumps);
same fail-closed gate before the first mutation; sequence is now **stop → volumes →
`RecreateStackDefinitionFromUnit` → `StartStackServices` → replay → `StartStack` (full) → health
wait**, with the pre-existing `dataErr` / "completed with data errors" semantics preserved.
Untouched, as specified: `restore_db.go`, `ImportDump`, `waitDBReady`, the dump flags
(`--clean --if-exists`, `ON_ERROR_STOP=1`), `mapOffsiteRestorePaths`, the copiers, the honesty
surfaces, `IsDownState`/alerting (R-51), and the agent/hub.
## 3. Tests — 19 new, Groups A–G
| Group | Test | Result |
|---|---|---|
| A | `TestReconstituteReplaysWithOnlyTheDBServiceUp` — order **plus state-at-replay-time** | PASS |
| A | `TestReconstituteReplaysDBAndOrdersOperations` (existing, sequence assertion updated) | PASS |
| B | `TestReconstituteNoDBAppNeverStartsServicesOnly` — negative, zero scoped starts | PASS |
| C | `TestReconstituteRefusesWhenNoDBServiceIdentifiable` — zero-mutation effect | PASS |
| C | `TestRestoreFromUnitRefusesWhenNoDBServiceIdentifiable` — zero-mutation effect | PASS |
| D | `TestRestoreFromUnitReplaysWithOnlyTheDBServiceUp` | PASS |
| D | `TestRestoreFromUnitNoDumpsTakesOneFullStart` | PASS |
| D | `TestRestoreFromUnitIgnoresSafetyDumpsWhenDecidingToReplay` | PASS |
| E | `TestReconstituteReplayFailureStillBringsTheStackUp` | PASS |
| E | `TestReconstituteDBOnlyStartFailureStillBringsTheStackUp` | PASS |
| E | `TestRestoreFromUnitReplayFailureStillBringsTheStackUp` | PASS |
| F | `TestDBTypeForImage`, `TestDBServiceNames` (8 sub-cases), `TestDBServiceNames_TopLevelKeysAreNotServices`, `TestDBServiceNames_UnreadableAndUnparseableError`, `TestDiscoverAndComposeAgreeOnTheSameImages` | PASS |
| G | `TestStartStackServicesRefusesEmptyList`, `TestPersistUnitRedeployConfigPersistsWithoutStarting`, `TestPersistUnitRedeployConfigRejectsUnknownStack` | PASS |
The core assertion is deliberately not "no error": a recording provider captures whether the FULL
stack had been started at the moment the import fired. Asserting only `err == nil` passes on the
pre-fix shape — which is exactly how this shipped.
The compose-parser decoys use the catalog's REAL immich template shape (`immich_ml_cache:`,
`immich_postgres_data:` as top-level `volumes:` keys, `ghcr.io/immich-app/postgres:16-vectorchord…`
as the pin) — the exact input a line scan would misread.
### Companion red-proofs — three run, all reverted, tree clean
| # | Pre-fix shape restored | Failure observed |
|---|---|---|
| 1 | offsite: `StartStackServices` → full `StartStack` before the replay | `TestReconstituteReplaysWithOnlyTheDBServiceUp`: *"the database service was NOT started before the replay"*; `TestReconstituteReplaysDBAndOrdersOperations`: sequence `"stop,start,start"` |
| 2 | local: full `StartStack` inserted before the replay | `TestRestoreFromUnitReplaysWithOnlyTheDBServiceUp`: *"the FULL stack was already up when the replay fired — the H4 race, on the local path"* |
| 3 | both fail-closed gates deleted | both `RefusesWhenNoDBServiceIdentifiable` tests: *"expected a refusal…"* |
### Green gate
`go build ./... && go vet ./... && go test ./...` — **23/23 packages green**, exit 0
(`internal/backup` 174 s). New tests by package: backup +11, appbackup +5, stacks +3.
## 4. Deployment
Built + pushed from the clean tree at `78ff991`: `gitea.dooplex.hu/admin/felhom-controller:0.153.0`,
digest `sha256:cc02c950c47456dac01aa754f23befbdfb3d4897b0a9863aafa3589cff95b8ab`. Deployed to guest
9201 via the bootstrap path (pull → `/etc/felhom-controller-image` → restart bootstrap service).
Verified: `gitea.dooplex.hu/admin/felhom-controller:0.153.0 | Up (healthy)`, clean startup, and
`Event pushed: controller_started (info) — Controller elindult (0.153.0)`.
## 4b. STOP-1 — supervised live leg: **PASSED** (2026-07-20, operator present)
Method: **endpoint-level** — the exact endpoints the UI posts to, driven with an authenticated
session inside the guest (no browser on DooPlex; no state hand-setting, no `docker exec` shortcut
around the pipeline). App: **immich** (a real DB-indexed app), snapshot `49e7cb46` — the SAME
snapshot that aborted in round 2.
Baseline before the run: **11 assets, all `active`**.
1. `POST /backup/offbox/restore` `app=immich mode=full confirm=1` → 302; scratch staged
**15:30:08 UTC**: `restored immich (49e7cb46, full=true) → …/backups/offsite-restore/immich`.
2. `POST /backup/offbox/reconstitute` `app=immich confirm=1` → 302, fired **15:39:36 UTC**.
**Controller log — the ordering, live:**
```
15:39:42 [offbox] immich: pre-restore safety dump written -> pre-restore-20260720T153941Z-immich-postgres.sql (49.9 MB)
15:39:42 [stacks] Stopping stack: immich
15:39:43 [stacks] Starting stack immich services only: [immich-postgres] <- THE FIX
15:39:43 [backup] Restore immich: replaying DB dump into immich-postgres (postgres)
15:40:03 [backup] Restore immich: replayed 1 DB dump(s) <- rc-0, 20 s
15:40:03 [stacks] Starting stack: immich <- full start, only now
15:40:27 [offbox] reconstituted immich from snapshot 49e7cb46: 6 file(s) placed,
1 DB dump(s) replayed, safety dump=pre-restore-…, skewed=false
```
**Verification through the system's own surfaces:**
| Check | Round 2 (v0.148.0) | This run (v0.153.0) |
|---|---|---|
| `already exists` / replay abort | `ERROR relation "clip_index" already exists` (exit 3) | **none** — replay exited 0 |
| App up during replay | yes (immich-server rebuilt `clip_index` mid-replay) | **no** — only `immich-postgres` was up |
| Operation outcome | reported FAILURE | **success**, `dbs=1` |
| immich's own schema verdict | **schema drift** reported | **`No schema drift detected`** — twice (Microservices + Api) |
| Assets | 11 (recovered by luck of `pg_dump` ordering) | **11, all `active`** |
| Containers | — | all four immich containers `Up (healthy)` |
| `public` indexes | incomplete (aborted script) | **231** |
The decisive line is `Starting stack immich services only: [immich-postgres]` followed by a replay
that exits 0 — the window in which H4 occurred no longer exists. The DB service name was resolved
from the LIVE compose by `DBServiceNames`, unassisted.
Credentials handling per GL-1: the operator's password was supplied file→file, never echoed, and the
file plus both cookie jars (host and guest) were shredded at the end of the run.
## 4c. Phase C — golden **0.153.0** baked and published (2026-07-20)
Probes first, all before any mutation:
| Probe | Result |
|---|---|
| **P1** — read `180:/mnt/5_hdd/felhom.eu/drill/bake-0.146.0.log` end to end | recipe extracted: `pct`-based LXC 9100 on felhom-pve, args `9100 <template> local-lvm local vmbr0 <controller-image>`, creds via `REGISTRY_USER`/`REGISTRY_TOKEN`, publish to the gitea generic package registry |
| **P2** — build environment matches the log's starting point | 9100 absent (clean slate ✓); local-lvm 277 G / local 80 G free ✓; **DEVIATION: the Debian 13 template cache was EMPTY** (the 0.146.0 bake had it cached) |
| **P3** — registry reachable from the vacation site (**load-bearing**) | **PASS.** `gitea.dooplex.hu` → `37.191.56.193` (public path); registry `/v2/` → 401 (alive, auth-gated); gitea API → 200; Docker Hub `/v2/` → 401. Independently corroborated: guest 9201 pulled `felhom-controller:0.153.0` from that registry the same afternoon |
**P2 deviation, handled explicitly:** `pveam download local debian-13-standard_13.6-1_amd64.tar.zst`
(129 954 319 B, checksum verified, 22 MB/s). This is the ONE departure from the 0.146.0 recipe and
it is environmental, not a build-golden defect. Operator approved before it ran.
Bake: `build-golden.sh` **v2.1.0** (confirmed on the host copy), run **detached under `setsid`+`nohup`**
so an SSH blip over the tailnet could not orphan a half-built guest. Controller image
`gitea.dooplex.hu/admin/felhom-controller:0.153.0`.
### Gate table — vs the 0.146.0 row
| Gate | 0.146.0 | **0.153.0** |
|---|---|---|
| Script version | v2.0.0 | **v2.1.0** |
| Docker in build guest | overlay2, separate `/var/lib/docker` + `/mnt/sys_drive` mounts | same ✓ |
| Controller image baked | 0.146.0 | **0.153.0** ✓ |
| **Infra images baked** | **3** (historical fallback list) | **4** — `traefik:v3.6.7`, `cloudflare/cloudflared:2026.6.0`, `gtstef/filebrowser:1.3.3-stable`, **`gitea.dooplex.hu/admin/felhom-samba:1.1.0`** ✓ |
| Source of the infra list | hard-coded fallback | **`--print-infra-images` from the 0.153.0 binary itself** — no WARN line in the log, so the fallback never fired |
| `docker image ls` inside the guest ⊇ that list | — | **verified** — all four present, plus the baked controller |
| Archive | 584 MB | **618 MB**, volid `local:backup/vzdump-lxc-9100-2026_07_20-17_50_57.tar.zst` |
| Publish: pre-delete | HTTP 404 | **HTTP 404** ✓ |
| Publish: upload | HTTP 201 | **HTTP 201** ✓ |
| Anonymous GET + byte-match | — | **HTTP 200, 648 549 366 B, sha256 matches exactly** ✓ |
| Ranged request (resumable restore) | — | **HTTP 206**, 1024 B ✓ |
| Hub can fetch it from its own network position | — | **verified** — `wget` from the `hub-…` pod exits 0 |
```
GOLDEN_VERSION=0.153.0
GOLDEN_SHA256=15fdd191f3c660a60dc8651111053dd84281aeebc6c4c0f9ecdd3a87cb45a9d0
```
**GL-1 teardown:** the token was written to a `0600` env file via STDIN (never in argv on either
host), sourced by the detached run, and **shredded**. Token-leak grep over the bake transcript
(host copy and the retained copy) = **0**; the build guest holds no registry credential; build guest
9100 left **stopped** (destroy with `pct destroy 9100 --purge`); the 618 MB local verification copy
was deleted. Log retained beside its predecessor: `180:/mnt/5_hdd/felhom.eu/drill/bake-0.153.0.log`.
**Honest scope note:** I verified the golden artifact is published, byte-correct and fetchable *by
the hub*. I did **not** render the hub's golden **dropdown** — that is the password-gated operator
UI, and it remains part of STOP-2.
## 4d. STOP-2 — hub saves: **DONE** (operator, 2026-07-20)
Both password-gated saves applied in the correct order and confirmed by screenshot:
| Setting | Value |
|---|---|
| Day-0 artifact — Golden | **0.153.0**, sha256 `15fdd191f3c660a60dc8651111053dd84281aeebc6c4c0f9ecdd3a87cb45a9d0` (matches the bake exactly) |
| Day-0 artifact — Agent | 0.90.0 (unchanged) |
| Min agent | 0.90.0 (unchanged — v0.153.0 declares no coupling) |
| Managed-updates global floor | **v0.153.0**, source `DB (hub_settings)`, saved **last** ✓ |
**Agent 0.90.1 is absent from the dropdown — correct, not a defect.** It was built on the old
Windows workstation but **never published**: `felhom-agent/0.90.1` in Gitea returns **404** (0.90.0
returns 206), and felhom-pve reports `felhom-agent 0.90.0`. The hub lists only published versions.
The v0.90.1 source IS committed (`9596d5a`, the R-39 `pvesm set --server` hotfix), so shipping it is
a build+publish away — tracked under R-39, out of scope here.
Build guest **9100 destroyed** (`pct destroy 9100 --purge`, all three LVs removed); only 9201
remains on the host.
## 4e. C6 — the DESTRUCTIVE customer-restore drill: **PASSED** (operator, 2026-07-20)
This is the run that today's earlier reconstitute could not be: **data was genuinely destroyed
first.** Operator deleted the photos in immich's own UI and **emptied the trash** (the step whose
absence makes a drill prove nothing), then ran the restore from the customer-facing UI —
„Teljes visszaállítás (fájlok + adatbázis)" on `/backups/restore`.
```
17:13:42 [offbox] immich: pre-restore safety dump written (49.6 MB)
17:13:42 [stacks] Stopping stack: immich
17:13:42 [stacks] Starting stack immich services only: [immich-postgres]
17:13:43 [backup] Restore immich: replaying DB dump into immich-postgres (postgres)
17:14:03 [backup] Restore immich: replayed 1 DB dump(s) <- rc-0
17:14:03 [stacks] Starting stack: immich
17:14:27 [offbox] reconstituted immich from snapshot 49e7cb46:
40 file(s) placed, 1 DB dump(s) replayed, skewed=false
```
**`40 file(s) placed` is the proof of destructiveness** — the 15:40 non-destructive run over an
already-good tree placed only 6. The files were really gone and really came back.
Verified after: **11 assets `active`**, all four containers healthy, immich's own DatabaseService
logged **`No schema drift detected`** (17:14:20), and the operator confirmed the photos are visible
in the timeline. Full UI path, no endpoint shortcuts — the customer's own buttons.
## 4f. R-23(a) — operator-UI save→apply round trip: **evidence banked** (2026-07-20)
Not a task deliverable; captured opportunistically because the STOP-2 floor save happened to be the
exact trigger R-23(a) needs, and the evidence was still in the debug ring.
| Source | Time | Event |
|---|---|---|
| Hub (CEST) | 18:56:27 | `Global controller-version floor set to "0.153.0"` |
| Controller (UTC) | **16:56:27Z** | `wait woke: generation=1 — firing out-of-cycle report` |
| Controller (UTC) | 16:56:29Z | `Building system report` |
`18:56:27 CEST` == `16:56:27 UTC` — **the same second**; the out-of-cycle report follows 2 s later.
The ring also shows `wait baseline generation=0` at startup (baseline recorded WITHOUT firing, as
designed) then `generation=1`, so the generation advanced past 0.
**The wake is `logx.Debugf`, so `docker logs` at INFO shows nothing** — this evidence exists only in
the debug ring (`GET /api/debug/logs?level=DEBUG`, never gated on `logging.level`). Anyone hunting
for it in stdout will wrongly conclude the box did not wake. That is arguably R-23(b)'s complaint
generalised: the Direction-2 path's most interesting moment is invisible at the default level.
**Still unproven, and R-23(a) is NOT complete:** the **self-restart** leg. The floor was set to
0.153.0 on a box already running 0.153.0, so there was no work to do and no restart — the
"restart **single-fire**, no storm, once the generation has advanced past 0" assertion remains
unexercised. Finish it by bumping the floor to a version the box does NOT yet run, with the debug
ring open, and asserting **exactly one** restart.
## 5. NOT yet live-validated — remaining human/supervised work
- ~~**STOP-1**~~ — **DONE 2026-07-20, PASSED.** See §4b for the log ordering, timestamps and the
before/after comparison against round 2. Residual: the immich **timeline screenshot** still cannot
be captured from here (no browser on DooPlex) — that one visual remains the operator's.
- ~~**Phase C**~~ — **DONE 2026-07-20.** Golden 0.153.0 baked, published, all gates green
(§4c). `GOLDEN_SHA256=15fdd191f3c660a60dc8651111053dd84281aeebc6c4c0f9ecdd3a87cb45a9d0`.
Housekeeping left for whoever is next at the host: `pct destroy 9100 --purge`.
- ~~**STOP-2**~~ — **DONE** (§4d). Golden 0.153.0 + floor v0.153.0 saved in the right order.
- ~~**C6 destructive customer-restore drill**~~ — **DONE 2026-07-20, PASSED** (§4e): trash emptied,
restored through the customer UI, 40 files placed, 11 assets back, no drift.
- **R-23(a) — PARTIALLY banked** (§4f). Save→wake→report proven to the same second. **The
self-restart single-fire leg is still open**: bump the floor to a version the box does NOT run,
with the debug ring open, and assert exactly one restart.
- **R-48 — restore-page layout still janky** (operator-confirmed again 2026-07-20 during the C6 run:
the overlong button row persists). Unchanged by this task and still the highest-value UX item on
that page, since it is the finding that CAUSED the round-1 incident.
## 6. Observations (out of scope, recorded not acted on)
- **The `pre-restore-` prefix is load-bearing in three separate places** (the replay's exact-name
match, `OffsiteScratchPair`'s dump sniff, and now `hasReplayableDump`) with no shared predicate
deciding "is this file a replay source". A fourth consumer that forgets the exclusion would arm the
DB-only window for an app that has nothing to replay. Worth a single helper at some point.
- **`reimportDBDumpsFrom`'s own `hasDump` scan does NOT exclude the safety prefix** (unchanged here —
`restore_db.go` was explicitly out of scope). Harmless today because the per-DB lookup is an exact
`<stack>-<dbtype>.sql` match, so a directory holding only safety dumps merely produces the
"no matching running DB container" WARN instead of a clean zero.
- **`dbTypeForImage` maps both `mysql` and `mariadb` to `DBTypeMariaDB`.** Pre-existing and correct
for the current catalog (the `mariadb` client speaks to both), but it is an assumption, not an
invariant, and it is now written down in one place instead of two.
- **`RedeployFromEnv` has no end-to-end test** (it shells out to compose), so the split's equivalence
is asserted on the persist half only. That is the half the split could break; the tail is
byte-identical code that was moved, not rewritten.
- **R-29a (`estimate.go` gate finding)** remains open and was not touched.
- **CORRECTION to an earlier claim in this session.** Mid-run I reported that the controller password
in `180:~/.config/credentials` was **stale** and had been superseded by the customer-claim flow.
**That was wrong.** The values in that file are single-quoted (`PASSWORD='…'`) and my
`cut -d= -f2-` extraction kept the quotes, so a 15-character string with literal `'` on both ends
was sent instead of the 13-character password. Re-tested with the quotes stripped: `302` + session
cookie. The credential was correct the entire time; no rotation, no drift, nothing to reconcile.
The lesson recorded in memory is the general one: **an auth failure is evidence about the bytes you
sent, not proof about the stored secret** — a 2-character length discrepancy is this bug's
signature, and it was stated confidently three times before being caught.
Reference in New Issue View Git Blame Copy Permalink