hub v0.107.0: the hub rewrote a severity and said nothing (R-387); golden 0.223.0
gates / gates (push) Successful in 17s

One handler, two fields, opposite discipline. An unknown event_type is rejected
with a loud 400. An unknown severity was rewritten to "info" without a word -
and severityNotifies drops "info" before BOTH legs, so the event was stored,
answered 200, and mailed to nobody.

Two shipped features went out that way: DiskAlertKind.Severity emitted "warn"
until controller v0.215.0, app_start_failed until v0.223.0. Measured on the live
hub DB today: 91 app_start_failed events stored all-time, ZERO notification_log
rows before this session - not one, on any channel.

The mechanism built to catch this class was structurally blind to it: the
dispatcher's `unrecognized severity` line cannot execute for anything arriving
over the API, because the coercion one line earlier guarantees the value it
looks for cannot arrive.

The coercion STAYS - a rejected event is a lost event, and losing an alarm is
worse than mis-routing one. Only the silence is fixed: a WARN naming the
customer, the event type and the rejected value.

The dispatcher branch is KEPT, not deleted as dead, and the reason is evidence
rather than caution: cmd/hub/main.go wires dispatcher.ProcessEvent DIRECTLY as
the monitor.EventNotifyFunc for the staleness, host-staleness and offsite-box
checkers, which never pass through the handler. For those it is the only
severity guard there is. All 90 severity literals in internal/monitor are
already valid, so the guard is silent because the producers are correct.

Test count 702 -> 709. Red-proof seen failing: delete the WARN line and the
coercion test fails with "the hub rewrote a severity and said nothing".

