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.
This commit is contained in:
@@ -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 `:<tier>` **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.
|
||||
|
||||
Reference in New Issue
Block a user