diff --git a/documentation/architecture/08-alarm-ladder.md b/documentation/architecture/08-alarm-ladder.md index 833a9c4e..30f1424d 100644 --- a/documentation/architecture/08-alarm-ladder.md +++ b/documentation/architecture/08-alarm-ladder.md @@ -327,6 +327,13 @@ message, not a wider cooldown. --- +**A failed operator mail is sent again (hub v0.140.0, 2026-10-06).** Until then an operator mail had ONE try with a 10 s +client timeout; a failure was only a `failed` row in the notification log, and because the cooldown is set before the +send, the next mail for the same alarm was silenced too. Measured: of 692 operator mails since 2026-02-16, ONE failed — +demo-hp's `whole_guest_backup_failed` (error) on 2026-10-05 04:27Z (Resend: *context deadline exceeded*), never sent +(`audits/readback-2026-10-07/C/`). Now it is tried again after 1, 5 and 15 minutes; each try is a row (`sent` „after +retry N" or `failed` „retry N: …"); giving up is an ERROR line. Pinned by TestOperatorMailRetry_*. + ## 6.3 Box alarms outside the app ladder: the tunnel and OS updates [DESIGN, hub v0.131.0, 2026-10-04] These are **operator-only** (the household can act on none of them — except `host_restarted_after_crash`, the household's diff --git a/hub/CHANGELOG.md b/hub/CHANGELOG.md index f776a7a7..2b74b4ac 100644 --- a/hub/CHANGELOG.md +++ b/hub/CHANGELOG.md @@ -1,3 +1,11 @@ +## v0.140.0 — a failed operator mail is sent again; a Docker set is approved only after the engine showed it reports a memory kill (decision 157) (2026-10-06) + +**Operator action on deploy: none.** Until agent v0.150.0 reaches the ring-0 boxes, no Docker set can be approved (none is pending: 29.8.2 is approved since 2026-10-04). + +- hub: a failed operator mail is tried again after 1, 5 and 15 minutes (it had ONE try with a 10 s timeout, and the cooldown set before the send silenced the next mail for the same alarm too). Measured: 1 of 692 operator mails ever failed — demo-hp's `whole_guest_backup_failed` (error) on 2026-10-05 04:27Z, never sent. Each try is a notification-log row; giving up is an ERROR line. Tests: TestOperatorMailRetry_* (3, red-proved). +- hub: `09` §3 decision 157 (R-528) — `DockerStatus` also requires, per ring-0 box, a PASSING `oom_check` in a report of the set (the agent's throwaway memory-kill container after its Docker step); a failed or errored check on any report blocks; no check at all blocks („has not reported the Docker step's memory-kill check"). `Report` keeps `oom_check` verbatim. Tests: TestDockerApproval_* (4, red-proved), TestSystemPage_DockerButtonHiddenWithoutTheMemoryKillCheck; the existing Docker tests' fake reports now carry a passing check. +- `internal/notify/dispatcher.go`: gofmt (an older map's alignment). + ## v0.139.0 — the System page shows each box's last disk trim; the 05:00 check says why it did not judge a down box (R-444, R-872) (2026-10-06) **Operator action on deploy: none.** diff --git a/hub/internal/notify/dispatcher.go b/hub/internal/notify/dispatcher.go index 616e03c7..f86ae258 100644 --- a/hub/internal/notify/dispatcher.go +++ b/hub/internal/notify/dispatcher.go @@ -36,8 +36,19 @@ type Dispatcher struct { // Resend custom headers — used for the high-priority nudge on error/critical mails (v0.71.0, // audit F14-light). sendEmailFn func(to, subject, textBody string, headers map[string]string) error + + // afterFn schedules a delayed call (time.AfterFunc; a seam so tests run the retries at once). Used by + // retryOperatorEmail (the lost alarm of 2026-10-05). + afterFn func(time.Duration, func()) } +// operatorRetryDelays are the waits before each further try of an operator mail whose send FAILED (the lost alarm of 2026-10-05). Measured +// 2026-10-05: demo-hp's whole_guest_backup_failed (error) hit a 10 s Resend client timeout, was logged `failed`, and was +// never sent — the only operator mail of 692 that failed, and the one alarm the operator needed that night. The +// cooldown is armed before the send, so without a retry a failed mail also silences the next one for the same key. +// Pinned by TestOperatorMailRetry_FailedOperatorMailIsRetried. +var operatorRetryDelays = []time.Duration{1 * time.Minute, 5 * time.Minute, 15 * time.Minute} + // NewDispatcher creates a new notification dispatcher. func NewDispatcher(s *store.Store, resendAPIKey, fromEmail, operatorEmail string, operatorOn bool, logger *log.Logger) *Dispatcher { d := &Dispatcher{ @@ -52,9 +63,31 @@ func NewDispatcher(s *store.Store, resendAPIKey, fromEmail, operatorEmail string custCooldowns: make(map[string]time.Time), } d.sendEmailFn = d.sendEmail + d.afterFn = func(wait time.Duration, f func()) { time.AfterFunc(wait, f) } return d } +// retryOperatorEmail tries a failed operator mail again after operatorRetryDelays[attempt], then the next delay, +// until one send succeeds or the delays run out. Each try is logged and recorded in the notification log (`sent` +// with "after retry N", or `failed` with "retry N: …"); giving up is an ERROR line. +func (d *Dispatcher) retryOperatorEmail(customerID, eventType, severity, message, subject, body string, headers map[string]string, attempt int) { + if attempt >= len(operatorRetryDelays) { + d.logger.Printf("[ERROR] Operator email for %s/%s GAVE UP after %d retries — it was never sent", customerID, eventType, attempt) + return + } + d.afterFn(operatorRetryDelays[attempt], func() { + n := attempt + 1 + if err := d.sendEmailFn(d.operatorEmail, subject, body, headers); err != nil { + d.logger.Printf("[ERROR] Operator email retry %d failed for %s/%s: %v", n, customerID, eventType, err) + d.store.LogNotification(customerID, eventType, severity, message, "failed", fmt.Sprintf("retry %d: %v", n, err), "operator") + d.retryOperatorEmail(customerID, eventType, severity, message, subject, body, headers, n) + return + } + d.logger.Printf("[INFO] Operator email sent for %s/%s after retry %d", customerID, eventType, n) + d.store.LogNotification(customerID, eventType, severity, message, "sent", fmt.Sprintf("after retry %d", n), "operator") + }) +} + // priorityHeaders returns the Resend custom headers that nudge mail clients toward attention for // error/critical mails (X-Priority + Importance; v0.71.0, audit F14-light: delivered ≠ noticed). // Everything else gets nil — a warning or info mail must NOT masquerade as urgent. Pure → tested. @@ -573,9 +606,11 @@ func (d *Dispatcher) processOperator(customerID, eventType, severity, message, d subject, body := FormatOperatorEmail(customerID, eventType, severity, message, detailsJSON) - if err := d.sendEmailFn(d.operatorEmail, subject, body, priorityHeaders(severity)); err != nil { - d.logger.Printf("[ERROR] Operator email failed for %s/%s: %v", customerID, eventType, err) + hdrs := priorityHeaders(severity) + if err := d.sendEmailFn(d.operatorEmail, subject, body, hdrs); err != nil { + d.logger.Printf("[ERROR] Operator email failed for %s/%s: %v — retrying in %v", customerID, eventType, err, operatorRetryDelays[0]) d.store.LogNotification(customerID, eventType, severity, message, "failed", err.Error(), "operator") + d.retryOperatorEmail(customerID, eventType, severity, message, subject, body, hdrs, 0) return } d.logger.Printf("[INFO] Operator email sent for %s/%s", customerID, eventType) @@ -689,11 +724,11 @@ var operatorOnlyEvents = map[string]bool{ // hub v0.133.0 (`11` §5.3.1): a TEST approval cancelled at a start without the override. "os_release_cancelled": true, // R-840 (hub v0.133.0): a box's root-owned config bundle behind the vouched one for 7 days. - "os_config_bundle_behind": true, + "os_config_bundle_behind": true, // hub v0.135.0: R-530 (a box behind the vouched agent for 7 days) and R-604 (a global floor raise that did not // move every box). Fleet facts only the operator can act on — listed in the SAME commit that mints them. - "agent_behind": true, - "floor_raise_skipped": true, + "agent_behind": true, + "floor_raise_skipped": true, "os_update_settings_changed": true, // R-841 (hub v0.131.0): the tunnel alarm — a box fact the household can do nothing about from inside. "tunnel_down": true, diff --git a/hub/internal/notify/operator_mail_retry_test.go b/hub/internal/notify/operator_mail_retry_test.go new file mode 100644 index 00000000..98ecfd58 --- /dev/null +++ b/hub/internal/notify/operator_mail_retry_test.go @@ -0,0 +1,84 @@ +package notify + +import ( + "errors" + "io" + "log" + "sync" + "testing" + "time" +) + +// The lost alarm of 2026-10-05 (fixed without a row, `audits/readback-2026-10-07/C/`): a failed operator mail is tried again (operatorRetryDelays) instead of being dropped. The consequence +// asserted is that the mail is SENT and recorded `sent`. +// +// COMPANION RED-PROOF (REPORT): drop the retryOperatorEmail call from processOperator → "the failed mail was never +// sent again". +func TestOperatorMailRetry_FailedOperatorMailIsRetried(t *testing.T) { + st := newDispStore(t) + d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0)) + var mu sync.Mutex + tries, waits := 0, []time.Duration{} + d.afterFn = func(w time.Duration, f func()) { mu.Lock(); waits = append(waits, w); mu.Unlock(); f() } + d.sendEmailFn = func(string, string, string, map[string]string) error { + mu.Lock() + defer mu.Unlock() + tries++ + if tries <= 2 { // the first send and the first retry time out + return errors.New("context deadline exceeded (Client.Timeout exceeded while awaiting headers)") + } + return nil + } + d.processOperator("demo-hp", "whole_guest_backup_failed", "error", "Whole-guest backup FAILED", "", "box") + if tries != 3 { + t.Fatalf("the failed mail was never sent again (tries=%d)", tries) + } + if len(waits) != 2 || waits[0] != operatorRetryDelays[0] || waits[1] != operatorRetryDelays[1] { + t.Fatalf("retries not on the schedule: %v", waits) + } + rows, err := st.GetRecentNotifications("demo-hp", 50) + if err != nil { + t.Fatal(err) + } + var sent, failed int + for _, r := range rows { + if r.Channel != "operator" { + continue + } + switch r.Status { + case "sent": + sent++ + case "failed": + failed++ + } + } + if sent != 1 || failed != 2 { + t.Fatalf("notification log: sent=%d failed=%d, want 1 and 2", sent, failed) + } +} + +// The retries stop: a send that never succeeds is tried len(operatorRetryDelays) more times, then given up. +func TestOperatorMailRetry_RetriesAreBounded(t *testing.T) { + st := newDispStore(t) + d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0)) + tries := 0 + d.afterFn = func(_ time.Duration, f func()) { f() } + d.sendEmailFn = func(string, string, string, map[string]string) error { tries++; return errors.New("down") } + d.processOperator("demo-hp", "whole_guest_backup_failed", "error", "x", "", "box") + if tries != 1+len(operatorRetryDelays) { + t.Fatalf("tries=%d, want %d", tries, 1+len(operatorRetryDelays)) + } +} + +// A mail that is sent the first time is not retried. +func TestOperatorMailRetry_SuccessIsNotRetried(t *testing.T) { + st := newDispStore(t) + d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0)) + scheduled := 0 + d.afterFn = func(_ time.Duration, f func()) { scheduled++; f() } + d.sendEmailFn = func(string, string, string, map[string]string) error { return nil } + d.processOperator("demo-hp", "whole_guest_backup_failed", "error", "x", "", "box") + if scheduled != 0 { + t.Fatalf("a sent mail scheduled %d retries", scheduled) + } +} diff --git a/hub/internal/osupdates/docker_test.go b/hub/internal/osupdates/docker_test.go index 33bbbd1a..9edefb3c 100644 --- a/hub/internal/osupdates/docker_test.go +++ b/hub/internal/osupdates/docker_test.go @@ -1,6 +1,7 @@ package osupdates import ( + "encoding/json" "strings" "testing" "time" @@ -10,13 +11,23 @@ var engineSet = []Package{{Name: "docker-ce", Version: "5:29.8.2-1~debian.13~tri {Name: "containerd.io", Version: "2.3.6-1~debian.13~trixie", Origin: "Docker"}} func (f *fix) dockerNight(t *testing.T, host string, healthy bool) { + t.Helper() + f.dockerNightOOM(t, host, healthy, `{"result":"pass","oom_killed":true,"oom_event":true,"exit_code":137,"image":"felhom-controller","detail":""}`) +} + +// dockerNightOOM is dockerNight with the step's memory-kill check as given ("" = an agent that reports none). +func (f *fix) dockerNightOOM(t *testing.T, host string, healthy bool, oom string) { t.Helper() out := "nothing" if !healthy { out = "health_failed" } - f.ingest(t, host, Report{Layer: LayerDocker, Trigger: "night", Mode: "apply", Outcome: out, Healthy: healthy, - Installed: append([]Package{pk("libc6", "x")}, engineSet...)}) + r := Report{Layer: LayerDocker, Trigger: "night", Mode: "apply", Outcome: out, Healthy: healthy, + Installed: append([]Package{pk("libc6", "x")}, engineSet...)} + if oom != "" { + r.OOMCheck = json.RawMessage(oom) + } + f.ingest(t, host, r) } // The Docker set is NEVER approved automatically (`11` §5.8: the operator approves it). Red-proof: add LayerDocker to @@ -77,3 +88,67 @@ func TestDocker_UnhealthyStepBlocksTheButton(t *testing.T) { t.Fatalf("an unhealthy Docker step did not block: %v", err) } } + +// Decision 157 (R-528): the Docker set is approved only when every ring-0 box's step showed the engine reports a +// memory kill. RED-PROOF (REPORT): make oomCheckWaiting return "" — the three blocking tests below approve. +func TestDockerApproval_AFailedMemoryKillCheckBlocks(t *testing.T) { + f := newFix(t) + fail := `{"result":"fail","oom_killed":false,"oom_event":true,"exit_code":137,"image":"felhom-controller","detail":"OOMKilled=false"}` + for i := 0; i < 2; i++ { + f.dockerNight(t, "hp", true) + f.dockerNightOOM(t, "n100", true, fail) + if i == 0 { + f.s.Evaluate() // stamps the set\'s first-seen at the first night, as the tick does + } + f.now = f.now.Add(24 * time.Hour) + } + if _, err := f.s.ApproveDocker(); err == nil || !strings.Contains(err.Error(), "memory-kill check did not pass") { + t.Fatalf("a set whose engine missed a memory kill was approvable: %v", err) + } +} + +func TestDockerApproval_AMissingMemoryKillCheckBlocks(t *testing.T) { + f := newFix(t) + for i := 0; i < 2; i++ { + f.dockerNight(t, "hp", true) + f.dockerNightOOM(t, "n100", true, "") // an older agent: no check at all + if i == 0 { + f.s.Evaluate() // stamps the set\'s first-seen at the first night, as the tick does + } + f.now = f.now.Add(24 * time.Hour) + } + if _, err := f.s.ApproveDocker(); err == nil || !strings.Contains(err.Error(), "has not reported the Docker step's memory-kill check") { + t.Fatalf("a set with no memory-kill check was approvable: %v", err) + } +} + +func TestDockerApproval_AnErroredMemoryKillCheckBlocks(t *testing.T) { + f := newFix(t) + errd := `{"result":"error","oom_killed":false,"oom_event":false,"exit_code":null,"image":null,"detail":"the controller's image could not be read"}` + for i := 0; i < 2; i++ { + f.dockerNight(t, "hp", true) + f.dockerNightOOM(t, "n100", true, errd) + if i == 0 { + f.s.Evaluate() // stamps the set\'s first-seen at the first night, as the tick does + } + f.now = f.now.Add(24 * time.Hour) + } + if _, err := f.s.ApproveDocker(); err == nil { + t.Fatal("a set whose memory-kill check errored was approvable") + } +} + +func TestDockerApproval_APassingCheckOnEveryBoxAllows(t *testing.T) { + f := newFix(t) + for i := 0; i < 2; i++ { + f.dockerNight(t, "hp", true) + f.dockerNight(t, "n100", true) + if i == 0 { + f.s.Evaluate() // stamps the set\'s first-seen at the first night, as the tick does + } + f.now = f.now.Add(24 * time.Hour) + } + if _, err := f.s.ApproveDocker(); err != nil { + t.Fatalf("passing checks on every ring-0 box should allow the approval: %v", err) + } +} diff --git a/hub/internal/osupdates/service.go b/hub/internal/osupdates/service.go index a28cc2c1..806a9215 100644 --- a/hub/internal/osupdates/service.go +++ b/hub/internal/osupdates/service.go @@ -111,6 +111,9 @@ type Report struct { DockerEngine string `json:"docker_engine,omitempty"` // docker layer (agent v0.142.0) Authority string `json:"authority,omitempty"` // docker layer: ring0 | signed Undo bool `json:"undo,omitempty"` // docker layer: a signed undo + // OOMCheck (agent v0.150.0, decision 157): the Docker step's memory-kill check, kept verbatim — oomCheckWaiting + // reads it from the stored report. + OOMCheck json.RawMessage `json:"oom_check,omitempty"` } // PendingPkg is one update the sources offer. @@ -599,10 +602,46 @@ func (s *Service) DockerStatus() (Status, error) { st.Waiting = fmt.Sprintf("%s has %d of %d healthy night Docker step(s) with this set", h, nights, need) return st, nil } + if why := oomCheckWaiting(h, reps); why != "" { + st.Waiting = why + return st, nil + } } return st, nil } +// oomCheckWaiting is `09` §3 decision 157 (R-528): a Docker engine set is approved only when every ring-0 box showed, +// after its Docker step with this set, that the engine reports a memory kill correctly — the wrapper's `oom_check` +// (agent v0.150.0: a throwaway container under a 64 MB cap killed for memory; pass = `OOMKilled=true` AND the `oom` +// event). A failed or errored check on ANY report of the set blocks; no passing check at all blocks („missing"). +// Returns "" when the box is clear. Pinned by TestDockerApproval_*. +func oomCheckWaiting(host string, reps []store.OSReport) string { + passed := false + for _, r := range reps { + var body struct { + OOMCheck *struct { + Result string `json:"result"` + Detail string `json:"detail"` + } `json:"oom_check"` + } + if json.Unmarshal([]byte(r.ReportJSON), &body) != nil || body.OOMCheck == nil { + continue + } + switch body.OOMCheck.Result { + case "pass": + passed = true + default: + return fmt.Sprintf("%s: the Docker step's memory-kill check did not pass (%s: %s) at %s — a set whose engine "+ + "may miss a memory kill is not approved (decision 157)", host, body.OOMCheck.Result, body.OOMCheck.Detail, + r.ReceivedAt.UTC().Format(time.RFC3339)) + } + } + if !passed { + return fmt.Sprintf("%s has not reported the Docker step's memory-kill check with this set (agent v0.150.0 or newer runs it; decision 157)", host) + } + return "" +} + // ApproveDocker is the operator's button: it approves the Docker engine set ring 0 runs, only when DockerStatus allows. // A ring-1 box then takes it only through a signed operator job (`11` §5.8) — approval alone installs nothing. func (s *Service) ApproveDocker() (string, error) { diff --git a/hub/internal/osupdates/service_test.go b/hub/internal/osupdates/service_test.go index 4f05104b..cd8d4399 100644 --- a/hub/internal/osupdates/service_test.go +++ b/hub/internal/osupdates/service_test.go @@ -1,6 +1,7 @@ package osupdates import ( + "encoding/json" "log" "os" "path/filepath" @@ -52,8 +53,12 @@ func (f *fix) reportL(t *testing.T, host, layer, trigger string, healthy bool, p if !healthy { outcome = "health_failed" } - if err := f.s.Ingest(host, Report{RunID: host + trigger + f.now.String(), Layer: layer, Trigger: trigger, Mode: "apply", Outcome: outcome, - Healthy: healthy, Installed: pkgs, Upgraded: pkgs[:1]}); err != nil { + r := Report{RunID: host + trigger + f.now.String(), Layer: layer, Trigger: trigger, Mode: "apply", Outcome: outcome, + Healthy: healthy, Installed: pkgs, Upgraded: pkgs[:1]} + if layer == LayerDocker { // an agent >= v0.150.0 reports the step's memory-kill check (decision 157) + r.OOMCheck = json.RawMessage(`{"result":"pass","oom_killed":true,"oom_event":true,"exit_code":137,"image":"felhom-controller","detail":""}`) + } + if err := f.s.Ingest(host, r); err != nil { t.Fatal(err) } } diff --git a/hub/internal/web/system_test.go b/hub/internal/web/system_test.go index 53d95a1b..8fbd197d 100644 --- a/hub/internal/web/system_test.go +++ b/hub/internal/web/system_test.go @@ -1,6 +1,8 @@ package web import ( + "encoding/json" + "fmt" "net/http" "net/http/httptest" "net/url" @@ -80,19 +82,45 @@ func TestSystemPage_DockerButtonOnlyWhenReady(t *testing.T) { // and drop it (the flake seen 2026-10-05 under full-suite load). clock := time.Date(2026, 10, 5, 3, 0, 0, 0, time.UTC) svc.Now = func() time.Time { return clock } - night := func() { - if err := svc.Ingest("full-1", osupdates.Report{RunID: time.Now().String(), Layer: "docker", Trigger: "night", Mode: "apply", + nightOOM := func(oom string) { + r := osupdates.Report{RunID: time.Now().String(), Layer: "docker", Trigger: "night", Mode: "apply", + Outcome: "nothing", Healthy: true, Installed: []osupdates.Package{{Name: "docker-ce", Version: "5:29.8.2-1", Origin: "Docker"}}} + if oom != "" { + r.OOMCheck = json.RawMessage(oom) + } + if err := svc.Ingest("full-1", r); err != nil { + t.Fatal(err) + } + } + pass := `{"result":"pass","oom_killed":true,"oom_event":true,"exit_code":137,"image":"felhom-controller","detail":""}` + nightOOM(pass) + if strings.Contains(getSystem(t, s), `action="/os/approve-docker"`) { + t.Fatal("button shown after ONE night") + } + nightOOM(pass) + if !strings.Contains(getSystem(t, s), `action="/os/approve-docker"`) { + t.Fatal("button missing after two healthy nights") + } +} + +// Decision 157: two healthy nights WITHOUT the memory-kill check (an older agent) show no button, and the page says why. +func TestSystemPage_DockerButtonHiddenWithoutTheMemoryKillCheck(t *testing.T) { + s, st, svc := systemServer(t) + _ = st.SetOSRing("full-1", 0) + clock := time.Date(2026, 10, 5, 3, 0, 0, 0, time.UTC) + svc.Now = func() time.Time { return clock } + for i := 0; i < 2; i++ { + if err := svc.Ingest("full-1", osupdates.Report{RunID: time.Now().String() + fmt.Sprint(i), Layer: "docker", Trigger: "night", Mode: "apply", Outcome: "nothing", Healthy: true, Installed: []osupdates.Package{{Name: "docker-ce", Version: "5:29.8.2-1", Origin: "Docker"}}}); err != nil { t.Fatal(err) } } - night() - if strings.Contains(getSystem(t, s), `action="/os/approve-docker"`) { - t.Fatal("button shown after ONE night") + page := getSystem(t, s) + if strings.Contains(page, `action="/os/approve-docker"`) { + t.Fatal("button shown although no ring-0 box reported the memory-kill check") } - night() - if !strings.Contains(getSystem(t, s), `action="/os/approve-docker"`) { - t.Fatal("button missing after two healthy nights") + if !strings.Contains(page, "memory-kill check") { + t.Fatal("the page does not say why the button is missing") } }