From fb91c8d76643ed1e3f69232ed414e4078a6b2667 Mon Sep 17 00:00:00 2001 From: kisfenyo Date: Tue, 28 Jul 2026 10:27:28 +0200 Subject: [PATCH] F-OBS: the dead-app check gets a positive observable (v0.180.0) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit deadapp-check had no observable at default info level: its per-cycle line goes through Scheduler.dbg(), gated on logging.level==debug, so on a default box it is never PRODUCED (not merely filtered) and cannot reach the always-DEBUG ring. A 30s interval also puts it on the scheduler's quiet path. 'No alarms' was therefore indistinguishable from 'the detector never ran' — which undermines confidence in the F-CRIT-1 fix in the field. A periodic summary, not a line per run: at 30s a per-run line is 2880 lines/day, which is why the original author chose silence. Every 20th scan (~10 min) emits one INFO with the scan count, apps evaluated and apps down. A test pins the cadence so it cannot be widened into uselessness. Also corrects the 'unquiesce guaranteed by defer' comment — fault 10 established the guarantee is the crash marker plus Recover(). --- CHANGELOG.md | 32 ++++++ .../cmd/controller/deadapp_observable_test.go | 97 +++++++++++++++++++ controller/cmd/controller/main.go | 37 +++++++ controller/internal/quiesce/quiesce.go | 6 +- 4 files changed, 171 insertions(+), 1 deletion(-) create mode 100644 controller/cmd/controller/deadapp_observable_test.go diff --git a/CHANGELOG.md b/CHANGELOG.md index 661c8dd..9cccbe5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,37 @@ ## Changelog +### v0.180.0 — F-OBS: the dead-app check gets a positive observable (2026-07-28) + +On a default `logging.level: info` box there was **no way to tell whether `deadapp-check` had run**. +Its per-cycle scheduler line goes through `Scheduler.dbg()`, which is gated on `s.debug` — so on an +info-level box the line is never *produced*, not merely filtered, and therefore cannot reach the +always-DEBUG ring either. A 30 s interval also puts the job on the scheduler's quiet path +(`quiet := job.Interval <= 30*time.Second`). + +So "no alarms" was indistinguishable from "the detector never ran" — the exact fallacy this project +now has a standing rule against, and it directly undermines confidence in the **F-CRIT-1** fix in the +field: that fix's whole value is that a genuinely dead app now alarms, and an operator had no way to +confirm the thing that alarms is alive. + +**A periodic summary, not a line per run.** At 30 s a per-run line is 2880 lines/day, which is +precisely why the original author chose silence — so a fix that floods is not a fix. Every 20th scan +(≈10 minutes) emits one INFO carrying the scan count, how many deployed apps were evaluated, and how +many are currently down. An operator can answer "is it running, and what does it see?" from a default +box, and a STALLED detector shows up as the heartbeat stopping. + +10 minutes is chosen to stay useful as a liveness signal: it is well inside the 180 s alarm grace this +check feeds, and a test pins the cadence so nobody can widen it to hours and quietly make the +observable useless again. + +### Also +Corrected the comment claiming the quiesce unquiesce is "guaranteed by defer". Campaign 8 fault 10 +established that a SIGKILL runs no deferred function — the guarantee is the crash MARKER plus +`Recover()`, which brought the stacks back 1 s after restart. The `defer` covers only the graceful +exits. + +Files: `cmd/controller/main.go`, `internal/quiesce/quiesce.go` (comment), +`cmd/controller/deadapp_observable_test.go` (new). + ### 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 diff --git a/controller/cmd/controller/deadapp_observable_test.go b/controller/cmd/controller/deadapp_observable_test.go new file mode 100644 index 0000000..96910f1 --- /dev/null +++ b/controller/cmd/controller/deadapp_observable_test.go @@ -0,0 +1,97 @@ +package main + +import ( + "bytes" + "log" + "strings" + "testing" +) + +// F-OBS (Campaign 8): on a default `info`-level box there was NO positive observable that +// `deadapp-check` had run. Its per-cycle scheduler line goes through Scheduler.dbg(), which is gated +// on logging.level==debug and therefore never PRODUCED on a default box — so it could not even reach +// the always-DEBUG ring — and a 30 s interval also puts the job on the scheduler's quiet path. +// +// "No alarms" was therefore indistinguishable from "the detector never ran", which is exactly the +// fallacy this project now has a standing rule against, and it undermines confidence in the +// F-CRIT-1 fix in the field. +// +// Scenario F — the observable must appear AT INFO LEVEL. These tests assert the emitted LINE, not +// merely that a function was called; asserting the call would reproduce the original mistake. + +// RED-PROOF: delete the logger.Printf in noteDeadAppScan (or drop the whole call from the job +// closure) → every case below sees an empty buffer and this fails with +// "no observable emitted at scan 20 — silence is indistinguishable from not running". +func TestNoteDeadAppScan_EmitsAtInfoLevel(t *testing.T) { + var buf bytes.Buffer + lg := log.New(&buf, "", 0) + + noteDeadAppScan(lg, deadAppHeartbeatEvery, 7, 2) + + out := buf.String() + if out == "" { + t.Fatalf("no observable emitted at scan %d — silence is indistinguishable from not running", deadAppHeartbeatEvery) + } + if !strings.Contains(out, "[INFO]") { + t.Errorf("the observable is not at INFO level, so a default `logging.level: info` box would never see it:\n%s", out) + } + if !strings.Contains(out, "[deadapp]") { + t.Errorf("the observable does not identify the check that produced it:\n%s", out) + } + // it must carry WHAT IT SAW, not just "I ran" — an operator needs to distinguish + // "running and everything is up" from "running and 2 apps are down". + for _, want := range []string{"scans since boot", "evaluated", "currently down"} { + if !strings.Contains(out, want) { + t.Errorf("the observable omits %q — it proves the check ran but not what it found:\n%s", want, out) + } + } +} + +// It must NOT be a line per run. At a 30 s cadence that is 2880 lines/day, which is precisely why +// the original author chose silence — so a fix that floods is not a fix. +// +// RED-PROOF: change the guard to `scans%1 != 0` (i.e. emit every run) → this fails with +// "emitted 60 lines across 60 scans — that is the flood that made silence attractive". +func TestNoteDeadAppScan_IsASummaryNotAFlood(t *testing.T) { + var buf bytes.Buffer + lg := log.New(&buf, "", 0) + + const scans = 60 + for i := 1; i <= scans; i++ { + noteDeadAppScan(lg, i, 3, 0) + } + + got := strings.Count(buf.String(), "[deadapp] check alive") + want := scans / deadAppHeartbeatEvery + if got == scans { + t.Fatalf("emitted %d lines across %d scans — that is the flood that made silence attractive", got, scans) + } + if got != want { + t.Errorf("emitted %d heartbeat lines across %d scans, want %d (one per %d)", got, scans, want, deadAppHeartbeatEvery) + } +} + +// The cadence must be frequent enough that a STALLED detector is obvious well inside the 180 s alarm +// grace this check feeds. 20 scans x 30 s = 10 min; if someone widens it to hours the observable +// stops being useful as a liveness signal, and this is the tripwire. +func TestDeadAppHeartbeatEvery_StaysUsefulAsALivenessSignal(t *testing.T) { + const scanInterval = 30 // seconds, matching sched.Every("deadapp-check", 30*time.Second, ...) + periodSec := deadAppHeartbeatEvery * scanInterval + if periodSec > 15*60 { + t.Errorf("heartbeat period is %ds (>15min) — too sparse to notice a stalled detector", periodSec) + } + if deadAppHeartbeatEvery < 2 { + t.Errorf("heartbeat every %d scans is a per-run flood", deadAppHeartbeatEvery) + } +} + +// Off-cadence scans stay quiet, and a nil logger is tolerated (the job closure must never panic). +func TestNoteDeadAppScan_QuietOffCadenceAndNilSafe(t *testing.T) { + var buf bytes.Buffer + lg := log.New(&buf, "", 0) + noteDeadAppScan(lg, deadAppHeartbeatEvery-1, 1, 0) + if buf.Len() != 0 { + t.Errorf("emitted off-cadence:\n%s", buf.String()) + } + noteDeadAppScan(nil, deadAppHeartbeatEvery, 1, 0) // must not panic +} diff --git a/controller/cmd/controller/main.go b/controller/cmd/controller/main.go index 9310556..4ff5c5c 100644 --- a/controller/cmd/controller/main.go +++ b/controller/cmd/controller/main.go @@ -468,6 +468,20 @@ func main() { // quiet path (no ring spam — fix-6 friendly); the dashboard banner is state-based (self-clears) and // the hub event fires once per running→down transition (notifier tracks it). A boot grace skips the // controller's own startup settle so apps that legitimately take 30–60 s to come up don't alert. + // + // F-OBS (Campaign 8): this check had NO positive observable at default `info` level. Its per-cycle + // scheduler line is emitted through Scheduler.dbg(), which is gated on logging.level==debug and so + // is never PRODUCED on a default box (not merely filtered — the always-DEBUG ring cannot capture + // it either), and a 30 s interval also puts it on the scheduler's quiet path. So on every customer + // box, "no alarms" was indistinguishable from "the detector never ran" — the precise fallacy this + // project now has a standing rule against, and it directly undermines confidence in the F-CRIT-1 + // fix in the field. + // + // The observable is a PERIODIC SUMMARY, not a line per run: at 30 s a per-run line is 2880 + // lines/day of pure noise, which is what made the original author choose silence. Every + // deadAppHeartbeatEvery-th scan emits one INFO carrying the scan count and what it found, so an + // operator can always answer "is it running, and what does it see?" from a default box — and a + // STALLED detector is visible as the heartbeat stopping. sched.Every("deadapp-check", 30*time.Second, func(ctx context.Context) error { if time.Since(startTime) < deadAppBootGrace { return nil // still inside the startup settle window @@ -475,6 +489,8 @@ func main() { dead, states := scanDeployedAppRunStates(stackMgr, quiesceLoop) alertMgr.SetDeadAppAlerts(dead) notifier.NotifyAppStartFailures(states) + deadAppScans++ + noteDeadAppScan(logger, deadAppScans, len(states), len(dead)) return nil }) @@ -1173,6 +1189,27 @@ func main() { // own boot. After the grace, an app that still isn't running alerts (the F11 dead-at-boot case). const deadAppBootGrace = 90 * time.Second +// deadAppHeartbeatEvery is how many 30 s scans pass between deadapp heartbeat lines (F-OBS). +// 20 scans = one line per ~10 minutes: frequent enough that a stalled detector is obvious well +// inside the 180 s alarm grace it feeds, and 144 lines/day instead of 2880. +const deadAppHeartbeatEvery = 20 + +// deadAppScans counts completed deadapp scans since boot. Single-goroutine (the scheduler runs +// each job serially), so it needs no lock. +var deadAppScans int + +// noteDeadAppScan emits the F-OBS heartbeat every deadAppHeartbeatEvery-th scan, at [INFO] so it +// survives a default `logging.level: info` box. Extracted from the job closure so a test can assert +// the OBSERVABLE (the line, at info) rather than merely that the scan function ran — which is the +// distinction F-OBS is about. +func noteDeadAppScan(logger *log.Logger, scans, evaluated, down int) { + if logger == nil || deadAppHeartbeatEvery <= 0 || scans%deadAppHeartbeatEvery != 0 { + return + } + logger.Printf("[INFO] [deadapp] check alive: %d scans since boot, %d deployed app(s) evaluated, %d currently down", + scans, evaluated, down) +} + // bootReconcileSettle lets the initial scan, the first status refresh and the quiesce recovery // settle before the R-52 sweep decides what "down" means. 5 s + at most one 30 s retry gap keeps // the whole sweep inside deadAppBootGrace (90 s), which is what makes a successful recovery silent. diff --git a/controller/internal/quiesce/quiesce.go b/controller/internal/quiesce/quiesce.go index 16cabf8..ca48a3c 100644 --- a/controller/internal/quiesce/quiesce.go +++ b/controller/internal/quiesce/quiesce.go @@ -449,7 +449,11 @@ func (l *Loop) allTiersForManualRun(ctx context.Context) []dueTier { // matters — see resolveDueTiers. // // Crash-safety is unchanged and non-negotiable: the marker is written BEFORE anything stops, -// unquiesce is guaranteed by defer, and it fires exactly once no matter which tier fails. A crash +// unquiesce fires exactly once no matter which tier fails, and the GUARANTEE is the crash MARKER plus +// Recover() — not the defer. Campaign 8 fault 10 established that: a SIGKILL mid-quiesce runs no +// deferred function, and what brought the stacks back was Recover() reading the marker 1 s after +// restart. The defer covers the graceful exits (backup error, poll error, max-quiesce bound, context +// cancellation); the marker covers the hard crash. Do not describe this as "guaranteed by defer". A crash // between two backups leaves the marker on disk and Recover() restarts the stacks at startup. func (l *Loop) quiesceAndPollTiers(ctx context.Context, tiers []dueTier) error { if len(tiers) == 0 {