Files
felhom.eu/hub/internal/monitor/deadline.go
T
admin 7fff45d688
gates / gates (push) Successful in 7s
R-195: a customer with no machine ever bound does not alarm (hub v0.92.0) + R-193/R-192 spike
Part 4 (ships): `david` — a prospective customer with hosts=0, host_deletions=0,
reports=0 — e-mailed an expected_dbdump_missed ERROR at 03:00 UTC three mornings
running. The existing down-skip could never cover it: it reads the staleness
checker's state, which is seeded from a query over the `reports` table, so a
customer that never reported has no state at all and GetState() returns "" rather
than "down". store.HasEverBoundHost (hosts row OR host_deletions tombstone) is
consulted once per customer at the top of the deadline loop. The discriminator is
"was a host EVER bound", never "has a report arrived" — a box installed and never
heard from is a real fault and keeps alarming. Fail-OPEN on a read error. Red-proof
observed: removing the guard fails with `got [expected_dbdump_missed]`, verbatim the
event david sent.

Parts 0-3 (spike, NO production code for R-193/R-192):
audits/SPIKE-offsite-credential-recovery-2026-08-04.md establishes that the one-shot
provider password is the RECOVERABLE secret and the restic repository password is the
irreplaceable one — and that a guest rebuild mints a fresh one, orphaning the previous
off-site history. Measured without touching a box, by comparing
host_escrow.restic_pw_sha256 against host_escrow_superseded: BOTH demo boxes changed
(demo-hp 15 snapshots / 40.9 MB, demo-felhom 36 snapshots / 1.14 GB). demo-felhom's
"lucky" 76-second recovery restored delivery and not the repository, silently, for 13h.
ReissueCredentials does NOT rotate the restic password (R-39's record and two hub
comments are wrong -> R-196); candidate (b) is not implementable against a
zero-knowledge escrow; candidate (a) already exists as F3 and is wired to the wrong
event. Ends in ranked options and an unanswered question for the operator.

R-195 SHIPPED; R-196 + R-197 filed; R-192 + R-193 updated, neither closed.
2026-08-04 11:04:39 +02:00

