From f27f7a265928075828051c9e6fdc7cc72952e9b7 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 28 Jul 2026 11:14:56 +0200 Subject: [PATCH] guest-power: add the liveness observable it shipped without (v0.109.0) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The v0.107.0 watchdog was silent on a healthy box, so its health could only be inferred from absence — F-OBS's shape, shipped in the same session F-OBS was fixed. INFO summary every 10th sweep with what it saw; aborted sweeps are not counted. Red-proofs 7 and 8. --- CHANGELOG.md | 27 ++++ internal/localapi/guestpower.go | 32 +++++ .../localapi/guestpower_observable_test.go | 120 ++++++++++++++++++ internal/localapi/server.go | 6 +- 4 files changed, 184 insertions(+), 1 deletion(-) create mode 100644 internal/localapi/guestpower_observable_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index cbde816..d8e2d5b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,3 +1,30 @@ +## v0.109.0 — the guest-power watchdog gets the observable it was shipped without (2026-07-28) + +**Self-correction to v0.107.0, found by running the very check this session added elsewhere.** The new +guest-power watchdog logged at startup and when it ACTED, and was otherwise silent — so on a healthy +box the only evidence the sweep was running was the *absence* of start lines. That is exactly F-OBS's +shape, and exactly what standing rule 3 forbids: an absent log line is not evidence of correct +behaviour. It shipped in the same session F-OBS was fixed in `deadapp-check`, which is what makes it +worth recording rather than quietly patching. + +`GuestPowerTick` now emits an INFO summary every **10th** sweep (10 x 60 s = 10 min, matching the +controller's deadapp heartbeat) carrying `sweeps_since_boot`, `guests_evaluated` and +`currently_stopped`. It reports **what the sweep saw**, not merely that it ran — "alive, all guests up" +and "alive, one guest deliberately left down" are different operator facts and a bare liveness ping +cannot express the second. + +Two bounds, both pinned by test in the direction that would break them: +- **Not a flood.** One line per sweep would be 1440/day, which is the pressure that made silence + attractive in the first place. A test fails if the cadence degenerates to per-sweep. +- **An aborted sweep does not count.** If `Guests()` fails, ownership is unproven and the sweep + examines nothing; counting it would have the heartbeat claim liveness for a watchdog doing nothing — + a worse lie than silence. The counter increments only after the guest list is in hand. + +Red-proofs 7 and 8, both observed failing: removing the call → +`no liveness observable after 10 sweeps — silence is indistinguishable from a dead watchdog`; +moving the increment above the error return → +`an aborted sweep was counted as healthy (sweeps=20)`. + # felhom-agent — Changelog ## v0.108.0 — F-LEAK: the pool-adoption fix was WRONG; the fix is a path-scoped ACL (2026-07-28) diff --git a/internal/localapi/guestpower.go b/internal/localapi/guestpower.go index d59c364..4376ba4 100644 --- a/internal/localapi/guestpower.go +++ b/internal/localapi/guestpower.go @@ -2,6 +2,7 @@ package localapi import ( "context" + "log/slog" "sync" "time" @@ -53,6 +54,16 @@ const ( // guestPowerMaxAttempts bounds the retry. A guest that will not start must not be started in a // loop forever (Scenario C) — after this many failures the watchdog stops trying and raises it. guestPowerMaxAttempts = 3 + + // guestPowerHeartbeatEvery emits a summary line every Nth sweep. 10 x 60s = 10 minutes, matching + // the controller's deadapp heartbeat. + // + // WHY THIS EXISTS, and it is a correction to this file's OWN first version (v0.107.0): the + // watchdog logged at startup and when it ACTED, and was otherwise silent. A silent watchdog is + // indistinguishable from a dead one — which is F-OBS, the very finding fixed in the same session + // this file shipped in, and it is what standing rule 3 exists to prevent. An operator needs a + // POSITIVE observable that the sweep is running; "no start lines" must not be the only evidence. + guestPowerHeartbeatEvery = 10 ) // guestPowerBackoff is the delay before each retry: 1m, 2m, 4m. @@ -106,12 +117,33 @@ func (s *Server) GuestPowerTick(ctx context.Context) { s.logger.Warn("guest-power: guest list unavailable — skipping sweep (ownership unproven)", "err", err) return } + var stopped int for _, g := range guests { if ctx.Err() != nil { return } + if g.Status != "running" { + stopped++ + } s.recoverOneStoppedGuest(ctx, g) } + + s.guestPowerSweeps++ + noteGuestPowerSweep(s.logger, s.guestPowerSweeps, len(guests), stopped) +} + +// noteGuestPowerSweep emits the liveness observable every guestPowerHeartbeatEvery sweeps. +// +// It carries WHAT THE SWEEP SAW, not merely that it ran: a line saying "I am alive" cannot +// distinguish "alive, all guests up" from "alive, one guest down and being left alone on purpose", +// and the second is the state an operator needs to see. Pure and separately testable — the mistake +// being corrected here was untestable precisely because it lived inline. +func noteGuestPowerSweep(logger *slog.Logger, sweeps, evaluated, stopped int) { + if logger == nil || sweeps <= 0 || sweeps%guestPowerHeartbeatEvery != 0 { + return + } + logger.Info("guest-power: watchdog alive", + "sweeps_since_boot", sweeps, "guests_evaluated", evaluated, "currently_stopped", stopped) } // recoverOneStoppedGuest starts a single guest that should be running and is not. diff --git a/internal/localapi/guestpower_observable_test.go b/internal/localapi/guestpower_observable_test.go new file mode 100644 index 0000000..91a9616 --- /dev/null +++ b/internal/localapi/guestpower_observable_test.go @@ -0,0 +1,120 @@ +package localapi + +import ( + "bytes" + "context" + "errors" + "log/slog" + "strings" + "testing" + + "gitea.dooplex.hu/admin/felhom-agent/internal/proxmox" +) + +// A CORRECTION TO THIS PACKAGE'S OWN v0.107.0. The guest-power watchdog logged at startup and when it +// ACTED, and was silent otherwise — so on a healthy box the only evidence it was running was the +// absence of start lines, which is equally consistent with the sweep having died. That is F-OBS's +// shape and what standing rule 3 forbids, shipped in the same session F-OBS was fixed. +// +// These tests assert the emitted LINE. Asserting that a function was called would reproduce the +// original mistake, which was invisible precisely because nothing pinned the output. + +// RED-PROOF: delete the noteGuestPowerSweep call at the end of GuestPowerTick (or the Info line +// inside it) → this fails with "no liveness observable after 10 sweeps — silence is +// indistinguishable from a dead watchdog". +func TestGuestPowerSweep_EmitsLivenessObservable(t *testing.T) { + var buf bytes.Buffer + ctl := &fakeGuestPowerCtl{ + guests: []proxmox.Guest{{VMID: 9201, Status: "running"}, {VMID: 9100, Status: "stopped"}}, + locks: map[int]string{9201: "", 9100: ""}, + onboot: map[int]bool{9201: true, 9100: false}, // 9100 is a deliberate stop + } + s := gpServer(t, ctl, nil) + s.logger = slog.New(slog.NewTextHandler(&buf, nil)) + + for i := 0; i < guestPowerHeartbeatEvery; i++ { + s.GuestPowerTick(context.Background()) + } + + out := buf.String() + if !strings.Contains(out, "watchdog alive") { + t.Fatalf("no liveness observable after %d sweeps — silence is indistinguishable from a dead watchdog:\n%s", + guestPowerHeartbeatEvery, out) + } + if !strings.Contains(out, "level=INFO") { + t.Errorf("the observable is not at INFO — a box on the default level would never see it:\n%s", out) + } + // It must carry WHAT IT SAW. "currently_stopped=1" is the operator-relevant fact here: the sweep is + // alive AND is deliberately leaving one guest down, which "I ran" alone cannot express. + for _, want := range []string{"sweeps_since_boot=", "guests_evaluated=2", "currently_stopped=1"} { + if !strings.Contains(out, want) { + t.Errorf("the observable omits %q — it proves the sweep ran but not what it found:\n%s", want, out) + } + } +} + +// It must be a summary, not a line per sweep: at 60 s that would be 1440 lines/day, which is the +// pressure that made silence attractive in the first place. +// +// RED-PROOF: change the guard to `sweeps%1 != 0` → this fails with +// "emitted 30 observables across 30 sweeps — that is the flood that made silence attractive". +func TestGuestPowerSweep_IsASummaryNotAFlood(t *testing.T) { + var buf bytes.Buffer + lg := slog.New(slog.NewTextHandler(&buf, nil)) + + const sweeps = 30 + for i := 1; i <= sweeps; i++ { + noteGuestPowerSweep(lg, i, 1, 0) + } + + got := strings.Count(buf.String(), "watchdog alive") + want := sweeps / guestPowerHeartbeatEvery + if got == sweeps { + t.Fatalf("emitted %d observables across %d sweeps — that is the flood that made silence attractive", got, sweeps) + } + if got != want { + t.Errorf("emitted %d observables across %d sweeps, want %d", got, sweeps, want) + } +} + +// The heartbeat period must stay short enough that a STALLED sweep is obvious well inside the outage +// window this watchdog exists to close (the finding's incident was 9m47s of total appliance +// downtime). If someone widens the cadence to hours the observable stops being a liveness signal. +func TestGuestPowerHeartbeat_StaysUsefulAsALivenessSignal(t *testing.T) { + period := guestPowerHeartbeatEvery * int(guestPowerInterval.Seconds()) + if period > 15*60 { + t.Errorf("heartbeat period is %ds (>15min) — too sparse to notice a stalled watchdog", period) + } + if guestPowerHeartbeatEvery < 2 { + t.Errorf("heartbeat every %d sweeps is a per-sweep flood", guestPowerHeartbeatEvery) + } +} + +// Off-cadence sweeps stay quiet; a nil logger must not panic (the ticker goroutine has no recovery). +func TestGuestPowerSweep_QuietOffCadenceAndNilSafe(t *testing.T) { + var buf bytes.Buffer + lg := slog.New(slog.NewTextHandler(&buf, nil)) + noteGuestPowerSweep(lg, guestPowerHeartbeatEvery-1, 1, 0) + if buf.Len() != 0 { + t.Errorf("emitted off-cadence:\n%s", buf.String()) + } + noteGuestPowerSweep(nil, guestPowerHeartbeatEvery, 1, 0) // must not panic +} + +// A sweep that ABORTED on unproven ownership must NOT count as a healthy sweep — otherwise the +// heartbeat would report liveness for a watchdog that is examining nothing, which is a worse lie than +// silence. +// +// RED-PROOF: move the s.guestPowerSweeps++ above the Guests() error return → this fails with +// "an aborted sweep was counted as healthy". +func TestGuestPowerSweep_AbortedSweepIsNotCounted(t *testing.T) { + ctl := &fakeGuestPowerCtl{guestsErr: errors.New("pool read failed")} + s := gpServer(t, ctl, nil) + for i := 0; i < guestPowerHeartbeatEvery*2; i++ { + s.GuestPowerTick(context.Background()) + } + if s.guestPowerSweeps != 0 { + t.Errorf("an aborted sweep was counted as healthy (sweeps=%d) — the heartbeat would claim liveness for a watchdog examining nothing", + s.guestPowerSweeps) + } +} diff --git a/internal/localapi/server.go b/internal/localapi/server.go index d03294e..db524f3 100644 --- a/internal/localapi/server.go +++ b/internal/localapi/server.go @@ -266,7 +266,11 @@ type Server struct { // guestPower (F-REBOOT) is per-guest start-attempt state for the guest-power watchdog. // Guarded by guestPowerMu in guestpower.go; in-memory on purpose (see guestPowerState). guestPower map[int]guestPowerState - host storage.HostReader // role classification source (optional; defaults to ProcHostReader) + + // guestPowerSweeps counts completed guest-power sweeps, for the liveness observable. Touched only + // from GuestPowerTick, which the ticker calls serially. + guestPowerSweeps int + host storage.HostReader // role classification source (optional; defaults to ProcHostReader) hostMetrics HostMetricsProvider // slice 9 (optional) hostID string // slice 10B: for the data-bearing-format pending-op hint