R-389: key the operator cooldown per app for app_start_failed; gate 11 makes an unfiled observation refuse the push

The cooldown key was customerID:eventType plus the tier and run suffixes, and none of them names an app, so every app going down inside the same hour collapsed onto one key and only the first was mailed. Measured on demo-hp: bookstack sent 09:27:51, privatebin suppressed 09:31:51 under key=demo-hp:app_start_failed. cooldownStackSuffix is the third sibling of cooldownTierSuffix and cooldownRunSuffix, and separate for the reason the second one's docstring already gives: the existing two keep byte-identical semantics for every type that uses them. It is ALLOW-LISTED to app_start_failed and takes the event type as well as the details, unlike its siblings, and that asymmetry is the safety property. The backup family's cooldown is coarse ON PURPOSE (R-97a, R-182) so one full disk sends one digest rather than one mail per app - and crossdrive_failed is severity error, reaches the operator leg, and carries stack_name through a DIFFERENT struct, so a payload-shape rule would have split it silently. The hour itself does not change. Gate 11 refuses a push whose REPORT.md carries an observation with neither `FILED: R-NNN` nor `NOT-A-FINDING: <reason>`. It deliberately does NOT accept a passing mention of some other R-number: the lost item cited R-182 as an analogy, so "cites a register row" would have passed the very item the gate exists to catch. That discrepancy with the spec is recorded in the gate's docstring. Registered here and in the controller and agent runners. NOT in the catalog runner - it has no shared-gate mechanism and appends --all to every gate; filed as R-391 rather than left as a sentence, which is this session's lesson. PROMPT-TEMPLATE.md §15.9 corrected: "documented, NOT acted on" was the wording that invited the gap, and it now names the markers and points at the gate. R-390 filed for the golden-bake runbook's missing `pveam update`. Hub tests 709 -> 716.
2026-08-23 13:53:01 +02:00
parent f751aea4e3
commit 2fc4a15fa3
7 changed files with 635 additions and 4 deletions
@@ -329,12 +329,83 @@ func cooldownRunSuffix(detailsJSON string) string {
 	return ":" + d.RunID
 }

