R-359/R-397 closed, R-398 corrected, R-399/R-400 filed with measured numbers

THE MEASUREMENT IS THE STORY, and it re-frames the row it was filed under. A pack was corrupted WITHOUT changing its size; plain `restic check` -- the depth that ships ON -- returned `no errors were found`, exit 0. Only --read-data caught it. So the check that shipped verifies the index, the pack inventory and the snapshot graph, and does NOT re-hash pack contents. R-399 was filed as a bandwidth-and-cadence question; it is more than that, and its row now says so. R-399 gets three MEASURED numbers instead of estimates: store 140 829 678 B / 2651 blobs / 67 snapshots; structure check 35.0 s; curve 10% 35.9 s, 50% 37.3 s, 100% 39.2 s. At this size re-reading everything costs four seconds more than reading none, because the wall clock is SFTP round-trips not transfer. The row states the limit too: these do NOT extrapolate. R-400: the sweep the task asked for found EIGHT dead debug buttons, not one. 24 endpoints referenced in debug.html, 17 dispatched. Single dispatcher, exact match, default NotFound -- so they 404. A third of a debug page does nothing, on the surface an operator reaches for when something is already wrong. R-398 is CORRECTED AND LEFT OPEN, not closed. I filed it yesterday saying resticStep is not a seam so no test can drive a restic path. The layer below it has been injectable since the off-site tier shipped. The row survives as the record that the seam EXISTS so nobody re-files it. 07 gap register: R-359 and R-397 closed; R-87 restated IN PLACE as "AND IT IS NOT R-359" because the two rows are adjacent and a check is not a restore-test. 08 alarm ladder: both event types recorded, including that `ok` is `info` and therefore mails nobody BY DESIGN, and that all three registers were checked and deliberately left alone. 00 capability map: PROVEN-LIVE for the check, the notifier and the hazard control; the scheduled firing is IMPLEMENTED only, because a week has not passed. wire_contract_gate: `offsite.last_integrity_ok` allowlisted WITH A REASON. The gate was right -- the controller emits a field no hub struct can decode. Building the display is a hub change and R-331 ruled that class the operator's decision; the entry says to delete it when a surface exists. This push used `git push --no-verify`. golden-currency is CONVICTED and right: 0.227.1 is released and the golden carries 0.226.1. A BYPASS, not a waiver, and the task spec directs it -- golden and fleet delivery are Viktor's (R-242). It is item 3 under "Waiting on you". Register 163 -> 165 -> 163.
2026-08-30 21:29:37 +02:00
parent 4f875174fe
commit 99af997ab9
17 changed files with 363 additions and 14 deletions
@@ -0,0 +1,131 @@
+# R-359 / R-397 — the off-site integrity check, validated live on `demo-hp` (2026-08-30)
+
+Controller **v0.227.0**. Everything below was run on `demo-hp`; `demo-felhom`, `ep0`, DooPlex and
+Peti's box were not touched.
+
+---
+
+## ⚠ THE HEADLINE FINDING — the check that ships ON does NOT catch silent corruption
+
+This is the most important result of the run and it changes what the feature is worth.
+
+A throwaway repository was built, one pack was corrupted **without changing its size** (64 zero bytes
+written at offset 1024 — the subtlest form of bit-rot), and both depths were run against it:
+
+| depth | exit | verdict |
+|---|---|---|
+| `restic check` — **the depth that ships ON** | **0** | **`no errors were found`** |
+| `restic check --read-data` | 1 | `Pack ID does not match, want 288afd3e…, got 4b6847bb…` → `Fatal: repository contains errors` |
+| `restic check --read-data-subset=1/1` | 1 | same |
+| `restic check --read-data-subset=100%` | 1 | same |
+| `restic check --read-data-subset=50%` | 1 | same |
+
+**The structure check reported a corrupted store as healthy.** It verifies the index, the pack
+inventory and the snapshot graph — real failure modes, and it catches missing packs, broken indexes
+and unreadable snapshots. It does **not** re-hash pack contents, so it cannot see rot inside a pack
+that is still the right size.
+
+**What this means for R-399, and it is not what the task assumed.** R-399 was framed as a bandwidth and
+cadence question. It is more than that: **at the shipped default, a class of damage is not checked at
+all**, and it is the class that silently eats a customer's photos. The numbers below make the decision
+much easier than expected.
+
+> **A measurement error of my own, corrected rather than reported as a defect.** An earlier run showed
+> `exit=0` for the two subset forms while they printed `Fatal: repository contains errors`. That was
+> not restic: the commands were piped through `tail`, so `$?` was **tail's** exit code. Re-measured
+> without pipes, every read-data form exits **1**. This is the project's own "exit codes that lie"
+> trap, and it was caught by re-measuring rather than by reasoning.
+
+## The cost curve — MEASURED against the live store, not estimated
+
+Live store: **140 829 678 B (134.3 MB)**, 2 651 blobs, **67 snapshots** (`restic stats --mode raw-data`).
+
+| depth | wall-clock | over structure-only |
+|---|---|---|
+| structure only (**ships ON**) | **35.0 s** | — |
+| `--read-data-subset=10%` | 35.9 s | **+0.9 s (+3%)** |
+| `--read-data-subset=50%` | 37.3 s | +2.2 s (+6%) |
+| `--read-data-subset=100%` | **39.2 s** | **+4.2 s (+12%)** |
+
+**At this store size, re-reading ALL the data costs four seconds more than reading none.** The wall
+clock is dominated by SFTP round-trips over the WireGuard tunnel, not by transfer.
+
+**The caveat that keeps this honest:** the structure check's cost tracks the INDEX; a read-data run's
+cost tracks the DATA. These figures do not extrapolate — a 50 GB store is ~370× the data and this
+curve says nothing about it. What they do establish is that **for a store of today's size the depth
+question has almost no cost attached**, which is the fact R-399 needed and did not have.
+
+## Part 5, step by step
+
+1. **Scratch repo** at `/mnt/felhom-drives/hdd_1/r359-scratch-repo`, three files (195.4 KiB),
+   snapshot `3611a338`. Hashes recorded in `step1`–`step2`.
+2. **Negative control FIRST** (a control that has only seen the failing case proves nothing):
+   healthy repo → `no errors were found`, exit 0, **703 ms**.
+3. **Damage:** pack `288afd3e868dc6bd…217bf0cc`, 64 zero bytes at offset 1024,
+   `conv=notrunc`. Size **unchanged** at 200 333 B; sha256 moved to `4b6847bb5eec…dc496d2b`.
+4. **Positive control:** see the table above.
+5. **Teardown:** repo removed, **1 511 424 bytes** returned to `/mnt/felhom-drives/hdd_1`; guest and
+   container temp files removed; nothing else provisioned.
+
+## The live wiring, end to end
+
+**The debug button that had never done anything** (`debug.html:83` posted to
+`/api/debug/backup/integrity`; the dispatch had no case) now answers:
+
+```json
+{"data":{"duration_ms":35550,"ok":true,"read_data_subset":"","skip_reason":"","skipped":false,
+         "unreachable":false},"message":"Az ellenőrzés rendben lezajlott","ok":true}
+```
+
+**R-397's orphaned notifier has its caller, observed on real hardware:**
+
+```
+[INFO] [offbox] integrity: check PASSED in 35s (structure and index only — no pack data was downloaded)
+[DEBUG] PushEvent: type=backup_integrity_ok severity=info url=https://hub.felhom.eu/api/v1/event
+[DEBUG] PushEvent: backup_integrity_ok pushed OK (HTTP 200)
+[INFO] Event pushed: backup_integrity_ok (info) — A távoli mentés ellenőrzése rendben lezajlott. (35s)
+```
+
+Severity `info`, which `severityNotifies` drops before either leg — so it **mails nobody, by design**.
+
+**The scheduled job is registered live:**
+
+```
+[INFO] [scheduler] Daily job offsite-integrity scheduled for 2026-08-31 06:00 CEST
+daily job registered: name="offsite-integrity" schedule="06:00" nextRun=2026-08-31T06:00:00+02:00
+```
+
+## THE HAZARD CONTROL, observed live
+
+`resticStep` escalates to **`unlock --remove-all`** on a lock error, and that is only safe because
+every caller holds the single-writer flag. A check that did not take it could remove a live prune's
+lock and retry over the top of it.
+
+The intended demonstration (start an off-site backup, then run the check) **could not be performed**:
+`POST /api/backup/offbox/run` returns **404** — there is no operator-triggerable off-site backup, which
+is **R-279 and remains open**. So the same flag was exercised by its other holder: two checks fired
+6 seconds apart.
+
+```
+check B (fired while A held the flag):
+  {"skipped":true,"skip_reason":"a backup or restore is already running","duration_ms":0,"ok":false}
+check A (completed):
+  {"skipped":false,"ok":true,"duration_ms":34953}
+```
+
+`duration_ms: 0` is the observable that matters: **B never ran restic at all.** It yielded, it did not
+queue, and it did not advance due-ness.
+
+## Files
+
+| file | what |
+|---|---|
+| `step1-negative-control.txt` | healthy scratch repo passes |
+| `step2-damage.txt` | which pack, how, before/after hashes |
+| `step3-positive-control.txt` | structure check says "no errors" over the corrupted pack |
+| `step4-readdata.txt` | read-data catches it (first run; note the pipe caveat above) |
+| `step5-exit-codes.txt` | exit codes re-measured without pipes |
+| `step7-readdata-cost.txt` | store size + the four-depth cost curve |
+| `step6-live-debug-route.txt` | the live debug route against the real store |
+| `step8-skip-live.txt` | the hazard control, live |
+| `step9-teardown.txt` | scratch removed, space returned |
@@ -0,0 +1,10 @@
+### NEGATIVE CONTROL ��� healthy repo ###
+using temporary cache in /tmp/restic-check-cache-3049426411
+create exclusive lock for repository
+load indexes
+check all packs
+check snapshots, trees and blobs
+[0:00] 100.00%  1 / 1 snapshots
+
+no errors were found
+exit=0  wall_ms=703
@@ -0,0 +1,9 @@
+### the packs before damage ###
+/mnt/felhom-drives/hdd_1/r359-scratch-repo/repo/data/59/59a4f8ae6b79a6e7055679d18641f6f514364aaacb910b927a0abf13ec39e52b
+/mnt/felhom-drives/hdd_1/r359-scratch-repo/repo/data/28/288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc
+
+CHOSEN PACK: /mnt/felhom-drives/hdd_1/r359-scratch-repo/repo/data/28/288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc
+size before: 200333  sha256 before: 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc
+### DAMAGE: overwrite 64 bytes at offset 1024 with zeros (the pack stays the same SIZE, so only a content check can see it) ###
+64 bytes copied, 0.000152678 s, 419 kB/s
+size after : 200333  sha256 after : 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
@@ -0,0 +1,14 @@
+### POSITIVE CONTROL A ��� plain structure check (what ships ON by default) ###
+using temporary cache in /tmp/restic-check-cache-962728151
+create exclusive lock for repository
+load indexes
+check all packs
+check snapshots, trees and blobs
+[0:00] 100.00%  1 / 1 snapshots
+
+no errors were found
+exit=0
+
+### POSITIVE CONTROL B ��� with --read-data-subset=100%% (what ships OFF) ###
+Fatal: check flag --read-data-subset has invalid value, please see documentation
+exit=1
@@ -0,0 +1,30 @@
+### --read-data (re-reads every pack) ###
+using temporary cache in /tmp/restic-check-cache-1793499921
+create exclusive lock for repository
+load indexes
+check all packs
+check snapshots, trees and blobs
+[0:00] 100.00%  1 / 1 snapshots
+
+read all data
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+[0:00] 100.00%  2 / 2 packs
+
+Fatal: repository contains errors
+exit=1
+
+### --read-data-subset=1/1 (the n/m form) ###
+
+read group #1 of 2 data packs (out of total 2 packs in 1 groups)
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+[0:00] 100.00%  2 / 2 packs
+
+Fatal: repository contains errors
+exit=0
+
+### --read-data-subset=100% (the percent form my regex accepts) ###
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+[0:00] 100.00%  2 / 2 packs
+
+Fatal: repository contains errors
+exit=0
@@ -0,0 +1,22 @@
+### exit codes measured WITHOUT a pipe (the earlier run piped through tail and read TAIL's code) ###
+plain check                 exit=0
+--read-data                 exit=1
+--read-data-subset=1/1      exit=1
+--read-data-subset=100%   exit=1
+--read-data-subset=50%    exit=1
+
+### and what each SAID ###
+--- o1 ---
+no errors were found
+--- o2 ---
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+Fatal: repository contains errors
+--- o3 ---
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+Fatal: repository contains errors
+--- o4 ---
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+Fatal: repository contains errors
+--- o5 ---
+Pack ID does not match, want 288afd3e868dc6bd210e33bd6f821e9f088a5fd71a0464c23ce82eb8217bf0cc, got 4b6847bb5eece6c56e69d7381733827330a4eb799fc26a92287a181edc496d2b
+Fatal: repository contains errors
@@ -0,0 +1,4 @@
+started 19:07:13
+{"data":{"duration_ms":35550,"ok":true,"read_data_subset":"","skip_reason":"","skipped":false,"unreachable":false},"message":"Az ellenőrzés rendben lezajlott","ok":true}
+
+ended   19:07:52
@@ -0,0 +1,10 @@
+### live store size ###
+{"total_size":140829678,"total_file_count":0,"total_blob_count":2651,"snapshots_count":67}
+
+### --read-data-subset=10% MEASURED against the live store (READ ONLY) ###
+exit=0  wall_ms=35780
+no errors were found
+structure only (ships ON)        exit=0  wall_ms=35024  no errors were found
+--read-data-subset=10%           exit=0  wall_ms=35913  no errors were found
+--read-data-subset=50%           exit=0  wall_ms=37269  no errors were found
+--read-data-subset=100%          exit=0  wall_ms=39232  no errors were found
@@ -0,0 +1,11 @@
+--- check A (will hold the single-writer flag for ~35s) ---
+--- check B, fired WHILE A holds the flag ---
+{"data":{"duration_ms":0,"ok":false,"read_data_subset":"","skip_reason":"a backup or restore is already running","skipped":true,"unreachable":false},"message":"Kihagyva: a backup or restore is already running","ok":true}
+
+--- A finished with ---
+{"data":{"duration_ms":34953,"ok":true,"read_data_subset":"","skip_reason":"","skipped":false,"unreachable":false},"message":"Az ellenőrzés rendben lezajlott","ok":true}
+
+2026/08/30 19:14:19 offbox_integrity.go:200: [INFO] [offbox] integrity: check PASSED in 35s (structure and index only — no pack data was downloaded)
+2026/08/30 19:14:19 notifier.go:206: [DEBUG] PushEvent: type=backup_integrity_ok severity=info url=https://hub.felhom.eu/api/v1/event
+2026/08/30 19:14:20 notifier.go:232: [DEBUG] PushEvent: backup_integrity_ok pushed OK (HTTP 200)
+2026/08/30 19:14:20 notifier.go:234: [INFO] Event pushed: backup_integrity_ok (info) — A távoli mentés ellenőrzése rendben lezajlott. (35s)
@@ -0,0 +1,4 @@
+scratch repo size before removal: 1.5M (1485107 bytes)
+space returned: 1511424 bytes
+scratch repo still present? no
+guest + container temp files removed