diff --git a/documentation/audits/DRILL-chaos-night-2026-09-17.md b/documentation/audits/DRILL-chaos-night-2026-09-17.md index d246a565..2b6a502e 100644 --- a/documentation/audits/DRILL-chaos-night-2026-09-17.md +++ b/documentation/audits/DRILL-chaos-night-2026-09-17.md @@ -142,10 +142,42 @@ whole lifecycle on a box nobody had set up for the test. tonight's guide meets a stderr fragment about a `-storage` flag, while every page urges them on. Filed **R-546** (P2). No product code was changed — this is a validation run. -## Phase 1 — the twelve rounds +## Phase 1 — the rounds + +Rounds run at ~25-minute spacing. The schedule above is fixed; only the wall-clock start moved, +because Phase 0 ran long (the storage wizard submits by JavaScript and the endpoint was worked out +rather than guessed). Round 1 began 23:07 CEST. + +### Round 1 — `offsite-run` / adventurelog / accident: **nothing** (control round) + +| the five things | | +|---|---| +| what the customer saw | „A távoli mentés elindult — az állapot itt frissül." and, at the end, „A távoli mentési tároló elárvult: a benne lévő mentések egy korábbi, már nem elérhető kulccsal készültek (újratelepítés)." | +| what the box did by itself | walked all twelve apps — stop, dump each volume with real byte counts, restart — captured eleven, could not capture the one that was crash-looping, and finished | +| time to steady | **1m45s** (`last_duration`), `last_run` 21:09:00Z, `progress.active` false, `last_error` empty. A control round: the box never left steady | +| alarm fired / true? | **three, all true** — `app_start_failed` named Nextcloud · `backup_run_failures` „1 of 12 apps failed to back up in this nightly run: nextcloud" · `offbox_repo_orphaned`, matching the status endpoint's own `"orphaned": true` | +| should have fired, did not | **none** | + +**Household loop in the window:** 3 lines marked FAILED, **all three mine** — the loop counted the +dashboard's 301 redirect as a failure while accepting the same 301 for app reads. Fixed at 21:11:25Z +and marked in the log; only lines after that marker are scored. + +**What round 1 actually establishes.** The off-site tier is armed (escrowed) and the run works +end-to-end, but on THIS box — a rebuild for an existing customer — the remote repository was written +under a key the box no longer holds, so **no snapshot was written**. That is the documented rebuild +behaviour, surfaced honestly with the route out named in the message rather than reported as success. + +**Two things that looked like defects in this round and are not**, both established with controls +rather than inference — five front doors answering 404 (traefik has no route to an unhealthy +container; identical byte-for-byte to a no-such-host control) and a crash-looping Nextcloud (image +layers corrupted while my thin pool stood at 100 %; „invalid ELF header", repaired by a re-pull). +Detail in `evidence-chaos-night-2026-09-17/round-1-notes.txt`. + +### Rounds 2-12 PENDING + ## Phase 2 — the morning after PENDING diff --git a/documentation/audits/evidence-chaos-night-2026-09-17/round-1-notes.txt b/documentation/audits/evidence-chaos-night-2026-09-17/round-1-notes.txt index 51ebd9f5..7d2282f5 100644 --- a/documentation/audits/evidence-chaos-night-2026-09-17/round-1-notes.txt +++ b/documentation/audits/evidence-chaos-night-2026-09-17/round-1-notes.txt @@ -64,3 +64,119 @@ The only app that was broken is the only app that was named. were written under a key this box does not have. That is the documented rebuild behaviour („Guest rebuild orphans the off-site repo"), surfaced to the customer rather than hidden, with the route out named in the message. + +## The 404s, settled with controls — and my first explanation was WRONG +I first explained the five 404s as „my sweep ran while the backup was quiescing apps". After the +backup finished, four of the five were **still** 404, so that explanation was wrong for them. What it +actually is, established with both controls rather than by inference: + + negative control nosuchapp.enkicsifelhom.hu -> 404, **19 bytes**, „404 page not found" + wiki / share / paperless / photos -> 404, **19 bytes**, „404 page not found" (identical) + positive control status.enkicsifelhom.hu -> **200, 1200 bytes** + +Identical to the no-such-host control, byte for byte: **traefik has no route for them.** The apps did +not answer 404 — nothing answered. And the reason there is no route is the container state, because +traefik only routes to a container that is up and healthy: + + bookstack Up 5 minutes (**unhealthy**) + gokapi **Restarting (0)** + immich-server **Restarting (1)** + paperless-webserver Up 9 seconds (health: starting) <- this one was simply still starting + nextcloud Up 20 seconds (health: starting) <- the image re-pull REPAIRED it + +So the sequence is: my disk-full episode corrupted image layers -> containers crash-loop or stay +unhealthy -> traefik has no route -> the front door 404s. Nextcloud proves the chain from the other +end: drop the corrupt image, let compose pull it again, and the app comes up. The same repair is +applied to bookstack, gokapi and immich, with each one's failing log lines captured BEFORE the fix so +the cause is recorded and not just the cure. + +**None of this is filed as a product defect** — the corruption is mine. What the product did with it +was correct throughout: it refused to route to unhealthy containers, it reported `app_start_failed` +for the app that was down, and it named that same app as the one that failed to back up. + +## The nextcloud repair, with its own record (not inferred from a health badge) + stop through the product's API -> 200 + docker image rm nextcloud:34.0.1-apache -> Deleted: sha256:f2ec4de84f559f5c7be4233b589cdbdbb5507807e05621b77320edd55a1f2a0f + start through the product's API -> 200 (compose re-pulls the missing image) + t+15s nextcloud Up 15 seconds (health: starting) + +That closes the chain from both ends: corrupt layer -> `invalid ELF header` -> exit 127 crash loop +-> no traefik route -> 404 at the front door; and then drop the image -> fresh pull -> the app comes +up. The repair was done through the product's own stop/start endpoints, not by hand-running compose, +so the controller's record of the app stayed consistent throughout. + +## The cause evidence contradicts my own hypothesis — recorded before the repair overwrote it +I had assumed all the broken apps were corrupt-layer damage like nextcloud. The logs captured BEFORE +touching them say otherwise: + + * **bookstack** — a perfectly normal startup: „Waiting for DB to be available" … „INFO Nothing to + migrate." … „[custom-init] No custom files found, skipping…" … „[ls.io-init] done." No error at + all. It was merely marked `unhealthy`, i.e. its healthcheck was not passing — which is enough for + traefik to refuse it a route, but is NOT corruption. Dropping its image was probably unnecessary. + * **gokapi** — **no log output whatsoever**, and `Restarting (0)`: it exits cleanly and instantly. + That is a configuration/first-run shape, not a corrupt binary. + * **immich-server** — `file: 'auth.c', line: '331', routine: 'auth_failed'` under Node.js. That is + **PostgreSQL refusing the password**, not a broken library. + +### The likely real cause, and it is mine: regenerated secrets over existing databases +My sequential re-seed called `gen` again for every app, so each one was deployed with **freshly +generated DB passwords** — while the database volumes created during the first (failed, parallel) +burst still hold databases initialised with the FIRST passwords. Postgres/MariaDB keep the password +from `POSTGRES_PASSWORD`/`MYSQL_PASSWORD` at volume-init time and ignore it afterwards, so the app +then authenticates with a password the database has never heard of. `auth_failed` is exactly that. + +**Consequence:** re-pulling an image cannot fix this, and neither can restarting. The apps whose +volumes predate the re-seed need a clean removal (with their data) and a fresh deploy — which costs +nothing here because none of them holds real household data yet. + +**Not a product defect.** The product deployed exactly what I asked it to deploy, twice, with the +values I supplied each time. + +## CORRECTION — „nextcloud is repaired" was WRONG, and the container badge is why I believed it +I wrote that the image re-pull repaired nextcloud, on the strength of `Up (healthy)`. Checking the +log with timestamps against the guest's own clock: + + guest time now 2026-09-16T21:16:02Z + 2026-09-16T21:14:09Z „Access denied for user 'nextcloud'@'172.21.0.4' (using password: YES)" + 2026-09-16T21:14:19Z „Error while trying to create admin account: … Access denied for user + 'nextcloud'@'172.21.0.4' (using password: YES)" + +Two minutes old — **current, not leftovers from the crash-looping period.** The re-pull did fix the +corrupt library (the app now starts instead of exiting 127), but the SECOND fault is still there: the +database was initialised with the first deploy's password and the app now presents the re-seed's new +one. It could not even create its admin account. + +**And the container says `healthy` the whole time.** The healthcheck is the app image's own — Apache +answers, so the probe passes — while the application cannot reach its database at all. This is the +project's standing lesson in another costume: **a health signal is not a data signal**, and „healthy" +answered a different question from the one I was asking. + +So nextcloud joins gokapi and paperless in the clean remove-and-redeploy. Retracted here rather than +left standing, because the wrong version of this paragraph was already written two entries above. + +## An HTTP 000 is „no answer", not „it failed" — and the action still happened +The immich repair's start call returned: + start -> 000 +`000` is curl's code for „no response received", not a refusal by the server. Twenty seconds later: + immich-server Up 4 seconds (health: starting) +So the start DID take effect; only the answer was lost (the controller was busy stopping/starting +several stacks at once). Recorded because reading `000` as „the start failed" would have led me to +issue a second start on an app that was already coming up. + +## Household state at 21:17Z, and the decision to move round 2 + immich-server Up 4 seconds (health: starting) — DB password mismatch still expected + gokapi Restarting (1) — clean remove+redeploy in progress + bookstack Up about a minute (**unhealthy**) — healthcheck not passing + nextcloud Up about a minute (healthy) — but DB-broken, see the correction above + paperless-webserver Up 8 seconds — clean remove+redeploy in progress + (the other seven apps: up and serving) + +**Decision: round 2 moves to ~23:45 CEST.** Five of twelve apps are mid-repair from damage I caused, +and a chaos round measures nothing if the household is already broken before the accident lands. The +SCHEDULE is unchanged — same actions, same apps, same accidents, same order, drawn from the seed +before anything ran; only the wall clock moves, and the 05:00 stop is unchanged. At ~25-minute +spacing a 23:45 start still reaches round 12 by about 04:20. + +The queue behind the current job: **nextcloud, immich and bookstack** get the same clean +remove-and-redeploy. They are done one at a time, never two repair jobs at once on the same box — +concurrent stop/start on one controller is what produced half of tonight's confusion already. diff --git a/documentation/audits/evidence-chaos-night-2026-09-17/round-1.txt b/documentation/audits/evidence-chaos-night-2026-09-17/round-1.txt index f763e620..dcde7539 100644 --- a/documentation/audits/evidence-chaos-night-2026-09-17/round-1.txt +++ b/documentation/audits/evidence-chaos-night-2026-09-17/round-1.txt @@ -15,3 +15,52 @@ 2026-09-16T21:09:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": 2026-09-16T21:09:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": 2026-09-16T21:10:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:10:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:10:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:11:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + +## ROUND 1 — the five things +**action:** `offsite-run` (drawn app: adventurelog — an off-site run is a TIER action; the whole +repository is one run, so the named app is which row is read afterwards) +**accident:** none — round 1 is a control round by the schedule's own constraint 5 + +1. **What the customer saw.** „A távoli mentés elindult — az állapot itt frissül." then, at the end, + the repository reported ORPHANED: „A távoli mentési tároló elárvult: a benne lévő mentések egy + korábbi, már nem elérhető kulccsal készültek (újratelepítés). Új mentés a tároló visszaállít…" +2. **What the box did by itself.** Walked all twelve apps — stop, dump each volume with real byte + counts, restart („Stopping X for safe volume dump" / „Restarting X after volume dump") — captured + eleven, could not capture the one that was crash-looping, and finished. +3. **Time to steady.** `last_duration` **1m45s**, `last_run` 2026-09-16T21:09:00Z, `progress.active` + back to false, `last_error` empty. The box never left steady: this was a control round. +4. **Alarms that fired, and were they true.** Three, all TRUE: + `app_start_failed` (warning) named Nextcloud; `backup_run_failures` (error) said „1 of 12 apps + failed to back up in this nightly run: nextcloud"; `offbox_repo_orphaned` (warning) reported the + orphaned repository. The status endpoint agrees with the alarm: `"orphaned": true`. +5. **Alarms that should have fired and did not.** None. Everything that happened was announced, and + nothing was announced that had not happened. + +**Household loop in this window:** 3 lines marked FAILED — **all three are MY error**, not the box's: +the loop counted the dashboard's `http=301` redirect as a failure while counting the same 301 as OK +for app reads. Fixed at 21:12Z and marked in the log; only lines after that marker are scored. + +**Round 1's verdict:** the off-site tier is armed (escrowed) and runs, but on THIS box — a rebuild for +an existing customer — the remote repository belongs to a key the box no longer has, so no snapshot +was written. That is the documented rebuild behaviour, surfaced honestly with the route out named. + 2026-09-16T21:11:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:11:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:12:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:12:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:12:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:13:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:13:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:13:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:14:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:14:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:14:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:15:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:15:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:15:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:16:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:16:35Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:16:55Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files": + 2026-09-16T21:17:15Z {"last_duration":"1m45s","last_error":"","last_run":"2026-09-16T21:09:00Z","orphaned":true,"progress":{"active":false,"current_app":"","percent":0,"bytes_done":0,"total_bytes":0,"done_human":"","total_human":"","files_done":0,"total_files":