From bd18347c1c04d8b082763eab1d3985847f7660b7 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Fri, 30 Oct 2026 09:20:37 +0100 Subject: [PATCH] =?UTF-8?q?R-1344=20decided=20from=20the=20night's=20measu?= =?UTF-8?q?rement:=20a=20controller=20that=20runs=20but=20does=20not=20ans?= =?UTF-8?q?wer=20is=20restarted=20at=2010=20unhealthy=20sweeps=20(alarm=20?= =?UTF-8?q?at=206)=20=E2=80=94=20busy=20file=20+=20the=20brake=20refuse;?= =?UTF-8?q?=20stanza=20carries=20unresponsive=5Frestart=5Fafter=5Fs=20/=20?= =?UTF-8?q?unresponsive=5Frestart=5Fat?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- CHANGELOG.md | 22 +++ REUSE.md | 4 +- internal/hub/report.go | 6 + internal/localapi/controllersupervisor.go | 116 +++++++++++++--- internal/localapi/opreboot.go | 5 +- .../localapi/supervisor_unresponsive_test.go | 128 ++++++++++++++---- 6 files changed, 237 insertions(+), 44 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 56338ad..05f74e3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,25 @@ +## Unreleased — R-1344 decided from the night's measurement: a controller that runs but does not answer is RESTARTED + +- **The measurement (operator brief 2026-10-29 Part 2, read 2026-10-30).** Docker's own health record of the controller + on Tester 1 and demo-hp, every probe from 2026-10-29 11:12 to 2026-10-30 07:00 UTC: 4 733 probes through the night + chain (demo-hp's PBS vzdump, Tester 1's local vzdump, both DB dumps, tier-2, the off-site push, a restore test, two + controller updates). No failed probe, no 5-s timeout; slowest 303 ms (demo-hp, during the PBS vzdump). The only + „unhealthy" was the controller stopped by hand for a proof. A busy night never came near ONE failed probe. +- **So the alarm becomes a restart.** At `controllerUnresponsiveConfirm` = 6 unhealthy sweeps the alarm is raised, as + before. At `controllerUnresponsiveRestart` = 10 (2 minutes later; ~6.5 minutes after the first failed probe) the agent + restarts the controller's bootstrap unit — unless the controller's busy file is fresh (a backup, a restore, an + update, an export) or cannot be read, or the brake refuses (3 restarts in 15 minutes → the crash-loop pause, which + the hub mails). A swap, a parked guest, a locked guest and a vzdump keep resetting the count, as before. A refusal + keeps the alarm and is logged once per reason. After a restart the count starts again from zero. +- **The stanza** carries `unresponsive_restart_after_s` (120: the hub's alarm text says when the restart comes) and + `unresponsive_restart_at` (equals `last_restart_at` for that act; the hub mails `controller_unresponsive_restart`). +- **Refactor, no behaviour change:** the not-running restart's brake and its record are now `supervisorBrakeAllows` + and `recordSupervisorRestart`, shared by both restarts. The busy-file stale log line no longer says „operator reboot". +- Tests `TestSupervisor_UnresponsiveIsAlarmedThenRestarted`, `…Guards` (now also: never restarted), + `…RestartRefusals` (busy fresh, busy unreadable, the brake, a crash-loop pause), `…StaleBusyFileDoesNotShield` — + red first (build failure, then 3 behaviour failures); 7 mutants, each killed (one survivor — the count reset after a + restart — found and pinned). + ## v0.170.0 (2026-10-29) — „Reboot guest" from the hub (D65 = A): `reboot_guest` joins the agent's closed list — RELEASED (release-agent.sh from a clean clone of `ca15a31`; agent sha256 da8d12a05ef607c338b9ba307e7a81b18253a3188721bbd8421ba36658a22404, config bundle 03f2ff6442fc3ca600b1f25f26767ce4da466a770a258f3e362cf95f6e76b543; signed agent_config_update + agent_update on Tester 1, demo-hp, demo-felhom; vouched by the operator 2026-10-29 18:57:48 CET; `pinned.day0_agent` = 0.170.0) - **D65 = A (operator ruling 2026-10-29 15:50; felhom.eu `04` §6.1, `03`).** The agent's closed operator-action list is diff --git a/REUSE.md b/REUSE.md index 759a17a..35c08a5 100644 --- a/REUSE.md +++ b/REUSE.md @@ -88,8 +88,8 @@ | `EnsureLeaf` | internal/localapi/cert.go | `EnsureLeaf(certPath, keyPath, host) (cert, fingerprint, generated, err)` | pinned self-signed leaf | `generated=true` invalidates every issued bootstrap pin — log LOUD (B.1) | | `Server.RecoverStaleLockedGuests` | internal/localapi/stalelock.go | `RecoverStaleLockedGuests(ctx)` | startup stale vzdump-lock heal (F2-b) | Clears ONLY `backup`/`snapshot-delete`, only when no vzdump in-flight; A1 RESOLVED (v0.62.0): scan is pool-intersected (`ListLXC` ∩ `Client.Pool`), fail-safe skip on pool-read failure | | `ControllerSwapper.Swap` + `ValidControllerImage` | internal/localapi/controllerswap.go | `Swap(ctx, vmid, target) *ControllerSwapState` | agent-owned controller image swap + rollback | Strict image regex (repo + 3-part semver); state file written BEFORE swap; no-healthcheck images need `verifyDwell` | -| `Server.ControllerSupervisorTick` + `ControllerParkedMarker` | internal/localapi/controllersupervisor.go | `ControllerSupervisorTick(ctx)` | R-523: restart a provisioned guest's not-running controller via its bootstrap unit | Two-sweep confirm; honours swapInFlight, the host-side park marker, guest lock + vzdump; 3 restarts/15 min → 30 min pause; record rides the report as `controller_supervisor` (the hub mints the events — the agent has no event channel) | -| `Server.OnEnvelope` / `OperatorActionResults` (operator actions) | internal/localapi/opactions.go | `OnEnvelope(ctx, env)`, `OperatorActionResults() []hub.OperatorActionResult` | 2026-10-29: the operator's actions for THIS agent from the host-report reply — a CLOSED list (`restart_controller` only, `TestOpActions_AgentClosedList`), once per id, the result re-sent until the reply stops listing it, the report requested at once (`SetOperatorActionTrigger`). The restart is the supervisor's act with its guards; the 3-in-15-min brake counts operator restarts too (30-min refusal, `opBrakeUntil`). A new verb is an operator decision AND a hub `store.hostOperatorActionNames` entry in the same release | +| `Server.ControllerSupervisorTick` + `ControllerParkedMarker` | internal/localapi/controllersupervisor.go | `ControllerSupervisorTick(ctx)` | R-523: restart a provisioned guest's not-running controller via its bootstrap unit | Two-sweep confirm; honours swapInFlight, the host-side park marker, guest lock + vzdump; 3 restarts/15 min → 30 min pause (`supervisorBrakeAllows` — every supervisor restart passes it; `recordSupervisorRestart` puts one on the record + R-539's slow counter); R-1344 (2026-10-30): a RUNNING controller whose Docker health reads „unhealthy" is alarmed at 6 sweeps and restarted at 10 (`restartUnresponsive`: the controller's busy file, then the brake); record rides the report as `controller_supervisor` (the hub mints the events — the agent has no event channel) | +| `Server.OnEnvelope` / `OperatorActionResults` (operator actions) | internal/localapi/opactions.go | `OnEnvelope(ctx, env)`, `OperatorActionResults() []hub.OperatorActionResult` | 2026-10-29: the operator's actions for THIS agent from the host-report reply — a CLOSED list (`restart_controller`, `reboot_guest` since D65 — `TestOpActions_AgentClosedList`), once per id, the result re-sent until the reply stops listing it, the report requested at once (`SetOperatorActionTrigger`). The restart is the supervisor's act with its guards; the 3-in-15-min brake counts operator restarts too (30-min refusal, `opBrakeUntil`). A new verb is an operator decision AND a hub `store.hostOperatorActionNames` entry in the same release | | `MemoryOps` + `Server.readMemoryBounds` | internal/localapi/guestmemory.go | `readMemoryBounds(ctx, vmid) (memoryBounds, err)` | guest RAM resize (v0.90.0, R-24): GET/POST /guest/memory | NEW narrow seam (never extend `GuestAPI` — it breaks every fake); the AGENT is the boundary — bounds recomputed FRESH per request (min 2048 / max host_total−2048 / shrink floor max(2048, usage+512)); §8 UNITS TRAP (config `memory`=MB, status/node=bytes); verify maxmem==target after `SetConfig` before claiming success; SetConfig NEVER called on a refusal path | ### Proxmox client / hub / PBS / provisioning diff --git a/internal/hub/report.go b/internal/hub/report.go index 58df779..b5d39fc 100644 --- a/internal/hub/report.go +++ b/internal/hub/report.go @@ -218,6 +218,12 @@ type ControllerSupervisorGuest struct { // looks like it). UnresponsiveSince is the episode's start; the hub keys on it MOVING (controller_unresponsive). Unresponsive bool `json:"unresponsive"` UnresponsiveSince string `json:"unresponsive_since,omitempty"` // RFC3339 + // R-1344 restart (decided 2026-10-30 from the night's measurement): UnresponsiveRestartAfterS is how long after the + // alarm the agent restarts a controller that still does not answer (0 / absent = an older agent: alarm only — the + // hub's message says which). UnresponsiveRestartAt is the last such restart; the hub keys on it MOVING + // (controller_unresponsive_restart) and it equals LastRestartAt for that act. + UnresponsiveRestartAfterS int `json:"unresponsive_restart_after_s,omitempty"` + UnresponsiveRestartAt string `json:"unresponsive_restart_at,omitempty"` // RFC3339 } // PBSDRStatus is the per-heartbeat PBS-DR-tier bridge state (slice 2). States: diff --git a/internal/localapi/controllersupervisor.go b/internal/localapi/controllersupervisor.go index b66a8f4..9da5597 100644 --- a/internal/localapi/controllersupervisor.go +++ b/internal/localapi/controllersupervisor.go @@ -3,6 +3,7 @@ package localapi import ( "context" "encoding/json" + "fmt" "os" "path/filepath" "sort" @@ -87,10 +88,16 @@ const ( // R-1344 (operator brief 2026-10-29, Part 2) — a controller that RUNS but does not answer. Docker's own HEALTHCHECK // (`curl -f localhost:8080/api/health`, every 30 s, timeout 5 s) reads „unhealthy" only after 3 failed probes (~90 s); // controllerUnresponsiveConfirm more sweeps (3 minutes) make it an episode: logged, carried by the stanza, mailed by - // the hub (controller_unresponsive). ALARM ONLY — it is NOT restarted for this until the measurement (R-1344) shows a - // busy night (backups, updates) never reads unhealthy that long. Not counted during a swap, a parked guest, a locked - // guest or a vzdump. + // the hub (controller_unresponsive). Not counted during a swap, a parked guest, a locked guest or a vzdump. controllerUnresponsiveConfirm = 6 + // controllerUnresponsiveRestart (decided 2026-10-30 from the measurement): at this many consecutive unhealthy sweeps + // (5 minutes after Docker's „unhealthy", ~6.5 minutes after the first failed probe; 2 minutes after the alarm) the + // agent restarts the controller — the not-running restart's guards and brake, plus the controller's busy file. The + // numbers: Tester 1 and demo-hp, 2026-10-29 11:12 → 2026-10-30 07:00 UTC, 4 733 probes through the night chain (a + // PBS and a local vzdump, the DB dumps, tier-2, the off-site push, a restore test, two controller updates): no failed + // probe, slowest 303 ms against the 5 s timeout. A busy night never came near even ONE failed probe; ten sweeps is + // the margin. Pinned by TestSupervisor_UnresponsiveIsAlarmedThenRestarted. + controllerUnresponsiveRestart = 10 ) // controllerSupState is one guest's supervisor record. In-memory on purpose (the guest-power @@ -119,6 +126,10 @@ type controllerSupState struct { unhealthySeen int unresponsive bool unresponsiveSince time.Time + // unresponsiveRestartAt: the last restart for not answering (kept; the hub keys on it MOVING). unrespRefusal: the + // last reason the restart was refused, so a refusal is logged once per change, not every sweep. + unresponsiveRestartAt time.Time + unrespRefusal string } type controllerSupervisor struct { @@ -354,9 +365,27 @@ func (s *Server) superviseOneController(ctx context.Context, vmid int, guestStat return false } - // Backoff. + if !s.supervisorBrakeAllows(vmid, now) { + return false + } + + reason := "controller container " + status + " on " + strconv.Itoa(controllerSupervisorConfirm) + " consecutive sweeps" + s.logger.Warn("controller-supervisor: controller is NOT running — restarting the bootstrap unit", + "vmid", vmid, "status", status, "unit", bootstrapUnit) + if _, err := s.guestExec.GuestExec(ctx, vmid, "systemctl", "restart", bootstrapUnit); err != nil { + s.logger.Error("controller-supervisor: bootstrap restart failed", "vmid", vmid, "err", err) + reason += "; restart FAILED: " + err.Error() + } + s.recordSupervisorRestart(vmid, now, reason, nil) + return false +} + +// supervisorBrakeAllows is the brake every supervisor restart passes (the not-running one and R-1344's): a crash-loop +// pause in force refuses; controllerCrashloopMax restarts inside controllerCrashloopWindow start one (logged, carried by +// the stanza, mailed by the hub as controller_crashloop) and refuse. +func (s *Server) supervisorBrakeAllows(vmid int, now time.Time) bool { s.ctrlSup.mu.Lock() - st = s.supState(vmid) + st := s.supState(vmid) if !st.crashloopSince.IsZero() { if now.Sub(st.crashloopSince) < controllerCrashloopPause { s.ctrlSup.mu.Unlock() @@ -379,22 +408,23 @@ func (s *Server) superviseOneController(ctx context.Context, vmid int, guestStat return false } s.ctrlSup.mu.Unlock() + return true +} - reason := "controller container " + status + " on " + strconv.Itoa(controllerSupervisorConfirm) + " consecutive sweeps" - s.logger.Warn("controller-supervisor: controller is NOT running — restarting the bootstrap unit", - "vmid", vmid, "status", status, "unit", bootstrapUnit) - if _, err := s.guestExec.GuestExec(ctx, vmid, "systemctl", "restart", bootstrapUnit); err != nil { - s.logger.Error("controller-supervisor: bootstrap restart failed", "vmid", vmid, "err", err) - reason += "; restart FAILED: " + err.Error() - } +// recordSupervisorRestart puts a restart the supervisor performed on the record: the brake's window, the totals, the +// reason, and R-539's slow counter (persisted; raised at most once per 24 hours — the hub mails on the raise MOVING). +// mark, when set, runs under the same lock (R-1344 stamps its own record there). +func (s *Server) recordSupervisorRestart(vmid int, now time.Time, reason string, mark func(st *controllerSupState)) { s.ctrlSup.mu.Lock() - st = s.supState(vmid) + st := s.supState(vmid) st.restarts = append(st.restarts, now) st.restartsTotal++ st.lastRestartAt = now st.lastReason = reason st.notRunningSeen = 0 - // R-539: the slow counter. Raise at most once per 24 hours — the hub mails on the raise MOVING. + if mark != nil { + mark(st) + } st.restarts24h = append(pruneBefore(st.restarts24h, now.Add(-controllerSlowCrashloopWindow)), now) n24 := len(st.restarts24h) raised := false @@ -410,7 +440,6 @@ func (s *Server) superviseOneController(ctx context.Context, vmid int, guestStat s.logger.Warn("controller-supervisor: SLOW CRASH-LOOP — the controller keeps dying; still restarting it, raising controller_slow_crashloop", "vmid", vmid, "restarts_24h", n24, "window", controllerSlowCrashloopWindow.String(), "threshold", controllerSlowCrashloopMax) } - return false } // observeControllerHealth is R-1344's count for a RUNNING controller: Docker's health status, one read per sweep over @@ -452,11 +481,60 @@ func (s *Server) observeControllerHealth(ctx context.Context, vmid int, parked b if start { st.unresponsive, st.unresponsiveSince = true, now } + since := st.unresponsiveSince s.ctrlSup.mu.Unlock() if start { - s.logger.Error("controller-supervisor: the controller RUNS but does not answer its health check — raising controller_unresponsive; NOT restarting it (R-1344: alarm only until measured)", - "vmid", vmid, "unhealthy_sweeps", seen, "interval", controllerSupervisorInterval.String()) + s.logger.Error("controller-supervisor: the controller RUNS but does not answer its health check — raising controller_unresponsive; restarting it if it stays so", + "vmid", vmid, "unhealthy_sweeps", seen, "interval", controllerSupervisorInterval.String(), + "restart_after_sweeps", controllerUnresponsiveRestart) } + if seen >= controllerUnresponsiveRestart { + s.restartUnresponsive(ctx, vmid, seen, since, now) + } +} + +// restartUnresponsive is R-1344's restart (decided 2026-10-30): the controller's busy file (fresh = a backup, a +// restore, an update or an export is running; unreadable = cannot be ruled out) refuses, then the brake every +// supervisor restart passes. The swap, the parked marker, the lock and the vzdump never reach here — they reset the +// count. A refusal keeps the alarm and is logged once per reason; the next sweep asks again. +func (s *Server) restartUnresponsive(ctx context.Context, vmid, seen int, since, now time.Time) { + refuse := func(why string) { + s.ctrlSup.mu.Lock() + st := s.supState(vmid) + changed := st.unrespRefusal != why + st.unrespRefusal = why + s.ctrlSup.mu.Unlock() + if changed { + s.logger.Warn("controller-supervisor: the controller does not answer, but the restart is refused — the alarm stays", + "vmid", vmid, "why", why, "unhealthy_sweeps", seen) + } + } + busy, what, err := s.controllerBusy(ctx, vmid) + if err != nil { + refuse("the controller's busy file cannot be read: " + err.Error()) + return + } + if busy { + refuse("the controller is busy: " + what) + return + } + if !s.supervisorBrakeAllows(vmid, now) { + refuse("the restart brake") + return + } + reason := fmt.Sprintf("the controller ran but did not answer its health check for %d sweeps (since %s)", + seen, since.UTC().Format(time.RFC3339)) + s.logger.Warn("controller-supervisor: the controller does not answer — restarting the bootstrap unit", + "vmid", vmid, "unhealthy_sweeps", seen, "since", since.UTC().Format(time.RFC3339), "unit", bootstrapUnit) + if _, err := s.guestExec.GuestExec(ctx, vmid, "systemctl", "restart", bootstrapUnit); err != nil { + s.logger.Error("controller-supervisor: bootstrap restart failed", "vmid", vmid, "err", err) + reason += "; restart FAILED: " + err.Error() + } + s.recordSupervisorRestart(vmid, now, reason, func(st *controllerSupState) { + st.unresponsiveRestartAt = now + st.unhealthySeen = 0 + st.unrespRefusal = "" + }) } func (s *Server) resetNotRunning(vmid int) { @@ -517,6 +595,10 @@ func (s *Server) ControllerSupervisorStatus(_ context.Context) *hub.ControllerSu if !st.unresponsiveSince.IsZero() { g.UnresponsiveSince = st.unresponsiveSince.UTC().Format(time.RFC3339) } + g.UnresponsiveRestartAfterS = (controllerUnresponsiveRestart - controllerUnresponsiveConfirm) * int(controllerSupervisorInterval/time.Second) + if !st.unresponsiveRestartAt.IsZero() { + g.UnresponsiveRestartAt = st.unresponsiveRestartAt.UTC().Format(time.RFC3339) + } out.Guests = append(out.Guests, g) } sort.Slice(out.Guests, func(i, j int) bool { return out.Guests[i].VMID < out.Guests[j].VMID }) diff --git a/internal/localapi/opreboot.go b/internal/localapi/opreboot.go index 70fd048..b0a8874 100644 --- a/internal/localapi/opreboot.go +++ b/internal/localapi/opreboot.go @@ -137,7 +137,8 @@ func (s *Server) rebooter() interface { // controllerBusy reads the controller's busy file. busy=true with the controller's reason when the file is fresh; // a missing file is „not busy" (an idle controller, or one older than the file); any other read failure is an error -// (the caller refuses — it cannot prove no backup runs). +// (the caller refuses — it cannot prove no backup runs). Two callers: the operator's reboot (D65) and R-1344's restart +// of a controller that does not answer (controllersupervisor.go restartUnresponsive). func (s *Server) controllerBusy(ctx context.Context, vmid int) (bool, string, error) { out, err := s.guestExec.GuestExec(ctx, vmid, "cat", ControllerBusyMarkerGuestPath) if err != nil { @@ -152,7 +153,7 @@ func (s *Server) controllerBusy(ctx context.Context, vmid int) (bool, string, er return false, "", fmt.Errorf("the controller's busy file does not start with a time: %q", lines[0]) } if s.clock().Sub(at) > controllerBusyFresh { - s.logger.Info("operator reboot: the controller's busy file is stale — the controller stopped writing it; not busy", + s.logger.Info("controller-busy: the controller's busy file is stale — the controller stopped writing it; not busy", "vmid", vmid, "written", at.UTC().Format(time.RFC3339)) return false, "", nil } diff --git a/internal/localapi/supervisor_unresponsive_test.go b/internal/localapi/supervisor_unresponsive_test.go index 84cae17..9aff7a4 100644 --- a/internal/localapi/supervisor_unresponsive_test.go +++ b/internal/localapi/supervisor_unresponsive_test.go @@ -2,19 +2,25 @@ package localapi import ( "context" + "errors" + "strings" "testing" + "time" ) -// R-1344 (operator brief 2026-10-29, Part 2): a controller that RUNS but whose Docker health check reads „unhealthy" on -// controllerUnresponsiveConfirm consecutive sweeps is reported unresponsive (the stanza; the hub raises -// controller_unresponsive). ALARM ONLY: it is never restarted for it until the measurement licenses that. -// RED-PROOF: seen failing before the stanza carried it. +// R-1344 (operator brief 2026-10-29, Part 2; decided 2026-10-30 from the night's measurement): a controller that RUNS +// but whose Docker health check reads „unhealthy" on controllerUnresponsiveConfirm consecutive sweeps is reported +// unresponsive (the stanza; the hub raises controller_unresponsive). If it still reads „unhealthy" at +// controllerUnresponsiveRestart sweeps, the agent restarts it — with the not-running restart's guards and brake, plus +// the controller's own busy file. RED-PROOF: the restart tests seen failing before the restart existed. -func unrespServer(t *testing.T, health string) (*Server, *opExec, *fakeGuestPowerCtl) { +func unrespServer(t *testing.T, health string) (*Server, *rbExec, *fakeGuestPowerCtl, *supClock) { t.Helper() - s, ex, ctl, _, _, _ := opServer(t, "running") + s, ex, ctl, clk, _, _ := opServer(t, "running") ex.health = health - return s, ex, ctl + rb := &rbExec{opExec: ex} + s.guestExec = rb + return s, rb, ctl, clk } func sweep(s *Server, n int) { @@ -23,8 +29,8 @@ func sweep(s *Server, n int) { } } -func TestSupervisor_UnresponsiveIsAlarmedNeverRestarted(t *testing.T) { - s, ex, _ := unrespServer(t, "unhealthy") +func TestSupervisor_UnresponsiveIsAlarmedThenRestarted(t *testing.T) { + s, ex, _, _ := unrespServer(t, "unhealthy") sweep(s, controllerUnresponsiveConfirm-1) if g := s.ControllerSupervisorStatus(context.Background()).Guests; len(g) != 1 || g[0].Unresponsive { t.Fatalf("unresponsive before %d sweeps: %+v", controllerUnresponsiveConfirm, g) @@ -34,41 +40,117 @@ func TestSupervisor_UnresponsiveIsAlarmedNeverRestarted(t *testing.T) { if len(g) != 1 || !g[0].Unresponsive || g[0].UnresponsiveSince == "" { t.Fatalf("after %d unhealthy sweeps: %+v", controllerUnresponsiveConfirm, g) } + if g[0].UnresponsiveRestartAfterS != (controllerUnresponsiveRestart-controllerUnresponsiveConfirm)*int(controllerSupervisorInterval/time.Second) { + t.Fatalf("the stanza must tell the hub when the restart comes: %+v", g[0]) + } since := g[0].UnresponsiveSince - sweep(s, 10) + sweep(s, controllerUnresponsiveRestart-controllerUnresponsiveConfirm-1) if n := ex.count(9201); n != 0 { - t.Fatalf("an unresponsive controller was RESTARTED (%d) — the restart waits for the measurement", n) + t.Fatalf("restarted after %d unhealthy sweeps — the restart waits for %d", controllerUnresponsiveRestart-1, controllerUnresponsiveRestart) } if g := s.ControllerSupervisorStatus(context.Background()).Guests; g[0].UnresponsiveSince != since { t.Fatal("unresponsive_since moved while it stayed unresponsive — the hub would mail again") } - // it answers again - ex.health = "healthy" + sweep(s, 1) + if n := ex.count(9201); n != 1 { + t.Fatalf("after %d unhealthy sweeps: %d restarts, want 1", controllerUnresponsiveRestart, n) + } + g = s.ControllerSupervisorStatus(context.Background()).Guests + if g[0].UnresponsiveRestartAt == "" || g[0].UnresponsiveRestartAt != g[0].LastRestartAt || g[0].Restarts24h != 1 || + !strings.Contains(g[0].LastReason, "health check") { + t.Fatalf("the restart is not on the record the hub reads: %+v", g[0]) + } + // A restart that did not help (still „unhealthy" on the next sweep) is not repeated at once: the count starts again. + sweep(s, 1) + if n := ex.count(9201); n != 1 { + t.Fatalf("restarted again on the sweep after a restart: %d restarts", n) + } + // The restarted controller starts, then answers: the episode ends, its record stays. + ex.health = "starting" sweep(s, 1) if g := s.ControllerSupervisorStatus(context.Background()).Guests; g[0].Unresponsive || g[0].UnresponsiveSince != since { - t.Fatalf("after it answered: %+v (unresponsive must clear; since stays as the record)", g[0]) + t.Fatalf("after the restart: %+v (unresponsive must clear; since stays as the record)", g[0]) + } + // A second episode needs the whole count again — never a restart on the first unhealthy read after one. + ex.health = "unhealthy" + sweep(s, controllerUnresponsiveRestart-1) + if n := ex.count(9201); n != 1 { + t.Fatalf("a second episode restarted early: %d restarts", n) } } -// Slow but answering (healthy / starting), a swap, a vzdump or a parked guest never counts. +// Slow but answering (healthy / starting), a swap, a vzdump, a locked or a parked guest never counts — and so is never +// restarted. func TestSupervisor_UnresponsiveGuards(t *testing.T) { for _, tc := range []struct { name string - setup func(s *Server, ex *opExec, ctl *fakeGuestPowerCtl) + setup func(s *Server, ex *rbExec, ctl *fakeGuestPowerCtl) }{ - {"healthy", func(_ *Server, ex *opExec, _ *fakeGuestPowerCtl) { ex.health = "healthy" }}, - {"starting", func(_ *Server, ex *opExec, _ *fakeGuestPowerCtl) { ex.health = "starting" }}, - {"swap", func(s *Server, _ *opExec, _ *fakeGuestPowerCtl) { s.swapInFlight[9201] = true }}, - {"vzdump", func(_ *Server, _ *opExec, ctl *fakeGuestPowerCtl) { ctl.backupRun = map[int]bool{9201: true} }}, - {"locked", func(_ *Server, _ *opExec, ctl *fakeGuestPowerCtl) { ctl.locks[9201] = "backup" }}, + {"healthy", func(_ *Server, ex *rbExec, _ *fakeGuestPowerCtl) { ex.health = "healthy" }}, + {"starting", func(_ *Server, ex *rbExec, _ *fakeGuestPowerCtl) { ex.health = "starting" }}, + {"swap", func(s *Server, _ *rbExec, _ *fakeGuestPowerCtl) { s.swapInFlight[9201] = true }}, + {"vzdump", func(_ *Server, _ *rbExec, ctl *fakeGuestPowerCtl) { ctl.backupRun = map[int]bool{9201: true} }}, + {"locked", func(_ *Server, _ *rbExec, ctl *fakeGuestPowerCtl) { ctl.locks[9201] = "backup" }}, } { t.Run(tc.name, func(t *testing.T) { - s, ex, ctl := unrespServer(t, "unhealthy") + s, ex, ctl, _ := unrespServer(t, "unhealthy") tc.setup(s, ex, ctl) - sweep(s, controllerUnresponsiveConfirm+2) + sweep(s, controllerUnresponsiveRestart+2) if g := s.ControllerSupervisorStatus(context.Background()).Guests; len(g) == 1 && g[0].Unresponsive { t.Fatalf("%s counted as unresponsive: %+v", tc.name, g[0]) } + if n := ex.count(9201); n != 0 { + t.Fatalf("%s: restarted %d times", tc.name, n) + } }) } } + +// At the restart moment: the controller's busy file (fresh, or unreadable) and the brake refuse it; the alarm stays. +// RED-PROOF: each seen failing by deleting its guard. +func TestSupervisor_UnresponsiveRestartRefusals(t *testing.T) { + for _, tc := range []struct { + name string + setup func(s *Server, ex *rbExec, clk *supClock) + crashloop bool + }{ + {"busy file fresh", func(_ *Server, ex *rbExec, clk *supClock) { + ex.busy = clk.t.Add(-20*time.Second).Format(time.RFC3339) + "\na backup, a restore or an off-site run is running\n" + }, false}, + {"busy file unreadable", func(_ *Server, ex *rbExec, _ *supClock) { ex.busyErr = errors.New("pct exec: exit status 255") }, false}, + {"brake: 3 restarts in 15 minutes", func(s *Server, _ *rbExec, clk *supClock) { + st := s.supState(9201) + st.restarts = []time.Time{clk.t.Add(-10 * time.Minute), clk.t.Add(-5 * time.Minute), clk.t.Add(-time.Minute)} + }, true}, + {"crash-loop pause in force", func(s *Server, _ *rbExec, clk *supClock) { + s.supState(9201).crashloopSince = clk.t.Add(-5 * time.Minute) + }, true}, + } { + t.Run(tc.name, func(t *testing.T) { + s, ex, _, clk := unrespServer(t, "unhealthy") + tc.setup(s, ex, clk) + sweep(s, controllerUnresponsiveRestart+3) + if n := ex.count(9201); n != 0 { + t.Fatalf("%s: restarted %d times", tc.name, n) + } + g := s.ControllerSupervisorStatus(context.Background()).Guests + if len(g) != 1 || !g[0].Unresponsive || g[0].UnresponsiveRestartAt != "" { + t.Fatalf("%s: the alarm must stay and no restart be recorded: %+v", tc.name, g) + } + if tc.crashloop && !g[0].Crashloop { + t.Fatalf("%s: the brake did not raise the crash-loop: %+v", tc.name, g[0]) + } + }) + } +} + +// A busy file the controller stopped writing (older than controllerBusyFresh) is not „busy" — a hung controller must +// not shield itself with its last word. +func TestSupervisor_UnresponsiveStaleBusyFileDoesNotShield(t *testing.T) { + s, ex, _, clk := unrespServer(t, "unhealthy") + ex.busy = clk.t.Add(-10*time.Minute).Format(time.RFC3339) + "\nan app update is running\n" + sweep(s, controllerUnresponsiveRestart) + if n := ex.count(9201); n != 1 { + t.Fatalf("a stale busy file blocked the restart: %d restarts", n) + } +}