460 lines
21 KiB
Go
Raw Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
package monitor
import (
"encoding/json"
"fmt"
"log"
"strings"
"time"
"gitea.dooplex.hu/admin/felhom-hub/internal/store"
)
// backupStaleAfter is the maximum age of the newest offsite backup before the daily
// deadline check raises expected_backup_missed. 26h covers an evening backup schedule
// (e.g. ~18:0022:00) plus headroom, so a healthy once-daily cadence never trips the
// early-morning check.
//
// R-81 also reuses it as the ABSENCE window (see assessBackupFreshness): the existing
// threshold, anchored at first-contact, IS the newborn grace — no new knob, exactly as
// v0.73.0 reused offsite staleAfter for its never-ran anchor.
//
// ⚠️ LANDMINE — dependency on R-82 (the backup target split). This constant is applied to
// whichever tier is NEWEST, PBS or vzdump, with no tier-awareness. Today a daily vzdump
// always wins, so PBS's own age is invisible here and 26h is harmless. The moment PBS moves
// to a WEEKLY cadence, a perfectly healthy weekly snapshot is >26h old six days in seven and
// this constant alarms on it. Fixing that means per-tier thresholds, which cannot be built
// before the per-tier cadence config exists (`local_backup_target` is a single target and
// BackupCadence() a single 24h window today). Do NOT pre-build it — R-82 owns both halves.
const backupStaleAfter = 26 * time.Hour
// backupEvidenceLookback bounds how far back the hub looks for evidence that a backup ever
// happened, when the LATEST report carries none. Generous against any plausible daily cadence
// (and against an agent that stayed restarted for days), bounded so the cold path can't turn
// into a full-retention scan of every report the hub holds. Beyond this the verdict is
// "no evidence in the lookback", which is a fault in its own right once the anchor elapsed.
const backupEvidenceLookback = 7 * 24 * time.Hour
// hostReportBackups is the minimal slice of an agent host-report the deadline check
// reads to judge backup freshness (pbs_snapshots is the offsite-DR signal; backups is
// the local vzdump fallback). Mirrors the agent's hub.PBSSnapshot / hub.Backup wire
// contract for just the fields we need.
type hostReportBackups struct {
PBSSnapshots []struct {
BackupTime string `json:"backup_time"`
VerifyState string `json:"verify_state"`
} `json:"pbs_snapshots"`
Backups []struct {
// TargetID is the SLICE-C discriminator: a backups[] entry belongs to whichever tier its
// target storage belongs to, never to "the local tier" by virtue of being in this array.
TargetID string `json:"target_id"`
StartedAt string `json:"started_at"`
Success bool `json:"success"`
} `json:"backups"`
// StorageTargets carries the target TYPE, which is how a backups[] entry is attributed to a
// tier (target_id → name → type == "pbs"). See pbsTargetSet.
StorageTargets []struct {
Name string `json:"name"`
Type string `json:"type"`
Content string `json:"content"`
} `json:"storage_targets"`
}
// backupVerdict is the three-valued outcome of the freshness policy. The middle value is the
// whole point of R-81: "I have no evidence" is NOT "the backup failed".
type backupVerdict int
const (
verdictOK backupVerdict = iota // positive evidence of a recent backup
verdictUnknown // no evidence yet, and the anchored window has not elapsed
verdictMissed // positive evidence of a problem — alarm
)
// backupAssessment is the verdict for one customer's offsite backup health.
type backupAssessment struct {
verdict backupVerdict
reason string // human-readable cause (event message + logs)
}
// missed reports whether this assessment should raise expected_backup_missed.
func (a backupAssessment) missed() bool { return a.verdict == verdictMissed }
// backupEvidence is the hub-history half of the freshness policy, resolved by the caller so
// assessBackupFreshness stays PURE (see its doc comment on why that matters).
type backupEvidence struct {
// newestSeen is the newest backup evidence found across the retained host-report window
// (PBS backup_time or successful vzdump started_at), regardless of whether the LATEST
// report still carries it. haveSeen is false when the window held none.
newestSeen time.Time
haveSeen bool
// Per-tier window evidence (R-82 Slice C). A single "newest across everything" would let a
// fresh daily host backup satisfy the OFFSITE tier's lookup — the same error Slice A fixed
// agent-side. newestSeen/haveSeen above remain the pre-Slice-C combined values, used only by
// the no-tier fallback path.
newestHost time.Time
haveHost bool
newestOffsite time.Time
haveOffsite bool
// firstReportAt is when the hub first saw ANY host-report from this customer — the
// observation anchor. Zero when unknown, which the policy treats as "cannot defer"
// (fail toward visibility, matching the v0.73.0 zero-anchor branch).
firstReportAt time.Time
}
// assessBackupFreshness decides whether a customer's backups are healthy. Pure (now and the
// hub-history evidence are injected) so the policy is unit-tested — that purity is why the
// 2026-07-26 incident could be diagnosed at all, and why the fix below is provable.
//
// ── THE INVARIANT (R-81) ──────────────────────────────────────────────────────────────────
//
// Only POSITIVE EVIDENCE OF A PROBLEM raises an alarm. ABSENCE OF A SIGNAL IS UNKNOWN,
// and becomes a fault only once that absence has persisted beyond an ANCHORED window.
//
// This monitor family has made the same mistake three times, and it is written down here so
// the fourth is harder:
// - hub v0.12.0 — `expected_backup_missed` fired daily for every healthy customer, because
// it looked for a `backup_completed` event that no component emits anymore.
// - hub v0.73.0 — `offsite_stale` fired minutes after a HEALTHY repair, because the
// never-ran branch had no time anchor. Fixed by anchoring, not by silence.
// - R-81 (this) — `expected_backup_missed` fired on three boxes at once on 2026-07-26,
// because an agent restart empties the host-report `backups` array (the agent's store is
// in-memory) and empty was read as "no backup exists". The vzdump had in fact run.
//
// Note the shape of the fix in all three: NOT silence. Silence is the opposite failure — a
// box that genuinely never backs up would then alarm never, which is strictly worse than
// crying wolf. Absence is deferred, then alarmed on, with its own distinct reason string.
//
// ── THE BRANCHES ──────────────────────────────────────────────────────────────────────────
//
// unparseable latest report → missed ("could not be parsed")
// newest evidence (report OR window) older than staleAfter → missed ("newest backup is Xh old")
// newest PBS snapshot's verify_state == "failed" → missed ("failed verification")
// NO evidence anywhere, anchor NOT yet elapsed → UNKNOWN, silent + logged
// NO evidence anywhere, anchor elapsed → missed ("no backup evidence in …")
// otherwise → ok
//
// Each failure mode keeps its OWN reason string. That is not polish: the entire 2026-07-26
// diagnosis turned on reading the exact string, and collapsing them would have made it
// impossible. In particular "absence over time" and "a timestamp that is too old" are
// different faults with different causes, and must never share a message.
//
// A fresh-but-not-yet-verified snapshot (verify_state "none"/"") is NOT treated as a
// failure: PBS verification runs on its own cadence, so a snapshot taken hours before the
// 03:00 check may legitimately be unverified. Alarming on that would re-introduce exactly
// the daily false alarm the v0.12.0 repoint removed (hence "failed" only, not "≠ ok").
func assessBackupFreshness(reportJSON string, ev backupEvidence, now time.Time) backupAssessment {
var hr hostReportBackups
if err := json.Unmarshal([]byte(reportJSON), &hr); err != nil {
// Unparseable report → can't confirm a backup. Surface it rather than swallow it.
return backupAssessment{verdict: verdictMissed, reason: "latest host-report could not be parsed"}
}
var newestPBS time.Time
var newestPBSVerify string
havePBS := false
for _, ps := range hr.PBSSnapshots {
t, ok := parseBackupTime(ps.BackupTime)
if !ok {
continue
}
if !havePBS || t.After(newestPBS) {
havePBS = true
newestPBS = t
newestPBSVerify = strings.ToLower(strings.TrimSpace(ps.VerifyState))
}
}
var newestVzdump time.Time
haveVzdump := false
for _, b := range hr.Backups {
if !b.Success {
continue
}
t, ok := parseBackupTime(b.StartedAt)
if !ok {
continue
}
if !haveVzdump || t.After(newestVzdump) {
haveVzdump = true
newestVzdump = t
}
}
// ── R-82 Slice C: TIER-AWARE assessment ───────────────────────────────────────────────────
// Judge each tier against ITS OWN threshold. Falls through to the pre-Slice-C combined logic
// below only when NEITHER tier is identifiable — an old agent whose report carries no
// storage_targets and no target_id — so nothing regresses on a fleet mid-upgrade.
hostView, offView := splitTiers(hr)
if hostView.expected || offView.expected {
var as []backupAssessment
if hostView.expected {
as = append(as, assessTier(tierHost, hostView, ev.newestHost, ev.haveHost, ev.firstReportAt, now))
}
if offView.expected {
as = append(as, assessTier(tierOffsite, offView, ev.newestOffsite, ev.haveOffsite, ev.firstReportAt, now))
}
return worst(as...)
}
// The newest evidence the LATEST report itself carries.
newest := newestPBS
haveNewest := havePBS
if haveVzdump && (!haveNewest || newestVzdump.After(newest)) {
newest, haveNewest = newestVzdump, true
}
// R-81: fold in what the hub REMEMBERS. The agent's store is point-in-time and forgets
// across a restart; the hub's retained host-reports do not. An empty array in the latest
// report therefore says nothing on its own — the question is when evidence was last SEEN,
// not whether this one report happens to carry it.
if ev.haveSeen && (!haveNewest || ev.newestSeen.After(newest)) {
newest, haveNewest = ev.newestSeen, true
}
if !haveNewest {
// ABSENCE. Not a failure by itself — see the invariant above. It becomes one only
// once it has outlived the existing threshold, counted from first contact (the point
// at which a backup first became possible to observe).
if ev.firstReportAt.IsZero() {
// No anchor to defer against — fail toward visibility, as v0.73.0 does for the
// legacy zero-anchor shape. Distinct string: this is an unanchored absence.
return backupAssessment{
verdict: verdictMissed,
reason: "no backup evidence in any retained host-report, and no first-contact anchor to defer against",
}
}
watched := now.Sub(ev.firstReportAt)
if watched <= backupStaleAfter {
return backupAssessment{
verdict: verdictUnknown,
reason: fmt.Sprintf("no backup evidence yet, but only watching for %s (grace %s since first contact %s) — newborn host, not a fault",
watched.Round(time.Hour), backupStaleAfter, ev.firstReportAt.Format(time.RFC3339)),
}
}
return backupAssessment{
verdict: verdictMissed,
reason: fmt.Sprintf("no backup evidence in any host-report for %s (limit %s, first contact %s, lookback %s)",
watched.Round(time.Hour), backupStaleAfter, ev.firstReportAt.Format(time.RFC3339), backupEvidenceLookback),
}
}
if age := now.Sub(newest); age > backupStaleAfter {
return backupAssessment{verdict: verdictMissed, reason: fmt.Sprintf("newest backup is %s old (limit %s)", age.Round(time.Hour), backupStaleAfter)}
}
if havePBS && newestPBSVerify == "failed" {
return backupAssessment{verdict: verdictMissed, reason: "newest PBS snapshot failed verification"}
}
return backupAssessment{verdict: verdictOK}
}
// newestBackupEvidence scans the customer's retained host-reports (newest first) for the most
// recent backup evidence — a PBS snapshot backup_time or a SUCCESSFUL vzdump started_at —
// regardless of whether the latest report still carries it.
//
// Cost discipline: it stops as soon as it has found evidence FRESH enough that nothing older
// could change the verdict, so the healthy path reads one row. Only the genuinely-broken path
// (no fresh evidence anywhere) walks the full lookback, and that is bounded by
// backupEvidenceLookback rather than by retention.
func newestBackupEvidence(rows []store.HostReportRow, now time.Time) (time.Time, bool) {
var newest time.Time
have := false
for _, r := range rows {
var hr hostReportBackups
if err := json.Unmarshal([]byte(r.ReportJSON), &hr); err != nil {
continue // a single malformed retained report must not blind the scan
}
for _, ps := range hr.PBSSnapshots {
if t, ok := parseBackupTime(ps.BackupTime); ok && (!have || t.After(newest)) {
newest, have = t, true
}
}
for _, b := range hr.Backups {
if !b.Success {
continue
}
if t, ok := parseBackupTime(b.StartedAt); ok && (!have || t.After(newest)) {
newest, have = t, true
}
}
// Fresh evidence found → the age branch cannot fire and nothing older matters.
if have && now.Sub(newest) <= backupStaleAfter {
break
}
}
return newest, have
}
// parseBackupTime parses an RFC3339 timestamp from a host-report and normalizes to UTC.
func parseBackupTime(s string) (time.Time, bool) {
s = strings.TrimSpace(s)
if s == "" {
return time.Time{}, false
}
if t, err := time.Parse(time.RFC3339, s); err == nil {
return t.UTC(), true
}
return time.Time{}, false
}
// budapest returns the Europe/Budapest timezone (cached).
var budapest *time.Location
func init() {
var err error
budapest, err = time.LoadLocation("Europe/Budapest")
if err != nil {
// Fallback: UTC+1 (CET base; DST handled by OS if available)
budapest = time.FixedZone("CET", 3600)
}
}
// CheckBackupDeadlines checks whether active customers had their expected
// daily backups and DB dumps. Runs once daily (early morning, Budapest time).
//
// Backup half: read the agent's latest host-report and raise expected_backup_missed
// only when its PBS snapshots / vzdump backups show no fresh, verified backup (see
// assessBackupFreshness). This replaced the old backup_completed-event check, which
// fired daily for every healthy customer because no component emits that event anymore
// (the controller's disk-tier backup moved to the agent in slice 8C).
//
// DB-dump half: unchanged — the in-guest controller still emits db_dump_completed, so
// the event-based check there is correct.
//
// Customers whose nodes are "down" (no report in >1h) are skipped — they
// already have staleness events.
func CheckBackupDeadlines(s *store.Store, staleness *StalenessChecker, onEvent EventNotifyFunc, logger *log.Logger) {
customerIDs, err := s.GetActiveCustomerIDs()
if err != nil {
logger.Printf("[WARN] Deadline check: failed to get active customers: %v", err)
return
}
// Budapest midnight today
now := time.Now().In(budapest)
midnightBudapest := time.Date(now.Year(), now.Month(), now.Day(), 0, 0, 0, 0, budapest)
sinceUTC := midnightBudapest.UTC()
var backupMissed, dbdumpMissed, skipped, deferred, unbound int
for _, id := range customerIDs {
// Skip nodes that are down — they already have staleness events
if staleness != nil && staleness.GetState(id) == "down" {
skipped++
continue
}
// Check blocked
if s.IsCustomerBlocked(id) {
continue
}
// ── R-195: a customer with NO machine EVER bound is UNKNOWN, not missed ────────────────
//
// Both verdicts below ask "did the thing we expect every day happen?". For a customer
// that has never had a machine bound, nothing has ever been expected, so the honest
// answer is UNKNOWN — the same invariant assessBackupFreshness states above, applied one
// level up, at the question of whether there is a subject at all.
//
// The discriminator is "was a host EVER bound", NOT "has a report arrived". That is the
// case this check must not break: a box that was installed, bound, and then went silent
// has a real fault and must keep alarming. It is bound, so it is judged.
//
// WHY THIS WAS REACHABLE AT ALL, measured 2026-08-04: the down-skip above is what
// protects every other silent customer, and it reads the staleness checker's state — which
// is seeded from the `reports` table (store.GetCustomers). A customer that has NEVER
// reported appears in no report row, so it gets no staleness state at all and GetState()
// returns "" rather than "down". The skip misses exactly the customer it would most
// obviously cover, and the DB-dump half below then fires every night: `david`, a
// prospective customer whose record was created 2026-08-01 with no machine ever bound,
// e-mailed an expected_dbdump_missed ERROR at 03:00 UTC on three consecutive days.
//
// Fail-open on a read error: an unreadable binding must never SUPPRESS a real alarm.
if bound, berr := s.HasEverBoundHost(id); berr != nil {
logger.Printf("[WARN] Deadline check: failed to read host binding for %s (judging anyway): %v", id, berr)
} else if !bound {
// Visible, per the v0.73.0 Part-7 precedent below: a quiet check must never be
// indistinguishable from a check that did not run. Once daily, one line per customer.
logger.Printf("[INFO] Deadline check: %s has no host EVER bound — all deadline verdicts UNKNOWN (no alarm)", id)
unbound++
continue
}
// Backup freshness from the agent's host-report (PBS snapshots + vzdump),
// the authoritative offsite-backup signal post-slice-8C.
reportJSON, rerr := s.GetLatestHostReportJSON(id)
switch {
case rerr != nil:
logger.Printf("[WARN] Deadline check: failed to read host-report for %s: %v", id, rerr)
case reportJSON == "":
// No agent host-report at all (legacy/defunct controller-only customer).
// Liveness is owned by the host-staleness checker; the backup deadline check
// has no PBS data to judge here and must not emit a daily backup alarm of its
// own. (The DB-dump half below still applies.)
default:
nowUTC := time.Now().UTC()
// R-81: resolve the hub-history half BEFORE judging. A read failure here must not
// invent a fault — it degrades to "the latest report is all I know", which is the
// pre-R-81 behaviour, and is logged rather than swallowed.
var ev backupEvidence
if rows, rerr := s.GetHostReportsSince(id, nowUTC.Add(-backupEvidenceLookback)); rerr != nil {
logger.Printf("[WARN] Deadline check: failed to read host-report window for %s: %v", id, rerr)
} else {
ev.newestSeen, ev.haveSeen = newestBackupEvidence(rows, nowUTC)
// Slice C: per-tier window evidence. Which tiers to look for comes from the LATEST
// report, so a box with no offsite tier never pays for scanning one.
var latest hostReportBackups
wantHost, wantOffsite := true, true
if json.Unmarshal([]byte(reportJSON), &latest) == nil {
h, o := splitTiers(latest)
wantHost, wantOffsite = h.expected, o.expected
}
ev.newestHost, ev.haveHost, ev.newestOffsite, ev.haveOffsite =
newestBackupEvidenceByTier(rows, wantHost, wantOffsite, nowUTC)
}
if first, ferr := s.GetFirstHostReportAt(id); ferr != nil {
logger.Printf("[WARN] Deadline check: failed to read first host-report for %s: %v", id, ferr)
} else {
ev.firstReportAt = first
}
a := assessBackupFreshness(reportJSON, ev, nowUTC)
switch a.verdict {
case verdictMissed:
msg := "No fresh verified backup: " + a.reason
if _, err := s.SaveEvent(id, "expected_backup_missed", "error", msg, "{}", "hub"); err != nil {
logger.Printf("[WARN] Failed to save expected_backup_missed for %s: %v", id, err)
} else if onEvent != nil {
onEvent(id, "expected_backup_missed", "error", msg, "{}", "hub")
}
backupMissed++
case verdictUnknown:
// Make the deferral VISIBLE (the v0.73.0 Part-7 precedent): a quiet check must
// never be indistinguishable from a check that did not run. This check fires
// once daily, so this is at most one line per customer per day — not spam, and
// it is the line that proves the deferral happened rather than an error.
logger.Printf("[INFO] Deadline check: %s backup verdict UNKNOWN (no alarm) — %s", id, a.reason)
deferred++
}
}
// Check db_dump_completed / db_dump_failed since midnight
dumpOK, _ := s.GetEventsByType(id, "db_dump_completed", sinceUTC)
dumpFailed, _ := s.GetEventsByType(id, "db_dump_failed", sinceUTC)
if len(dumpOK) == 0 && len(dumpFailed) == 0 {
msg := "No DB dump completed or failed since midnight"
if _, err := s.SaveEvent(id, "expected_dbdump_missed", "error", msg, "{}", "hub"); err != nil {
logger.Printf("[WARN] Failed to save expected_dbdump_missed for %s: %v", id, err)
} else if onEvent != nil {
onEvent(id, "expected_dbdump_missed", "error", msg, "{}", "hub")
}
dbdumpMissed++
}
}
logger.Printf("[INFO] Deadline check: %d customers, %d backup missed, %d backup unknown (deferred), %d dbdump missed, %d skipped (down), %d unknown (no host ever bound)",
len(customerIDs), backupMissed, deferred, dbdumpMissed, skipped, unbound)
}