+// perAppCooldownEvents is the register of event types whose operator cooldown is keyed PER APP.
+//
+// R-389. **This is a named allow-list and not a behaviour inferred from the payload, deliberately.**
+// Several event types carry `stack_name` and must NOT be split per app — see the fence below — so a
+// rule of the form "if it has a stack_name, split it" would silently change them. The register makes
+// the decision reviewable one line at a time, exactly as `operatorOnlyEvents` does.
+//
+// ── THE FENCE, RECORDED SO IT CAN BE NARROWED LATER IF IT IS EVER WRONG ──────────────────────
+//
+// The backup family's cooldown is coarse **on purpose**. R-97a and R-182 exist precisely so that one
+// full disk produces ONE mail listing every affected app, rather than one mail per app. Adding
+// `stack_name` to the key for those types would undo both, and it would do it silently — the code
+// would look more precise while the operator's inbox got twenty times louder.
+//
+// It is not hypothetical: **`crossdrive_failed` is severity `error`, reaches the operator leg, and
+// carries `stack_name`** through a different struct (`CrossDriveDetails`, not `AppDetails`). A
+// payload-shape rule would have caught it and split it. This register does not.
+//
+// The fenced ACT is *adding an entry here for a type whose family has a digest or a coarse-by-design
+// cooldown*. Adding one for a type that genuinely has no digest and alarms per app is the intended
+// use.
+var perAppCooldownEvents = map[string]bool{
+	// The ONLY member as of hub v0.108.0. An app going down is a per-app fault with no digest: there
+	// is no `apps_down_run` summarising a scan the way `backup_run_failures` summarises a run, so
+	// per-app is the only grain available that does not lose alarms. Measured 2026-08-23: two apps
+	// four minutes apart produced one mail and one suppression.
+	"app_start_failed": true,
+}
+
+// cooldownStackSuffix returns ":"+stack_name when the event's details carry a non-empty `stack_name`
+// AND the event type is in `perAppCooldownEvents`, else "".
+//
+// R-389. The third sibling of `cooldownTierSuffix` and `cooldownRunSuffix`, and deliberately a
+// SEPARATE function for the reason `cooldownRunSuffix`'s docstring already gives: the existing two
+// keep byte-identical semantics for every type that uses them, so R-97a's and R-182's behaviour and
+// their tests are untouched by this.
+//
+// WHY AN APP NEEDS ONE. The operator cooldown collapses everything sharing a key for an hour. Until
+// v0.108.0 the key named the event TYPE and not the app, so a second app going down inside that hour
+// was recorded `suppressed` and never mailed. Measured live 2026-08-23: `bookstack` sent at 09:27:51,
+// `privatebin` suppressed at 09:31:51 under `key=demo-hp:app_start_failed`. **Three apps dying
+// together produced one mail.**
+//
+// IT TAKES THE EVENT TYPE AS WELL AS THE DETAILS, unlike its two siblings, and that asymmetry is the
+// whole safety property — see `perAppCooldownEvents`. The siblings can be payload-driven because
+// `tier` and `run_id` appear only on types that want that grain; `stack_name` does not have that
+// property.
+//
+// NARROW AND FAIL-SOFT, like its siblings: empty on an absent, malformed or empty value, so a
+// degraded payload falls back to today's key and **the mail still goes**. Losing an alarm is worse
+// than mis-routing one.
+func cooldownStackSuffix(eventType, detailsJSON string) string {
+	if !perAppCooldownEvents[eventType] {
+		return ""
+	}
+	if detailsJSON == "" || !strings.Contains(detailsJSON, "\"stack_name\"") {
+		return ""
+	}
+	var d struct {
+		StackName string `json:"stack_name"`
+	}
+	if err := json.Unmarshal([]byte(detailsJSON), &d); err != nil || d.StackName == "" {
+		return ""
+	}
+	return ":" + d.StackName
+}
+
 func (d *Dispatcher) processOperator(customerID, eventType, severity, message, detailsJSON, source string) {
 	if !d.operatorOn || d.operatorEmail == "" {
 		return
 	}

-	cooldownKey := customerID + ":" + eventType + cooldownTierSuffix(detailsJSON) + cooldownRunSuffix(detailsJSON)
+	// R-389 added the third suffix. It is allow-listed to one event type, so every other type's key
+	// is byte-identical to v0.107.0's — pinned by TestR389_NoOtherEventTypeKeyChanges.
+	cooldownKey := customerID + ":" + eventType +
+		cooldownTierSuffix(detailsJSON) + cooldownRunSuffix(detailsJSON) +
+		cooldownStackSuffix(eventType, detailsJSON)
 	d.mu.Lock()
 	if last, ok := d.opCooldowns[cooldownKey]; ok && time.Since(last) < 1*time.Hour {
 		d.mu.Unlock()
@@ -0,0 +1,270 @@
+package notify
+
+import (
+	"strings"
+	"testing"
+)
+
+// R-389 — the operator cooldown named the event TYPE and not the APP, so only the first broken app
+// per hour was ever mailed.
+//
+// THE DEFECT. `processOperator` keys the 1-hour cooldown on
+// `customerID:eventType[:tier][:run_id]`. None of those name an app. Measured live on `demo-hp`
+// 2026-08-23: `bookstack` alarmed at 09:27:51 and was `sent`; `privatebin` alarmed four minutes
+// later and was logged `suppressed — operator cooldown 1h, key=demo-hp:app_start_failed`. Three apps
+// dying together produce one mail.
+//
+// THE LAYER. These sit at the key builder and at `processOperator`. The key is where the collapse
+// happens, and the stored notification rows are where it is visible — asserting only that the suffix
+// function returns a string would repeat the "mechanism pinned, consequence unpinned" mistake.
+//
+// RED-PROOF (observed, see REPORT.md): drop `cooldownStackSuffix` from the key expression in
+// `processOperator` and TestR389_TwoAppsInsideTheHourBothReachTheOperator fails with
+// `2 apps down inside the hour produced 1 operator mail(s), want 2`.
+
+// --- the suffix itself ---------------------------------------------------------------------------
+
+func TestR389_StackSuffixIsAllowListedAndFailSoft(t *testing.T) {
+	const appDetails = `{"stack_name":"bookstack","display_name":"BookStack"}`
+
+	cases := []struct {
+		name      string
+		eventType string
+		details   string
+		want      string
+	}{
+		{"the allow-listed type gets the app", "app_start_failed", appDetails, ":bookstack"},
+
+		// THE FENCE. crossdrive_failed is severity `error`, reaches the operator leg, and carries
+		// stack_name through CrossDriveDetails — a payload-shape rule would have split it per app and
+		// silently undone R-97a/R-182.
+		{"crossdrive_failed is NOT split per app", "crossdrive_failed",
+			`{"stack_name":"bookstack","method":"rsync"}`, ""},
+		{"app_deployed is not in the register", "app_deployed", appDetails, ""},
+		{"app_removed is not in the register", "app_removed", appDetails, ""},
+		{"backup_failed is not in the register", "backup_failed", appDetails, ""},
+
+		// Fail-soft: a degraded payload must fall back to today's key, never panic, never drop.
+		{"empty details", "app_start_failed", "", ""},
+		{"no stack_name key", "app_start_failed", `{"display_name":"BookStack"}`, ""},
+		{"empty stack_name", "app_start_failed", `{"stack_name":""}`, ""},
+		{"malformed JSON that still contains the token", "app_start_failed", `{"stack_name":`, ""},
+		{"null details", "app_start_failed", "null", ""},
+		{"array instead of object", "app_start_failed", `["stack_name"]`, ""},
+	}
+	for _, tc := range cases {
+		t.Run(tc.name, func(t *testing.T) {
+			if got := cooldownStackSuffix(tc.eventType, tc.details); got != tc.want {
+				t.Fatalf("cooldownStackSuffix(%q, %q) = %q, want %q", tc.eventType, tc.details, got, tc.want)
+			}
+		})
+	}
+}
+
+// The register must stay narrow. A second entry is a deliberate act and should fail this until
+// someone changes it on purpose, having read the fence.
+func TestR389_TheAllowListHasExactlyOneMember(t *testing.T) {
+	if len(perAppCooldownEvents) != 1 || !perAppCooldownEvents["app_start_failed"] {
+		var got []string
+		for k := range perAppCooldownEvents {
+			got = append(got, k)
+		}
+		t.Fatalf("perAppCooldownEvents = %v, want exactly [app_start_failed]. Adding a member is the "+
+			"fenced act: the backup family's cooldown is coarse ON PURPOSE (R-97a, R-182) so one full "+
+			"disk sends one digest, not one mail per app. Read the fence before widening this.", got)
+	}
+}
+
+// --- Scenario C: the absence claim, WITH its positive control ------------------------------------
+//
+// "No other event type's key changed" is an absence claim. The control below proves this test can
+// SEE a key change first — otherwise a broken key builder would make every row look unchanged and
+// the test would pass forever.
+func TestR389_NoOtherEventTypeKeyChanges(t *testing.T) {
+	// The v0.107.0 key expression, modelled inline. This is the BEFORE value, and modelling it here
+	// rather than reading it from git is deliberate: the comparison must survive the file moving.
+	oldKey := func(customerID, eventType, details string) string {
+		return customerID + ":" + eventType + cooldownTierSuffix(details) + cooldownRunSuffix(details)
+	}
+	newKey := func(customerID, eventType, details string) string {
+		return customerID + ":" + eventType + cooldownTierSuffix(details) + cooldownRunSuffix(details) +
+			cooldownStackSuffix(eventType, details)
+	}
+
+	// POSITIVE CONTROL FIRST: the pair must be able to differ at all.
+	if oldKey("c1", "app_start_failed", `{"stack_name":"bookstack"}`) ==
+		newKey("c1", "app_start_failed", `{"stack_name":"bookstack"}`) {
+		t.Fatal("the control failed: old and new key agree even for the allow-listed type, so this " +
+			"test cannot see a key change and its 'unchanged' verdicts below would be worthless")
+	}
+
+	// Every other type — including the ones that carry stack_name — must be byte-identical.
+	for _, tc := range []struct{ eventType, details string }{
+		{"crossdrive_failed", `{"stack_name":"bookstack","method":"rsync"}`},
+		{"crossdrive_completed", `{"stack_name":"docmost"}`},
+		{"app_deployed", `{"stack_name":"bookstack","display_name":"BookStack"}`},
+		{"app_removed", `{"stack_name":"bookstack"}`},
+		{"backup_failed", `{"error":"boom"}`},
+		{"backup_run_failures", `{"run_id":"r-42"}`},
+		{"whole_guest_backup_failed", `{"tier":"felhom-pbs"}`},
+		{"db_dump_failed", `{"stack_name":"docmost"}`},
+		{"disk_warning", `{"path":"/mnt/data"}`},
+		{"expected_backup_missed", `{"tier":"offsite","run_id":"r-9"}`},
+		{"storage_disconnected", `{}`},
+		{"health_critical", ""},
+	} {
+		o := oldKey("demo-hp", tc.eventType, tc.details)
+		n := newKey("demo-hp", tc.eventType, tc.details)
+		if o != n {
+			t.Errorf("%s: cooldown key CHANGED\n  v0.107.0: %s\n  v0.108.0: %s\n"+
+				"Only app_start_failed may move. Splitting a backup-family key per app undoes R-97a "+
+				"and R-182 — twenty mails where one digest belongs.", tc.eventType, o, n)
+		}
+	}
+}
+
+// --- the CONSEQUENCE, asserted from the stored notification rows --------------------------------
+
+// appEvent builds the details payload the controller actually sends for app_start_failed.
+func appEvent(stack string) string {
+	return `{"stack_name":"` + stack + `","display_name":"` + strings.ToUpper(stack[:1]) + stack[1:] + `"}`
+}
+
+// operatorMails returns the operator-channel rows for a customer, newest first.
+func operatorMails(t *testing.T, d *Dispatcher, customerID string) (sent, suppressed int, rows []string) {
+	t.Helper()
+	entries, err := d.store.GetRecentNotifications(customerID, 50)
+	if err != nil {
+		t.Fatal(err)
+	}
+	for _, e := range entries {
+		if e.Channel != "operator" || e.EventType != "app_start_failed" {
+			continue
+		}
+		rows = append(rows, e.Status+" | "+e.Message+" | "+e.ErrorMessage)
+		switch e.Status {
+		case "sent":
+			sent++
+		case "suppressed":
+			suppressed++
+		}
+	}
+	return sent, suppressed, rows
+}
+
+// SCENARIO A — two apps go down inside the hour. Both must reach the operator.
+//
+// This is R-389's whole point, and it asserts the STORED rows, not a return value.
+func TestR389_TwoAppsInsideTheHourBothReachTheOperator(t *testing.T) {
+	st := opOnlyStore(t)
+	rec := &sentTo{}
+	d := opOnlyDispatcher(t, st, rec)
+
+	// POSITIVE CONTROL: the operator leg must be able to deliver at all in this configuration,
+	// before any count below means anything. (Yesterday's live run could not prove the customer leg
+	// because no address was set — do not repeat that shape.)
+	d.ProcessEvent("c1", "app_start_failed", "warning",
+		"Telepített alkalmazás nem fut: BookStack", appEvent("bookstack"), "controller")
+	if sent, _, rows := operatorMails(t, d, "c1"); sent != 1 {
+		t.Fatalf("control failed: the FIRST app produced %d sent operator row(s), want 1 — the "+
+			"operator leg is not delivering here, so the counts below would be meaningless. rows=%v",
+			sent, rows)
+	}
+
+	// A different app, same hour, same event type.
+	d.ProcessEvent("c1", "app_start_failed", "warning",
+		"Telepített alkalmazás nem fut: PrivateBin", appEvent("privatebin"), "controller")
+
+	sent, suppressed, rows := operatorMails(t, d, "c1")
+	if sent != 2 {
+		t.Fatalf("2 apps down inside the hour produced %d operator mail(s), want 2 "+
+			"(suppressed=%d). This is R-389: the second app's alarm took the first app's cooldown "+
+			"slot.\nrows: %v", sent, suppressed, rows)
+	}
+	if suppressed != 0 {
+		t.Errorf("a DIFFERENT app was suppressed: %v", rows)
+	}
+
+	// And the addresses actually attempted — two distinct deliveries, not one row written twice.
+	opCount := 0
+	for _, to := range rec.to {
+		if to == "operator@felhom.eu" {
+			opCount++
+		}
+	}
+	if opCount != 2 {
+		t.Errorf("the dispatcher attempted %d operator send(s), want 2 — a stored row without a send "+
+			"attempt would be a record of something that did not happen", opCount)
+	}
+}
+
+// SCENARIO B — the SAME app twice inside the hour. The hour is unchanged: one mail, one suppression.
+func TestR389_SameAppTwiceInsideTheHourIsStillSuppressed(t *testing.T) {
+	st := opOnlyStore(t)
+	rec := &sentTo{}
+	d := opOnlyDispatcher(t, st, rec)
+
+	for i := 0; i < 2; i++ {
+		d.ProcessEvent("c1", "app_start_failed", "warning",
+			"Telepített alkalmazás nem fut: BookStack", appEvent("bookstack"), "controller")
+	}
+
+	sent, suppressed, rows := operatorMails(t, d, "c1")
+	if sent != 1 || suppressed != 1 {
+		t.Fatalf("the same app twice gave sent=%d suppressed=%d, want 1 and 1 — R-389 changes the "+
+			"GRAIN, not the hour, and re-alarming the same app is the flood the cooldown exists to "+
+			"stop.\nrows: %v", sent, suppressed, rows)
+	}
+	// The suppression must still name the key, which is what made R-389 findable at all.
+	if !strings.Contains(rows[0]+rows[1], "bookstack") {
+		t.Errorf("the suppression row does not name the app in its key — that visibility is R-182's "+
+			"contribution and is how this defect was found: %v", rows)
+	}
+}
+
+// SCENARIO D — details missing or malformed. The key degrades to today's and the mail STILL GOES.
+func TestR389_DegradedDetailsStillDeliver(t *testing.T) {
+	for _, details := range []string{"", "null", `{}`, `{"stack_name":""}`, `{"stack_name":`} {
+		st := opOnlyStore(t)
+		rec := &sentTo{}
+		d := opOnlyDispatcher(t, st, rec)
+
+		d.ProcessEvent("c1", "app_start_failed", "warning", "Telepített alkalmazás nem fut", details, "controller")
+
+		sent, _, rows := operatorMails(t, d, "c1")
+		if sent != 1 {
+			t.Errorf("details %q: %d operator mail(s), want 1 — a degraded payload must fall back to "+
+				"the old key and still deliver. Losing an alarm is worse than mis-routing one. rows=%v",
+				details, sent, rows)
+		}
+	}
+}
+
+// A backup-family event carrying stack_name must still collapse — the coarse grain is the design.
+func TestR389_CrossdriveStillCollapsesPerHour(t *testing.T) {
+	st := opOnlyStore(t)
+	rec := &sentTo{}
+	d := opOnlyDispatcher(t, st, rec)
+
+	for _, stack := range []string{"bookstack", "docmost", "privatebin"} {
+		d.ProcessEvent("c1", "crossdrive_failed", "error",
+			"Másodlagos mentés sikertelen: "+stack,
+			`{"stack_name":"`+stack+`","method":"rsync"}`, "controller")
+	}
+
+	entries, err := d.store.GetRecentNotifications("c1", 50)
+	if err != nil {
+		t.Fatal(err)
+	}
+	sent := 0
+	for _, e := range entries {
+		if e.Channel == "operator" && e.EventType == "crossdrive_failed" && e.Status == "sent" {
+			sent++
+		}
+	}
+	if sent != 1 {
+		t.Fatalf("three crossdrive_failed events produced %d operator mail(s), want 1 — this family's "+
+			"cooldown is coarse ON PURPOSE (R-97a, R-182), and it carries stack_name, so a global "+
+			"suffix would have split it into three", sent)
+	}
+}