From ba8bf9cd755802ad9aa6d603e2684b209742cd44 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Mon, 27 Jul 2026 17:07:10 +0200 Subject: [PATCH] docs: REPORT for R-97 (controller v0.177.0 + hub v0.78.0) Includes the cooldown keying finding (per-event-type only; fixed narrowly with a tier suffix), the 180s grace window derivation, and the end-to-end event evidence with its control: the new type 200s, a bogus type 400s, and notification_log shows one operator row and zero customer rows. --- REPORT.md | 192 ++++++++++++++++++++++++++---------------------------- 1 file changed, 93 insertions(+), 99 deletions(-) diff --git a/REPORT.md b/REPORT.md index 1895440..14146ba 100644 --- a/REPORT.md +++ b/REPORT.md @@ -1,124 +1,118 @@ -# REPORT — R-88 Part 1: the quiesce failure breaker (v0.176.0) (2026-07-27) +# REPORT — R-97: a failing backup is HEARD, and stops blaming the apps (v0.177.0) (2026-07-27) -**Overwritten** per the standing rule. Controller **v0.175.0 → v0.176.0**. **MinAgent UNCHANGED** — -this is controller-internal scheduling; no agent surface is touched. +**Overwritten** per the standing rule. Controller **v0.176.0 → v0.177.0**; **hub v0.77.0 → v0.78.0** +(required — the controller emits event types the hub must allowlist). **MinAgent unchanged.** -## What was broken +## Part 0 — ops -`internal/quiesce` had **no consecutive-failure counter, no backoff and no circuit breaker of any -kind**, and the loop driver is a plain 5-minute `time.Ticker`. A tier that was due and kept failing -was therefore re-quiesced every five minutes — and a quiesce cycle stops and restarts **every -customer app stack**. +| Item | Result | +|---|---| +| **0.1 swap on ep0** | **4 GiB live and persistent.** `swapon --show` → `/swapfile file 4G`; `free -h` → `Swap: 4.0Gi`. Persistence verified **without rebooting**: `systemd-fstab-generator` produced `swapfile.swap` (`RequiredBy=swap.target`, `is-enabled: generated`, `ActiveState=active`), and `findmnt --verify --fstab` → **0 parse errors, 0 errors**. `vm.swappiness` **unchanged at the default 60** — no sysctl override added. Done ahead of Sunday's first-ever GC. | +| **0.2 R-95 mitigation** | **Snapshot plan IS set** on `storage-box-pool-1` (611714): `{"max_snapshots":7,"minute":0,"hour":0,"day_of_week":null,"day_of_month":null}` → **daily at 00:00, keep 7**. But **0 snapshots exist and `size_snapshots=0`** — it is ARMED, not yet PROVEN; the first fires tonight. The **root exposure remains open**: subaccounts are still `readonly=False` and `restic forget --prune` still runs from the box. | +| **0.3 R-91 gate** | **NOT satisfied — do not delete.** demo-felhom's newest offsite snapshot is still `2026-07-26T12:21:48Z`, i.e. **before** the volume migration (attached 2026-07-27 06:29:40 UTC). demo-hp has two post-migration (07-27 08:25:47Z, 09:37:29Z). `/srv/pbs-felhom` remains 13 G. | +| **0.4 residue** | Removed `/root/.ssh/known_hosts.pre-storagebox.bak` and stripped the 3 `u629193` lines from `/root/.bash_history` (0 remaining). `CONTEXT.md` corrected: the datastore is `/mnt/pbs-datastore`, not `/srv/pbs-felhom`. | +| **0.4 R-88 watcher** | **The first in-window scheduled backup has NOT landed, and could not have.** The window is 02:30–06:30 UTC and the fix deployed at 14:23 UTC, so the next opportunity is 2026-07-28. Last vzdump of any kind: the incident's `07:13:06Z FAIL`. This is **timing, not health** — reporting it as "quiet therefore fine" would be the absent-log-line fallacy the new rule 3 forbids. | -Observed live on demo-felhom 2026-07-27: three full cycles at 09:02:57, 09:07:58 and 09:12:57 -Budapest, each stopping and restarting `bookstack calibre-web docmost immich` (~19 s down per cycle, -~50 s per full cycle) against a PBS tier that could not succeed. **It stopped after three only -because PBS came back**, not because anything gave up. Had the outage lasted, so would the loop. +## The cooldown keying finding -## Phase 0 (read-only) — the three answers +**Per-event-type only, and it would have masked one tier with the other.** `dispatcher.go:233` keyed +the operator cooldown `customerID + ":" + eventType` with a hardcoded 1 h window. Correct for an event +describing ONE thing; wrong for one describing ONE TIER when a box has two — `felhom-pbs` failing at +09:00 would swallow `local` failing at 09:20 for the rest of the hour. -**P0.1 — case (a): agent-side.** The storage read **errored**; it was never an empty success. The -defect is a type boundary: `newestArchiveOn` (`localapi/server.go:1095-1111`) promises in its own -comment that *"errors … degrade to unknown, never to 'no backup'"*, but its `(time.Time, bool)` -signature **cannot represent unknown** — an error and a genuinely-empty storage both become -`(zero, false)`. `handleBackupDue` (`server.go:934-941`) then emits a *positive* claim: -`Due: true, Reason: "no successful backup recorded yet", AgeSecs: nil`. The fail-safe that does -exist (`targetStoragePresent` — "a storage-view error must never read as 'not there'") answers a -different question and behaved correctly. +Two clarifications that changed the fix's shape: +- it gates the **email only** — `SaveEvent` runs before dispatch, so both events are always stored; +- widening the key for **everything** would be a flood, not a fix (one hourly `app_start_failed` + becomes one per app). -**Decisive for scoping: the errored path and the genuine-never path are byte-identical on the wire.** -Same `Due`, same `Reason`, same nil `AgeSecs` — the controller has nothing to discriminate on, so -Part 2 cannot be done here. It needs an agent wire change plus a compat rule both ways → own task. +So the fix is **narrow**: `cooldownTierSuffix` appends `:` **only when the event details carry a +`tier`**. No existing event type's behaviour changes. Pinned by `TestCooldownTierSuffix_EmptyForEverythingElse`. -**P0.2 — deliberate restarts, not self-update.** Four on 2026-07-27 (07:36:39, 07:54:06, 08:50:16, -11:31:52 CEST), all clean `Stopping → Stopped → Started`, `NRestarts=0`, `Result=success`, zero -self-update lines. No automatic mechanism arms the trigger — but ordinary operator/config work armed -it four times in one day, making the trigger **more** frequent than "only when ep0 is down", not less. +## The grace window (Part 2) -**P0.3 — the loop alerted nobody.** Zero `backup_failed` events, and not because of the allowlist -(the hub carries that type). **`internal/quiesce` does not import `internal/notify` at all.** The -only trace was `07:13:27 info app_start_failed "Telepített alkalmazás nem fut: BookStack"` — a -customer-tier, Hungarian, info-severity *symptom* of the third cycle catching BookStack mid-restart. -Filed as **R-97**; out of scope here. +**`quiesceAlarmGrace = 180 s`**, derived rather than picked round: +- the **deploy flow already allows 120 s** for a stack to come up healthy — the project's own existing + answer to "how long is too long"; +- the slowest catalog healthcheck `start_period` is **Mealie's 60 s**, after which a couple of check + intervals must still elapse before a verdict means anything. -## What shipped +180 s clears both with margin, and is deliberately not longer: the app-state scan runs on its own +cadence, so a genuinely dead app alarms on the first scan after the window closes. The cost is a +**bounded delay** in reporting a real failure, never its loss. -`internal/quiesce/breaker.go` — consecutive failures per **target**; a tier inside its backoff is -dropped from the due set **before any stack is stopped**. The gate is on the QUIESCE, not the backup, -because the harm was never the failing backup but the outage taken to attempt it. +**Why a cycle-keyed window and not a state test:** v0.164.0's filter is +`IsDownState(st.State) && st.State != StateStopped` and suppresses *deliberately stopped* apps. +BookStack alarmed because the third cycle caught it **mid-restart** — `starting`/`unhealthy`, not +`StateStopped`. No state classification can distinguish "restarting because a backup stopped me" from +"restarting because I keep crashing"; the distinguishing fact is that *we* stopped it, and we know it. +Consumed at the **same single derivation point** (`classifyRunStates`) that computes both the banner +dead-list and the notifier Down-set — still one place. -**Backoff `15m → 30m → 1h → 2h → 4h`, then 4h forever.** The cap is chosen against two real -constants: 4 h sits well inside the shortest tier cadence (local 24 h), so a recovered tier still -gets several attempts within its own cadence; and it equals the width of the window gate -`[W+2h, W+6h)`, so a tier at maximum backoff still gets at least one attempt inside any given -night's window rather than stepping over it. +## Tests — controller 27 pkg ok / hub 17 pkg ok, 0 failed; `build`/`vet`/`test` each rc=0, run separately, vet unpiped -Bounded four ways, each with a test: **never permanent** (the cap bounds the interval, never stops -retrying — a latched breaker is a silent backup outage, worse than the loop); **never global**; -**never gates `TriggerNow`** (manual runs still record their outcome, so a manual success clears the -backoff); **`stillRunning` is not a failure** (a first full offsite snapshot legitimately runs for -hours). State is **in-memory on purpose** — a restart forgets the backoff and re-attempts, the cheap -direction to fail. - -**Part 3** — the invariant is written at the head of `scheduledRunAllowed`: a missing value means -UNKNOWN, and only a *positive* "never backed up" may fire the safety valve. Fourth instance of the -class (hub v0.12.0, v0.73.0, R-81, R-88), all four named in the comment. - -## Tests — 27 packages ok, 0 failed; `build` / `vet` / `test` each rc=0, run separately - -11 new: 7 breaker + 4 contract. Three red-proofs, each observed and restored: +Controller +9 (8 quiesce + 1 wiring reachability); hub +8. Red-proofs observed and restored: | Scenario | Mutation | Observed failure | |---|---|---| -| **A** | remove the `dropBackedOffTiers` call | `R-88: 3 failing ticks stopped the apps 3 time(s); want 1 — the breaker did not defer anything` | -| **D** | flip the nil branch to `return false` | `CONTRACT VIOLATED: a never-backed-up box outside its window did NOT back up (0 stack stop(s)) — the safety valve was removed; a box only ever powered on outside its window would starve` | -| **F** | make the breaker global (any blocked tier halts all) | `R-88 Scenario F: the healthy local tier was backed up 2 time(s) across 4 ticks; want >= 3 — a broken tier must not halt a working one` | +| **C** | key the breaker on a constant (one global failure record) | `both tiers must be reported; got local=1 felhom-pbs=0 — one broken tier must not mask another` | +| **E** | `SuppressedStacks` returns nil (pre-fix shape) | `R-97b: the apps we stopped for a backup must not be reported down; bookstack still alarmed` | +| **F** | suppression never expires (permanent) | `CONTRACT VIOLATED: suppression must EXPIRE — bookstack is still suppressed 3m1s after the cycle; permanent suppression is a silent real alarm` | -**Scenario A asserts a COUNT, not a log line** — the harm is the stop/start pairs, so the test counts -them, at the exact incident cadence: 3 failing ticks → **3 pairs before the fix, 1 after**. -(Deleting the D branch outright panics on the nil deref two lines down; `return false` is the -mutation a real over-correction would produce, so that is the one recorded.) +## The end-to-end event evidence -**How Scenario D is preserved:** the nil branch of `scheduledRunAllowed` is untouched and still fires -the valve, so a genuinely never-backed-up box powered on only outside its window still backs up. -`TestContract_NeverBackedUp_RunsOutsideTheWindow` pins it; -`TestContract_RecentBackup_DefersOutsideTheWindow` is the control (without it the first test would -also pass against a gate that was simply disabled); and -`TestContract_BreakerNeverStarvesAFirstBackup` proves the breaker cannot starve a first backup either. +**Induced deliberately, and it travelled.** A real `whole_guest_backup_failed` was POSTed from **inside +guest 9201**, with the controller's own hub URL and API key, over the live `/api/v1/event` route — the +exact path `PushEvent` uses. Message prefixed `[R-97a VERIFICATION - induced by Claude Code, NOT a real +fault]`, details `{"tier":"felhom-pbs",...}`. + +``` +1. the new type → HTTP 200 {"ok":true} +2. CONTROL: bogus type → HTTP 400 "Invalid event_type: whole_guest_backup_bogus" +``` + +The control matters: without it, a 200 is equally consistent with "my type is allowlisted" and "the +gate is off". At the far end, from a **freshly copied** hub DB (mtime checked — a stale copy already +produced one confident wrong answer today): + +``` +events: 2026-07-27 15:04:57 error whole_guest_backup_failed [R-97a VERIFICATION …] +notification_log: 2026-07-27 15:04:58 whole_guest_backup_failed channel=operator status=sent + OPERATOR rows: 1 CUSTOMER rows: 0 +``` + +**Operator notified, customer not** — the operator-only property confirmed positively, not assumed. +No storage target was altered and nothing was pointed at a dead endpoint, so nothing needed restoring. ## Deployed -`gitea.dooplex.hu/admin/felhom-controller:0.176.0` — **demo-hp first, then demo-felhom**, both -`Up … (healthy)`, both image digests matching the DooPlex build byte-for-byte -(`sha256:98fcbc677bfa1ab8…`), both logging `[quiesce] loop started (poll 5m0s, max-quiesce 30m0s)`. +- **hub v0.78.0** — GitOps: manifest bumped, ArgoCD hard-refresh + deliberate sync → `Synced`, + rollout complete, pod image `felhom-hub:0.78.0`, startup clean. **Deployed FIRST**, so the + controller never emits a type the hub would 400. +- **controller v0.177.0** — demo-hp first, then demo-felhom; both `Up (healthy)`. -**Positive confirmation the loop still works, not merely the absence of complaints.** The quiesce -loop is *silent by design* when nothing is due (`len(dueTiers) == 0 → return nil`), so "no error -lines" proves nothing on its own. The observable that does prove it is the agent's per-tier -due-check: every `/backup/due` makes the agent read that tier's storage content (R-84 ground truth), -which lands in `pveproxy/access.log`. On demo-felhom after the deploy: - -``` -16:28:44 +0200 GET …/storage/local/content 200 -16:28:45 +0200 GET …/storage/felhom-pbs/content 200 -16:33:44 +0200 GET …/storage/local/content 200 -16:33:45 +0200 GET …/storage/felhom-pbs/content 200 -``` - -Both tiers polled every 5 minutes, both answering **200** — so the loop is ticking, both tiers are -being evaluated, and the storage reads succeed (real ages, no nil, no valve firing). The tick phase -shifted from `:02:57/:07:58/:12:57` to `:28:44/:33:44`, which is the 14:23:43 UTC restart resetting -the ticker — consistent with the deploy and nothing else. **Zero backoff or deferral lines on either -box**, and no vzdump attempted since the incident's last failure at 07:13:06 UTC. +Post-deploy on both boxes: **0 spurious suppression/backoff lines, 0 startup errors**, quiesce loop +started, all app stacks up (10 on demo-felhom, 3 on demo-hp). The positive observable still lands — +both tiers polled every 5 min with `200`s in `pveproxy/access.log`. ## NOT yet live-validated -- **The loop was reproduced in UNIT TESTS ONLY.** Reproducing it live needs PBS unavailable, and ep0 - must not be taken down for it — a live DR tier on a box with no swap that already OOM'd once today - (R-90). No non-production controller was stood up. -- **No backoff has armed on real hardware** — both boxes are healthy, so what is verified live is the - negative: it does not fire spuriously. -- **Scenario C is not fixed and not testable here** → R-88 Part 2 (agent). -- demo-felhom's local tier becomes due ~2026-07-27 14:53 UTC; with a real age (~24 h, under - cadence+24 h) it should **defer** to the 02:30–06:30 UTC window rather than run — correct - behaviour, and it means the first live in-window backup under v0.176.0 lands tomorrow. +- **The quiesce → notify link is UNIT-PROVEN ONLY.** The hub half is proven live end-to-end with a + control (above), and the adapter's reachability is pinned by `TestQuiesceTierNotifierIsWired` — but + no real quiesce failure has fired the seam on hardware, because inducing one means an app outage on + a demo box. The join is proven by test + inspection, not observation. +- **No R-88 backoff has ever armed on real hardware.** Both boxes are healthy, so the breaker's + behaviour under a failing tier still rests on unit tests alone. Unchanged by this task. +- **R-97b's suppression has never fired live** — it needs a real quiesce cycle, i.e. tomorrow's + in-window backup at the earliest. +- **The 180 s grace has not been measured against a real restart** on these boxes; it is derived from + the deploy flow's 120 s and Mealie's 60 s, not observed. +- **The snapshot plan (0.2) is armed but has taken 0 snapshots** — first one due tonight at 00:00. +- **demo-felhom's first in-window scheduled backup** under v0.176.0/v0.177.0 lands 2026-07-28 at the + earliest. + +## OPEN-ITEMS rows touched + +**Closed:** R-97 (both halves shipped) · R-96 (three standing rules committed to `CLAUDE.md`) · +R-90 (swap done; the CX33 rescale stays open as the durable fix). +**Re-ranked:** R-95 split — mitigation ARMED (awaiting first snapshot), root exposure still READY. +**Unchanged:** R-91 (gate not satisfied) · R-88b (agent wire change) · R-86 · R-87.