F-OBS: the dead-app check gets a positive observable (v0.180.0)
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().
This commit is contained in:
@@ -1,5 +1,37 @@
|
|||||||
## Changelog
|
## 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)
|
### 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
|
Both Campaign 8 findings live in `internal/quiesce` and its `classifyRunStates` consumer, and both
|
||||||
|
|||||||
@@ -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
|
||||||
|
}
|
||||||
@@ -468,6 +468,20 @@ func main() {
|
|||||||
// quiet path (no ring spam — fix-6 friendly); the dashboard banner is state-based (self-clears) and
|
// 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
|
// 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.
|
// 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 {
|
sched.Every("deadapp-check", 30*time.Second, func(ctx context.Context) error {
|
||||||
if time.Since(startTime) < deadAppBootGrace {
|
if time.Since(startTime) < deadAppBootGrace {
|
||||||
return nil // still inside the startup settle window
|
return nil // still inside the startup settle window
|
||||||
@@ -475,6 +489,8 @@ func main() {
|
|||||||
dead, states := scanDeployedAppRunStates(stackMgr, quiesceLoop)
|
dead, states := scanDeployedAppRunStates(stackMgr, quiesceLoop)
|
||||||
alertMgr.SetDeadAppAlerts(dead)
|
alertMgr.SetDeadAppAlerts(dead)
|
||||||
notifier.NotifyAppStartFailures(states)
|
notifier.NotifyAppStartFailures(states)
|
||||||
|
deadAppScans++
|
||||||
|
noteDeadAppScan(logger, deadAppScans, len(states), len(dead))
|
||||||
return nil
|
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).
|
// own boot. After the grace, an app that still isn't running alerts (the F11 dead-at-boot case).
|
||||||
const deadAppBootGrace = 90 * time.Second
|
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
|
// 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
|
// 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.
|
// the whole sweep inside deadAppBootGrace (90 s), which is what makes a successful recovery silent.
|
||||||
|
|||||||
@@ -449,7 +449,11 @@ func (l *Loop) allTiersForManualRun(ctx context.Context) []dueTier {
|
|||||||
// matters — see resolveDueTiers.
|
// matters — see resolveDueTiers.
|
||||||
//
|
//
|
||||||
// Crash-safety is unchanged and non-negotiable: the marker is written BEFORE anything stops,
|
// 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.
|
// 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 {
|
func (l *Loop) quiesceAndPollTiers(ctx context.Context, tiers []dueTier) error {
|
||||||
if len(tiers) == 0 {
|
if len(tiers) == 0 {
|
||||||
|
|||||||
Reference in New Issue
Block a user