Files
felhom-controller/REPORT.md
T
admin ccefff4f39 docs: record POSITIVE post-deploy verification for v0.176.0
The quiesce loop is silent by design when nothing is due, so 'no error lines' is
not evidence. The observable that is: every /backup/due makes the agent read that
tier's storage content, which lands in pveproxy/access.log. Both tiers polled
every 5 min, both HTTP 200, tick phase consistent with the deploy restart.
2026-07-27 16:36:30 +02:00

8.2 KiB
Raw Blame History

REPORT — R-88 Part 1: the quiesce failure breaker (v0.176.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.

What was broken

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.

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.

Phase 0 (read-only) — the three answers

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.

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.

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.

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.

What shipped

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.

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.

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:

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

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.)

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.

Deployed

gitea.dooplex.hu/admin/felhom-controller:0.176.0demo-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).

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.

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:3006:30 UTC window rather than run — correct behaviour, and it means the first live in-window backup under v0.176.0 lands tomorrow.