soak drill COMPLETE: 7 phases, 4 findings, the observer found the worst one (R-414)
gates / gates (push) Failing after 17s
gates / gates (push) Failing after 17s
Overnight soak 22:39->06:10 CEST. demo-hp the victim, demo-felhom the untouched observer.
No production code, no golden, no version bump. Report at
documentation/audits/DRILL-soak-2026-08-31/REPORT.md.
VERDICTS: 1 lock-collision FAIL, 2 guard-interactions PASS-with-one-defect, 3 R-357 PASS,
4 proof-edges PASS, 5 mutated-cycle PASS, 6 observer FAIL, 7 teardown PASS.
R-414 - THE MOST VALUABLE FINDING, AND ONLY AN UNTOUCHED BOX COULD HAVE FOUND IT. On
demo-felhom the nightly proof fired for the first time unattended at 05:30 and REFUSED:
"nowhere to restore to - nincs regisztralt adatmeghajto". Cause established, not inferred:
storage_paths is EMPTY, so there is no path to put a scratch on. It will fail this way every
night forever with only a WARN, and because the error path reaches no verdict,
last_proof_result stays ABSENT - which is also what a pre-0.231.0 controller sends. The hub
cannot tell "never ran" from "not deployed": the StatsKnown trap one level up. The box is
NOT unprotected; its off-site backup ran fine in 46.9s. It is the PROOF that cannot run.
R-411 - measured, not reasoned: restic stats TAKES A LOCK; a customer full-restore runs it
while holding no acquireRunning; the integrity check is therefore not blocked, meets that
lock and escalates to unlock --remove-all. The sampler caught "restore ..." and
"unlock --remove-all" in the SAME sample. Contained: the check was classified unreachable,
not damage, so no false alarm.
R-412 - CORRECTED from HIGH to LOW. I filed it on a mechanism I had not finished measuring.
The off-site run has its own pre-push dump leg, so a hollow unit is REPAIRED before it
ships - proven on two apps and confirmed by pulling the snapshot back out of the store.
What survives is a narrow race, plus a success line over a backup holding no data.
R-413 - the R-87 proof caught a product-produced hollow snapshot unattended, and the
nightly job fired on its own schedule at 05:30 for the first time (bentopdf PASSED on
9d002b38 in 2.315s). Both were listed "not yet live-validated" yesterday.
R-403 mirror guard PROVEN live, with a negative control: it fired when a unit was hollow
("The copy was PRESERVED rather than replaced with an empty one") and skipped 0 legs at
teardown when every unit was sound.
R-357 PASS at last, six days owed: a real full filesystem, refused BEFORE StopStack, app
never stopped, live data byte-identical, and it worked once the space came back.
Phase 4 built the false-alarm control the whole R-87 design rests on: bentopdf is the only
template of 53 with neither a database nor a named volume. It passes silently.
EIGHT of my own instrument errors are named in the report, each caught by its own control -
including a time guard that fired an injection four hours early, and filing R-412 at the
wrong severity.
Teardown clean on all three layers of both boxes; both healthy on 0.231.0.
OWED: a golden for 0.231.0, and a decision on keeping bentopdf.
This commit is contained in:
@@ -0,0 +1,136 @@
|
||||
# Overnight soak — the week's five new guards, run against each other
|
||||
|
||||
**22:39 → 06:10 CEST, 2026-08-31/09-01. `demo-hp` the victim, `demo-felhom` the untouched observer.**
|
||||
No production code written. No golden baked. No version bumped.
|
||||
|
||||
| # | phase | verdict | the one sentence |
|
||||
|---|---|---|---|
|
||||
| 1 | lock collision | **FAIL** | a background job **deletes the lock of a live customer restore** and logs a crash that did not happen — customer-facing consequence contained |
|
||||
| 2 | guard interactions | **PASS with one defect** | 4 of 5 guards clean; a unit lost *inside* a run ships hollow and is reported a success |
|
||||
| 3 | R-357 full disk | **PASS** | six days owed, now proven against a real full filesystem — refused before the app went down, data byte-identical |
|
||||
| 4 | proof edges | **PASS** | the false-alarm control the whole R-87 design rests on now exists and stays silent |
|
||||
| 5 | mutated cycle | **PASS** | every job ran; the R-403 guard fired and named itself; the nightly proof fired unattended for the first time |
|
||||
| 6 | observer | **FAIL** | on a box with no registered drive the nightly proof **cannot run at all**, every night, with only a WARN |
|
||||
| 7 | teardown | **PASS** | all three layers clean on both boxes; both healthy on 0.231.0 |
|
||||
|
||||
---
|
||||
|
||||
## 1. What surprised me, worst first
|
||||
|
||||
### The proof is inert on a whole class of box (R-414) — and only the untouched observer could find it
|
||||
|
||||
`demo-felhom` has **zero registered storage paths**. At 05:30 the new job fired for the first time
|
||||
unattended and refused: *"proof: opengist has nowhere to restore to — nincs regisztrált
|
||||
adatmeghajtó"*. It will do that **every night, forever**, and the only signal is a `WARN`.
|
||||
|
||||
Worse than a failure: the error path reaches no verdict, so `last_proof_result` stays **absent** — and
|
||||
absent is also what a pre-0.231.0 controller sends. **The hub cannot tell "never ran" from "not
|
||||
deployed".** That is the exact `StatsKnown` trap the field was designed to avoid, reappearing one
|
||||
level up. The same absence explains that box's `tier2-backup` finishing in **3 ms**.
|
||||
|
||||
The box is not unprotected — its off-site backup ran normally in 46.9 s.
|
||||
|
||||
### `unlock --remove-all` really does run against a live operation (R-411)
|
||||
|
||||
Measured, not reasoned. `restic stats` **takes a repository lock** (clean-room test). A customer
|
||||
full-restore runs `stats` while holding **no** single-writer flag, so the integrity check is not
|
||||
blocked, runs, meets that lock, and escalates. The sampler caught `restore …` and
|
||||
`unlock --remove-all` **in the same sample**, and the log said *"a stale exclusive lock left by a
|
||||
previous crash"*. There was no crash.
|
||||
|
||||
**Contained**: the check was classified *unreachable*, not damage — no false "your backups are
|
||||
damaged" mail, and due-ness held. The opposite direction is fenced: five restores fired into a running
|
||||
check were all refused, zero restic invoked.
|
||||
|
||||
### I over-claimed a finding and had to correct it (R-412)
|
||||
|
||||
Filed **HIGH** on a mechanism I had not finished establishing. Overnight measurement showed the
|
||||
off-site run has its **own** pre-push dump leg, so a hollow unit is **repaired before it ships** —
|
||||
proven on two apps, and confirmed by pulling the snapshot back out of the store. **Corrected to LOW**,
|
||||
with the over-claim written into the row rather than quietly edited away.
|
||||
|
||||
What survives is narrower and real: a unit destroyed *inside* a run, after that app's dump leg, ships
|
||||
hollow and the run logs `backed up opengist (… 0 mandatory path(s))` — a success line over a backup
|
||||
holding none of the app's data.
|
||||
|
||||
### A quiet one worth saying: three attempts to damage a backup were repaired by the product
|
||||
|
||||
A stopped app's tar was re-made; a deleted unit was rebuilt; a corrupted manifest was rewritten — each
|
||||
by the run's own capture, before any push. That is reassuring, and it is why the hollow snapshot
|
||||
needed a race to happen at all.
|
||||
|
||||
---
|
||||
|
||||
## 2. Findings filed
|
||||
|
||||
| id | severity | what |
|
||||
|---|---|---|
|
||||
| **R-411** | MEDIUM | a background job deletes a live restore's lock and calls it a crash |
|
||||
| **R-412** | LOW *(was HIGH — corrected)* | a unit lost inside a run ships hollow and reports success |
|
||||
| **R-413** | CLOSED | the R-87 proof caught a product-produced hollow snapshot unattended |
|
||||
| **R-414** | MEDIUM | the nightly proof is inert on a box with no registered drive |
|
||||
|
||||
Register: `OPEN-ITEMS.md` **173 → 174** rows. Evidence:
|
||||
`documentation/audits/DRILL-soak-2026-08-31/`, seven phase directories.
|
||||
|
||||
---
|
||||
|
||||
## 3. What I could not test, and why
|
||||
|
||||
- **"Mark a drive disconnected" (Phase 5).** No endpoint reaches `SetDisconnected`; a hand-set flag
|
||||
would be reverted by the live monitor before 04:15, so the run would have read as a passing test of
|
||||
a fault that was not present. Unmounting a live drive risks a wedged mount that needs a reboot.
|
||||
04:15 was observed against a real injected fault instead.
|
||||
- **"Corrupt a manifest before the proof."** Phase 4 established the capture rewrites it before any
|
||||
push, so nothing I do to the live manifest can change what the proof sees. Covered by
|
||||
`TestR87_UnparseableManifestFails`.
|
||||
- **Two failing apps in one hour → one mail.** Only two alarms fired all night and they were 1 h 42 m
|
||||
apart, so the coarse cooldown was never exercised. **UNDETERMINED.**
|
||||
- **The 06:00 integrity check at full depth on `demo-hp`.** It completed in **0 s — not due**, because
|
||||
my own manual runs during Phases 1–3 had already advanced its due-ness. My doing, and correct
|
||||
behaviour.
|
||||
|
||||
---
|
||||
|
||||
## 4. Left changed on the boxes
|
||||
|
||||
- **`demo-felhom` is hand-deployed to 0.231.0** (was 0.230.0). Reversible; the golden bake supersedes
|
||||
it. **Recorded here because a hand-deployed box nobody records is how a fleet drifts.**
|
||||
- **`bentopdf` is deployed on `demo-hp` and I recommend KEEPING it.** It is the **only** template of
|
||||
53 with neither a database nor a named volume, so it is the only possible live subject for R-87's
|
||||
false-alarm control. Deleting it deletes the control.
|
||||
- A hollow `opengist` snapshot (`35ba9fe7`) remains in the off-site store as history. Its newest
|
||||
snapshot is sound and the proof passes it.
|
||||
- Nothing else. All ballast, scratches, markers, probe scripts and credentials removed from all three
|
||||
layers on both boxes; `/root` on both hosts holds only `.cache` and `.ssh`; both container `/tmp`
|
||||
directories are empty.
|
||||
|
||||
---
|
||||
|
||||
## 5. My own mistakes, by name — eight, all caught by their own controls
|
||||
|
||||
1. Used a **hub** log line as the positive control for a **controller** recorder.
|
||||
2. A grep pattern that reported a registered job as missing when it was there.
|
||||
3. A heredoc that mangled a planted marker, and an escaping error that reported `"full":false` as a
|
||||
failure when the file plainly read `"full":false`.
|
||||
4. A catalogue scan that read **0 of 0** apps from the wrong path.
|
||||
5. A wait that matched my **own earlier output** replayed by the log follower — a false "job observed".
|
||||
6. **A time guard `[ 2334 -ge 0315 ]` that fired the Phase 5 injection four hours early**, changing
|
||||
the drill.
|
||||
7. **Filing R-412 at HIGH on a mechanism I had not finished measuring** — the worst one, because it
|
||||
went into the register wrong.
|
||||
8. A baseline grep whose control failed, nearly making a 10-day-old stale directory look like
|
||||
tonight's damage; mtime settled it.
|
||||
|
||||
Every zero reported above was earned by a positive control first. That is the only reason the list is
|
||||
eight and not eight-plus-a-wrong-verdict.
|
||||
|
||||
---
|
||||
|
||||
## 6. Owed to Viktor in the morning
|
||||
|
||||
1. **A golden carrying 0.231.0** — still owed from yesterday; the fleet floor is 0.230.0.
|
||||
2. **A decision on `bentopdf`** — keep it as the permanent false-alarm control (my recommendation),
|
||||
or remove it.
|
||||
3. **R-414** is the one worth reading first: a feature that shipped yesterday does not run at all on a
|
||||
box shaped like `demo-felhom`.
|
||||
@@ -0,0 +1,50 @@
|
||||
# Phase 5 — `demo-hp`'s own nightly cycle, mutated. **PASS**
|
||||
|
||||
Every scheduled job ran, on time, with a light load (a unit restore every 20 min) contending for the
|
||||
single-writer flag across the whole window.
|
||||
|
||||
| job | CEST | duration | outcome |
|
||||
|---|---|---|---|
|
||||
| db-dump | 02:30 | 1 m 24.7 s | completed — **and it re-made the volume tars**, healing the injected fault |
|
||||
| tier2-backup | 03:30 | 5.9 s | completed, 9 apps |
|
||||
| fill-watch | 03:30 | 0 s | completed |
|
||||
| metrics-prune | 04:00 | 0 s | completed |
|
||||
| offbox-backup | 04:15 | 2 m 57.7 s | completed — **its own pre-push dump leg repaired a hollow unit** |
|
||||
| offsite-abandon-sweep | 05:10 | 0 s | completed, clean beside the rest |
|
||||
| **offsite-proof** | **05:30** | **5.0 s** | **completed — `bentopdf` PASSED on `9d002b38` in 2.315 s** |
|
||||
| offsite-integrity | 06:00 | 0 s | **not due** — my own manual runs had advanced due-ness |
|
||||
|
||||
## The headline: the nightly proof fired unattended, for the first time
|
||||
|
||||
Yesterday's report listed *"the unattended nightly firing"* as **not yet live-validated**. It is now:
|
||||
the job fired on its own schedule at 05:30, picked one app, proved it in 2.315 s, and scheduled the
|
||||
next run for `2026-09-02 05:30 CEST`. **One app per night held.**
|
||||
|
||||
## The R-403 guard: PASS, forced after the natural test evaporated
|
||||
|
||||
`privatebin` was injected hollow at 23:34 to meet the 03:30 mirror. **The 02:30 db-dump re-made its
|
||||
tar**, so by 03:30 the primary was sound and the guard had nothing to refuse. Forced instead on
|
||||
`calibre-web` through the real Tier-2 path — and the guard fired and named itself:
|
||||
|
||||
```
|
||||
Tier 2 calibre-web: unit leg SKIPPED — the recovery unit on the source drive lists no database dumps
|
||||
and no volume tars, while the existing copy ... does. The copy was PRESERVED rather than replaced
|
||||
with an empty one (R-403). The other legs continue.
|
||||
```
|
||||
|
||||
Secondary byte-identical: 23 files, 5 808 704 B, tar sha `d7e7f422…`. **Negative control** at
|
||||
teardown: with every unit sound, the same job skipped **0** unit legs.
|
||||
|
||||
## Alarms across the whole mutated night
|
||||
|
||||
**One WARN** — the R-403 skip above. **Zero ERRORs.** Every event pushed was `info`
|
||||
(`db_dump_completed`, `crossdrive_completed` ×12), all dropped by `severityNotifies`. **No customer
|
||||
was mailed anything.**
|
||||
|
||||
## Half-marks, stated
|
||||
|
||||
- The runbook wanted *"the run does not report a plain success"* when a leg is skipped. **The log does
|
||||
not** — it states the skip and the reason. **The event does**: `crossdrive_completed (info) —
|
||||
Másodlagos mentés elkészült: calibre-web`, no mention of the skipped leg. It is not delivered
|
||||
(`info`), so nobody is misled by mail, but an event list would read as a clean completion.
|
||||
- Two of four injections were not performed; reasons in `03-injections-not-performed.md`.
|
||||
@@ -0,0 +1,46 @@
|
||||
=== scheduled-job activity after 2026-08-31T23:00:00Z ===
|
||||
-- db-dump -- (2 line(s))
|
||||
2026-09-01 00:30:00 [scheduler] Running job: db-dump
|
||||
2026-09-01 00:31:24 [scheduler] Job db-dump completed (took 1m24.696s)
|
||||
-- tier2-backup -- (2 line(s))
|
||||
2026-09-01 01:30:00 [scheduler] Running job: tier2-backup
|
||||
2026-09-01 01:30:05 [scheduler] Job tier2-backup completed (took 5.895s)
|
||||
-- offbox-backup -- (2 line(s))
|
||||
2026-09-01 02:15:00 [scheduler] Running job: offbox-backup
|
||||
2026-09-01 02:17:57 [scheduler] Job offbox-backup completed (took 2m57.669s)
|
||||
-- offsite-abandon-sweep -- (2 line(s))
|
||||
2026-09-01 03:10:00 [scheduler] Running job: offsite-abandon-sweep
|
||||
2026-09-01 03:10:00 [scheduler] Job offsite-abandon-sweep completed (took 0s)
|
||||
-- offsite-proof -- (2 line(s))
|
||||
2026-09-01 03:30:00 [scheduler] Running job: offsite-proof
|
||||
2026-09-01 03:30:04 [scheduler] Job offsite-proof completed (took 4.994s)
|
||||
-- offsite-integrity -- (2 line(s))
|
||||
2026-09-01 04:00:00 [scheduler] Running job: offsite-integrity
|
||||
2026-09-01 04:00:00 [scheduler] Job offsite-integrity completed (took 0s)
|
||||
-- metrics-prune -- (2 line(s))
|
||||
2026-09-01 02:00:00 [scheduler] Running job: metrics-prune
|
||||
2026-09-01 02:00:00 [scheduler] Job metrics-prune completed (took 0s)
|
||||
-- fill-watch -- (2 line(s))
|
||||
2026-09-01 01:30:00 [scheduler] Running job: fill-watch
|
||||
2026-09-01 01:30:00 [scheduler] Job fill-watch completed (took 0s)
|
||||
=== every EVENT pushed ===
|
||||
2026-09-01 00:31:24 db_dump_completed (info) — Adatbázis mentés elkészült
|
||||
2026-09-01 01:30:00 crossdrive_completed (info) — Másodlagos mentés elkészült: bentopdf
|
||||
2026-09-01 01:30:01 crossdrive_completed (info) — Másodlagos mentés elkészült: bookstack
|
||||
2026-09-01 01:30:01 crossdrive_completed (info) — Másodlagos mentés elkészült: calibre-web
|
||||
2026-09-01 01:30:02 crossdrive_completed (info) — Másodlagos mentés elkészült: docmost
|
||||
2026-09-01 01:30:04 crossdrive_completed (info) — Másodlagos mentés elkészült: kimai
|
||||
2026-09-01 01:30:04 crossdrive_completed (info) — Másodlagos mentés elkészült: opengist
|
||||
2026-09-01 01:30:04 crossdrive_completed (info) — Másodlagos mentés elkészült: paperless-ngx
|
||||
2026-09-01 01:30:04 crossdrive_completed (info) — Másodlagos mentés elkészült: privatebin
|
||||
2026-09-01 01:30:05 crossdrive_completed (info) — Másodlagos mentés elkészült: romm
|
||||
2026-09-01 01:35:26 crossdrive_completed (info) — Másodlagos mentés elkészült: calibre-web
|
||||
2026-09-01 01:35:26 crossdrive_completed (info) — Másodlagos mentés elkészült: paperless-ngx
|
||||
2026-09-01 01:35:26 crossdrive_completed (info) — Másodlagos mentés elkészült: romm
|
||||
=== every ERROR / WARN of interest ===
|
||||
2026-09-01 01:35:26 [backup] Tier 2 calibre-web: unit leg SKIPPED — the recovery unit on the source drive lists no database dumps and no volume tars, while the existing c
|
||||
=== proof verdicts ===
|
||||
2026-09-01 03:30:00 execution starting
|
||||
2026-09-01 03:30:04 bentopdf PASSED on snapshot 9d002b38 in 2.315s — the backup holds what this app should have
|
||||
2026-09-01 03:30:04 next run at 2026-09-02 05:30:00 CEST (waiting 23h59m55s)
|
||||
=== integrity verdicts ===
|
||||
@@ -0,0 +1,52 @@
|
||||
23:34:13 phase5 driver started
|
||||
23:34:13 cycle recorder started
|
||||
23:34:13 light load started (a restore every 20 min)
|
||||
23:34:13 injection armed for 03:15
|
||||
23:34:13 === INJECTING the hollow primary (privatebin) ===
|
||||
perl: warning: Setting locale failed.
|
||||
perl: warning: Please check that your locale settings:
|
||||
LANGUAGE = (unset),
|
||||
LC_ALL = (unset),
|
||||
LC_CTYPE = "UTF-8",
|
||||
LC_NUMERIC = (unset),
|
||||
LC_COLLATE = (unset),
|
||||
LC_TIME = (unset),
|
||||
LC_MESSAGES = (unset),
|
||||
LC_MONETARY = (unset),
|
||||
LC_ADDRESS = (unset),
|
||||
LC_IDENTIFICATION = (unset),
|
||||
LC_MEASUREMENT = (unset),
|
||||
LC_PAPER = (unset),
|
||||
LC_TELEPHONE = (unset),
|
||||
LC_NAME = (unset),
|
||||
LANG = "en_US.UTF-8"
|
||||
are supported and installed on your system.
|
||||
perl: warning: Falling back to a fallback locale ("en_US.UTF-8").
|
||||
=== BEFORE ===
|
||||
primary : 5 files, 2123006 bytes
|
||||
secondary: 6 files, 2123007 bytes
|
||||
secondary tar sha: c3ea1bae0731bcc3082d6c94
|
||||
|
||||
=== INJECT: remove privatebin's primary unit. The 5-min capture will rebuild it HOLLOW
|
||||
(it cannot conjure a volume tar - that leg runs on the backup schedule). ===
|
||||
primary removed
|
||||
23:34:14 load: restore kimai -> [http=302 wall=0.012033s]
|
||||
23:54:15 load: restore bookstack -> [http=302 wall=0.011206s]
|
||||
00:14:16 load: restore docmost -> [http=302 wall=0.011085s]
|
||||
00:34:17 load: restore kimai -> [http=302 wall=0.010686s]
|
||||
00:54:18 load: restore bookstack -> [http=302 wall=0.011526s]
|
||||
01:14:19 load: restore docmost -> [http=302 wall=0.011364s]
|
||||
01:34:20 load: restore kimai -> [http=302 wall=0.010521s]
|
||||
01:54:21 load: restore bookstack -> [http=302 wall=0.011243s]
|
||||
02:14:22 load: restore docmost -> [http=302 wall=0.011166s]
|
||||
02:34:23 load: restore kimai -> [http=302 wall=0.011049s]
|
||||
02:54:24 load: restore bookstack -> [http=302 wall=0.011425s]
|
||||
03:14:25 load: restore docmost -> [http=302 wall=0.011215s]
|
||||
03:34:26 load: restore kimai -> [http=302 wall=0.011015s]
|
||||
03:54:27 load: restore bookstack -> [http=302 wall=0.012046s]
|
||||
04:14:28 load: restore docmost -> [http=302 wall=0.010933s]
|
||||
04:34:28 load: restore kimai -> [http=302 wall=0.010720s]
|
||||
04:54:29 load: restore bookstack -> [http=302 wall=0.010774s]
|
||||
05:14:30 load: restore docmost -> [http=302 wall=0.011732s]
|
||||
05:34:31 load: restore kimai -> [http=302 wall=0.010919s]
|
||||
05:54:32 load: restore bookstack -> [http=302 wall=0.011551s]
|
||||
@@ -0,0 +1,52 @@
|
||||
# Phase 6 — the untouched observer's verdict. **FAIL, and it is the night's most valuable finding.**
|
||||
|
||||
`demo-felhom` was hand-deployed to 0.231.0 at 22:40 and **not touched again**. Its whole nightly cycle
|
||||
was recorded by a follow stream on the PVE host.
|
||||
|
||||
## Did every job run? Yes — all eight, on time.
|
||||
|
||||
| job | CEST | duration | outcome |
|
||||
|---|---|---|---|
|
||||
| db-dump | 02:30 | 674 ms | completed, `db_dump_completed (info)` |
|
||||
| tier2-backup | 03:30 | **3 ms** | completed — **a no-op** |
|
||||
| fill-watch | 03:30 | 0 s | completed |
|
||||
| metrics-prune | 04:00 | 3 ms | completed |
|
||||
| offbox-backup | 04:15 | **46.9 s** | completed |
|
||||
| offsite-abandon-sweep | 05:10 | 0 s | completed |
|
||||
| **offsite-proof** | **05:30** | 2.6 s | **REFUSED — could not run** |
|
||||
| offsite-integrity | 06:00 | 0 s | **not due** (last success 24 h ago) — correct due-ness |
|
||||
|
||||
## Did any two overlap, and did the flag hold?
|
||||
|
||||
No two scheduled jobs overlapped on this box — the schedule spaces them 45–90 min apart and the
|
||||
longest took 47 s. The flag was never contended here, so this box proves the **schedule**, not the
|
||||
lock. Contention was tested on `demo-hp` (Phase 1).
|
||||
|
||||
## Did the proof pick one app and record a snapshot? **No — and that is the finding.**
|
||||
|
||||
```
|
||||
03:30:02 [WARN] [offbox] proof: opengist has nowhere to restore to: nincs regisztralt
|
||||
adatmeghajto, ezert nincs hova visszaallitani — a meghajtok megvannak, csak ujra kell...
|
||||
```
|
||||
|
||||
**Cause established, not inferred:** `storage_paths: []` — zero registered storage paths, so
|
||||
`offboxRestoreScratchDir` has nowhere to write a scratch and returns R-252's refusal. The same absence
|
||||
explains `tier2-backup` at 3 ms: no second drive to mirror to.
|
||||
|
||||
`last_proof_result` is **ABSENT** and `proved_snapshots` is **ABSENT** — the error path reaches no
|
||||
verdict, so nothing is recorded, so the hub cannot tell this from a controller too old to have the
|
||||
feature. Filed **R-414**.
|
||||
|
||||
**The box is not unprotected**: its off-site backup ran normally in 46.9 s, because recovery units
|
||||
live on the system data path, which needs no registration. It is the PROOF that cannot run.
|
||||
|
||||
## Did the integrity check run at full depth? No — and correctly.
|
||||
|
||||
`not due (last successful check 24h0m0s ago)`. The 7-day max age had not elapsed. Due-ness working as
|
||||
designed; this box's last real full-depth check was 2026-08-31 04:00.
|
||||
|
||||
## **Did anything alarm on a healthy box?**
|
||||
|
||||
**No.** One event in the whole night — `db_dump_completed (info)`, which `severityNotifies` drops.
|
||||
**Zero ERROR lines. One WARN**, and it is the R-414 refusal above. On a box left completely alone for
|
||||
seven hours, the product was silent, and silence was the correct answer.
|
||||
@@ -0,0 +1,33 @@
|
||||
=== scheduled-job activity after 2026-08-31T23:00:00Z ===
|
||||
-- db-dump -- (2 line(s))
|
||||
2026-09-01 00:30:00 [scheduler] Running job: db-dump
|
||||
2026-09-01 00:30:00 [scheduler] Job db-dump completed (took 674ms)
|
||||
-- tier2-backup -- (2 line(s))
|
||||
2026-09-01 01:30:00 [scheduler] Running job: tier2-backup
|
||||
2026-09-01 01:30:00 [scheduler] Job tier2-backup completed (took 3ms)
|
||||
-- offbox-backup -- (2 line(s))
|
||||
2026-09-01 02:15:00 [scheduler] Running job: offbox-backup
|
||||
2026-09-01 02:15:46 [scheduler] Job offbox-backup completed (took 46.946s)
|
||||
-- offsite-abandon-sweep -- (2 line(s))
|
||||
2026-09-01 03:10:00 [scheduler] Running job: offsite-abandon-sweep
|
||||
2026-09-01 03:10:00 [scheduler] Job offsite-abandon-sweep completed (took 0s)
|
||||
-- offsite-proof -- (2 line(s))
|
||||
2026-09-01 03:30:00 [scheduler] Running job: offsite-proof
|
||||
2026-09-01 03:30:02 [scheduler] Job offsite-proof completed (took 2.565s)
|
||||
-- offsite-integrity -- (2 line(s))
|
||||
2026-09-01 04:00:00 [scheduler] Running job: offsite-integrity
|
||||
2026-09-01 04:00:00 [scheduler] Job offsite-integrity completed (took 0s)
|
||||
-- metrics-prune -- (2 line(s))
|
||||
2026-09-01 02:00:00 [scheduler] Running job: metrics-prune
|
||||
2026-09-01 02:00:00 [scheduler] Job metrics-prune completed (took 3ms)
|
||||
-- fill-watch -- (2 line(s))
|
||||
2026-09-01 01:30:00 [scheduler] Running job: fill-watch
|
||||
2026-09-01 01:30:00 [scheduler] Job fill-watch completed (took 0s)
|
||||
=== every EVENT pushed ===
|
||||
2026-09-01 00:30:00 db_dump_completed (info) — Adatbázis mentés elkészült
|
||||
=== every ERROR / WARN of interest ===
|
||||
2026-09-01 03:30:02 [offbox] proof: opengist has nowhere to restore to: nincs regisztrált adatmeghajtó, ezért nincs hová visszaállítani — a meghajtók megvannak, csak újra
|
||||
=== proof verdicts ===
|
||||
2026-09-01 03:30:02 opengist has nowhere to restore to: nincs regisztrált adatmeghajtó, ezért nincs hová visszaállítani — a meghajtók megvannak, csak újra kell
|
||||
=== integrity verdicts ===
|
||||
2026-09-01 04:00:00 not due (last successful check 24h0m0s ago, at 2026-08-31 04:00) — nothing was run
|
||||
@@ -0,0 +1,4 @@
|
||||
=== demo-felhom storage registry (the cause) ===
|
||||
registered storage paths: 0
|
||||
last_proof_result: '<ABSENT>'
|
||||
proved_snapshots : <ABSENT>
|
||||
File diff suppressed because it is too large
Load Diff
@@ -0,0 +1,51 @@
|
||||
# Phase 7 — restore the world. **PASS**
|
||||
|
||||
| layer | `demo-hp` | `demo-felhom` |
|
||||
|---|---|---|
|
||||
| PVE host `/root` | `.cache .ssh` only | soak files: 0 |
|
||||
| guest `/root` | soak files: 0 | soak files: 0 |
|
||||
| container `/tmp` | **empty** | n/a (never touched) |
|
||||
| scratches (`offsite-restore`, `offsite-proof`) | **both empty** | n/a |
|
||||
| ballast | 0 files; 949 GB free on `hdd_1` | n/a |
|
||||
| controller | 0.231.0, healthy | 0.231.0, healthy |
|
||||
| apps | **18 containers, all healthy**, none exited or restarting | all healthy |
|
||||
|
||||
Local credential copies `shred -u`'d.
|
||||
|
||||
## One clean cycle of each tier, checked for the RIGHT reason
|
||||
|
||||
- **Tier-2**: 3 apps copied, and **0 unit legs skipped** — the R-403 guard's *negative* control. It
|
||||
fired earlier tonight when a unit was hollow and correctly does **not** fire now that every unit is
|
||||
sound.
|
||||
- **Proof**: `bookstack` → `pass`.
|
||||
- **Off-site**: the real 04:15 run completed in 2 m 57 s. Not re-run.
|
||||
|
||||
## Every primary unit, final
|
||||
|
||||
```
|
||||
bentopdf dumps=0 tars=0 <- correct: it legitimately has neither (the R-87 control)
|
||||
bookstack dumps=1 tars=2 opengist dumps=0 tars=1
|
||||
docmost dumps=1 tars=3 privatebin dumps=0 tars=1
|
||||
kimai dumps=1 tars=2 calibre-web dumps=0 tars=1
|
||||
paperless-ngx dumps=1 tars=3 romm dumps=1 tars=3
|
||||
```
|
||||
|
||||
All Tier-2 copies present and sized as expected.
|
||||
|
||||
## Two dispositions stated rather than left silent
|
||||
|
||||
1. **`bentopdf` — KEEP** (recommendation). It is the only template of 53 with neither a database nor
|
||||
a named volume, so it is the only possible live subject for R-87's false-alarm control. Removing it
|
||||
removes the control. Viktor's call.
|
||||
2. **`/mnt/sys_drive/felhom-data/backups/primary/paperless/`** — a stale, manifest-less directory for
|
||||
a stack that is not deployed, dated **21–22 August**. **Not mine**, established by mtime after my
|
||||
own baseline grep failed its control. Left in place: I did not create it and do not know why it is
|
||||
there. Harmless (no manifest ⇒ treated as hollow ⇒ the R-403 guard protects any copy), but it reads
|
||||
as an error in any unit sweep.
|
||||
|
||||
## The hub layer — the one that is invisible from the box
|
||||
|
||||
The hub's host page mentions `proof` **zero** times: the controller publishes `last_proof_*` and no
|
||||
hub surface reads them. That is R-402's shape, already allowlisted with that reason in
|
||||
`wire_contract_gate.py`. No scratch customers, appliances or configs were created tonight, so there is
|
||||
nothing to discard there.
|
||||
@@ -0,0 +1,77 @@
|
||||
### demo-hp 04:02:36 UTC
|
||||
--- controller ---
|
||||
gitea.dooplex.hu/admin/felhom-controller:0.231.0
|
||||
gitea.dooplex.hu/admin/felhom-controller:0.231.0 Up 9 hours (healthy)
|
||||
--- every app: running and healthy? ---
|
||||
bentopdf Up 51 minutes (healthy)
|
||||
bookstack Up 51 minutes (healthy)
|
||||
bookstack-db Up 51 minutes (healthy)
|
||||
calibre-web Up 51 minutes (healthy)
|
||||
docmost Up 51 minutes (healthy)
|
||||
docmost-postgres Up 51 minutes (healthy)
|
||||
docmost-redis Up 51 minutes (healthy)
|
||||
filebrowser Up 10 days (healthy)
|
||||
kimai Up 51 minutes (healthy)
|
||||
kimai-db Up 51 minutes (healthy)
|
||||
opengist Up 51 minutes (healthy)
|
||||
paperless-postgres Up 51 minutes (healthy)
|
||||
paperless-redis Up 51 minutes (healthy)
|
||||
paperless-webserver Up 51 minutes (healthy)
|
||||
privatebin Up 51 minutes (healthy)
|
||||
romm Up 50 minutes (healthy)
|
||||
romm-db Up 51 minutes (healthy)
|
||||
romm-redis Up 51 minutes (healthy)
|
||||
--- unhealthy or exited (must be empty) ---
|
||||
--- primary units: is each a REAL package? ---
|
||||
bentopdf dumps=0 tars=0 HOLLOW
|
||||
bookstack dumps=1 tars=2
|
||||
docmost dumps=1 tars=3
|
||||
kimai dumps=1 tars=2
|
||||
opengist dumps=0 tars=1
|
||||
paperless MANIFEST UNREADABLE: [Errno 2] No such file or directory: '/mnt/sys_drive/felhom-data/backups/primary/paperless/manifest.json'
|
||||
privatebin dumps=0 tars=1
|
||||
calibre-web dumps=0 tars=1
|
||||
paperless-ngx dumps=1 tars=3
|
||||
romm dumps=1 tars=3
|
||||
--- tier2 copies ---
|
||||
bentopdf: 5 files, 4156 bytes
|
||||
bookstack: 11 files, 167027817 bytes
|
||||
docmost: 12 files, 123773625 bytes
|
||||
kimai: 8 files, 213231243 bytes
|
||||
opengist: 6 files, 185665 bytes
|
||||
privatebin: 6 files, 2122929 bytes
|
||||
calibre-web: 23 files, 5808704 bytes
|
||||
paperless-ngx: 13 files, 84582358 bytes
|
||||
romm: 10 files, 185703681 bytes
|
||||
--- leftover probes / scratches / ballast ---
|
||||
offsite-restore: [bookstack calibre-web docmost kimai paperless-ngx ]
|
||||
offsite-proof : []
|
||||
root leftover: .soak-bentopdf-manifest.bak
|
||||
root leftover: .soak-cookie
|
||||
root leftover: .soak-csrf
|
||||
root leftover: .soak-hdr
|
||||
root leftover: .soak-pw
|
||||
root leftover: insp.sh
|
||||
root leftover: p21.sh
|
||||
root leftover: p21b.sh
|
||||
root leftover: p21c.sh
|
||||
root leftover: p25.sh
|
||||
root leftover: p3a.sh
|
||||
root leftover: p3b.sh
|
||||
root leftover: p3c.sh
|
||||
root leftover: p3d.sh
|
||||
root leftover: p4a.sh
|
||||
root leftover: p4b.sh
|
||||
root leftover: p4c.sh
|
||||
root leftover: soak-api.sh
|
||||
root leftover: soak-baseline.sh
|
||||
root leftover: soak-collide.sh
|
||||
root leftover: soak-locksample.sh
|
||||
root leftover: soak-login.sh
|
||||
root leftover: soak-reverse.sh
|
||||
root leftover: stale.sh
|
||||
container /tmp: [insp.sh soak-env.sh soak-locks.log soak-locksample.sh ]
|
||||
--- free space ---
|
||||
Mounted on Avail
|
||||
/mnt/felhom-drives/hdd_1 949284630528
|
||||
/var/lib/felhom 57631019008
|
||||
@@ -0,0 +1,6 @@
|
||||
guest /root soak leftovers : [0]
|
||||
container /tmp : []
|
||||
offsite-restore : []
|
||||
offsite-proof : []
|
||||
ballast : [0]
|
||||
PVE host /root leftovers: [6]
|
||||
@@ -0,0 +1,10 @@
|
||||
|
||||
=== what IS in primary/paperless ? ===
|
||||
total 12
|
||||
drwxr-xr-x 3 root root 4096 Aug 21 20:39 .
|
||||
drwxr-xr-x 9 root root 4096 Aug 31 21:35 ..
|
||||
drwxr-xr-x 2 root root 4096 Aug 22 07:38 db-dumps
|
||||
|
||||
=== is a stack called paperless deployed? ===
|
||||
0
|
||||
0
|
||||
@@ -0,0 +1,18 @@
|
||||
=== one clean cycle of each tier, checking the REASON not just the exit code ===
|
||||
--- tier2 ---
|
||||
"count":3 "ok":true
|
||||
apps copied: 3
|
||||
unit legs skipped (0 expected now all units are sound): 0
|
||||
--- proof ---
|
||||
"stack":"bookstack" "verdict":"pass"
|
||||
--- every primary unit, final ---
|
||||
bentopdf dumps=0 tars=0
|
||||
bookstack dumps=1 tars=2
|
||||
docmost dumps=1 tars=3
|
||||
kimai dumps=1 tars=2
|
||||
opengist dumps=0 tars=1
|
||||
paperless no manifest
|
||||
privatebin dumps=0 tars=1
|
||||
calibre-web dumps=0 tars=1
|
||||
paperless-ngx dumps=1 tars=3
|
||||
romm dumps=1 tars=3
|
||||
@@ -0,0 +1,4 @@
|
||||
guest /root soak files: [0]
|
||||
container /tmp: []
|
||||
scratches: [/mnt/felhom-drives/hdd_1/backups/offsite-proof: /mnt/felhom-drives/hdd_1/backups/offsite-restore: ]
|
||||
PVE host /root: [.cache .ssh ]
|
||||
@@ -597,6 +597,7 @@ class (an image `VOLUME` at an unmounted path) is still live — `immich-server`
|
||||
| **R-411** | **A background job DELETES the lock of a live customer restore, and logs it as a crash that did not happen.** MEASURED on demo-hp 2026-08-31 during the overnight soak, through the product's own endpoints — this is R-408's consequence, which until tonight had only been reasoned about. **The chain, every step observed:** (1) a customer full-restore runs `OffboxRestorePrepareFull` → `restic stats`, and **`restic stats` TAKES A REPOSITORY LOCK** (clean-room test: nothing else running, 4x stats, sampler reads `locks=1`); (2) the restore holds `opRunning` but **NOT `acquireRunning`** (R-408), so the integrity check is not blocked and runs concurrently; (3) the check meets that lock, and `resticStep` escalates to **`unlock --remove-all`** — caught by the argv sampler at **20:50:51 with `restore 3c11059b --target …` and `unlock --remove-all` in the SAME sample**; (4) the log says *"cleared a stale exclusive lock left by a previous crash (single-writer repo)"* — **there was no crash**, and `resticStep` cannot know there was, because it fires on ANY `repository is already locked`. **THE CUSTOMER-FACING CONSEQUENCE WAS CONTAINED, and that is R-359's guard working:** the check returned `ok:false` in 6.7 s and was classified **Unreachable, NOT damage** — *"the check could not run to a verdict (other) — NOT reported as damage"* — so no `backup_integrity_failed` and no customer mail. Due-ness was not advanced either, so it retries. **What is NOT contained:** a live operation's lock is deleted by a background job; the single-writer premise `resticStep`'s own comment rests on is false in this pairing; and that night's integrity check silently did not verify the store, with only a WARN. **The opposite direction is FENCED and was measured too:** five restores fired into a running check at 5/15/25/35/40 s offsets were ALL refused by `restoreOpBlocked` (`offbox_handlers.go:358`), zero restic invoked — so the hazard is reachable only restore-FIRST. | **OPEN — MEDIUM** | R-408, R-407, R-359 | Decide ONE way, and R-408 is the same decision: either `RestoreOffboxScratch` (and the full-restore preparation) takes `acquireRunning`, or `resticStep`'s escalation stops claiming a crash it cannot verify and refuses instead of removing. **Pin whichever is chosen with a test that reproduces this pairing** — a unit test on `resticStep` alone cannot see it. Evidence: `audits/DRILL-soak-2026-08-31/phase1-lock-collision/`. | CC |
|
||||
| **R-412** | **A recovery unit lost DURING an off-site run — after its own dump leg, before its push — is shipped hollow and the run reports success.** **CORRECTED 2026-09-01 04:22, and the first wording of this row OVERSTATED it.** As first filed it claimed the hollow unit sat in the store for a whole cycle because "the volume-dump leg runs on the backup schedule, not on capture". **That is wrong, and measuring it overnight is what showed it:** the off-site run has its OWN pre-push dump leg — *"Stopping calibre-web for safe volume dump"*, *"Volume dump: calibre-web/calibre-web_calibre_web_config -> 877.5 KB"* — so a unit that is hollow when a run starts is **REPAIRED before it is pushed**. Proven twice: `opengist` (2026-08-31 21:0x) and `calibre-web` (2026-09-01 04:15) both went in hollow and came out complete, and the snapshot pulled back from the store (`6fee3b5a`) holds the volume tar and all 17 userdata files. **WHAT REMAINS REAL, and it is narrower:** the one hollow snapshot that DID reach the store (`35ba9fe7`, opengist) was created when the unit was destroyed **inside** a run that had already completed opengist's dump leg — so the push shipped what the capture had just rebuilt empty, and logged *"backed up opengist (… 0 mandatory path(s))"*, **a success line over a backup holding none of the app's data**. That race is real, it was observed, and the success wording is wrong either way. **The R-403 mirror guard holds throughout** — proven live: *"unit leg SKIPPED … The copy was PRESERVED rather than replaced with an empty one"*, secondary byte-identical. | **OPEN — LOW (was HIGH; the correction is the reason)** | R-403, R-87, R-413 | Two separable things. (1) The success line: a per-app push that carried no dumps and no tars should not read as a plain success — that is a wording fix in the run's own reporting, not a new guard. (2) The race: decide whether the push should re-read the unit it is about to send, or whether the window is small enough to accept. **Do NOT guard the capture** (08 §8.2). Evidence: `audits/DRILL-soak-2026-08-31/phase2-guard-interactions/` and `phase5-mutated-cycle/09-what-reached-the-store.txt`. | CC |
|
||||
| **R-413** | **R-87's proof caught a naturally-produced hollow snapshot, end to end, unattended — the validation yesterday's session could only do with a declared hand-built fixture.** 2026-08-31 soak, demo-hp. After R-412's chain left `opengist`'s newest off-site snapshot hollow, the nightly proof rotated to it and returned **`verdict:"fail"`, `reason:"volumes_expected_none_captured"`, missing `opengist_data`**, logged *"READABLE AND EMPTY — the store is not damaged; the backup does not contain this app's data"*, and pushed **one** `offsite_proof_empty` at severity `error`. The four apps ahead of it in the rotation all passed, so the discrimination is real and not a constant fail. **This is recorded as a row rather than only as a report line because it upgrades a claim:** the capability map's R-87 row cites a CONSTRUCTED failing case; it can now cite a natural one. | **CLOSED 2026-08-31 — the claim it upgrades is recorded** | R-87, R-412 | Nothing to build. When the capability map is next touched, cite this instead of the constructed case. | CC |
|
||||
| **R-414** | **The nightly off-site PROOF is INERT on a box with no registered data drive, every night, and the only signal is a WARN in the log.** FOUND 2026-09-01 by the soak's UNTOUCHED observer, `demo-felhom`, on the first unattended run of the job — which is exactly what an untouched box was for. At 05:30 CEST the job fired, picked `opengist`, and refused: *"proof: opengist has nowhere to restore to: nincs regisztralt adatmeghajto, ezert nincs hova visszaallitani"* — `offboxRestoreScratchDir`'s R-252 refusal. **CAUSE ESTABLISHED, not inferred:** that box has **zero** registered storage paths (`storage_paths: []`), so there is no non-network schedulable path to put a scratch on. The same absence explains its `tier2-backup` completing in **3 ms** — a no-op with no second drive to mirror to. **The box is NOT unprotected:** its off-site backup ran normally in 46.9 s, because units live on the system data path, which needs no registration. **It is the PROOF that cannot run.** **WHY IT IS WORSE THAN A FAILED RUN:** the Err path reaches no verdict, so `RecordProofVerdict` is never called, so `last_proof_result` stays **ABSENT** — and absent is also what a controller older than v0.231.0 sends. **The hub therefore cannot tell "never ran" from "not deployed"**, which is the StatsKnown trap the field was explicitly designed to avoid, reappearing one level up. It will fail this way every night forever with nothing but a WARN. | **OPEN — MEDIUM** | R-87, R-402, R-252 | Decide what a box with no registered drive should do: fall back to the system data path for the scratch (it already holds the units), or record a distinct NOT-APPLICABLE verdict so the hub can tell it apart from never-ran. **Do not leave it as a WARN** — that is the shape R-397 and R-107 both cost a drill. Evidence: `audits/DRILL-soak-2026-08-31/phase6-observer/`. | CC |
|
||||
|
||||
<!-- DUE-CHECKS-BEGIN — machine-readable. Parsed by scripts/due_checks_gate.py.
|
||||
One row per dated check. The R-number must have a row above. Dates are UTC.
|
||||
|
||||
Reference in New Issue
Block a user