R-379/R-380 docs: the failure ladder, the drill record, register housekeeping

07-backup-architecture.md 6.3 gains a dated [DESIGN] paragraph on replay -> rollback -> hold, including why no engine flag closes it: --single-transaction makes Postgres atomic, MariaDB DDL is not transactional, so the rollback is the fix and the flag is a belt. Drill record for the live walk, including the TWO defects the walk found in the fix itself (a rollback into a re-created container; an operator route that cleared the file while the running controller kept refusing) and the ONE red-proof that PASSED, which is reported rather than omitted. R-379..R-382 compressed into CLOSED-ITEMS.md. OPEN-ITEMS 330683 -> 325236 bytes. STATUS.md restates the outcome and names the next operator step.
2026-08-22 18:31:23 +02:00
parent 4e488321bf
commit a8caa0fdde
23 changed files with 744 additions and 75 deletions
@@ -0,0 +1,114 @@
+# DRILL — R-379/R-380: the rollback, proven live (2026-08-22)
+
+**Subject:** `demo-hp` (Tier 0), guest 9201. **Controller v0.220.0 → v0.220.1 → v0.220.2** during the
+walk — the walk itself found two defects and both were fixed and re-proven.
+**Method:** endpoint-level, the exact endpoints the UI's forms post to. No browser on DooPlex.
+**Subjects were FOUND, not rebuilt:** `docmost` (Postgres 16) and `bookstack` (MariaDB 12.3), left
+running with their planted data by the 2026-08-22 R-356b drill.
+
+## The ladder, proven rung by rung
+
+| step | subject | result |
+|---|---|---|
+| 1 | `docmost` (Postgres) | replay forced to fail → **rollback succeeded** → app healthy → data byte-identical |
+| 2 | `bookstack` (MariaDB) | same → **`migrations` back at 102 rows**, the exact cell R-380 was measured in |
+| 3 | `docmost` | both failed → **app held, not started**; every start path refused; survived a controller restart; cleared via the operator route |
+| 4 | `docmost` | clean restore → **no rollback, no hold**, proven with a working positive control |
+| 5 | `/backups/apps` | no phantom rows; the undo cap holds at 3 per app |
+
+**Step 1 data check.** Pre-restore: 4 pages, `ALTERED-VALUE-B`, titles sha256
+`8ec1fa8710c5ca08589161a2d930ede24a98c6b8ad3395308a90def21b68be19`. Post-restore: **identical on all
+three**.
+
+**Step 2 data check.** Pre: entities 1, users 2, migrations 102, book name hex
+`C3817276C3AD7A74C5B172C591206BC3B66E79766573706F6C6320E28094205233353662`, disc `ORIGINAL-VALUE-A`.
+Post: **identical on all five**.
+
+## The customer message, verbatim
+
+**257 bytes** (was 407 on this path, of which ~250 were engine output):
+
+> A teljes visszaállítás sikertelen: a(z) docmost adatbázisának visszaállítása sikertelen — az adataid
+> visszakerültek a visszaállítás előtti állapotba, az alkalmazás fut tovább. Ha újra megpróbálnád,
+> előbb vedd fel velünk a kapcsolatot
+
+Hex in `10-step1-message.txt`. **Judged, not just recorded:** it states the failure AND the recovery.
+A message reporting only the failure would leave a customer believing their data was gone when it is
+not. Checked for `ERROR:`, `LINE 1:`, `COPY public.`, `exit status`, `psql`, `INSERT INTO` — **all
+absent**.
+
+The held-app message (Scenario C), **verbatim**:
+
+> a(z) docmost adatbázisának visszaállítása sikertelen, és a korábbi állapot visszatöltése sem
+> sikerült. Az alkalmazást biztonsági okból LEÁLLÍTVA hagytuk, hogy az adatai ne sérüljenek tovább.
+> Vedd fel velünk a kapcsolatot — a korábbi állapot mentése megvan: pre-restore-…-docmost-postgres.sql
+
+## Scenario C in plain words
+
+**What a customer sees:** the app is stopped and stays stopped. Pressing start returns, in Hungarian,
+that the restore broke, the previous state could not be put back, the app is deliberately stopped so
+the data cannot be damaged further, and to contact us. The app's row is **red**, not green.
+
+**What an operator does:** `docker exec felhom-controller /usr/local/bin/felhom-controller
+--restore-holds` lists the app with both errors. After checking the data (the undo copies are in the
+app's unit `db-dumps/`), `--clear-restore-hold <app>` clears it — **and then the controller must be
+restarted**, which the command now says.
+
+## TWO DEFECTS THE WALK FOUND IN THE FIX ITSELF
+
+**1. The rollback used a dead container (v0.220.1).** `writeSafetyDump` captures its `DiscoveredDB`
+before the stop; the DB-only start re-creates the container. Measured: `docmost-postgres` captured as
+`9adbc14f9af6` at 16:05:44, re-created as `309795897b82` at 16:05:47, rollback's `docker exec` against
+the dead id sat in `waitDBReady` for 30 s. **So the app was HELD for an infrastructure reason while
+its data was perfectly recoverable** — the hold behaved correctly on a case that should never have
+reached it. **No unit test could see this: they all inject the import seam and never look at container
+identity.** Fixed by re-discovering and matching on `{stack, engine}`; a new test asserts the identity
+handed to the import, and its red-proof convicts.
+
+**2. The operator route did not take effect (v0.220.2).** `--clear-restore-hold` runs as a second
+process: it cleared `settings.json` correctly and the running controller went on refusing, because it
+holds its own in-memory settings. Found by using the route, not by reading it. The command now prints
+the restart it needs. The lost-update window between the two processes is recorded rather than hidden.
+
+## Red-proofs — eight planned, one PASSED
+
+| # | mutation | observed |
+|---|---|---|
+| 1 | remove the rollback entirely | 3 tests failed: "the undo copy must be re-applied exactly once, got 0" |
+| 2 | roll back only the first database | "BOTH databases must be rolled back, got 1" |
+| 3 | start the app anyway after a failed rollback | "the app was STARTED onto a half-written database" |
+| 4 | move the hold check below the driveless early return | "the hold check (line 1822) is AFTER the driveless early return (line 1820)" |
+| 5 | paste engine stderr back into the customer error | **PASSED — reported, not omitted.** See below |
+| 6 | delete the operator log line | "the engine stderr is no longer logged either" |
+| 7 | revert the undo naming | "must resolve to the app it belongs to, not a phantom; got `pre-restore-…-docmost`" |
+| 8 | prune keeps the oldest | "the newest 3 must survive; 20260401T000000Z is gone" |
+| 9 | use the captured container id | "the rollback used the CAPTURED container id 9adbc14f9af6" |
+
+**Red-proof 5 passed and that is a finding.** The R-381 behavioural test injects at `m.importDBDump`,
+i.e. BELOW `ImportDump`, so re-adding the stderr inside `ImportDump` could not fail it — the test was
+hollow for the layer the leak lives in. A guard was added at that layer (an AST assertion that the
+returned error does not carry the captured stderr, plus a positive control that it is still logged),
+and the mutation then convicted.
+
+## What did NOT reproduce
+
+**The undo copies rendering as apps on the customer's backup page.** The live page was read BEFORE any
+change and contained **zero** `pre-restore` strings while four such files sat on disk — with a
+positive control showing 8 real app rows and a database section. `buildAppBackupRows` iterates
+DEPLOYED apps and only reads the derived-name map by key, so a phantom name becomes a KEY and never a
+ROW. The phantom key was real and is fixed; the visible row was not. Their visibility is unchanged and
+remains deliberate.
+
+## Teardown — three layers
+
+1. **Nothing was provisioned.** `docmost` and `bookstack` were already on the box. Both are healthy at
+   the end, with their data byte-identical to the start.
+2. **No storage was added.** The undo copies are now capped at **3 per app** (was 4 and 2 growing),
+   and the cap was observed firing live: *"pruned old undo copy … (keeping the newest 3)"*.
+3. **No hub-side record was created.** No customer, no appliance. Nothing to dispose of.
+
+## Deliberately left open
+
+R-102 (the Tier-2 unit mirror read by nothing), R-359 (no readability check on the off-site store),
+R-361 (the app's own dump vanishing from the unit after a reconstitution — reproduced again here and
+still not fixed). Separate rows, untouched.
@@ -0,0 +1,14 @@
+== docmost PRE-RESTORE state
+  pages : 4
+  users : 1
+  disc  : ERROR:  relation "felhom_r356b_disc" does not exist
+LINE 1: SELECT marker FROM felhom_r356b_disc
+                           ^
+  titles (sha256 of the sorted set):
+8ec1fa8710c5ca08589161a2d930ede24a98c6b8ad3395308a90def21b68be19  -
+  per-title hex:
+    52333536422d504147452d312d73656e74696e656c
+    52333536422d504147452d322d73656e74696e656c
+    5c753030633172765c75303065647a745c7530313731725c753031353120745c75303066636b5c753030663672665c7530306661725c7530306633675c753030653970205c7532303134205233353662206472696c6c
+    c3817276c3ad7a74c5b172c5912074c3bc6bc3b67266c3ba72c3b367c3a970203220e28094205233353662
+ALTERED-VALUE-B
@@ -0,0 +1,3 @@
+size before: 141363
+size after : 62000
+tail: public; Owner: ---COPY public.felhom_r356b_discriminator 
@@ -0,0 +1,7 @@
+2026/08/22 16:05:41 auth.go:134: [DEBUG] [web] auth: valid session for POST /backup/offbox/reconstitute
+2026/08/22 16:05:41 server.go:393: [DEBUG] [web] ServeHTTP: POST /backup/offbox/reconstitute from 172.18.0.4:54196
+2026/08/22 16:05:44 offbox_reconstitute.go:200: [INFO] [offbox] docmost: pre-restore safety dump written → pre-restore-20260822T160544Z-docmost-postgres.sql (138.0 KB)
+2026/08/22 16:05:48 offbox_reconstitute.go:642: [ERROR] [offbox] docmost: database replay failed, rolling back to the pre-restore state: importing postgres dump for docmost: postgres import into docmost-postgres failed: exit status 3
+2026/08/22 16:05:48 offbox_reconstitute.go:349: [INFO] [offbox] docmost: rolling back to the pre-restore state from pre-restore-20260822T160544Z-docmost-postgres.sql
+2026/08/22 16:06:19 offbox_reconstitute.go:647: [ERROR] [offbox] docmost: ROLLBACK ALSO FAILED (a korábbi állapot visszaállítása sikertelen (docmost-postgres): waiting for docmost-postgres (postgres) readiness: timeout after 30s) — holding the app stopped; replay error was: importing postgres dump for docmost: postgres import into docmost-postgres failed: exit status 3
+2026/08/22 16:06:19 offbox_handlers.go:451: [ERROR] [web] off-box reconstitute docmost (async): a(z) docmost adatbázisának visszaállítása sikertelen, és a korábbi állapot visszatöltése sem sikerült. Az alkalmazást biztonsági okból LEÁLLÍTVA hagytuk, hogy az adatai ne sérüljenek tovább. Vedd fel velünk a kapcsolatot — a korábbi állapot mentése megvan: pre-restore-20260822T160544Z-docmost-postgres.sql
@@ -0,0 +1,7 @@
+=== operator CLI: --restore-holds
+docmost	held since 2026-08-22T16:06:19Z
+  replay error : importing postgres dump for docmost: postgres import into docmost-postgres failed: exit status 3
+  rollback err : a korábbi állapot visszaállítása sikertelen (docmost-postgres): waiting for docmost-postgres (postgres) readiness: timeout after 30s
+
+=== the CUSTOMER's start button (POST /api/stacks/docmost/start):
+{"ok":false,"error":"a(z) docmost adatainak visszaállítása 2026-08-22 16:06-kor megszakadt, és a korábbi állapotot sem sikerült visszatölteni. Az alkalmazás biztonsági okból leállítva marad, hogy az adatai ne sérüljenek tovább. Vedd fel velünk a kapcsolatot"}
@@ -0,0 +1,14 @@
+=== after a controller RESTART — did anything start the held app?
+docmost-postgres | Up 2 minutes (healthy)
+
+=== the boot sweep / Recover lines:
+2026/08/22 16:07:52 sync.go:371: [DEBUG] [sync] docmost/docker-compose.yml: hash match, skipped
+2026/08/22 16:07:52 sync.go:371: [DEBUG] [sync] docmost/.felhom.yml: hash match, skipped
+309795897b82	docmost-postgres	docmost	postgres:16-alpine
+2026/08/22 16:07:52 dbdump.go:176: [DEBUG] DiscoverDatabases: found postgres container: docmost-postgres (id=309795897b82)
+2026/08/22 16:07:52 dbdump.go:196: [DEBUG] DiscoverDatabases: docmost-postgres → stack=docmost, dbUser=docmost, dbName=docmost
+2026/08/22 16:07:52 [INFO] [stacks] ParseComposeHDDMounts: found 0 HDD mounts for /opt/docker/stacks/docmost/docker-compose.yml
+2026/08/22 16:07:52 recovery_unit.go:194: [INFO] [backup] Recovery unit captured for docmost → /mnt/sys_drive/felhom-data/backups/primary/docmost (images=3, secrets-referenced=2, data_keys=0, portable-carried=2/2, withheld=0)
+2026/08/22 16:07:52 offbox_reconstitute.go:256: [INFO] [backup] docmost: pruned old undo copy pre-restore-20260822T140501Z-docmost-postgres.sql (keeping the newest 3)
+2026/08/22 16:07:58 logscanner.go:69: [DEBUG] [metrics] logscanner: scanned docmost-postgres: errors=1 warnings=0 issues=1 (took 22ms)
+2026/08/22 16:08:02 healthprobe.go:162: [WARN] Health probe docmost: HTTP GET :3000/ → Get "http://docmost-postgres:3000/": dial tcp: lookup docmost-postgres on 127.0.0.11:53: no such host
@@ -0,0 +1,2 @@
+restore hold cleared for docmost — the app may be started again. Check its data first: the undo copies are in its unit's db-dumps dir.
+{"ok":false,"error":"a(z) docmost adatainak visszaállítása 2026-08-22 16:06-kor megszakadt, és a korábbi állapotot sem sikerült visszatölteni. Az alkalmazás biztonsági okból leállítva marad, hogy az adatai ne sérüljenek tovább. Vedd fel velünk a kapcsolatot"}
@@ -0,0 +1,3 @@
+4
+ALTERED-VALUE-B
+8ec1fa8710c5ca08589161a2d930ede24a98c6b8ad3395308a90def21b68be19  -
@@ -0,0 +1,8 @@
+2026/08/22 16:23:44 auth.go:134: [DEBUG] [web] auth: valid session for POST /backup/offbox/reconstitute
+2026/08/22 16:23:44 server.go:393: [DEBUG] [web] ServeHTTP: POST /backup/offbox/reconstitute from 172.18.0.4:41900
+2026/08/22 16:23:47 offbox_reconstitute.go:200: [INFO] [offbox] docmost: pre-restore safety dump written → pre-restore-20260822T162347Z-docmost-postgres.sql (138.0 KB)
+2026/08/22 16:23:51 offbox_reconstitute.go:690: [ERROR] [offbox] docmost: database replay failed, rolling back to the pre-restore state: importing postgres dump for docmost: postgres import into docmost-postgres failed: exit status 3
+2026/08/22 16:23:52 offbox_reconstitute.go:394: [DEBUG] [offbox] docmost: docmost-postgres was re-created during the restore (309795897b82 → 48817bfb454a) — rolling back into the live container
+2026/08/22 16:23:52 offbox_reconstitute.go:397: [INFO] [offbox] docmost: rolling back to the pre-restore state from pre-restore-20260822T162347Z-docmost-postgres.sql
+2026/08/22 16:23:53 offbox_reconstitute.go:402: [INFO] [offbox] docmost: rollback complete — 1 database(s) returned to the pre-restore state
+2026/08/22 16:24:04 offbox_handlers.go:451: [ERROR] [web] off-box reconstitute docmost (async): a(z) docmost adatbázisának visszaállítása sikertelen — az adataid visszakerültek a visszaállítás előtti állapotba, az alkalmazás fut tovább. Ha újra megpróbálnád, előbb vedd fel velünk a kapcsolatot
@@ -0,0 +1,11 @@
+=== app state:
+docmost | Up 29 seconds (healthy)
+docmost-redis | Up 39 seconds (healthy)
+docmost-postgres | Up 43 seconds (healthy)
+=== POST-RESTORE data (must equal the pre-restore state exactly):
+4
+ALTERED-VALUE-B
+8ec1fa8710c5ca08589161a2d930ede24a98c6b8ad3395308a90def21b68be19  -
+  expected: 4 / ALTERED-VALUE-B / 8ec1fa8710c5ca08589161a2d930ede24a98c6b8ad3395308a90def21b68be19
+=== was a hold written? (must be none)
+restore_holds = None
@@ -0,0 +1,15 @@
+=== CUSTOMER MESSAGE, VERBATIM (Postgres, rollback succeeded) ===
+A teljes visszaállítás sikertelen: a(z) docmost adatbázisának visszaállítása sikertelen — az adataid visszakerültek a visszaállítás előtti állapotba, az alkalmazás fut tovább. Ha újra megpróbálnád, előbb vedd fel velünk a kapcsolatot
+
+=== UTF-8 hex ===
+412074656c6a657320766973737a61c3a16c6cc3ad74c3a1732073696b657274656c656e3a2061287a2920646f636d6f7374206164617462c3a17a6973c3a16e616b20766973737a61c3a16c6cc3ad74c3a173612073696b657274656c656e20e2809420617a206164617461696420766973737a616b6572c3bc6c74656b206120766973737a61c3a16c6cc3ad74c3a17320656cc59174746920c3a16c6c61706f7462612c20617a20616c6b616c6d617ac3a1732066757420746f76c3a162622e20486120c3ba6a7261206d65677072c3b362c3a16c6ec3a1642c20656cc591626220766564642066656c2076656cc3bc6e6b2061206b617063736f6c61746f74
+
+=== byte length: 257
+
+=== engine-output leak check:
+   ERROR:         present: False
+   LINE 1:        present: False
+   COPY public.   present: False
+   exit status    present: False
+   psql           present: False
+   INSERT INTO    present: False
@@ -0,0 +1,5 @@
+  entities  : 1
+  users     : 2
+  migrations: 102
+  book hex  : C3817276C3AD7A74C5B172C591206BC3B66E79766573706F6C6320E28094205233353662
+  disc      : ORIGINAL-VALUE-A
@@ -0,0 +1,6 @@
+2026/08/22 16:25:56 offbox_reconstitute.go:200: [INFO] [offbox] bookstack: pre-restore safety dump written → pre-restore-20260822T162555Z-bookstack-mariadb.sql (57.4 KB)
+2026/08/22 16:26:05 offbox_reconstitute.go:690: [ERROR] [offbox] bookstack: database replay failed, rolling back to the pre-restore state: importing mariadb dump for bookstack: mariadb import into bookstack-db failed: exit status 1
+2026/08/22 16:26:05 offbox_reconstitute.go:394: [DEBUG] [offbox] bookstack: bookstack-db was re-created during the restore (0f251288ec4a → e5895283fa31) — rolling back into the live container
+2026/08/22 16:26:05 offbox_reconstitute.go:397: [INFO] [offbox] bookstack: rolling back to the pre-restore state from pre-restore-20260822T162555Z-bookstack-mariadb.sql
+2026/08/22 16:26:06 offbox_reconstitute.go:402: [INFO] [offbox] bookstack: rollback complete — 1 database(s) returned to the pre-restore state
+2026/08/22 16:26:08 offbox_handlers.go:451: [ERROR] [web] off-box reconstitute bookstack (async): a(z) bookstack adatbázisának visszaállítása sikertelen — az adataid visszakerültek a visszaállítás előtti állapotba, az alkalmazás fut tovább. Ha újra megpróbálnád, előbb vedd fel velünk a kapcsolatot
@@ -0,0 +1,5 @@
+  entities  : 1
+  users     : 2
+  migrations: 102
+  book hex  : C3817276C3AD7A74C5B172C591206BC3B66E79766573706F6C6320E28094205233353662
+  disc      : ORIGINAL-VALUE-A
@@ -0,0 +1,15 @@
+=== the run:
+2026/08/22 16:27:37 offbox_reconstitute.go:722: [INFO] [offbox] reconstituted docmost from snapshot 750b7b4d: 0 file(s) placed, 3 volume(s) replayed, 1 DB dump(s) replayed, safety dump=pre-restore-20260822T162708Z-docmost-postgres.sql, skewed=false
+=== ABSENCE CLAIMS — no rollback, no hold:
+  rollback lines in this run: 3
+  restore_holds: None
+=== This run's window: safety dump 16:27:08 → reconstituted 16:27:37
+=== every 'rolling back' line today, with timestamps:
+    2026/08/22 16:23:52 offbox_reconstitute.go:397: [INFO] [offbox] docmost: rolling back to the pre-restore state from pre-restore-20260822T162347Z-docmost-postgres.sql
+    2026/08/22 16:26:05 offbox_reconstitute.go:397: [INFO] [offbox] bookstack: rolling back to the pre-restore state from pre-restore-20260822T162555Z-bookstack-mariadb.sql
+
+=== POSITIVE CONTROL: the grep above finds rollback lines (it printed some).
+=== NEGATIVE: none of them falls between 16:27:08 and 16:27:37 — this run rolled back nothing.
+
+=== and the R-382 fix, visible on the same line:
+    2026/08/22 16:27:37 offbox_reconstitute.go:722: [INFO] [offbox] reconstituted docmost from snapshot 750b7b4d: 0 file(s) placed, 3 volume(s) replayed, 1 DB dump(s) replayed, safety dump=pre-restore-20260822T162708Z-docmost-postgres.sql, skewed=false
@@ -0,0 +1,12 @@
+=== LIVE /backups/apps on 0.220.2
+  'pre-restore' occurrences on the page : 0
+  real app rows (positive control)      : bookstack docmost kimai privatebin 
+  undo copies on disk right now         : 6
+
+  So: undo copies exist, the page renders real apps, and no phantom row appears.
+  The reported symptom did NOT reproduce on v0.219.0 either — it was read on the live page
+  BEFORE any change was made. What was real was the phantom map KEY, now fixed.
+
+=== the prune cap in force (max 3 per app):
+  docmost    3 undo copies
+  bookstack  3 undo copies