Golden 0.223.0 baked and published (sha 9eaf39ac3921...), round-trip HTTP 206.
Vouching is the operator's act and was not done here.
This commit is contained in:
2026-08-23 11:57:26 +02:00
parent 55274d5ef3
commit 68a9f5475c
8 changed files with 762 additions and 2 deletions
+50
View File
@@ -1,3 +1,53 @@
## v0.107.0 — the hub rewrote a severity and said nothing, and the guard for that sat downstream of the rewrite (2026-08-23, R-387)
**One handler, two fields, opposite discipline.** An unknown **event type** is rejected with a loud
`400` (`allowedEventTypes`). An unknown **severity** was rewritten to `info` without a word — and
`info` is dropped by `severityNotifies` before either delivery leg, so the event was stored, answered
`200`, and mailed to nobody.
**Two shipped features went out that way.** The controller's `DiskAlertKind.Severity` emitted `"warn"`
until controller v0.215.0; `app_start_failed` emitted it until controller v0.223.0. Both were
undeliverable for the whole life of the feature, on both legs, with every gate green.
**The mechanism built to catch exactly this was structurally blind to it.** `dispatcher.go` has a line
whose job is to log an unrecognised severity — and for anything arriving over the API it can never
execute, because this handler guarantees the value it looks for has already been overwritten one line
earlier.
**The coercion STAYS; only the silence is fixed.** A rejected event is a *lost* event, and losing an
alarm is worse than mis-routing one — which is why this was a coercion in the first place. The
producer is our own controller, so the fix belongs at the emitter (controller v0.223.0); this release
is what makes the emitter's mistake **visible the first time it happens instead of never**. The new
line is at `WARN` and names the customer, the event type and the rejected value.
### The dispatcher's branch is KEPT, and this is the reason
It was examined as dead code. **It is not dead.** `cmd/hub/main.go` wires `dispatcher.ProcessEvent`
**directly** as the `monitor.EventNotifyFunc` for the staleness, host-staleness and offsite-box
checkers, and those hub-generated events never pass through the ingest handler at all. For every one
of them that line is the **only** severity guard there is. Deleting it as "dead" would have removed
the live half while the dead half supplied the justification.
Verified while deciding: **all 90 severity literals in `internal/monitor` are already in the
vocabulary**, so the guard is currently silent because the producers are correct — which is what a
working guard looks like. (The `"warn"` strings in `internal/web` are UI badge vocabulary, not
severities.)
### Tests
`internal/api/r387_severity_visibility_test.go` — the coercion still happens, the event is still
stored, the event is **not** lost, and the WARN line names all three facts; plus a guard that a valid
severity stays silent, because an alarm on the normal path is one people learn to ignore.
`internal/notify/r329_app_start_failed_test.go` — the routing consequence: with the corrected
severity the **operator is emailed and the customer is not**, unless they opted in, in which case both
legs deliver and the customer's copy carries the Hungarian template rather than raw internal text.
Test count **702 → 709**.
**Red-proof (seen failing):** delete the ingest `WARN` line → the coercion test fails with
`the hub rewrote a severity and said nothing`, the log showing only the ordinary `[INFO] Event from
c1: backup_failed (info)`.
## v0.106.0 — the hub says something when it loses sight of the off-site stores (2026-08-18, R-339)
**The gap this closes, measured rather than supposed.** On 2026-08-18 ep0's PBS proxy was wedged for
+23 -1
View File
@@ -2118,10 +2118,32 @@ func (h *Handler) handleEvent(w http.ResponseWriter, r *http.Request) {
return
}
// Validate/default severity (exact-match lowercase; unknown values coerce to info)
// Validate/default severity (exact-match lowercase; unknown values coerce to info).
//
// R-387 — THE COERCION STAYS. THE SILENCE DOES NOT.
//
// Note the asymmetry two blocks up: an unknown event TYPE is rejected with a loud 400, while an
// unknown SEVERITY was rewritten without a word. The silent one is the one that hid a real defect
// for the whole life of two features — `DiskAlertKind.Severity` emitted "warn" until controller
// v0.215.0, and `app_start_failed` emitted it until v0.223.0. Both were stored, both were
// coerced here to "info", and "info" is dropped by severityNotifies — so both were mailed to
// NOBODY, on either leg, while every POST returned 200.
//
// The dispatcher has a line whose job is exactly this (`unrecognized severity %q`), and it can
// never execute, because this block guarantees the value it looks for cannot reach it. **The
// mechanism built to detect this class was structurally blind to it.**
//
// WHY NOT A 400. A rejected event is a LOST event, and losing an alarm is worse than mis-routing
// one — the same reasoning that made this a coercion in the first place. The producer is our own
// controller, so the fix belongs at the emitter; this line is how the emitter's mistake becomes
// VISIBLE the first time it happens instead of never.
switch payload.Severity {
case "info", "warning", "error", "critical":
default:
h.logger.Printf("[WARN] [api] Event from %s: severity %q is not in {info,warning,error,critical} "+
"— coercing to \"info\", which severityNotifies DROPS, so this %s alert will reach NOBODY. "+
"Fix the emitting controller; this event is stored but not routed.",
payload.CustomerID, payload.Severity, payload.EventType)
payload.Severity = "info"
}
@@ -0,0 +1,133 @@
package api
import (
"bytes"
"encoding/json"
"io"
"log"
"net/http/httptest"
"path/filepath"
"strings"
"testing"
"gitea.dooplex.hu/admin/felhom-hub/internal/store"
)
// R-387 — the ingest handler rewrote an unknown severity WITHOUT SAYING SO, and the guard built to
// catch that class sat downstream of the rewrite, permanently blind to it.
//
// THE ASYMMETRY. Two fields, same handler, opposite discipline: an unknown event TYPE is rejected
// with a loud 400; an unknown SEVERITY was silently coerced to "info" — after which severityNotifies
// drops it and NEITHER leg runs. Two shipped features (`DiskAlertKind.Severity` until controller
// v0.215.0, `app_start_failed` until v0.223.0) emitted "warn" and were mailed to nobody, while every
// POST returned 200 and every dashboard showed the alert.
//
// THE LAYER. The guard sits at INGEST, because that is the last point at which the offending value
// still exists — by design it ceases to exist one line later, which is exactly why nothing downstream
// could ever detect it.
//
// WHY NOT A 400. A rejected event is a LOST event, and losing an alarm is worse than mis-routing one.
// The coercion is deliberate and stays; only the silence is fixed.
//
// RED-PROOF (observed, see REPORT.md): delete the h.logger.Printf from the default branch and
// TestR387_UnknownSeverityIsCoercedAndAnnounced fails with `the hub rewrote a severity and said
// nothing`.
func severityTestHandler(t *testing.T) (*Handler, *store.Store, *bytes.Buffer) {
t.Helper()
var buf bytes.Buffer
path := filepath.Join(t.TempDir(), "test.db")
st, err := store.New(path, log.New(io.Discard, "", 0))
if err != nil {
t.Fatalf("store.New: %v", err)
}
t.Cleanup(func() { st.Close() })
if err := st.SaveCustomerConfig(&store.CustomerConfig{
CustomerID: "c1", APIKey: "k1", RetrievalPassword: "p",
}); err != nil {
t.Fatal(err)
}
h := New(st, globalKey, "", "", nil, log.New(&buf, "", 0))
return h, st, &buf
}
func postEvent(t *testing.T, h *Handler, eventType, severity string) *httptest.ResponseRecorder {
t.Helper()
body, _ := json.Marshal(map[string]any{
"customer_id": "c1", "event_type": eventType, "severity": severity,
"message": "test message",
})
return do(h, "POST", "/event", "k1", string(body))
}
func TestR387_UnknownSeverityIsCoercedAndAnnounced(t *testing.T) {
h, st, logs := severityTestHandler(t)
rr := postEvent(t, h, "backup_failed", "warn")
// The event must NOT be lost — that is the whole reason this is a coercion and not a 400.
if rr.Code >= 400 {
t.Fatalf("HTTP %d — an unknown severity must never LOSE the event; a rejected alarm is worse "+
"than a mis-routed one", rr.Code)
}
// The STORED effect: coerced to info, exactly as before.
events, err := st.GetRecentEvents("c1", 10)
if err != nil {
t.Fatal(err)
}
if len(events) != 1 {
t.Fatalf("stored %d events, want 1 — the event was lost", len(events))
}
if events[0].Severity != "info" {
t.Errorf("stored severity = %q, want \"info\" — the coercion behaviour must not change", events[0].Severity)
}
// THE FIX: it is no longer silent.
out := logs.String()
if !strings.Contains(out, "WARN") {
t.Fatalf("the hub rewrote a severity and said nothing — this is R-387, and it is how two "+
"features shipped undeliverable for months. log=%q", out)
}
for _, want := range []string{`"warn"`, "c1", "backup_failed"} {
if !strings.Contains(out, want) {
t.Errorf("the log line does not name %q, so nobody can act on it: %q", want, out)
}
}
}
// A VALID severity must stay silent — a guard that fires on the normal path is one people learn to
// ignore, which is the same failure one door over.
func TestR387_ValidSeveritiesAreSilent(t *testing.T) {
for _, sev := range []string{"info", "warning", "error", "critical"} {
h, _, logs := severityTestHandler(t)
if rr := postEvent(t, h, "backup_failed", sev); rr.Code >= 400 {
t.Fatalf("severity %q: HTTP %d", sev, rr.Code)
}
if strings.Contains(logs.String(), "not in {info,warning,error,critical}") {
t.Errorf("severity %q produced a coercion warning: %q", sev, logs.String())
}
}
}
// The asymmetry this finding is about, pinned so it stays deliberate: an unknown TYPE is still
// rejected loudly, an unknown SEVERITY is still accepted-and-logged. Two different answers, both on
// purpose, and now both visible.
func TestR387_UnknownTypeStillRejectedUnknownSeverityStillAccepted(t *testing.T) {
h, st, _ := severityTestHandler(t)
if rr := postEvent(t, h, "no_such_event_type", "warning"); rr.Code != 400 {
t.Errorf("unknown event_type: HTTP %d, want 400 — an unlisted type must stay a loud refusal", rr.Code)
}
if rr := postEvent(t, h, "backup_failed", "nonsense"); rr.Code >= 400 {
t.Errorf("unknown severity: HTTP %d, want <400 — it must be accepted and logged, never lost", rr.Code)
}
events, err := st.GetRecentEvents("c1", 10)
if err != nil {
t.Fatal(err)
}
if len(events) != 1 {
t.Errorf("stored %d events, want exactly 1 (the bad-severity one; the bad-type one must not "+
"be stored)", len(events))
}
}
+15
View File
@@ -141,6 +141,21 @@ func (d *Dispatcher) ProcessEvent(customerID, eventType, severity, message, deta
// warning / error / critical trigger notifications. "info" is an intentional non-notify (status/
// recovery events). Anything else is UNRECOGNIZED — log it (don't silently drop), so a bad severity
// surfaces instead of vanishing (the felhom-pve-class lesson: a critical event must never be lost).
//
// R-387 — THIS BRANCH IS **KEPT DELIBERATELY**, and here is why, because the question was asked
// and a branch that cannot execute without a note is the thing to avoid.
//
// For an event arriving over the API it is genuinely unreachable: the ingest handler coerces any
// unknown severity to "info" before this is called, so the one value it looks for cannot arrive.
// **But the API is not the only producer.** `cmd/hub/main.go` wires `dispatcher.ProcessEvent`
// DIRECTLY as the `monitor.EventNotifyFunc` for the staleness, host-staleness and offsite-box
// checkers, and those hub-generated events never pass through the handler at all. For every one
// of them this line is the ONLY severity guard there is.
//
// Removing it as "dead" would therefore have deleted the live half while leaving the dead half
// looking like the reason. Verified 2026-08-23: every severity literal in `internal/monitor` (90
// of them) is already in the vocabulary — so the guard is currently silent because the producers
// are correct, which is exactly what a guard looks like when it is working.
if !severityNotifies(severity) {
if severity != "info" {
d.logger.Printf("[WARN] Dispatcher: unrecognized severity %q for %s/%s — not routing", severity, customerID, eventType)
@@ -0,0 +1,166 @@
package notify
import (
"bytes"
"log"
"strings"
"sync"
"testing"
)
// R-329 — `app_start_failed` was emitted with severity "warn", which the hub coerces to "info" and
// then drops. These tests pin the ROUTING the fixed severity produces, from the dispatcher's side.
//
// THE LAYER. The emitter's word is pinned in the controller (AST walk). This pins the CONSEQUENCE at
// the hub: with the correct severity the OPERATOR is emailed and the CUSTOMER is not, unless the
// customer opted in. Asserting only the controller's string would be case #9's mistake — mechanism
// pinned, consequence unpinned — and this is the half a customer actually experiences.
//
// RED-PROOF (observed, see REPORT.md): pass "warn" instead of "warning" in Scenario A and it fails
// with `operator was NOT emailed` — the exact live defect, reproduced in a unit test.
// SCENARIO A — an app goes down and the customer has NOT opted in.
// The operator must be emailed; the customer must not.
func TestR329_ScenarioA_OperatorMailedCustomerNot(t *testing.T) {
st := opOnlyStore(t)
// A customer with an address and the DEFAULT set — app_start_failed deliberately absent.
if err := st.SaveNotificationPrefs("c1", "customer@example.com",
[]string{"backup_failed", "disk_warning"}, 6); err != nil {
t.Fatal(err)
}
rec := &sentTo{}
d := opOnlyDispatcher(t, st, rec)
d.ProcessEvent("c1", "app_start_failed", "warning",
"Telepített alkalmazás nem fut: BookStack", `{"stack_name":"bookstack"}`, "controller")
var gotOperator, gotCustomer bool
for _, to := range rec.to {
switch to {
case "operator@felhom.eu":
gotOperator = true
case "customer@example.com":
gotCustomer = true
}
}
if !gotOperator {
t.Errorf("operator was NOT emailed for app_start_failed (severity \"warning\") — this is the "+
"R-329 defect: a severity outside {info,warning,error,critical} is coerced to \"info\" "+
"and dropped by severityNotifies, reaching nobody. sent=%v", rec.to)
}
if gotCustomer {
t.Errorf("the CUSTOMER was emailed although app_start_failed is not in their enabled events "+
"— the operator ruled this OFF by default. sent=%v", rec.to)
}
}
// SCENARIO B — the customer HAS opted in. Both legs deliver, and the customer's copy must carry the
// hub's HUNGARIAN template, not raw English. That is the v0.78.0 defect the registers exist to stop.
//
// This is also the POSITIVE CONTROL for Scenario A's absence claim: it proves the customer leg can
// deliver at all for this event type, so "the customer was not emailed" in A means the gate held,
// not that the path is broken.
func TestR329_ScenarioB_OptedInCustomerGetsTheHungarianMessage(t *testing.T) {
st := opOnlyStore(t)
if err := st.SaveNotificationPrefs("c1", "customer@example.com",
[]string{"backup_failed", "app_start_failed"}, 6); err != nil {
t.Fatal(err)
}
type mail struct{ to, subject, body string }
var sent []mail
d := NewDispatcher(st, "test-key", "from@felhom.eu", "operator@felhom.eu", true, discardLogger())
d.sendEmailFn = func(to, subject, body string, _ map[string]string) error {
sent = append(sent, mail{to, subject, body})
return nil
}
d.ProcessEvent("c1", "app_start_failed", "warning",
"Telepített alkalmazás nem fut: BookStack", `{"stack_name":"bookstack"}`, "controller")
var customer *mail
var gotOperator bool
for i := range sent {
if sent[i].to == "customer@example.com" {
customer = &sent[i]
}
if sent[i].to == "operator@felhom.eu" {
gotOperator = true
}
}
if !gotOperator {
t.Errorf("operator not emailed when the customer opted in — both legs must deliver. sent=%v", sent)
}
if customer == nil {
t.Fatalf("the customer opted in and was NOT emailed — the toggle would be a lie. sent=%v", sent)
}
// The Hungarian template, not the raw English/controller string.
want := customerMessages["app_start_failed"]
if want == "" {
t.Fatal("app_start_failed has no customerMessages entry — a customer-switchable event with " +
"no Hungarian copy sends a household raw internal text (the v0.78.0 defect)")
}
if !strings.Contains(customer.body+customer.subject, want) {
t.Errorf("the customer's mail does not carry the Hungarian template %q.\n subject: %q\n body: %q",
want, customer.subject, customer.body)
}
}
// The two registers must stay as they are: app_start_failed is customer-reachable BY CONFIGURATION,
// which is precisely what makes the toggle honest.
func TestR329_AppStartFailedIsNotOperatorOnly(t *testing.T) {
if operatorOnlyEvents["app_start_failed"] {
t.Fatal("app_start_failed is in operatorOnlyEvents — the customer toggle added in controller " +
"v0.223.0 would then be visible, switchable and STRUCTURALLY INCAPABLE of delivering. " +
"A toggle that cannot do what it says is worse than no toggle.")
}
if customerMessages["app_start_failed"] == "" {
t.Fatal("app_start_failed has no customerMessages entry — see above")
}
}
// SCENARIO H's dispatcher half: an unrecognized severity must be LOGGED, not silently dropped. This
// branch is reachable from the hub's own monitor checkers, which call ProcessEvent directly and never
// pass the API handler's coercion — which is why it was KEPT rather than deleted as dead.
func TestR329_UnrecognizedSeverityIsLoggedNotSilent(t *testing.T) {
st := opOnlyStore(t)
if err := st.SaveNotificationPrefs("c1", "customer@example.com", []string{"backup_failed"}, 6); err != nil {
t.Fatal(err)
}
buf := &lineBuf{}
d := NewDispatcher(st, "test-key", "from@felhom.eu", "operator@felhom.eu", true, buf.logger())
d.sendEmailFn = func(to, _, _ string, _ map[string]string) error {
t.Errorf("an unrecognized severity was ROUTED to %s — it must not be", to)
return nil
}
// The hub-internal path: straight into ProcessEvent, bypassing the handler.
d.ProcessEvent("c1", "backup_failed", "warn", "msg", "{}", "hub")
out := buf.String()
if !strings.Contains(out, "unrecognized severity") {
t.Errorf("a bad severity from a hub-internal producer vanished without a word: %q", out)
}
if !strings.Contains(out, `"warn"`) {
t.Errorf("the log line does not name the offending value, so nobody can fix it: %q", out)
}
}
// lineBuf is a tiny concurrency-safe log sink — the dispatcher logs from the calling goroutine here,
// but ProcessEvent is documented as goroutine-safe and the hub calls it with `go`.
type lineBuf struct {
mu sync.Mutex
buf bytes.Buffer
}
func (b *lineBuf) Write(p []byte) (int, error) {
b.mu.Lock()
defer b.mu.Unlock()
return b.buf.Write(p)
}
func (b *lineBuf) String() string {
b.mu.Lock()
defer b.mu.Unlock()
return b.buf.String()
}
func (b *lineBuf) logger() *log.Logger { return log.New(b, "", 0) }