R-100: offsite staleness counts from the last SUCCESS (hub v0.80.0)

isStale counted from last_run, written unconditionally on failure, so a nightly-failing
tier read as fresh forever. Now anchored on last_success with an explicit legacy degrade
(logged once) and the never-ran branch untouched. emitStale states the real reason.
This commit is contained in:
2026-07-28 13:17:04 +02:00
parent 6369570e8d
commit b505ee9125
4 changed files with 405 additions and 16 deletions
+109 -16
View File
@@ -27,7 +27,11 @@ type OffsiteChecker struct {
logger *log.Logger
onEvent EventNotifyFunc
staleAfter time.Duration
now func() time.Time // injectable clock (tests)
// legacyWarned tracks the one-shot R-100 legacy-degrade log, per customer.
legacyMu sync.Mutex
legacyWarned map[string]bool
now func() time.Time // injectable clock (tests)
mu sync.Mutex
fillStates map[string]string // customerID → fill band
@@ -38,10 +42,13 @@ const defaultOffsiteStaleAfter = 48 * time.Hour
// offsiteReport mirrors the controller report's `offsite` object (v0.109.0).
type offsiteReport struct {
Enabled bool `json:"enabled"`
EscrowState string `json:"escrow_state"`
LastRun string `json:"last_run"`
LastStatus string `json:"last_status"`
Enabled bool `json:"enabled"`
EscrowState string `json:"escrow_state"`
LastRun string `json:"last_run"`
LastStatus string `json:"last_status"`
// LastSuccess (R-100) is the last run that actually SUCCEEDED — the staleness anchor. Absent on a
// controller older than v0.181.0; isStale degrades explicitly in that case, see there.
LastSuccess string `json:"last_success"`
SnapshotCount int `json:"snapshot_count"`
RepoSizeBytes int64 `json:"repo_size_bytes"`
QuotaGB int `json:"quota_gb"`
@@ -100,9 +107,20 @@ func (oc *OffsiteChecker) fillBand(off *offsiteReport) string {
return bandForPercent(pct, 90, 95)
}
// isStale: enabled + ESCROWED (the only state where runs are expected) with no run in >staleAfter (or
// never ran, ANCHORED — see below). Pending/disabled = normal onboarding, never stale. A
// recent-but-failing run is NOT stale (backup_failed owns that signal).
// isStale: enabled + ESCROWED (the only state where runs are expected) with no SUCCESSFUL run in
// >staleAfter (or never ran, ANCHORED — see below). Pending/disabled = normal onboarding, never stale.
//
// R-100 — PRESENCE IS NOT SUCCESS. This counted from `LastRun`, which the controller writes
// unconditionally at the end of every run INCLUDING failures. So it asked "how long since we last
// TRIED", and a tier failing on every single run refreshed the clock nightly and read as perfectly
// fresh forever. It now counts from `LastSuccess`, which only a successful run advances.
//
// The old comment here said "a recent-but-failing run is NOT stale (backup_failed owns that signal)",
// and that WAS true — `backup_failed` does fire, nightly, and reaches the operator. The defect is not
// silence, it is DEFEATED DEFENCE IN DEPTH: this checker is the hub-side, pull-based net that exists to
// be independent of controller-PUSHED events, and anchoring it on a field the failing controller keeps
// refreshing made it depend on the very thing it backs up. F-HUB (the hub dropping an event under
// SQLITE_BUSY, no retry) is exactly that loss. INVARIANT pinned by TestIsStale_* in offsite_r100_test.go.
//
// Part-7 (v0.73.0) — the never-ran branch no longer fires on sight. The 2026-07-23 cry-wolf:
// demo-hp's tier was repaired and escrowed at 10:01Z and offsite_stale fired MINUTES later
@@ -117,6 +135,11 @@ func (oc *OffsiteChecker) isStale(customerID string, off *offsiteReport) bool {
if !off.Enabled || off.EscrowState != "escrowed" {
return false
}
// NEVER RAN AT ALL — unchanged v0.73.0 behaviour, and it must stay unchanged. A newborn box has no
// LastRun and no LastSuccess; alarming it on sight is the 2026-07-23 cry-wolf. Checked on LastRun
// (not LastSuccess) deliberately: LastRun is the "has anything ever happened here" signal, and a box
// whose first run FAILED has a LastRun but no LastSuccess — that is a run, not a newborn, and it
// belongs on the anchored path below.
if off.LastRun == "" {
anchor := oc.neverRanAnchor(customerID)
if anchor.IsZero() {
@@ -124,13 +147,52 @@ func (oc *OffsiteChecker) isStale(customerID string, off *offsiteReport) bool {
}
return oc.now().Sub(anchor) > oc.staleAfter
}
t, err := time.Parse(time.RFC3339, off.LastRun)
// LEGACY CONTROLLER — it has run, but sends no last_success (pre-v0.181.0). Handle it EXPLICITLY,
// in the direction that preserves known behaviour: count from LastRun exactly as before.
// - treating absence as FAILURE would alarm every un-upgraded box in the fleet at once;
// - treating it as SUCCESS is the bug.
// Preserving today's behaviour is correct here; the controller version floor drives the upgrade.
// Same degrade direction as R-88 Part 2's age_state, and for the same reason.
if off.LastSuccess == "" {
oc.warnLegacyOnce(customerID)
t, err := time.Parse(time.RFC3339, off.LastRun)
if err != nil {
return true // unparseable = unknown-old — fail toward visibility
}
return oc.now().Sub(t) > oc.staleAfter
}
// THE ANCHORED VERDICT. Note what is NOT consulted: LastStatus. A single failed night does not make
// a tier stale — the threshold simply keeps running from the last good run, so one blip is tolerated
// and a persistent failure is caught. Reading LastStatus here ("error ⇒ stale") would alarm on every
// transient blip, which is the F-A1 noise path that trains an operator to ignore the alarm.
// `running` is a real wire value (a report captured mid-run) and is likewise none of our business.
t, err := time.Parse(time.RFC3339, off.LastSuccess)
if err != nil {
return true // unparseable = unknown-old — fail toward visibility
}
return oc.now().Sub(t) > oc.staleAfter
}
// warnLegacyOnce logs the legacy degrade a single time per customer. Once, because this is a
// steady-state condition until the box upgrades — a per-cycle line would be pure noise — but it must be
// logged at all, so a fleet silently running on the old anchor is visible rather than assumed.
func (oc *OffsiteChecker) warnLegacyOnce(customerID string) {
oc.legacyMu.Lock()
defer oc.legacyMu.Unlock()
if oc.legacyWarned == nil {
oc.legacyWarned = map[string]bool{}
}
if oc.legacyWarned[customerID] {
return
}
oc.legacyWarned[customerID] = true
if oc.logger != nil {
oc.logger.Printf("[WARN] [offsite] %s: controller sends no last_success — staleness degraded to the last-ATTEMPT anchor (pre-v0.181.0 controller; a persistently failing tier will not go stale here until it upgrades)", customerID)
}
}
// neverRanAnchor returns the newest hub-held timestamp from which a never-ran-but-applied tier's
// staleness may be counted (zero when the hub holds neither — the pre-v0.5x legacy shape).
func (oc *OffsiteChecker) neverRanAnchor(customerID string) time.Time {
@@ -258,16 +320,47 @@ func (oc *OffsiteChecker) emitFill(customerID string, off *offsiteReport, band s
}
}
func (oc *OffsiteChecker) emitStale(customerID string, off *offsiteReport) {
age := "never ran"
if off.LastRun != "" {
if t, err := time.Parse(time.RFC3339, off.LastRun); err == nil {
age = fmt.Sprintf("last run %s ago", oc.now().Sub(t).Round(time.Hour))
// staleAge describes WHY the tier is stale, in the terms the verdict actually used.
//
// R-100: this must not say "last run 8h ago" while alarming, which is what it did when the verdict
// moved to the success anchor — a tier that RUNS nightly and FAILS nightly would have alarmed with a
// fresh-looking timestamp, and the operator would have read a true alarm as a false one. The two cases
// are genuinely different diagnoses and the message now separates them:
// - runs are not happening at all → check the schedule/controller
// - runs happen and FAIL → check the error; this is the case backup_failed also reports
func (oc *OffsiteChecker) staleAge(off *offsiteReport) (age, hint string) {
parse := func(v string) (time.Duration, bool) {
t, err := time.Parse(time.RFC3339, v)
if err != nil {
return 0, false
}
return oc.now().Sub(t).Round(time.Hour), true
}
message := fmt.Sprintf("Customer %s: offsite backup is STALE — enabled + escrowed but %s (threshold %s). The offsite leg is silently not running; check the controller/schedule", customerID, age, oc.staleAfter)
if off.LastSuccess == "" {
if d, ok := parse(off.LastRun); ok {
return fmt.Sprintf("no run has EVER succeeded (last attempt %s ago, status %q)", d, off.LastStatus),
" Runs are happening and failing — check the error, not the schedule"
}
return "never ran", " The offsite leg is silently not running; check the controller/schedule"
}
d, ok := parse(off.LastSuccess)
if !ok {
return "last successful run at an unparseable time", " Check the controller/schedule"
}
if la, ok := parse(off.LastRun); ok && off.LastRun != off.LastSuccess {
return fmt.Sprintf("last SUCCESSFUL run %s ago (it last attempted %s ago, status %q)", d, la, off.LastStatus),
" Runs are happening and failing — check the error, not the schedule"
}
return fmt.Sprintf("last successful run %s ago", d),
" The offsite leg is silently not running; check the controller/schedule"
}
func (oc *OffsiteChecker) emitStale(customerID string, off *offsiteReport) {
age, hint := oc.staleAge(off)
message := fmt.Sprintf("Customer %s: offsite backup is STALE — enabled + escrowed but %s (threshold %s).%s", customerID, age, oc.staleAfter, hint)
details, _ := json.Marshal(map[string]any{
"customer_id": customerID, "last_run": off.LastRun, "last_status": off.LastStatus, "stale_after": oc.staleAfter.String(),
"customer_id": customerID, "last_run": off.LastRun, "last_success": off.LastSuccess,
"last_status": off.LastStatus, "stale_after": oc.staleAfter.String(),
})
oc.logger.Printf("[INFO] Offsite staleness: %s (%s)", customerID, age)
if _, err := oc.store.SaveEvent(customerID, "offsite_stale", "warning", message, string(details), "hub"); err != nil {