Files
felhom.eu/hub/internal/notify/backup_run_digest_test.go
T
admin dd40f85bb8
gates / gates (push) Successful in 7s
hub v0.90.0 — a dropped notification leaves a trace, and the backup digest arrives (R-182)
processOperator's cooldown no longer returns bare. It dropped the event BEFORE
LogNotification, so a suppressed operator alert and an event that never happened
were indistinguishable — from the operator's side and from the hub's own records.
Measured 2026-08-03: nine recovery_unit_capture_failed events arrived, two were
mailed, seven left no row anywhere. That is why the defect took a day to get the
right way round: there was nothing to read.

A suppressed operator event now writes a `suppressed` row carrying the message
and the key that suppressed it. This applies to EVERY operator event, not only
the one that exposed it. It does NOT change the cooldown's duration or semantics.

backup_run_failures: the per-run digest. In allowedEventTypes AND in
operatorOnlyEvents — allowlisting alone does not make an event operator-only,
and FormatCustomerEmail falls back to the raw English message rather than
blocking. A test demonstrates a customer with the type enabled receiving nothing.

recordOnlyEvents: a third routing class — stored and recorded, never mailed.
recovery_unit_capture_failed moves here: it is the record, the digest is the
notification. A register rather than downgrading severity to info, which would
relabel a genuine failure as informational everywhere it is queried.

cooldownRunSuffix: a sibling of cooldownTierSuffix, not a branch inside it, so
tier keeps byte-identical semantics and R-97a's tests are untouched. It makes
the cooldown effectively inert for the digest, which is the intent — a digest is
already rate-limited by construction; the refresh sweep sends no run_id and so
stays under the ordinary hourly cooldown.

The email renders as a list, not a JSON blob. An absent space reading renders as
unavailable, never as zeros.
2026-08-03 13:46:48 +02:00

267 lines
13 KiB
Go

