Files
mesh-catalog/modules/messenger/cmd/messenger/history_test.go
T
jochen 3345ff9317 One message per problem: a reminder replaces, a blip says nothing (issues 373 and 369)
The operator stopped believing the mesh's notifications: one problem stood
twice on the desk (a reminder beside the message it followed, an escalation
then a reminder 31 s later), a unit failing again at each apply was said
again 22 times, and a question's buttons outlived it on a reminder the
ask's end never reached.

- messenger: a reminder or escalation is said in place of the problem's
  message (Replace under its handle), alone, never as a digest line; a
  problem first said in a digest gets its own message next time. A
  reminder counts from when it was last said. A clearing is said once it
  stays cleared 2 min (10 min once it came back); back before that, the
  message continues without a word. Cleared before ever said and back:
  said. An ask's expiry is said with its day.
- desk-channel: a send or show under a handle already shown replaces its
  notification by the notifier's replace id.
- telegram: the same deletes the earlier message and sends the new one,
  ringing as its kind rings; one it cannot delete loses its buttons.
2026-10-10 14:22:42 +02:00

461 lines
16 KiB
Go

package main
// History is never news (novox/hq issue 271). testdata/backlog-2026-10-06.json is the controller's
// own record of every condition event of that morning — 96 of them, raised and cleared between 08:32
// and 09:49 UTC — exactly the bodies the events stream held when the holder's consumer was first made
// at 09:48, and handed over in one go. The holder of that day sent 20 desktop notifications in one
// second and folded the rest. These replay it.
import (
"encoding/json"
"fmt"
"os"
"strings"
"testing"
"time"
)
type backlogEvent struct {
event string
body json.RawMessage
at time.Time
}
func loadBacklog(t *testing.T) []backlogEvent {
t.Helper()
raw, err := os.ReadFile("testdata/backlog-2026-10-06.json")
if err != nil {
t.Fatal(err)
}
var bodies []json.RawMessage
if err := json.Unmarshal(raw, &bodies); err != nil {
t.Fatal(err)
}
var out []backlogEvent
for _, b := range bodies {
var head struct {
Event string `json:"event"`
At time.Time `json:"at"`
}
if err := json.Unmarshal(b, &head); err != nil {
t.Fatal(err)
}
out = append(out, backlogEvent{head.Event, b, head.At})
}
if len(out) != 96 {
t.Fatalf("the backlog has %d events, want the 96 of that morning", len(out))
}
return out
}
// openAt is the controller's open set at a moment, as the backlog makes it: what was raised and not
// cleared by then.
func openAt(t *testing.T, backlog []backlogEvent, at time.Time) []Condition {
t.Helper()
open := map[string]Condition{}
var order []string
for _, e := range backlog {
if e.at.After(at) {
continue
}
c, err := DecodeCondition(e.event, e.body)
if err != nil {
t.Fatal(err)
}
switch e.event {
case EventCleared:
delete(open, c.Key)
default:
if _, ok := open[c.Key]; !ok {
order = append(order, c.Key)
}
c.At = time.Time{}
open[c.Key] = c
}
}
var out []Condition
for _, k := range order {
if c, ok := open[k]; ok {
out = append(out, c)
}
}
return out
}
// replay hands the holder every event of the backlog the way run() does: read by name, then taken.
func replay(t *testing.T, h *Holder, backlog []backlogEvent, skip func(Condition, string) bool) {
t.Helper()
for _, e := range backlog {
event, ok := eventOf(ControllerSeat + "." + e.event)
if !ok {
t.Fatalf("%s is not a condition event", e.event)
}
c, err := DecodeCondition(event, e.body)
if err != nil {
t.Fatalf("today's event is unreadable: %v", err)
}
if skip != nil && skip(c, event) {
continue
}
h.Condition(event, c)
}
}
// runFor lets time pass as main does: a flush every 5 s, a tick every minute.
func runFor(h *Holder, c *clock, d time.Duration) {
for passed := time.Duration(0); passed < d; passed += 5 * time.Second {
c.pass(5 * time.Second)
h.Flush()
if passed%time.Minute == 0 {
h.Tick()
}
}
}
func said(chs ...*fakeChannel) int {
n := 0
for _, ch := range chs {
n += len(ch.sends) + len(ch.edits)
}
return n
}
// The consumer was made at 09:48:46 UTC; the holder had started a moment before.
func incidentHolder(t *testing.T) (*Holder, *fakeChannel, *fakeChannel, *clock) {
h, tg, dt, c, _ := newHolder(t)
c.t = time.Date(2026, 10, 6, 9, 49, 30, 0, time.UTC)
h.Start()
return h, tg, dt, c
}
func TestTodaysBacklogReplayedSaysNothing(t *testing.T) {
backlog := loadBacklog(t)
h, tg, dt, c := incidentHolder(t)
open := openAt(t, backlog, c.now())
if len(open) != 0 {
t.Fatalf("at 09:49 the controller had %d open; the record says none", len(open))
}
h.Sync(open, c.now())
c.pass(time.Second)
replay(t, h, backlog, nil)
runFor(h, c, 30*time.Minute)
if n := said(tg, dt); n != 0 {
t.Fatalf("the replay of that morning said %d thing(s): telegram %v desktop %v", n, tg.sends, dt.sends)
}
st := h.Status("listening")
if st.History != 96 || st.Open != 0 {
t.Fatalf("events already in the state %d (want all 96), open %d", st.History, st.Open)
}
}
func TestTodaysBacklogWithTheControllerUnreachableSaysNothing(t *testing.T) {
backlog := loadBacklog(t)
h, tg, dt, c := incidentHolder(t)
h.SyncFailed(fmt.Errorf("no answer in 30 s"))
replay(t, h, backlog, nil)
runFor(h, c, 30*time.Minute)
if n := said(tg, dt); n != 0 {
t.Fatalf("said %d: telegram %v desktop %v", n, tg.sends, dt.sends)
}
// Old by their own time, all but the last two: state, and the state is asked for again.
if st := h.Status("listening"); st.Stale < 90 || st.Open != 0 || !h.WantsSync() {
t.Fatalf("taken as state %d, open %d, wants the state read: %v", st.Stale, st.Open, h.WantsSync())
}
}
func TestTodaysBacklogRedeliveredAndReplayedAgainLaterSaysNothing(t *testing.T) {
backlog := loadBacklog(t)
h, tg, dt, c := incidentHolder(t)
h.Sync(openAt(t, backlog, c.now()), c.now())
replay(t, h, backlog, nil)
replay(t, h, backlog, nil) // redelivered: unacknowledged in time
runFor(h, c, time.Hour)
// An hour on, the consumer is deleted and made again: the stream hands the morning over once more.
h.SyncFailed(fmt.Errorf("the bus is restarting"))
replay(t, h, backlog, nil)
runFor(h, c, 30*time.Minute)
if n := said(tg, dt); n != 0 {
t.Fatalf("said %d: telegram %v desktop %v", n, tg.sends, dt.sends)
}
}
func TestTodaysBacklogWithAnUrgentStillOpenIsOneMessage(t *testing.T) {
backlog := loadBacklog(t)
h, tg, dt, c := incidentHolder(t)
// Suppose the merge never got acted on, and three machines stayed behind: still open at 09:49.
stillOpen := map[string]bool{"merge.mesh-catalog.f2b51686.not-acted": true,
"machine.ace.core-behind": true, "machine.g14.core-behind": true, "machine.shanks.core-behind": true}
var kept []backlogEvent
for _, e := range backlog {
c, _ := DecodeCondition(e.event, e.body)
if e.event == EventCleared && stillOpen[c.Key] {
continue
}
kept = append(kept, e)
}
open := openAt(t, kept, c.now())
if len(open) != 4 {
t.Fatalf("open %d", len(open))
}
h.Sync(open, c.now())
replay(t, h, kept, nil)
runFor(h, c, 30*time.Minute)
// The urgent one, never said: one message on each channel urgent goes to. The warnings, hours
// old: state, not news.
if len(tg.sends) != 1 || len(dt.sends) != 1 || len(tg.edits)+len(dt.edits) != 0 {
t.Fatalf("telegram %d desktop %d", len(tg.sends), len(dt.sends))
}
if !strings.HasPrefix(tg.sends[0].Title, "Urgent: ") || !strings.Contains(tg.sends[0].Text(), "Merge not acted") {
t.Fatalf("message: %q", tg.sends[0].Text())
}
if got := len(h.Open()); got != 4 {
t.Fatalf("open here %d", got)
}
}
func TestAnEventOlderThanTheReadingIsNotActedOn(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
h.Sync(nil, c.now())
k := cond("machine.ace.silent", Urgent, "the home server is silent")
k.At = c.now().Add(-time.Minute)
k.Raised = k.At
h.Condition(EventRaised, k) // already cleared in the state read after it
runFor(h, c, time.Minute)
if said(tg, dt) != 0 || len(h.Open()) != 0 {
t.Fatalf("a raising already over was said or kept")
}
}
func TestAnOldEventIsStateNeverAMessage(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
k := cond("machine.ace.silent", Urgent, "the home server is silent")
k.At = c.now().Add(-FreshFor - time.Second)
h.Condition(EventRaised, k)
runFor(h, c, 2*time.Minute)
if said(tg, dt) != 0 {
t.Fatalf("an old raising was said")
}
open := h.Open()
if len(open) != 1 || !open[0].History || !h.WantsSync() {
t.Fatalf("not kept as state: %+v", open)
}
// Its clearing, now: it was never said, so nothing is.
k.At = c.now()
h.Condition(EventCleared, k)
runFor(h, c, time.Minute)
if said(tg, dt) != 0 {
t.Fatalf("a clearing of what was never said was said")
}
// The state, read now, says an urgent one is open that was never said: that is said, once.
h.Condition(EventRaised, Condition{Key: "machine.shanks.silent", Scope: "machine", ID: "shanks", Kind: "silent",
Severity: Urgent, Summary: "the desktop is silent", At: c.now().Add(-time.Hour)})
h.Sync([]Condition{cond("machine.shanks.silent", Urgent, "the desktop is silent")}, c.now())
h.Sync([]Condition{cond("machine.shanks.silent", Urgent, "the desktop is silent")}, c.now().Add(time.Second))
if len(tg.sends) != 1 || len(dt.sends) != 1 {
t.Fatalf("telegram %d desktop %d", len(tg.sends), len(dt.sends))
}
}
func TestAClearingOfSomethingNeverSaidSaysNothing(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
k := cond("plan.41.stalled", Warning, "plan 41 waits")
h.Condition(EventRaised, k)
c.pass(10 * time.Second)
h.Condition(EventCleared, k) // inside its burst window: it never went out
runFor(h, c, 20*time.Minute)
if said(tg, dt) != 0 {
t.Fatalf("said: telegram %v desktop %v", tg.sends, dt.sends)
}
}
func TestABurstIsOneMessage(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
h.Desk = nil
for i := 0; i < 5; i++ {
h.Condition(EventRaised, cond(fmt.Sprintf("seat.s%d.silent", i), Warning, fmt.Sprintf("seat %d is silent", i)))
c.pass(2 * time.Second)
}
h.Flush()
if len(tg.sends) != 0 {
t.Fatalf("sent inside the window: %d", len(tg.sends))
}
runFor(h, c, time.Minute)
if len(tg.sends) != 1 || !strings.HasPrefix(tg.sends[0].Title, "Mesh: 5 new problems") {
t.Fatalf("sends %d: %+v", len(tg.sends), tg.sends)
}
for i := 0; i < 5; i++ {
if !strings.Contains(tg.sends[0].Body, fmt.Sprintf("seat s%d silent", i)) {
t.Fatalf("the digest does not name s%d: %q", i, tg.sends[0].Body)
}
}
// Said in a digest, a clearing is a line in the next one — never an edit of the digest.
for i := 0; i < 3; i++ {
h.Condition(EventCleared, Condition{Key: fmt.Sprintf("seat.s%d.silent", i)})
}
runFor(h, c, ClearSettle+time.Minute) // a clearing is said once it stays cleared (issue 373)
if len(tg.sends) != 2 || len(tg.edits) != 0 || !strings.HasPrefix(tg.sends[1].Title, "Mesh: 3 resolved") {
t.Fatalf("sends %d edits %d: %q", len(tg.sends), len(tg.edits), tg.sends[len(tg.sends)-1].Title)
}
// A burst of urgent ones: the first at once, the rest as one.
c.pass(time.Minute)
for i := 0; i < 6; i++ {
h.Condition(EventRaised, cond(fmt.Sprintf("machine.m%d.silent", i), Urgent, "a machine is silent"))
c.pass(time.Second)
}
runFor(h, c, time.Minute)
if len(tg.sends) != 4 || !strings.HasPrefix(tg.sends[3].Title, "Urgent: 5 urgent problems") {
t.Fatalf("sends %d: %q", len(tg.sends), tg.sends[len(tg.sends)-1].Title)
}
}
func TestTheDesktopIsGentle(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
h.Condition(EventRaised, cond("plan.1.stalled", Warning, "plan 1 waits"))
h.Condition(EventRaised, cond("plan.2.stalled", Warning, "plan 2 waits"))
runFor(h, c, time.Minute)
if len(dt.sends) != 1 || len(tg.sends) != 0 {
t.Fatalf("desktop %d telegram %d", len(dt.sends), len(tg.sends))
}
h.Condition(EventRaised, cond("plan.3.stalled", Warning, "plan 3 waits"))
runFor(h, c, 5*time.Minute)
h.Condition(EventRaised, cond("plan.4.stalled", Warning, "plan 4 waits"))
// Urgent is not held to the desktop's rhythm.
h.Condition(EventRaised, cond("machine.ace.silent", Urgent, "the home server is silent"))
h.Flush()
if len(dt.sends) != 2 || !strings.HasPrefix(dt.sends[1].Title, "Urgent: ") || len(tg.sends) != 1 {
t.Fatalf("urgent: desktop %d telegram %d", len(dt.sends), len(tg.sends))
}
// The urgent message took the held warnings along — one notification, read in one go. What
// comes after waits for the fifteen minutes.
h.Condition(EventRaised, cond("plan.5.stalled", Warning, "plan 5 waits"))
runFor(h, c, 8*time.Minute)
if len(dt.sends) != 2 {
t.Fatalf("a warning reached the desktop inside fifteen minutes: %d", len(dt.sends))
}
runFor(h, c, 15*time.Minute)
if len(dt.sends) != 3 {
t.Fatalf("desktop %d", len(dt.sends))
}
for i := 0; i < len(dt.sends)-1; i++ {
if !dt.sends[i].Urgent && !dt.sends[i+1].Urgent {
t.Fatalf("two warning messages close together")
}
}
}
func TestNothingIsSentInTheFirstMinuteButTheUrgentOpenAsOne(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
h.Start()
u1 := cond("machine.ace.silent", Urgent, "the home server is silent")
u1.Raised = c.now().Add(-3 * time.Hour)
u2 := cond("bus.controller.refused", Urgent, "the bus refuses the controller")
u2.Raised = c.now().Add(-20 * time.Minute)
old := cond("plan.41.stalled", Warning, "plan 41 waits")
old.Raised = c.now().Add(-2 * time.Hour)
fresh := cond("plan.42.stalled", Warning, "plan 42 waits")
fresh.Raised = c.now().Add(-2 * time.Minute)
res := h.Sync([]Condition{u1, u2, old, fresh}, c.now())
if len(res.Said) != 2 || len(res.State) != 1 || len(res.News) != 1 {
t.Fatalf("sync: %+v", res)
}
if len(tg.sends) != 1 || len(dt.sends) != 1 || !strings.HasPrefix(tg.sends[0].Title, "Urgent: 2 urgent problems") {
t.Fatalf("telegram %d desktop %d: %+v", len(tg.sends), len(dt.sends), tg.sends)
}
c.pass(10 * time.Second)
k := cond("plan.43.stalled", Warning, "plan 43 waits")
k.At = c.now()
h.Condition(EventRaised, k)
u3 := cond("machine.shanks.silent", Urgent, "the desktop is silent")
u3.At = c.now()
h.Condition(EventRaised, u3)
runFor(h, c, 45*time.Second)
if len(tg.sends) != 1 || len(dt.sends) != 1 {
t.Fatalf("sent in the grace minute: telegram %d desktop %d", len(tg.sends), len(dt.sends))
}
runFor(h, c, 20*time.Second)
// After it: what waited, as one message per channel.
if len(dt.sends) != 2 || len(tg.sends) != 2 {
t.Fatalf("after the grace: telegram %d desktop %d", len(tg.sends), len(dt.sends))
}
if d := dt.sends[1]; !strings.Contains(d.Body, "plan 42 stalled") || !strings.Contains(d.Body, "plan 43 stalled") ||
!strings.Contains(d.Body, "machine shanks silent") || strings.Contains(d.Body, "plan 41 stalled") {
t.Fatalf("desktop digest: %q", d.Text())
}
}
func TestWhatEndedWhileAwayIsEndedQuietly(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
k := cond("machine.ace.silent", Urgent, "the home server is silent")
k.At = c.now()
h.Condition(EventRaised, k)
if len(tg.sends) != 1 || len(dt.sends) != 1 {
t.Fatalf("telegram %d desktop %d", len(tg.sends), len(dt.sends))
}
c.pass(2 * time.Hour)
h.Sync(nil, c.now())
runFor(h, c, 20*time.Minute)
// Telegram's edit notifies nobody, so the message there says it is over; the desktop is not
// woken for something that ended while nobody said so.
if len(tg.sends) != 1 || len(dt.sends) != 1 || len(tg.edits) != 1 || len(dt.edits) != 0 {
t.Fatalf("telegram %d/%d desktop %d/%d", len(tg.sends), len(tg.edits), len(dt.sends), len(dt.edits))
}
if len(h.Open()) != 0 {
t.Fatalf("still open here")
}
}
func TestARestartSaysNothingAgain(t *testing.T) {
h, tg, dt, c, st := newHolder(t)
k := cond("machine.ace.silent", Urgent, "the home server is silent")
k.At = c.now()
h.Condition(EventRaised, k)
w := cond("plan.41.stalled", Warning, "plan 41 waits")
w.At = c.now()
h.Condition(EventRaised, w) // held when the holder stops
c.pass(5 * time.Second)
again := &Holder{Away: tg, Desk: dt, Store: st, Now: c.now, Logf: t.Logf}
if err := again.Load(); err != nil {
t.Fatal(err)
}
again.Start()
again.Sync([]Condition{k, w}, c.now())
runFor(again, c, time.Hour)
if len(tg.sends) != 1 || len(dt.sends) != 1 {
t.Fatalf("a restart said it again: telegram %d desktop %d", len(tg.sends), len(dt.sends))
}
}
func TestTheOpenSetIsReadInEveryShape(t *testing.T) {
one := `{"key":"machine.ace.silent","kind":"silent","subject":{"scope":"machine","id":"ace"},"severity":"urgent","summary":"s","raised":"2026-10-06T09:00:00Z"}`
for _, raw := range []string{
`{"conditions":[` + one + `],"open":1}`,
`{"answer":{"conditions":[` + one + `]},"ok":true}`,
`{"output":"{\"conditions\":[` + strings.ReplaceAll(one, `"`, `\"`) + `]}"}`,
`{"content":[{"type":"text","text":"{\"conditions\":[` + strings.ReplaceAll(one, `"`, `\"`) + `]}"}]}`,
} {
got, err := DecodeOpen(json.RawMessage(raw))
if err != nil || len(got) != 1 || got[0].Key != "machine.ace.silent" || got[0].Severity != Urgent {
t.Fatalf("%s: %+v %v", raw, got, err)
}
}
if got, err := DecodeOpen(json.RawMessage(`{"conditions":[],"open":0}`)); err != nil || len(got) != 0 {
t.Fatalf("empty: %v %v", got, err)
}
for _, bad := range []string{`{"ok":true}`, `[]`, `{"content":[{"text":"denied"}],"isError":true}`} {
if _, err := DecodeOpen(json.RawMessage(bad)); err == nil {
t.Fatalf("%s was read as an open set", bad)
}
}
}
func TestAnEventSaysItsOwnTime(t *testing.T) {
c, err := DecodeCondition(EventCleared, []byte(`{"key":"machine.ace.silent","at":"2026-10-06T08:36:50Z","raised":"2026-10-06T08:32:30Z"}`))
if err != nil || !c.When(EventCleared).Equal(time.Date(2026, 10, 6, 8, 36, 50, 0, time.UTC)) {
t.Fatalf("%v %v", c.When(EventCleared), err)
}
c.At = time.Time{}
if !c.When(EventRaised).Equal(c.Raised) || !c.When(EventChanged).IsZero() {
t.Fatalf("fallbacks")
}
}