From 079265ad8e66e36ebc22d25410ea8e56bb714491 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 28 Jul 2026 08:50:11 +0200 Subject: [PATCH] F-CRIT-1 + F-A1: one alarm that never fired, one that fired wrongly (v0.179.0) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit F-CRIT-1 — an app that failed to restart after a quiesce never alarmed, for two independent reasons, either of which alone kept it dead: 1. restartAll returned nothing, so the failure was logged and dropped and no caller could learn a customer's app had not come back. It now returns the stacks that failed; both call sites record the outcome. 2. classifyRunStates whitelists StateStopped on invariant I1 ('StateStopped means the user stopped it'). The quiesce loop stops stacks by the same compose-down path, so a failed restart is also StateStopped and was whitelisted into silence. Loop.FailedRestarts() is now the only thing that lifts the whitelist, so genuine user stops stay silent (v0.164.0 pinned). F-A1 — HTTP 409 is the agent's single-flight gate refusing while a restore-test holds it, not a failure. agentapi now returns a typed *StatusError on POST, the adapter maps 409 -> quiesce.ErrTierBusy, and the loop defers: no breaker, no event, no operator email, tier stays DUE. Two traps avoided. Silence: contention outliving contentionAlarmAfter (3h, set by the agent's own 120m PBS restore-test ceiling) raises its own BLOCKED signal. App thrash: removing the failure treatment also removes the breaker's deferral, so a contended tier is dropped BEFORE anything stops (contentionRetryAfter 15m, against a 12m01s longest observed restore-test). Three comments corrected; the invariant rule added to both CLAUDE.md copies. Six red-proofs, all observed failing. --- CHANGELOG.md | 66 ++++++ .../cmd/controller/classify_runstates_test.go | 6 +- .../failed_restart_classify_test.go | 122 +++++++++++ controller/cmd/controller/main.go | 67 ++++-- controller/internal/agentapi/client.go | 25 ++- controller/internal/quiesce/contention.go | 146 +++++++++++++ .../internal/quiesce/contention_test.go | 201 ++++++++++++++++++ .../internal/quiesce/failed_restart_test.go | 130 +++++++++++ controller/internal/quiesce/quiesce.go | 90 +++++++- controller/internal/quiesce/suppress.go | 60 ++++++ 10 files changed, 884 insertions(+), 29 deletions(-) create mode 100644 controller/cmd/controller/failed_restart_classify_test.go create mode 100644 controller/internal/quiesce/contention.go create mode 100644 controller/internal/quiesce/contention_test.go create mode 100644 controller/internal/quiesce/failed_restart_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index eb864f0..661c8dd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,71 @@ ## Changelog +### v0.179.0 — F-CRIT-1 + F-A1: one alarm that never fired, one that fired wrongly (2026-07-28) + +Both Campaign 8 findings live in `internal/quiesce` and its `classifyRunStates` consumer, and both +are "the alarm is wrong" — one missing, one spurious. Fixed together, one pass over the same code. + +#### F-CRIT-1 — an app that failed to restart after a quiesce NEVER alarmed. **Two independent causes; either alone kept it dead.** + +*Cause 1 — the outcome was thrown away.* `restartAll` returned nothing; a failed `StartStack` was +logged and dropped on the spot, so no caller could learn a customer's app had not come back. It now +**returns the stacks that failed**, and both call sites (the cycle's unquiesce and crash recovery) +record the result. + +*Cause 2 — a documented invariant the quiesce path had made false.* `classifyRunStates` whitelists +`StateStopped` because v0.164.0 (correctly) refused to alarm on deliberate user stops, resting on +I1: *"StateStopped means deployed, deliberately stopped by the user."* **The quiesce loop stops +stacks by the same `docker compose down` path**, so a stack it stopped and then failed to restart is +also `StateStopped` — byte-identical to a user stop on the Docker side — and was whitelisted into +total silence. Campaign 8 watched a customer app sit dead indefinitely with no banner, no event and +no email while the dead-app scanner ran over it 11 times. + +No state test can separate the two; they *are* the same state. The distinguishing fact is that the +loop **tried to restart it and could not**, which it now reports via `Loop.FailedRestarts()`. That +set is the only thing that lifts the whitelist, so genuine user stops stay silent (pinned by +`TestClassifyRunStates_UserStopStillSilent`). + +*Why the existing tests missed it:* R-97b's Scenario F asserted that **suppression expires**. It +never asserted that **an alarm follows**. The suppression lifted correctly and the whitelist ate the +alarm one layer down — a green, red-proofed suite over a production path broken two ways. + +#### F-A1 — a correct refusal reported as a failure + +HTTP 409 from `POST /backup` is the agent's R-85 single-flight gate refusing while a restore-test +holds it. The start path had no 409 branch, so it called `noteTierFailure`: the R-88 breaker armed +and `whole_guest_backup_failed` was emailed. Campaign 8 saw it on both boxes in the same minute. +At real cadences a ~12-minute restore-test against a daily backup collides roughly once per 420 +guest-days — about **every 4 days on a 100-guest fleet, forever** — which trains the operator to +ignore the alarm and quietly undoes R-97a. + +409 is now **contention, not failure**: `agentapi` returns a typed `*StatusError` on POST, the +adapter maps 409 → `quiesce.ErrTierBusy` (the same seam that maps 404 → `ErrTiersUnsupported`), and +the loop defers instead of failing. No breaker, no event, no email; the tier stays **DUE**. + +**Two traps this deliberately avoids.** *Silence:* "just ignore 409" would let a wedged +restore-test block backups forever with nobody told — so contention lasting past +`contentionAlarmAfter` (**3h**) raises its own signal, headlined **BLOCKED**, not FAILED. The bound +is set by the agent's own ceiling, not taste: its PBS restore-test task is capped at 120 minutes, so +contention outliving that is a stuck gate rather than a busy one; 3h adds margin and is 15× the +longest contention actually observed (12m01s). *App thrash:* removing the failure treatment also +removes the breaker's deferral, which had been (accidentally) preventing a re-quiesce every 5 +minutes. Without a replacement the customer's apps would be stopped and restarted on **every poll** +for the whole restore-test — worse than the bug. A contended tier is therefore dropped from the due +set **before anything stops**, on a `contentionRetryAfter` of 15m (the longest observed restore-test +is 12m01s; the agent's local restore-test wait is 10m). + +#### Comments corrected (three of the six) +`classifyRunStates`' I1 now states what `StateStopped` actually means and names the quiesce path; +`quiesce.go`'s "would record a spurious failure" says that this was not hypothetical until now; and +the agent's `inflight.go` "a caller that cannot acquire DEFERS" records that this was true of the +restore-test caller and not the backup caller. A standing rule was added to both copies of +`CLAUDE.md`: **a comment asserting an invariant needs a test pinning it, or it is a wish.** + +Files: `internal/quiesce/{quiesce.go,suppress.go,contention.go (new)}`, +`internal/agentapi/client.go`, `cmd/controller/main.go`, plus new tests +`internal/quiesce/{failed_restart_test.go,contention_test.go}` and +`cmd/controller/failed_restart_classify_test.go`. No wire/contract change; no agent behaviour change. + ### v0.178.0 — R-88 Part 2 (controller) + R-97c comment fix (2026-07-27) — **MinAgent: 0.105.0** for the age_state semantics **The safety valve now needs a licence.** `scheduledRunAllowed` fired on ANY nil age — "no recorded diff --git a/controller/cmd/controller/classify_runstates_test.go b/controller/cmd/controller/classify_runstates_test.go index 52aa3ae..31ca4b4 100644 --- a/controller/cmd/controller/classify_runstates_test.go +++ b/controller/cmd/controller/classify_runstates_test.go @@ -56,7 +56,7 @@ func TestClassifyRunStates_StoppedIsSuppressed(t *testing.T) { stack("nextcloud", stacks.StateDegraded, true, false), } - dead, states := classifyRunStates(sts, nil) + dead, states := classifyRunStates(sts, nil, nil) gotDead := deadNames(dead) if len(gotDead) != 2 || !gotDead["immich"] || !gotDead["nextcloud"] { @@ -90,7 +90,7 @@ func TestClassifyRunStates_FaultParity(t *testing.T) { stack("nextcloud", stacks.StateDegraded, true, false), } - dead, states := classifyRunStates(sts, nil) + dead, states := classifyRunStates(sts, nil, nil) gotDead := deadNames(dead) if len(gotDead) != 2 || !gotDead["immich"] || !gotDead["nextcloud"] { @@ -116,7 +116,7 @@ func TestClassifyRunStates_SkipsDeployingAndUndeployed(t *testing.T) { stack("mid", stacks.StateDeploying, true, true), // mid-deploy → skipped stack("gone", stacks.StateExited, false, false), // not deployed → skipped } - dead, states := classifyRunStates(sts, nil) + dead, states := classifyRunStates(sts, nil, nil) if len(dead) != 0 || len(states) != 0 { t.Fatalf("deploying and undeployed stacks must be skipped, got dead=%+v states=%+v", dead, states) } diff --git a/controller/cmd/controller/failed_restart_classify_test.go b/controller/cmd/controller/failed_restart_classify_test.go new file mode 100644 index 0000000..123260a --- /dev/null +++ b/controller/cmd/controller/failed_restart_classify_test.go @@ -0,0 +1,122 @@ +package main + +import ( + "testing" + + "gitea.dooplex.hu/admin/felhom-controller/internal/stacks" +) + +// F-CRIT-1 cause 2 (Campaign 8): `classifyRunStates` whitelisted StateStopped on invariant I1 +// ("StateStopped means the USER stopped it"). The quiesce loop broke I1 by stopping stacks via the +// same `docker compose down` path, so a stack quiesce stopped and then FAILED to restart was also +// StateStopped — and was whitelisted into total silence. Live evidence: a customer app dead +// indefinitely, no banner, no event, no email, while the dead-app scanner ran 11 times over it. +// +// The two cases are byte-identical on the Docker side. The ONLY thing that separates them is that +// the quiesce loop knows it tried to restart and could not — `failedRestart` is that knowledge. + +// Scenario A (cause 2) — a stack quiesce failed to restart MUST alarm, despite being StateStopped. +// +// RED-PROOF: restore the unconditional whitelist (`down := IsDownState(st.State) && +// st.State != stacks.StateStopped && !quiesced[st.Name]`) → immich reports Down=false and stays out +// of the dead list, and this fails with "a stack that FAILED to restart is silent". +func TestClassifyRunStates_FailedRestartAlarmsDespiteStateStopped(t *testing.T) { + sts := []stacks.Stack{ + stack("bookstack", stacks.StateRunning, true, false), + stack("immich", stacks.StateStopped, true, false), // quiesce stopped it; restart FAILED + } + failed := map[string]bool{"immich": true} + + dead, states := classifyRunStates(sts, nil, failed) + + if !downByName(states)["immich"] { + t.Error("a stack that FAILED to restart is silent (Down=false) — this is F-CRIT-1") + } + if !deadNames(dead)["immich"] { + t.Error("a stack that FAILED to restart is absent from the dashboard dead-list — this is F-CRIT-1") + } + if downByName(states)["bookstack"] { + t.Error("a healthy running stack was marked down") + } +} + +// Scenario B — a DELIBERATE user stop must still be silent. This pins v0.164.0 and is what stops +// the fix above from becoming a regression. +// +// RED-PROOF: make the whitelist unconditional in the other direction (drop the `&& !failedRestart` +// term, i.e. treat every StateStopped as a failed restart) → cwa alarms and this fails with +// "a deliberate user stop alarmed". +func TestClassifyRunStates_UserStopStillSilent(t *testing.T) { + sts := []stacks.Stack{ + stack("cwa", stacks.StateStopped, true, false), // the user stopped this from the UI + stack("immich", stacks.StateStopped, true, false), + } + // only immich failed to restart; cwa was never touched by a quiesce + failed := map[string]bool{"immich": true} + + dead, states := classifyRunStates(sts, nil, failed) + down := downByName(states) + + if down["cwa"] || deadNames(dead)["cwa"] { + t.Error("a deliberate user stop alarmed — that is the v0.164.0 regression this must not reintroduce") + } + if !down["immich"] { + t.Error("the failed restart went silent") + } +} + +// Scenario B, stronger form — with NO failed restarts at all, behaviour is byte-identical to +// v0.164.0: every StateStopped is silent. +func TestClassifyRunStates_NoFailedRestartsIsV0164Behaviour(t *testing.T) { + sts := []stacks.Stack{ + stack("radarr", stacks.StateRunning, true, false), + stack("cwa", stacks.StateStopped, true, false), + stack("immich", stacks.StateExited, true, false), + stack("nextcloud", stacks.StateDegraded, true, false), + } + + dead, states := classifyRunStates(sts, nil, nil) + down := downByName(states) + + if down["cwa"] { + t.Error("stopped alarmed with no failed restarts — v0.164.0 behaviour broken") + } + if !down["immich"] || !down["nextcloud"] { + t.Error("a genuine fault (exited/degraded) stopped alarming") + } + if got := len(deadNames(dead)); got != 2 { + t.Errorf("dead list has %d entries, want exactly {immich, nextcloud}", got) + } +} + +// Scenario C — during the R-97b grace window the stack is suppressed even if its restart failed. +// The grace exists so a slow-starting app is not called dead; it EXPIRES, and the alarm follows. +// +// RED-PROOF: drop the `&& !quiesced[st.Name]` term → the app alarms mid-restart on every normal +// backup, which is the false-alarm R-97b was built to remove. +func TestClassifyRunStates_GraceWindowStillSuppresses(t *testing.T) { + sts := []stacks.Stack{stack("immich", stacks.StateStopped, true, false)} + quiesced := map[string]bool{"immich": true} // still inside quiesceAlarmGrace + failed := map[string]bool{"immich": true} // and we already know the restart failed + + dead, states := classifyRunStates(sts, quiesced, failed) + + if downByName(states)["immich"] { + t.Error("alarmed while still inside the grace window — R-97b Scenario E broken") + } + if len(dead) != 0 { + t.Errorf("dead list not empty during grace: %v", deadNames(dead)) + } +} + +// An undeployed or mid-deploy stack is never classified, failed restart or not. +func TestClassifyRunStates_UndeployedIgnored(t *testing.T) { + sts := []stacks.Stack{ + stack("ghost", stacks.StateStopped, false, false), + stack("deploying", stacks.StateStopped, true, true), + } + dead, states := classifyRunStates(sts, nil, map[string]bool{"ghost": true, "deploying": true}) + if len(dead) != 0 || len(states) != 0 { + t.Errorf("undeployed/deploying stacks were classified: dead=%v states=%v", deadNames(dead), states) + } +} diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 300618a..9310556 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -1203,26 +1203,39 @@ func runBootReconcile(ctx context.Context, mgr bootrecon.StackProvider, logger * func scanDeployedAppRunStates(mgr *stacks.Manager, q *quiesce.Loop) ([]web.DeadApp, []notify.AppRunState) { // R-97b: a stack THIS controller stopped for a backup is not a fault. q may be nil (unprovisioned // guest) — SuppressedStacks is nil-safe and returns nothing, i.e. suppress nothing. - return classifyRunStates(mgr.GetStacks(), q.SuppressedStacks()) + return classifyRunStates(mgr.GetStacks(), q.SuppressedStacks(), q.FailedRestarts()) } // classifyRunStates is the pure fix-3 derivation over a plain stack slice. It splits the deployed // apps into the DEAD list (dashboard banner) and the per-app run states (notifier transition tracker). // // v0.164.0: a deliberate user stop is NOT a fault and must not alarm anywhere (banner OR email). The -// down predicate therefore EXCLUDES StateStopped, resting on two invariants: -// - I1: the UI stop path Manager.StopStack runs `docker compose down` → containers are removed, and -// a deployed stack with zero containers aggregates to StateStopped (manager.go refreshStatusLocked). -// So StateStopped means "deployed, deliberately stopped by the user". -// - I2: the P2 restart-policy census (2026-07-21, 53 templates / 78 services) found every catalog -// service on `unless-stopped`, so a crashing app never comes to rest at `stopped` — faults surface -// as StateExited / StateDegraded (and restarting/unhealthy). StateStopped is therefore never a fault. +// down predicate therefore excludes StateStopped — but NOT unconditionally. That exclusion rested on +// two invariants, and F-CRIT-1 (Campaign 8) showed the first of them had already become false: // -// If either invariant changes, revisit this suppression. (An out-of-band `docker compose stop` leaves -// the containers present → StateExited → still alerts, which is correct: out-of-band tampering IS -// reportable.) IsDownState is intentionally left unchanged — other callers rely on stopped counting as -// down; the suppression is a filter at this single derivation point only. -func classifyRunStates(sts []stacks.Stack, quiesced map[string]bool) ([]web.DeadApp, []notify.AppRunState) { +// - I1 (AS WRITTEN, AND WRONG): "the UI stop path Manager.StopStack runs `docker compose down` → +// containers are removed → a deployed stack with zero containers aggregates to StateStopped, so +// StateStopped means 'deployed, deliberately stopped by the user'." +// **The quiesce loop stops stacks by the SAME path.** So a stack that a backup quiesce stopped and +// then FAILED to restart is also StateStopped — byte-identical to a user stop on the Docker side — +// and the whitelist swallowed it. Campaign 8 observed a customer app dead indefinitely with no +// banner, no event and no email, while the dead-app scanner ran 11 times over it. +// - I2 (still true): the P2 restart-policy census (2026-07-21, 53 templates / 78 services) found +// every catalog service on `unless-stopped`, so a CRASHING app never comes to rest at `stopped` — +// faults surface as StateExited / StateDegraded (and restarting/unhealthy). +// +// I1 RESTATED, TRUE AS OF v0.179.0: StateStopped means "deployed with zero containers", which is +// EITHER a deliberate user stop OR a quiesce restart that failed. No state test can tell them apart, +// because they are the same state. The distinguishing fact is not in the state at all — it is that +// the quiesce loop TRIED to restart the stack and could not, which it now reports via +// Loop.FailedRestarts(). `failedRestart` is that set, and it is the ONLY thing that lifts the +// StateStopped whitelist. +// +// (An out-of-band `docker compose stop` leaves the containers present → StateExited → still alerts, +// which is correct: out-of-band tampering IS reportable.) IsDownState is intentionally left unchanged +// — other callers rely on stopped counting as down; the suppression is a filter at this single +// derivation point only. +func classifyRunStates(sts []stacks.Stack, quiesced map[string]bool, failedRestart map[string]bool) ([]web.DeadApp, []notify.AppRunState) { var dead []web.DeadApp var states []notify.AppRunState for _, st := range sts { @@ -1234,7 +1247,11 @@ func classifyRunStates(sts []stacks.Stack, quiesced map[string]bool) ([]web.Dead // mid-restart is `starting`/`unhealthy`, not StateStopped, so v0.164.0's state filter above // cannot see it. The window EXPIRES (quiesceAlarmGrace): an app that genuinely fails to come // back still alarms on the first scan after it closes. - down := stacks.IsDownState(st.State) && st.State != stacks.StateStopped && !quiesced[st.Name] + // F-CRIT-1: StateStopped is whitelisted as a deliberate user stop UNLESS the quiesce loop + // reports that it stopped this stack and could not restart it. That single term is what turns + // an indefinitely-silent dead app back into an alarm, without re-alarming genuine user stops. + userStopped := st.State == stacks.StateStopped && !failedRestart[st.Name] + down := stacks.IsDownState(st.State) && !userStopped && !quiesced[st.Name] states = append(states, notify.AppRunState{Name: st.Name, DisplayName: st.Meta.DisplayName, Down: down}) if down { dead = append(dead, web.DeadApp{Name: st.Name, DisplayName: st.Meta.DisplayName, State: string(st.State)}) @@ -1712,7 +1729,7 @@ func (b quiesceBackend) Due(ctx context.Context) (bool, *int64, error) { } func (b quiesceBackend) StartBackup(ctx context.Context) (string, error) { r, err := b.c.StartBackup(ctx) - return r.JobID, err + return r.JobID, mapBusy(err) // F-A1: the untargeted (pre-R-82) path can 409 identically } func (b quiesceBackend) BackupStatus(ctx context.Context) (string, error) { r, err := b.c.BackupStatus(ctx) @@ -1749,7 +1766,25 @@ func (b quiesceBackend) DueFor(ctx context.Context, target string) (bool, *int64 } func (b quiesceBackend) StartBackupFor(ctx context.Context, target string) (string, error) { r, err := b.c.StartBackupFor(ctx, target) - return r.JobID, err + // F-A1: translate the agent's HTTP 409 into the loop's vocabulary, exactly as Tiers translates a + // 404 into ErrTiersUnsupported. 409 means the agent's R-85 single-flight gate refused because a + // restore-test (or another backup) holds it — CONTENTION, not failure. `internal/quiesce` keeps + // no dependency on `internal/agentapi`, so the mapping belongs here at the seam. + return r.JobID, mapBusy(err) +} + +// mapBusy converts a 409 from the agent into quiesce.ErrTierBusy, preserving the original error for +// diagnosis. Any other status passes through untouched — treating a real 5xx as contention would +// swallow genuine failures, which is the over-correction F-A1's fix must not make. +func mapBusy(err error) error { + if err == nil { + return nil + } + var se *agentapi.StatusError + if errors.As(err, &se) && se.Code == http.StatusConflict { + return fmt.Errorf("%w: %v", quiesce.ErrTierBusy, err) + } + return err } func (b quiesceBackend) BackupStatusFor(ctx context.Context, target string) (string, error) { r, err := b.c.BackupStatusFor(ctx, target) diff --git a/controller/internal/agentapi/client.go b/controller/internal/agentapi/client.go index 46542a5..ef0e36c 100644 --- a/controller/internal/agentapi/client.go +++ b/controller/internal/agentapi/client.go @@ -1089,13 +1089,28 @@ func (c *Client) HostMetrics(ctx context.Context) (HostMetricsResponse, error) { // StatusError is a non-2xx agent HTTP status surfaced as a TYPED error (same text the old // fmt.Errorf produced). errors.As-able — the capability probe (features.go) keys on Code 404 to // distinguish "this agent predates the route" from every other failure. Never match the string. +// StatusError is a non-2xx response from the agent, carrying the STATUS CODE so callers can react +// to specific ones rather than string-matching an error message. +// +// F-A1: this exists on the POST path because HTTP 409 from `POST /backup` is not a failure — it is +// the agent's R-85 single-flight gate correctly refusing while a restore-test holds it. Treating +// that refusal as a tier failure armed the breaker and emailed the operator about a backup that was +// never actually broken. The controller now needs to tell 409 apart from a real error, and a typed +// code is the only honest way to do that. type StatusError struct { - Path string - Code int + // Method is the HTTP method. Empty means GET, so the message stays byte-identical for the + // pre-existing GET call sites. + Method string + Path string + Code int } func (e *StatusError) Error() string { - return fmt.Sprintf("agentapi: GET %s: HTTP %d", e.Path, e.Code) + m := e.Method + if m == "" { + m = http.MethodGet + } + return fmt.Sprintf("agentapi: %s %s: HTTP %d", m, e.Path, e.Code) } // get issues an authenticated GET and unwraps the {ok,data,error} envelope. @@ -1152,7 +1167,9 @@ func (c *Client) post(ctx context.Context, path string, body any) (json.RawMessa logx.Debugf(c.logger, "[agentapi] POST %s -> %d (%dms)", path, resp.StatusCode, time.Since(start).Milliseconds()) raw, _ := io.ReadAll(io.LimitReader(resp.Body, 1<<20)) if resp.StatusCode != http.StatusOK && resp.StatusCode != http.StatusAccepted { - return nil, fmt.Errorf("agentapi: POST %s: HTTP %d", path, resp.StatusCode) + // Typed, not fmt.Errorf: callers must be able to distinguish 409 (the agent's single-flight + // gate refusing — contention, not failure) from a genuine 5xx. See StatusError. + return nil, &StatusError{Method: http.MethodPost, Path: path, Code: resp.StatusCode} } var env apiResponse if err := json.Unmarshal(raw, &env); err != nil { diff --git a/controller/internal/quiesce/contention.go b/controller/internal/quiesce/contention.go new file mode 100644 index 0000000..90083c9 --- /dev/null +++ b/controller/internal/quiesce/contention.go @@ -0,0 +1,146 @@ +package quiesce + +import ( + "errors" + "sync" + "time" +) + +// F-A1 — contention is not failure, but unending contention is. +// +// THE BUG THIS EXISTS TO KILL. The agent refuses a backup with HTTP 409 while a restore-test holds +// its R-85 single-flight gate. That refusal is the gate working exactly as designed — nothing is +// broken, the backup simply cannot run this minute. The controller's start path had no 409 branch, +// so it called noteTierFailure: the R-88 breaker armed and `whole_guest_backup_failed` was emailed +// to the operator. Campaign 8 saw it on BOTH boxes in the same minute. +// +// Two comments in the tree asserted the opposite and were wrong: +// - inflight.go (agent): "A caller that cannot acquire DEFERS to its next cadence" — the backup +// caller did not defer, it recorded a failure. +// - quiesce.go: framed the agent's 409 as the thing that PREVENTS "a spurious failure" — on the +// start path it produced one. +// +// FREQUENCY IS WHY IT MATTERS. Campaign 8's rate was an artifact of compressed cadences, but at real +// cadences a ~12-minute restore-test against a daily backup collides on the order of once per 420 +// guest-days — roughly every 4 days on a 100-guest fleet, forever. An alarm that cries wolf on a +// schedule trains the operator to ignore it, which quietly undoes R-97a. +// +// ── THE TRAP THIS DELIBERATELY AVOIDS ──────────────────────────────────────────────────────── +// +// "Just ignore 409" would trade a false alarm for a SILENCE PATH: a wedged restore-test that never +// releases the gate would mean the backup never runs and nobody is ever told. That is the exact +// class of fault this whole arc has been closing. So contention DEFERS, and persistent contention +// ALARMS — see contentionAlarmAfter. +// +// ── AND THE SECOND TRAP: APP THRASH ────────────────────────────────────────────────────────── +// +// Removing the failure treatment also removes the R-88 breaker's deferral, which is what had been +// (accidentally) stopping the loop from re-quiescing every 5 minutes. Without a replacement, the +// customer's apps would be stopped and restarted on EVERY poll for the whole duration of a +// restore-test — strictly worse than the bug being fixed. So a contended tier is dropped from the +// due set BEFORE anything is stopped, exactly as R-88 does for failures. + +const ( + // contentionRetryAfter is how long a contended tier is skipped before trying again. + // + // Measured against the real thing, not picked round: restore-test durations observed on the + // fleet during Campaign 8 were 1m29s, 6m09s, 7m20s and 12m01s, and the agent's own wait on a + // LOCAL restore-test task is 10m. 15m therefore clears the realistic case in a single hop while + // capping app-stop churn during a long restore-test at 4/hour instead of 12/hour. + // + // It is deliberately NOT longer: the tier stays DUE throughout, and a needlessly long skip just + // delays a backup that could have run. + contentionRetryAfter = 15 * time.Minute + + // contentionAlarmAfter is the point at which contention stops being normal and becomes a fault + // worth an operator's attention. + // + // Bounded by the agent's OWN ceiling rather than by taste: the PBS restore-test restore task is + // capped at 120 minutes (`config.RestoreTestPBSRestoreTimeout`, default 120m), after which the + // agent times out and releases the gate itself. Contention lasting longer than that cannot be a + // legitimate restore-test — something has leaked the gate. 3h = that 120m ceiling plus an hour + // of margin for teardown and the 5-minute poll granularity, and 15x the longest contention + // actually observed (12m01s). + contentionAlarmAfter = 3 * time.Hour +) + +// ErrTierBusy is the loop's vocabulary for "the agent refused because a heavy operation is already +// in flight" (HTTP 409). The adapter translates the transport-layer status into this, the same way +// it translates a 404 on /backup/tiers into ErrTiersUnsupported — `internal/quiesce` keeps no +// dependency on `internal/agentapi`. +var ErrTierBusy = errors.New("quiesce: tier busy — a concurrent heavy operation holds the agent") + +// contentionState is one tier's current run of refusals. +type contentionState struct { + since time.Time // first 409 of this run + until time.Time // skip the tier until here + alarmed bool // the contentionAlarmAfter signal has already fired for this run +} + +// contentionTracker records per-target 409 runs. Like the R-88 breaker it is deliberately +// IN-MEMORY: a controller restart re-attempts immediately, which is the cheap direction to fail — +// forgetting a contention window costs one extra attempt, whereas persisting it could carry a stale +// "busy" verdict across a restart that actually cleared the gate. +type contentionTracker struct { + mu sync.Mutex + states map[string]contentionState +} + +func newContentionTracker() *contentionTracker { + return &contentionTracker{states: map[string]contentionState{}} +} + +// note records a refusal for target. It returns how long this run of contention has lasted, and +// whether THIS call is the one that crosses contentionAlarmAfter (true exactly once per run, so the +// operator is told once rather than every retry — the same edge-triggering rule as R-97a). +func (c *contentionTracker) note(target string, now time.Time) (elapsed time.Duration, alarmNow bool) { + c.mu.Lock() + defer c.mu.Unlock() + st, ok := c.states[target] + if !ok || st.since.IsZero() { + st.since = now + } + st.until = now.Add(contentionRetryAfter) + elapsed = now.Sub(st.since) + if elapsed >= contentionAlarmAfter && !st.alarmed { + st.alarmed = true + alarmNow = true + } + c.states[target] = st + return elapsed, alarmNow +} + +// blocked reports whether target is inside its contention skip window, and until when. +func (c *contentionTracker) blocked(target string, now time.Time) (time.Time, bool) { + c.mu.Lock() + defer c.mu.Unlock() + st, ok := c.states[target] + if !ok || st.until.IsZero() || !now.Before(st.until) { + return time.Time{}, false + } + return st.until, true +} + +// clear ends a run of contention. Returns true if there was one, so the caller can log the recovery +// without narrating every healthy cycle. Called on ANY non-409 outcome — success or a real failure — +// because either proves the gate is no longer holding us. +func (c *contentionTracker) clear(target string) bool { + c.mu.Lock() + defer c.mu.Unlock() + if _, ok := c.states[target]; !ok { + return false + } + delete(c.states, target) + return true +} + +// contendedFor exposes the current run length (tests + diagnosis). +func (c *contentionTracker) contendedFor(target string, now time.Time) time.Duration { + c.mu.Lock() + defer c.mu.Unlock() + st, ok := c.states[target] + if !ok || st.since.IsZero() { + return 0 + } + return now.Sub(st.since) +} diff --git a/controller/internal/quiesce/contention_test.go b/controller/internal/quiesce/contention_test.go new file mode 100644 index 0000000..f058e37 --- /dev/null +++ b/controller/internal/quiesce/contention_test.go @@ -0,0 +1,201 @@ +package quiesce + +import ( + "context" + "fmt" + "testing" + "time" +) + +// F-A1 (Campaign 8): the agent's HTTP 409 is its R-85 single-flight gate refusing while a +// restore-test holds it — contention, not failure. The controller armed the R-88 breaker and +// emailed the operator anyway, on both boxes. +// +// Scenarios E (contention is not failure), F (the tier stays due), G (a REAL error still alarms) +// and H (unending contention IS a fault). G and H are what make E safe: a suite containing only E +// passes against a controller that swallows every failure as contention and never alarms again. + +// recordingNotifier captures what would reach the operator. +type recordingNotifier struct { + failed []string + recovered []string +} + +func (r *recordingNotifier) BackupFailed(tier, message, errMsg string) { + r.failed = append(r.failed, tier+"|"+message) +} +func (r *recordingNotifier) BackupRecovered(tier, message string) { + r.recovered = append(r.recovered, tier) +} + +func busyErr() error { return fmt.Errorf("%w: agentapi: POST /backup: HTTP 409", ErrTierBusy) } + +// Scenario E — a 409 must NOT arm the breaker and must NOT notify. +// +// RED-PROOF: delete the `errors.Is(err, ErrTierBusy)` branch in the start path → the 409 falls into +// noteTierFailure and this fails on both counts ("breaker armed after a 409" and "operator was +// notified"). +func TestContention_409IsNotAFailure(t *testing.T) { + be := &fakeBackend{due: true, startErr: busyErr()} + st := &fakeStacks{running: []string{"paperless-ngx"}} + l := testLoop(t, be, st) + n := &recordingNotifier{} + l.SetTierNotifier(n) + + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("runOnce: %v", err) + } + + if got := l.breaker.failuresFor(""); got != 0 { + t.Errorf("breaker armed after a 409 (%d consecutive failures) — contention is not failure", got) + } + if len(n.failed) != 0 { + t.Errorf("operator was notified for a 409: %v", n.failed) + } + // the apps must still come back — a refusal must never hold the customer's stacks down + if len(st.startedNames()) != 1 { + t.Errorf("stacks not restarted after a 409: %v", st.startedNames()) + } +} + +// Scenario F — the tier stays DUE and the next cycle retries once the gate frees. +// +// RED-PROOF: mark the tier satisfied on a 409 (e.g. call noteTierSuccess) → the retry never +// happens and startCalls stays at 1. +func TestContention_TierStaysDueAndRetries(t *testing.T) { + be := &fakeBackend{due: true, startErr: busyErr()} + st := &fakeStacks{running: []string{"paperless-ngx"}} + l := testLoop(t, be, st) + + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("cycle 1: %v", err) + } + // the restore-test finishes; the contention skip window must not outlive it artificially + be.startErr = nil + be.phases = []string{"done"} + l.contention.clear("") + + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("cycle 2: %v", err) + } + if be.startCalls != 2 { + t.Errorf("backup attempted %d times, want 2 — the tier must stay due and retry after contention", be.startCalls) + } +} + +// Scenario G — a REAL failure (not 409) must still arm the breaker and notify, exactly as before. +// +// RED-PROOF: treat every start error as contention → this fails with "a real 500 was swallowed as +// contention", which is the over-correction that would make E worthless. +func TestContention_RealFailureStillAlarms(t *testing.T) { + be := &fakeBackend{due: true, startErr: fmt.Errorf("agentapi: POST /backup: HTTP 500")} + st := &fakeStacks{running: []string{"paperless-ngx"}} + l := testLoop(t, be, st) + n := &recordingNotifier{} + l.SetTierNotifier(n) + + _ = l.runOnce(context.Background()) + + if got := l.breaker.failuresFor(""); got != 1 { + t.Errorf("breaker did not arm on a real 500 (failures=%d) — a real 500 was swallowed as contention", got) + } + if len(n.failed) != 1 { + t.Fatalf("operator was NOT notified of a real failure: %v", n.failed) + } +} + +// Scenario H — unending contention IS a fault, and it alarms ONCE. +// +// RED-PROOF: remove the contentionAlarmAfter check in noteTierContention → contention is silent +// forever and this fails with "no alarm after ...". +func TestContention_UnendingContentionAlarmsOnce(t *testing.T) { + l := testLoop(t, &fakeBackend{}, &fakeStacks{}) + n := &recordingNotifier{} + l.SetTierNotifier(n) + + base := time.Now() + now := base + l.now = func() time.Time { return now } + + // contention starts, then persists past the bound + l.noteTierContention("felhom-pbs", "felhom-pbs") + for _, step := range []time.Duration{30 * time.Minute, 2 * time.Hour, contentionAlarmAfter + time.Minute, contentionAlarmAfter + 2*time.Hour} { + now = base.Add(step) + l.noteTierContention("felhom-pbs", "felhom-pbs") + } + + if len(n.failed) == 0 { + t.Fatalf("no alarm after %s of unbroken contention — that is a silence path, the exact thing this fix must not create", contentionAlarmAfter) + } + if len(n.failed) != 1 { + t.Errorf("alarmed %d times, want exactly 1 (edge-triggered like R-97a): %v", len(n.failed), n.failed) + } + if got := n.failed[0]; !contains(got, "BLOCKED") { + t.Errorf("the alarm must name CONTENTION, not a backup failure; got %q", got) + } +} + +// Below the bound, contention must stay quiet — otherwise every normal restore-test pages someone. +func TestContention_BelowTheBoundIsQuiet(t *testing.T) { + l := testLoop(t, &fakeBackend{}, &fakeStacks{}) + n := &recordingNotifier{} + l.SetTierNotifier(n) + base := time.Now() + now := base + l.now = func() time.Time { return now } + + // the longest restore-test actually observed on the fleet was 12m01s + for _, step := range []time.Duration{0, 5 * time.Minute, 12 * time.Minute, 90 * time.Minute} { + now = base.Add(step) + l.noteTierContention("felhom-pbs", "felhom-pbs") + } + if len(n.failed) != 0 { + t.Errorf("contention alarmed before %s: %v — a normal restore-test must never page anyone", contentionAlarmAfter, n.failed) + } +} + +// A contended tier is dropped BEFORE any stack is stopped. Without this, removing the (wrong) +// failure treatment would leave the loop re-quiescing every poll for the whole restore-test — +// stopping the customer's apps each time, which is worse than the bug being fixed. +func TestContention_ContendedTierIsDroppedBeforeStopping(t *testing.T) { + be := &fakeBackend{due: true, startErr: busyErr()} + st := &fakeStacks{running: []string{"paperless-ngx"}} + l := testLoop(t, be, st) + + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("cycle 1: %v", err) + } + stoppedAfterFirst := len(st.stoppedNames()) + + // immediately after, still inside contentionRetryAfter + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("cycle 2: %v", err) + } + if got := len(st.stoppedNames()); got != stoppedAfterFirst { + t.Errorf("stacks were stopped again while the tier was still contended (%d -> %d) — that is app thrash", stoppedAfterFirst, got) + } + if be.startCalls != 1 { + t.Errorf("backup re-attempted while contended (%d calls) — the tier should have been dropped before quiescing", be.startCalls) + } +} + +// The tracker's own contract: clear() reports whether there was a run to end. +func TestContentionTracker_ClearReportsTheEdge(t *testing.T) { + c := newContentionTracker() + if c.clear("x") { + t.Error("clear() on an unknown target reported an edge") + } + c.note("x", time.Now()) + if !c.clear("x") { + t.Error("clear() did not report the edge after a noted contention") + } +} + +func contains(hay, needle string) bool { + for i := 0; i+len(needle) <= len(hay); i++ { + if hay[i:i+len(needle)] == needle { + return true + } + } + return false +} diff --git a/controller/internal/quiesce/failed_restart_test.go b/controller/internal/quiesce/failed_restart_test.go new file mode 100644 index 0000000..8e09f97 --- /dev/null +++ b/controller/internal/quiesce/failed_restart_test.go @@ -0,0 +1,130 @@ +package quiesce + +import ( + "context" + "errors" + "sync" + "testing" +) + +// F-CRIT-1 cause 1 (Campaign 8): `restartAll` used to return nothing, so a failed restart was +// logged and dropped and no caller could ever learn a customer's app had not come back. +// +// Scenario D — the outcome must reach the caller. + +// stacksWithStartFailures is a Stacks whose StartStack fails for named stacks. +type stacksWithStartFailures struct { + mu sync.Mutex + running []string + startErr map[string]error + started []string + stopped []string +} + +func (f *stacksWithStartFailures) RunningAppStacks() []string { + f.mu.Lock() + defer f.mu.Unlock() + return append([]string(nil), f.running...) +} +func (f *stacksWithStartFailures) StopStack(name string) error { + f.mu.Lock() + defer f.mu.Unlock() + f.stopped = append(f.stopped, name) + return nil +} +func (f *stacksWithStartFailures) StartStack(name string) error { + f.mu.Lock() + defer f.mu.Unlock() + f.started = append(f.started, name) + if f.startErr != nil { + return f.startErr[name] + } + return nil +} + +// Scenario D — restartAll RETURNS the stacks that would not start. +// +// RED-PROOF: revert restartAll to `func (l *Loop) restartAll(stacks []string)` with the error only +// logged → this file does not compile ("l.restartAll(...) used as value"), which is the loudest +// possible form of "the caller cannot learn". +func TestRestartAll_ReturnsTheStacksThatFailed(t *testing.T) { + boom := errors.New("compose up: exit code 1") + st := &stacksWithStartFailures{startErr: map[string]error{"immich": boom}} + l := testLoop(t, &fakeBackend{}, st) + + failed := l.restartAll([]string{"bookstack", "immich", "docmost"}) + + if len(failed) != 1 || failed[0] != "immich" { + t.Fatalf("restartAll returned %v, want exactly [immich]", failed) + } + // every stack must still have been ATTEMPTED — one failure must not abort the rest + if len(st.started) != 3 { + t.Errorf("attempted %d restarts, want 3 — a failure must not stop the loop restarting the others", len(st.started)) + } +} + +// Scenario A (cause 1) — a failed restart is REMEMBERED on the Loop, so the classifier can see it. +// +// RED-PROOF: drop the `l.noteRestartOutcome(...)` call at the unquiesce site → FailedRestarts() is +// empty and this fails with "want immich to be recorded as a failed restart". +func TestFailedRestarts_RecordedAfterACycle(t *testing.T) { + boom := errors.New("compose up: exit code 1") + st := &stacksWithStartFailures{ + running: []string{"bookstack", "immich"}, + startErr: map[string]error{"immich": boom}, + } + be := &fakeBackend{due: true, phases: []string{"done"}} + l := testLoop(t, be, st) + + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("runOnce: %v", err) + } + + failed := l.FailedRestarts() + if !failed["immich"] { + t.Errorf("want immich to be recorded as a failed restart, got %v", failed) + } + if failed["bookstack"] { + t.Errorf("bookstack restarted fine and must NOT be recorded as failed, got %v", failed) + } +} + +// The flag must CLEAR when a later cycle restarts the stack successfully — otherwise a fixed app +// carries its old failure forever and would alarm the next time it is legitimately stopped. +func TestFailedRestarts_ClearedOnALaterSuccess(t *testing.T) { + boom := errors.New("compose up: exit code 1") + st := &stacksWithStartFailures{ + running: []string{"immich"}, + startErr: map[string]error{"immich": boom}, + } + be := &fakeBackend{due: true, phases: []string{"done"}} + l := testLoop(t, be, st) + + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("cycle 1: %v", err) + } + if !l.FailedRestarts()["immich"] { + t.Fatal("precondition: immich should be flagged after the failing cycle") + } + + // the operator fixes the app; the next cycle restarts it cleanly + st.mu.Lock() + st.startErr = nil + st.mu.Unlock() + if err := l.runOnce(context.Background()); err != nil { + t.Fatalf("cycle 2: %v", err) + } + + if l.FailedRestarts()["immich"] { + t.Error("the flag survived a SUCCESSFUL restart — a fixed app would carry its old failure forever") + } +} + +// FailedRestarts must be nil-safe on a nil *Loop, for the same reason SuppressedStacks is: an +// unprovisioned guest has no loop and the caller must not need a branch. +func TestFailedRestarts_NilSafe(t *testing.T) { + var l *Loop + if got := l.FailedRestarts(); got != nil { + t.Errorf("nil Loop returned %v, want nil", got) + } +} diff --git a/controller/internal/quiesce/quiesce.go b/controller/internal/quiesce/quiesce.go index aca10a1..16cabf8 100644 --- a/controller/internal/quiesce/quiesce.go +++ b/controller/internal/quiesce/quiesce.go @@ -105,6 +105,10 @@ type Loop struct { // breaker (R-88) defers the QUIESCE for a tier whose backups keep failing, so a broken target // cannot stop the customer's apps every 5 minutes forever. Scheduled path only — see breaker.go. breaker *failureBreaker + // contention (F-A1) tracks per-tier HTTP 409 runs. A refusal is NOT a failure, so it must never + // touch the breaker — but it still has to defer the quiesce (else the apps are stopped every + // poll for the whole restore-test) and it must alarm if it never ends. See contention.go. + contention *contentionTracker // tierNotify (R-97a) reports a tier's backup outcome to the hub. nil = not wired (pre-provisioning). // Init-only: set once at startup via SetTierNotifier, before Run. tierNotify TierNotifier @@ -112,6 +116,9 @@ type Loop struct { // SuppressedStacks so an app WE stopped is not reported to the customer as broken. suppressMu sync.Mutex suppressed map[string]time.Time + // restartFailed (F-CRIT-1) is the set of stacks this loop stopped and could NOT restart. Guarded + // by suppressMu — same concern, same lock. See suppress.go. + restartFailed map[string]struct{} } // SetTierNotifier wires the hub-event seam. INIT-ONLY — call once at startup, before Run. @@ -143,7 +150,8 @@ func New(o Options) *Loop { poll: o.Poll, statusPoll: o.StatusPoll, maxQuiesce: o.MaxQuiesce, logger: o.Logger, now: time.Now, windowStartFn: o.WindowStartFn, cadence: o.Cadence, - breaker: newFailureBreaker(), + breaker: newFailureBreaker(), + contention: newContentionTracker(), } } @@ -157,7 +165,7 @@ func (l *Loop) Recover() { } l.logger.Printf("[WARN] [quiesce] crash recovery: a quiesce was in progress (job %q, %d stack(s) stopped) — restarting them", m.JobID, len(m.StoppedStacks)) - l.restartAll(m.StoppedStacks) + l.noteRestartOutcome(m.StoppedStacks, l.restartAll(m.StoppedStacks)) if err := l.clearMarker(); err != nil { l.logger.Printf("[ERROR] [quiesce] crash recovery: clear marker: %v", err) } @@ -256,9 +264,38 @@ func (l *Loop) noteTierFailure(target, label, errMsg string) { } } +// noteTierContention records a 409 refusal: log it as contention, defer the tier, and — only if +// contention has run past contentionAlarmAfter — raise it as a fault. +// +// The headline deliberately says BLOCKED, not FAILED. The operator's action for "a concurrent +// operation has held the agent for three hours" is entirely different from "the backup errored", +// and the whole point of F-A1 is that the two stopped being distinguishable. +// +// It reuses the existing `whole_guest_backup_failed` event type rather than inventing one: a new +// type would need the hub's allowedEventTypes + customerMessages pair changed, i.e. a wire change, +// which this fix deliberately does not make. +func (l *Loop) noteTierContention(target, label string) { + elapsed, alarmNow := l.contention.note(target, l.now()) + l.logger.Printf("[INFO] [quiesce] tier %s is BUSY — the agent refused the backup because a concurrent heavy operation holds it. This is contention, NOT a failure: the tier stays due and retries in %s (contended for %s)", + label, contentionRetryAfter, elapsed.Round(time.Second)) + if !alarmNow { + return + } + l.logger.Printf("[ERROR] [quiesce] tier %s has been BLOCKED by a concurrent operation for over %s — that exceeds the agent's own restore-test ceiling, so the gate is stuck, not busy", + label, contentionAlarmAfter) + if l.tierNotify != nil { + l.tierNotify.BackupFailed(label, + fmt.Sprintf("Whole-guest backup BLOCKED on the %s tier — a concurrent operation has held the agent for over %s and the backup has still not run", label, contentionAlarmAfter), + fmt.Sprintf("contention (HTTP 409) unresolved for %s; exceeds the %s restore-test ceiling", elapsed.Round(time.Second), contentionAlarmAfter)) + } +} + // noteTierSuccess clears any backoff. Quiet unless there was something to clear — a line per healthy // backup would be noise, but a recovery is worth one. func (l *Loop) noteTierSuccess(target, label string) { + if l.contention.clear(target) { + l.logger.Printf("[INFO] [quiesce] tier %s is no longer contended — the concurrent operation released the agent", label) + } // recordSuccess's bool is the edge: true only when there WAS a backoff to clear. That is exactly // the recovery edge — an operator told a tier broke must also be told it healed, and a line (or // an event) per healthy backup would be noise. @@ -285,6 +322,15 @@ func (l *Loop) dropBackedOffTiers(tiers []dueTier) []dueTier { tierLabel(t.target), l.breaker.failuresFor(t.target), until.Format(time.RFC3339)) continue } + // F-A1: a CONTENDED tier is dropped here too, for the same reason R-88 drops a failing one — + // before any stack is stopped. Without this, removing the (wrong) failure treatment would + // leave the loop re-quiescing every 5 minutes for the whole restore-test, stopping the + // customer's apps each time: worse than the bug being fixed. + if until, busy := l.contention.blocked(t.target, now); busy { + l.logger.Printf("[DEBUG] [quiesce] tier %s is BUSY (a concurrent heavy operation holds the agent) — not quiescing until %s; the tier stays due", + tierLabel(t.target), until.Format(time.RFC3339)) + continue + } kept = append(kept, t) } return kept @@ -423,7 +469,9 @@ func (l *Loop) quiesceAndPollTiers(ctx context.Context, tiers []dueTier) error { } unquiesced = true l.logger.Printf("[INFO] [quiesce] unquiescing (%s): restarting %d stack(s)", reason, len(running)) - l.restartAll(running) + // F-CRIT-1: record which stacks came back and which did not, so the app-down classifier can + // tell "the user stopped this" from "we stopped it and could not restart it". + l.noteRestartOutcome(running, l.restartAll(running)) // R-97b: start the grace clock AFTER the restart call, so the window measures time the app // has actually had to come up rather than time it spent stopped. l.markUnquiesced(running) @@ -453,8 +501,20 @@ func (l *Loop) quiesceAndPollTiers(ctx context.Context, tiers []dueTier) error { last := i == len(tiers)-1 jobID, err := l.startBackupOn(ctx, t.target) + if errors.Is(err, ErrTierBusy) { + // F-A1: the agent's single-flight gate refused (HTTP 409). Nothing is broken — a + // restore-test or another backup holds it. This is CONTENTION, not failure: no breaker, + // no whole_guest_backup_failed, no operator email. The tier stays DUE and retries. + l.noteTierContention(t.target, label) + if last { + unquiesce("last tier is busy — deferring to a later cycle") + } + continue + } if err != nil { l.logger.Printf("[ERROR] [quiesce] start backup on tier %s: %v", label, err) + // A REAL error ends any contention run: whatever the gate was doing, this is a fault now. + l.contention.clear(t.target) l.noteTierFailure(t.target, label, err.Error()) if firstErr == nil { firstErr = fmt.Errorf("start backup on %s: %w", label, err) @@ -465,6 +525,9 @@ func (l *Loop) quiesceAndPollTiers(ctx context.Context, tiers []dueTier) error { } continue } + // The tier started, so it is not contended. Clear before the poll so a long backup cannot be + // mistaken for a stuck gate. + l.contention.clear(t.target) marker.JobID = jobID _ = l.writeMarker(marker) // best-effort: record the CURRENT tier's job id for diagnosis l.logger.Printf("[INFO] [quiesce] tier %s: backup job %s started — polling", label, jobID) @@ -488,8 +551,14 @@ func (l *Loop) quiesceAndPollTiers(ctx context.Context, tiers []dueTier) error { // offsite snapshot legitimately runs for hours). The app is already back up. We must // NOT start the next tier: ONE BACKUP AT A TIME PER GUEST (operator ruling // 2026-07-26) — vzdump still holds the guest lock, so a second start would be refused - // by the agent (409) or fail on the lock and record a spurious failure. The remaining - // tiers simply run on a later poll, once this one has finished. + // by the agent (409) or fail on the lock. The remaining tiers simply run on a later + // poll, once this one has finished. + // + // CORRECTED v0.179.0 (F-A1): this used to say the 409 would "record a spurious + // failure". Until v0.179.0 that was not a hypothetical the comment was guarding + // against — it was what the start path ACTUALLY did, on every 409, on both boxes. + // A 409 is now handled as CONTENTION (see contention.go): no breaker, no operator + // email, the tier stays due. So the outcome this comment feared no longer exists. l.logger.Printf("[INFO] [quiesce] tier %s still running past the quiesce bound — deferring %d remaining tier(s) to a later cycle", label, len(tiers)-i-1) break @@ -648,12 +717,21 @@ func within(p, start, span int) bool { return mod1440(p-start) < span } -func (l *Loop) restartAll(stacks []string) { +// restartAll restarts the given stacks and RETURNS the ones that failed. +// +// F-CRIT-1 cause 1: this used to return nothing. The error was logged and dropped on the spot, so +// no caller could learn that a customer's app had not come back — and the classifier downstream +// therefore had nothing to key on. A restart failure is the single most important fact this loop +// produces; it must leave the function. +func (l *Loop) restartAll(stacks []string) []string { + var failed []string for _, s := range stacks { if err := l.stacks.StartStack(s); err != nil { l.logger.Printf("[ERROR] [quiesce] restart %s: %v", s, err) + failed = append(failed, s) } } + return failed } // ---- marker persistence (atomic, 0600) -------------------------------------------------- diff --git a/controller/internal/quiesce/suppress.go b/controller/internal/quiesce/suppress.go index f0f4928..4bc5aed 100644 --- a/controller/internal/quiesce/suppress.go +++ b/controller/internal/quiesce/suppress.go @@ -88,3 +88,63 @@ func (l *Loop) SuppressedStacks() map[string]bool { } return out } + +// ---- F-CRIT-1: the loop remembers which stacks it FAILED to restart ------------------------- +// +// THE BUG THIS EXISTS TO KILL. `classifyRunStates` whitelists `StateStopped` because v0.164.0 +// (correctly) refused to alarm on a deliberate user stop. That rests on invariant I1: "a deployed +// stack with zero containers was stopped by the user". **The quiesce loop broke I1** — it stops +// stacks by the same `docker compose down` path, so a stack this loop stopped and then FAILED to +// restart is also `StateStopped`, and was therefore whitelisted into total silence. Campaign 8 +// observed exactly that: a customer's app dead indefinitely, no banner, no event, no email, while +// the dead-app scanner ran 11 times. +// +// No state test can separate the two cases — they are byte-identical on the Docker side. The +// distinguishing fact is not in the state at all: it is that WE tried to restart it and could not. +// That fact now leaves `restartAll`, and is remembered here. +// +// WHY A SET AND NOT A TIMESTAMP. The flag is only ever consulted for a stack that is ALREADY in a +// down state, so a stale entry cannot manufacture an alarm on a healthy app: if the operator fixes +// the app and starts it by any route, the stack is no longer down and the classifier never reaches +// this. The entry is cleared the moment a later restart of that stack succeeds. + +// noteRestartOutcome records the result of one restart pass: `failed` are the stacks that would not +// start, and everything else in `attempted` is cleared. Clearing on success is what stops a fixed +// app from carrying its old failure forever. +func (l *Loop) noteRestartOutcome(attempted, failed []string) { + if l == nil { + return + } + bad := make(map[string]bool, len(failed)) + for _, n := range failed { + bad[n] = true + } + l.suppressMu.Lock() + defer l.suppressMu.Unlock() + if l.restartFailed == nil { + l.restartFailed = map[string]struct{}{} + } + for _, n := range attempted { + if bad[n] { + l.restartFailed[n] = struct{}{} + } else { + delete(l.restartFailed, n) + } + } +} + +// FailedRestarts returns the stacks this loop stopped and could not restart. Nil-safe on a nil +// *Loop for the same reason SuppressedStacks is: an unprovisioned guest has no loop and must report +// nothing rather than force a branch on the caller. +func (l *Loop) FailedRestarts() map[string]bool { + if l == nil { + return nil + } + l.suppressMu.Lock() + defer l.suppressMu.Unlock() + out := make(map[string]bool, len(l.restartFailed)) + for n := range l.restartFailed { + out[n] = true + } + return out +}