package notify
import (
"io"
"log"
"strings"
"testing"
)
// R-182 — one e-mail per backup run, and nothing dropped without a trace.
//
// MEASURED, NOT SUPPOSED. On 2026-08-03 nine `recovery_unit_capture_failed` events reached the hub
// and TWO operator e-mails went out. The operator cooldown key is
// `customerID + ":" + eventType + cooldownTierSuffix(details)`, that event carries `app` but no
// `tier`, so the key held no app identifier: the first refused app took the hour's slot and every
// other app's failure was discarded — **before `LogNotification`**, so it left no row on any channel
// and could not be found afterwards.
//
// The operator ruled against the obvious fix (putting `app` in the key), because on a full disk that
// is one e-mail per app. These pin the shape that replaced it.
// ── Scenario D — a suppressed operator event leaves a trace ───────────────────────────────────────
// The bare `return` at the cooldown is the whole reason this defect took a day to get the right way
// round: there was nothing to read. A drop must be as visible in the record as a send.
//
// DELIBERATELY EXERCISED ON A DIFFERENT EVENT TYPE than the one that exposed the defect.
// `recovery_unit_capture_failed` is now record-only and never reaches the cooldown at all, so using
// it here would prove nothing. `whole_guest_backup_failed` is an ordinary operator event, and using
// it pins §2.1's actual claim: the suppression row applies to EVERY operator event, not only the one
// that happened to be measured.
func TestSuppressedOperatorEvent_LeavesARow(t *testing.T) {
st := newDispStore(t)
d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0))
sent := captureSeam(d)
// Two events of the SAME type with no discriminator — the second must be suppressed.
d.ProcessEvent("c1", "whole_guest_backup_failed", "error", "opengist failed", `{"app":"opengist"}`, "controller")
d.ProcessEvent("c1", "whole_guest_backup_failed", "error", "privatebin failed", `{"app":"privatebin"}`, "controller")
if got := len(mailsFor(*sent, "op@felhom.eu")); got != 1 {
t.Fatalf("operator mails = %d, want 1 — the premise of this test is that the second IS suppressed", got)
}
rows, err := st.GetRecentNotifications("c1", 50)
if err != nil {
t.Fatal(err)
}
var sentRows, suppressed []store2Row
for _, r := range rows {
if r.Channel != "operator" || r.EventType != "whole_guest_backup_failed" {
continue
}
switch r.Status {
case "sent":
sentRows = append(sentRows, store2Row{r.Status, r.Message, r.ErrorMessage})
case "suppressed":
suppressed = append(suppressed, store2Row{r.Status, r.Message, r.ErrorMessage})
}
}
if len(sentRows) != 1 {
t.Fatalf("want 1 'sent' operator row, got %d", len(sentRows))
}
if len(suppressed) != 1 {
t.Fatalf("want 1 'suppressed' operator row, got %d — a cooldown drop that writes NOTHING is "+
"indistinguishable from an event that never happened, which is exactly how seven "+
"failures went missing on 2026-08-03", len(suppressed))
}
// The row must name the app that was dropped, or it records that something was suppressed
// without recording WHAT — half a fix.
if !strings.Contains(suppressed[0].message, "privatebin") {
t.Fatalf("the suppressed row does not name the dropped event: %q", suppressed[0].message)
}
// And it must carry the key, so the reason it collided is readable without reading code.
if !strings.Contains(suppressed[0].errMsg, "key=") {
t.Fatalf("the suppressed row does not carry the cooldown key: %q", suppressed[0].errMsg)
}
}
type store2Row struct{ status, message, errMsg string }
// ── Scenario E — two runs in a day each report ───────────────────────────────────────────────────
// The operator ruled explicitly on this: someone pressing the backup button is actively trying to
// get a backup, and finding out tomorrow would be worse than an extra mail in a rare case.
func TestTwoRunsInAnHour_BothReport(t *testing.T) {
st := newDispStore(t)
d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0))
sent := captureSeam(d)
nightly := `{"run_id":"run-a","run_kind":"nightly","failed":2,"attempted":5,"apps":[{"app":"opengist","leg":"volume dump","reason":"reserve"},{"app":"privatebin","leg":"volume dump","reason":"reserve"}]}`
manual := `{"run_id":"run-b","run_kind":"manual","failed":2,"attempted":5,"apps":[{"app":"opengist","leg":"volume dump","reason":"reserve"},{"app":"privatebin","leg":"volume dump","reason":"reserve"}]}`
d.ProcessEvent("c1", "backup_run_failures", "error", "2 of 5 apps failed", nightly, "controller")
d.ProcessEvent("c1", "backup_run_failures", "error", "2 of 5 apps failed", manual, "controller")
if got := len(mailsFor(*sent, "op@felhom.eu")); got != 2 {
t.Fatalf("operator mails = %d, want 2 — the 1-hour cooldown swallowed the manual run's "+
"digest, which is the fix reappearing one level up: press the button, the run fails, "+
"and you are told nothing because the machine already wrote this hour", got)
}
}
// The run discriminator must be NARROW, exactly like its `tier` sibling — empty unless the producer
// opts in — or every existing event type's cooldown silently stops collapsing anything.
func TestCooldownRunSuffix_EmptyForEverythingElse(t *testing.T) {
cases := []struct{ name, details string }{
{"no details", ""},
{"details without run_id", `{"app":"opengist","error":"boom"}`},
{"empty run_id value", `{"run_id":""}`},
{"malformed json", `{{{nope`},
{"run_id mentioned in a STRING, not as a key", `{"error":"the run_id: abc failed"}`},
{"null details", `null`},
}
for _, c := range cases {
if got := cooldownRunSuffix(c.details); got != "" {
t.Errorf("%s: suffix must be EMPTY so every other type's cooldown is unchanged, got %q", c.name, got)
}
}
if got := cooldownRunSuffix(`{"run_id":"run-a"}`); got != ":run-a" {
t.Fatalf("suffix should be the run id, got %q", got)
}
// The two suffixes must not interfere: a tier event still keys on its tier and nothing else.
if got := cooldownTierSuffix(`{"tier":"felhom-pbs"}`) + cooldownRunSuffix(`{"tier":"felhom-pbs"}`); got != ":felhom-pbs" {
t.Fatalf("a tier-only event's key changed to %q — R-97a's behaviour must be byte-identical", got)
}
}
// ── Scenario G — the customer never receives the digest ──────────────────────────────────────────
// v0.78.0 asserted in a COMMENT that a type with no `customerMessages` entry structurally cannot
// reach a customer. It can: FormatCustomerEmail falls back to the raw English message and the only
// customer gate is configuration. So this is demonstrated, not argued.
func TestDigest_IsOperatorOnly_EvenWithAWideEnabledList(t *testing.T) {
st := newDispStore(t)
// A customer who has enabled EVERYTHING, including this type by name.
if err := st.SaveNotificationPrefs("c1", "cust@example.com",
[]string{"backup_run_failures", "node_down", "disk_warning"}, 6); err != nil {
t.Fatal(err)
}
d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0))
sent := captureSeam(d)
details := `{"run_id":"run-a","run_kind":"nightly","failed":1,"attempted":3,"apps":[{"app":"opengist","leg":"volume dump","reason":"reserve"}]}`
d.ProcessEvent("c1", "backup_run_failures", "error", "1 of 3 apps failed", details, "controller")
if got := mailsFor(*sent, "cust@example.com"); len(got) != 0 {
t.Fatalf("the CUSTOMER received an operator digest (%d mails) — a list of which apps' "+
"backups failed is not something they can act on, and the raw body is English", len(got))
}
if got := len(mailsFor(*sent, "op@felhom.eu")); got != 1 {
t.Fatalf("operator mails = %d, want 1", got)
}
if !operatorOnlyEvents["backup_run_failures"] {
t.Fatal("backup_run_failures is not in operatorOnlyEvents — allowlisting alone does NOT " +
"keep it from a customer; that assumption shipped once and was wrong (v0.78.0)")
}
}
// ── Part 3 — the e-mail a person actually reads ──────────────────────────────────────────────────
func TestDigestEmail_ListsAppsLegsAndReasons(t *testing.T) {
details := `{"run_id":"run-a","run_kind":"nightly","failed":3,"attempted":40,` +
`"target_path":"/mnt/sys_drive","used_gb":64.3,"avail_gb":0.9,"total_gb":68.7,` +
`"used_percent":94,"space_known":true,"apps":[` +
`{"app":"opengist","leg":"volume dump","reason":"refused: below the reserve (headroom)"},` +
`{"app":"privatebin","leg":"volume dump","reason":"refused: below the reserve (headroom)"},` +
`{"app":"immich","leg":"database dump","reason":"pg_dump: connection refused"}]}`
subject, body := FormatOperatorEmail("demo-hp", "backup_run_failures", "error",
"3 of 40 apps failed to back up", details)
// The subject must carry the counts: the operator's first decision is made from it alone.
for _, want := range []string{"demo-hp", "3 of 40", "nightly"} {
if !strings.Contains(subject, want) {
t.Errorf("subject %q missing %q", subject, want)
}
}
// Every app, its leg and its reason.
for _, want := range []string{
"opengist", "privatebin", "immich",
"volume dump", "database dump",
"below the reserve", "pg_dump: connection refused",
} {
if !strings.Contains(body, want) {
t.Errorf("body missing %q:\n%s", want, body)
}
}
// The counts and the free space, so "one broken app" and "a full disk" read differently.
if !strings.Contains(body, "3 of 40") {
t.Errorf("body does not carry the failed-of-attempted count:\n%s", body)
}
if !strings.Contains(body, "0.9 GB free") {
t.Errorf("body does not carry the free space:\n%s", body)
}
// It must NOT be a JSON blob.
if strings.Contains(body, `"apps":[`) {
t.Errorf("the digest rendered as raw JSON — unreadable on a phone at 07:00:\n%s", body)
}
}
// An absent space reading must render as unavailable, never as zeros: "0 GB free" and "we could not
// look" are opposite diagnoses, and the operator acts differently on each.
func TestDigestEmail_UnknownSpaceIsNotZero(t *testing.T) {
details := `{"run_id":"r","run_kind":"nightly","failed":1,"attempted":2,"target_path":"/mnt/x",` +
`"space_known":false,"apps":[{"app":"a","leg":"capture","reason":"boom"}]}`
_, body := FormatOperatorEmail("demo-hp", "backup_run_failures", "error", "1 of 2 failed", details)
if strings.Contains(body, "0.0 GB free") {
t.Fatalf("an unreadable filesystem rendered as zeros:\n%s", body)
}
if !strings.Contains(body, "unavailable") {
t.Fatalf("an unreadable filesystem must say so:\n%s", body)
}
}
// A payload that cannot be parsed must still produce a mail — degraded, never swallowed.
func TestDigestEmail_UnparseableDetailsStillMails(t *testing.T) {
_, body := FormatOperatorEmail("demo-hp", "backup_run_failures", "error", "something failed", `{{{`)
if body == "" || !strings.Contains(body, "something failed") {
t.Fatalf("an unparseable digest lost the mail entirely:\n%s", body)
}
}
// ── Scenario C — every failure is RECORDED, e-mailed or not ──────────────────────────────────────
// The per-app event is the record; the digest is the notification. The record must not inherit the
// notification's conditions — no cooldown, no preferences, no dependence on a mail going out.
func TestPerAppFailure_IsRecordedButNotMailed(t *testing.T) {
st := newDispStore(t)
d := NewDispatcher(st, "test-key", "from@felhom.eu", "op@felhom.eu", true, log.New(io.Discard, "", 0))
sent := captureSeam(d)
apps := []string{"opengist", "privatebin", "immich", "homebox", "nextcloud"}
for _, a := range apps {
d.ProcessEvent("c1", "recovery_unit_capture_failed", "error",
"Recovery unit capture FAILED for \""+a+"\"", `{"app":"`+a+`"}`, "controller")
}
// NOT mailed — the digest is the notification.
if got := len(*sent); got != 0 {
t.Fatalf("%d mail(s) sent for per-app failures — they are the RECORD; one mail per app on a "+
"full disk is the volume problem wearing the correctness problem's clothes, which is "+
"exactly what the operator ruled against", got)
}
// But ALL FIVE recorded — this is the assertion yesterday's defect would have failed: nine
// arrived, two were mailed, seven left no row anywhere.
rows, err := st.GetRecentNotifications("c1", 50)
if err != nil {
t.Fatal(err)
}
seen := map[string]bool{}
for _, r := range rows {
if r.EventType == "recovery_unit_capture_failed" && r.Status == "recorded" {
for _, a := range apps {
if strings.Contains(r.Message, a) {
seen[a] = true
}
}
}
}
if len(seen) != len(apps) {
t.Fatalf("only %d of %d per-app failures were recorded (%v) — a failure that produced no row "+
"anywhere is the measured defect of 2026-08-03", len(seen), len(apps), seen)
}
}