F-CRIT-1 + F-A1: one alarm that never fired, one that fired wrongly (v0.179.0)

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.
This commit is contained in:
2026-07-28 08:50:11 +02:00
parent 8f46495426
commit 079265ad8e
10 changed files with 884 additions and 29 deletions
@@ -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)
}
@@ -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)
}
}
+51 -16
View File
@@ -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)
+21 -4
View File
@@ -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 {
+146
View File
@@ -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)
}
@@ -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
}
@@ -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)
}
}
+84 -6
View File
@@ -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) --------------------------------------------------
+60
View File
@@ -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
}