Files
mesh-catalog/modules/messenger/cmd/messenger/holder_test.go
T
jschoubben 2927cb2ceb messenger: hold what a delivery walk touches and tell its end once, and say nothing again for a restart (hq ADR 0308, issues 532, 531)
A delivery's own restarts reached the operator as notifications while it ran, and every restart of the
tool runner popped the four silenced messages up again on the desk, twice. The router now reads the
controller's walk start and end on plan-moved, holds what an open walk touches until its end or bound,
tells the end as one message, and makes the restart pass once per restart from its own state, leaving
silenced, withheld, answered and held messages as they are.
2026-10-12 11:55:35 +02:00

536 lines
18 KiB
Go

package main
import (
"errors"
"fmt"
"strings"
"testing"
"time"
)
type fakeChannel struct {
to []string // whom each send was for, by account; "" for the linked one
name string
notReady error
fail error
sends []Message
edits map[string]Message
n int
silent bool // edits notify nobody, as Telegram's
// replaced is each message said again in place of an earlier one, as the id it replaced and the message.
replaced []replacement
}
type replacement struct {
id string
m Message
}
// Replace says a message again in place of an earlier one: shown as a new message is, under the same id.
func (f *fakeChannel) Replace(id string, m Message) error {
if f.fail != nil {
return f.fail
}
f.replaced = append(f.replaced, replacement{id, m})
return nil
}
func (f *fakeChannel) SilentEdit() bool { return f.silent }
func (f *fakeChannel) Name() string { return f.name }
func (f *fakeChannel) Ready() error { return f.notReady }
func (f *fakeChannel) CanEdit() bool { return true }
func (f *fakeChannel) Send(m Message) (string, error) {
if f.fail != nil {
return "", f.fail
}
f.n++
f.sends = append(f.sends, m)
f.to = append(f.to, m.To)
if f.name == "desktop" {
return fmt.Sprintf("g14=%d", f.n), nil // as the desktop answers: the machine and the notification
}
return fmt.Sprint(f.n), nil
}
func (f *fakeChannel) Edit(id string, m Message) error {
if f.fail != nil {
return f.fail
}
if f.edits == nil {
f.edits = map[string]Message{}
}
f.edits[id] = m
return nil
}
type memStore struct {
recs map[string]Record
recent []Sent
// walks and passes are what ADR 0308 keeps: the open walks and the restart passes.
walks map[string]Walk
passes map[string]Pass
// puts counts the writes, so a write of bytes identical to what is stored is still seen (issue 422's review).
puts int
}
func (m *memStore) Put(r Record) error {
if m.recs == nil {
m.recs = map[string]Record{}
}
m.recs[r.Key] = r
m.puts++
return nil
}
func (m *memStore) Delete(k string) error { delete(m.recs, k); return nil }
func (m *memStore) All() ([]Record, error) {
var out []Record
for _, r := range m.recs {
out = append(out, r)
}
return out, nil
}
func (m *memStore) PutRecent(s []Sent) error { m.recent = s; return nil }
func (m *memStore) PutWalk(w Walk) error {
if m.walks == nil {
m.walks = map[string]Walk{}
}
m.walks[w.ID] = w
return nil
}
func (m *memStore) DeleteWalk(id string) error { delete(m.walks, id); return nil }
func (m *memStore) Walks() ([]Walk, error) {
var out []Walk
for _, w := range m.walks {
out = append(out, w)
}
return out, nil
}
func (m *memStore) PutPasses(p map[string]Pass) error { m.passes = p; return nil }
func (m *memStore) Passes() (map[string]Pass, error) { return m.passes, nil }
func (m *memStore) Recent() ([]Sent, error) { return m.recent, nil }
type clock struct{ t time.Time }
func (c *clock) now() time.Time { return c.t }
func (c *clock) pass(d time.Duration) { c.t = c.t.Add(d) }
func start() *clock { return &clock{t: time.Date(2026, 10, 6, 12, 0, 0, 0, time.UTC)} }
func cond(key, sev, summary string) Condition {
parts := strings.Split(key, ".")
return Condition{Key: key, Scope: parts[0], ID: parts[1], Kind: parts[len(parts)-1], Severity: sev, Summary: summary,
Headline: headlineOf(key), Explanation: "Needs you: look at it. What it means: " + summary + ".",
Needs: "look at it."}
}
// headlineOf is the headline a test condition carries: its key in words, so a message can be told by it
// and never carries the key itself (novox/hq ADR 0253).
func headlineOf(key string) string { return strings.ReplaceAll(key, ".", " ") }
// keyless fails a message that carries a condition's key: the operator reads words, never keys.
func keyless(t *testing.T, ms ...Message) {
t.Helper()
for _, m := range ms {
for _, w := range strings.Fields(m.Text()) {
if strings.Count(w, ".") >= 2 && !strings.HasSuffix(w, ".") {
t.Errorf("a message carries a key %q: %q", w, m.Text())
}
}
}
}
// settle lets a burst window pass and sends what is due.
func settle(h *Holder, c *clock) {
c.pass(BurstWindow)
h.Flush()
}
func newHolder(t *testing.T) (*Holder, *fakeChannel, *fakeChannel, *clock, *memStore) {
t.Helper()
c := start()
tg, dt := &fakeChannel{name: "telegram", silent: true}, &fakeChannel{name: "desktop"}
st := &memStore{}
var emitted []string
h := &Holder{Away: tg, Desk: dt, Store: st, Now: c.now, Logf: t.Logf,
Emit: func(e string, _ any) error { emitted = append(emitted, e); return nil }}
h.init()
return h, tg, dt, c, st
}
func TestARaisedConditionIsSentOnceByItsKey(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
k := cond("machine.ace.silent", Urgent, "the home server has not been heard for 15 min")
k.Raised = c.now()
h.Condition(EventRaised, k)
h.Condition(EventRaised, k) // a redelivery
c.pass(time.Minute)
h.Condition(EventRaised, k) // said again by the controller
if len(tg.sends) != 1 || len(dt.sends) != 1 {
t.Fatalf("urgent: telegram %d, desktop %d; want one each", len(tg.sends), len(dt.sends))
}
keyless(t, tg.sends...)
if tg.sends[0].Title != "Urgent: machine ace silent" || !strings.HasPrefix(tg.sends[0].Body, "Needs you: look at it. What it means: ") ||
!strings.Contains(tg.sends[0].Body, "\nSince ") {
t.Fatalf("message: %q", tg.sends[0].Text())
}
if open := h.Open(); len(open) != 1 || open[0].Count != 1 {
t.Fatalf("open: %+v", open)
}
}
func TestAWarningGoesToTheDesktopWhenASessionAnswersElseTelegram(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
h.Condition(EventRaised, cond("plan.41.stalled", Warning, "plan 41 waits on a build"))
if len(dt.sends)+len(tg.sends) != 0 {
t.Fatalf("a warning went out before its burst window")
}
settle(h, c)
if len(dt.sends) != 1 || len(tg.sends) != 0 {
t.Fatalf("desktop answered: desktop %d telegram %d", len(dt.sends), len(tg.sends))
}
dt.fail = errors.New("the account is not logged in")
c.pass(DesktopWarningEvery)
h.Condition(EventRaised, cond("plan.42.stalled", Warning, "plan 42 waits on a build"))
settle(h, c) // the desktop fails: handed to Telegram
h.Flush()
if len(tg.sends) != 1 {
t.Fatalf("no session: telegram %d", len(tg.sends))
}
dt.fail, dt.notReady = nil, errors.New("not configured")
h.Condition(EventRaised, cond("plan.43.stalled", Warning, "plan 43 waits on a build"))
settle(h, c)
if len(tg.sends) != 2 {
t.Fatalf("no desktop configured: telegram %d", len(tg.sends))
}
}
func TestTheCapIsALastLineAndIsSaidOnce(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
h.Desk = nil
// Urgent conditions, each alone and after a quiet half minute: each is its own message — until
// the cap, which is said once, in a message of its own, and holds the rest.
for i := 0; i < 25; i++ {
h.Condition(EventRaised, cond(fmt.Sprintf("machine.m%d.silent", i), Urgent, "a machine is silent"))
c.pass(BurstWindow + time.Second)
h.Flush()
}
if len(tg.sends) != CapPerHour+1 {
t.Fatalf("sent %d, want the cap of %d and one saying so", len(tg.sends), CapPerHour)
}
if last := tg.sends[CapPerHour]; !strings.HasPrefix(last.Title, "Mesh messages paused for this hour") {
t.Fatalf("the cap was not said: %q", last.Title)
}
st := h.Status("listening")
if st.Channels[0].Held != 5 || st.Channels[0].SentLastHour != CapPerHour {
t.Fatalf("status: %+v", st.Channels[0])
}
for i := 0; i < 10; i++ {
c.pass(time.Minute)
h.Tick()
}
if len(tg.sends) != CapPerHour+1 {
t.Fatalf("said the cap again or sent past it: %d", len(tg.sends))
}
// The hour frees the channel: what was held goes out as one digest.
c.pass(time.Hour)
h.Tick()
if len(tg.sends) != CapPerHour+2 {
t.Fatalf("sends %d", len(tg.sends))
}
d := tg.sends[len(tg.sends)-1]
if !strings.HasPrefix(d.Title, "Urgent: 5 urgent problems") {
t.Fatalf("digest: %q", d.Title)
}
for i := 20; i < 25; i++ {
if !strings.Contains(d.Body, fmt.Sprintf("machine m%d silent", i)) {
t.Fatalf("the digest does not name m%d: %q", i, d.Body)
}
}
}
func TestAMessageCarryingAnAddressIsRefusedAndSaidWithItsWordsWithheld(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
var emitted []string
h.Emit = func(e string, _ any) error { emitted = append(emitted, e); return nil }
h.Condition(EventRaised, cond("provider.keycloak.ace.failing", Urgent, "cannot reach 192.168.1.20:8443 with token=abc"))
if len(tg.sends) != 1 {
t.Fatalf("sends: %d", len(tg.sends))
}
text := tg.sends[0].Text()
if strings.Contains(text, "192.168") || strings.Contains(text, "token=") {
t.Fatalf("the address left: %q", text)
}
if !strings.Contains(text, "withheld, because it carried an IPv4 address") || !strings.Contains(text, "provider keycloak ace failing") {
t.Fatalf("not said as refused, by key: %q", text)
}
hist := h.History(10)["refusals"].([]RefusalNote)
if len(hist) != 1 || hist[0].Class != "address" {
t.Fatalf("refusals: %+v", hist)
}
if len(emitted) != 1 || emitted[0] != "refused" {
t.Fatalf("emitted: %v", emitted)
}
// Its clearing keeps the words withheld.
h.Condition(EventCleared, Condition{Key: "provider.keycloak.ace.failing"})
c.pass(ClearSettle)
h.Tick()
for _, m := range tg.edits {
if strings.Contains(m.Text(), "192.168") {
t.Fatalf("the clearing carried it: %q", m.Text())
}
}
if len(tg.edits) != 1 {
t.Fatalf("edits: %d", len(tg.edits))
}
}
func TestAKeyThatCarriesAnAddressIsWithheldToo(t *testing.T) {
h, tg, _, _, _ := newHolder(t)
h.Desk = nil
h.Condition(EventRaised, cond("machine.10.0.0.7.silent", Urgent, "a machine is silent"))
if len(tg.sends) != 1 || strings.Contains(tg.sends[0].Text(), "10.0.0.7") {
t.Fatalf("sends: %+v", tg.sends)
}
}
func TestStillOpenPastItsBoundItIsSaidOnceMore(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
h.Desk = nil
u := cond("bus.controller.slow-consumer", Urgent, "the controller's consumer is far behind")
u.Raised = c.now()
w := cond("plan.41.stalled", Warning, "plan 41 waits")
w.Raised = c.now()
h.Condition(EventRaised, u)
h.Condition(EventRaised, w)
settle(h, c)
c.pass(59 * time.Minute)
h.Tick()
if len(tg.sends) != 2 || len(tg.replaced) != 0 {
t.Fatalf("reminded before the hour: %d %d", len(tg.sends), len(tg.replaced))
}
c.pass(2 * time.Minute)
h.Tick()
// Said once more in place of its first message (issue 373): one message per problem.
if len(tg.sends) != 2 || len(tg.replaced) != 1 || tg.replaced[0].id != "1" ||
tg.replaced[0].m.Title != "Still open: bus controller slow-consumer" || !strings.Contains(tg.replaced[0].m.Body, "for 61 min") {
t.Fatalf("urgent reminder: %d sends, %+v", len(tg.sends), tg.replaced)
}
c.pass(3 * time.Hour)
h.Tick()
if len(tg.replaced) != 1 {
t.Fatalf("reminded twice")
}
c.pass(9 * time.Hour) // the warning is now 13 h old
h.Tick()
settle(h, c)
if len(tg.sends) != 2 || len(tg.replaced) != 2 || tg.replaced[1].id != "2" || tg.replaced[1].m.Title != "Still open: plan 41 stalled" {
t.Fatalf("warning reminder: %d sends, %+v", len(tg.sends), tg.replaced)
}
}
func TestClearedEditsTheFirstMessageAndReopenedWithinTenMinutesIsNotNew(t *testing.T) {
h, tg, dt, c, st := newHolder(t)
k := cond("machine.ace.silent", Urgent, "the home server is silent")
k.Raised = c.now()
h.Condition(EventRaised, k)
c.pass(14 * time.Minute)
h.Condition(EventCleared, Condition{Key: k.Key})
c.pass(ClearSettle) // said once it stays cleared (issue 373)
h.Tick()
if len(tg.sends) != 1 || len(tg.edits) != 1 || len(dt.edits) != 1 {
t.Fatalf("telegram sends %d edits %d, desktop edits %d", len(tg.sends), len(tg.edits), len(dt.edits))
}
if m := tg.edits["1"]; m.Title != "Resolved: machine ace silent, after 14 min" || m.Body != "" {
t.Fatalf("edit: %q", m.Title)
}
if len(h.Open()) != 0 {
t.Fatalf("still open")
}
c.pass(3 * time.Minute)
k.At = c.now() // a reopening keeps its first raising time; the event says when it happened
h.Condition(EventRaised, k)
// Urgent, and its end was said: it rings again, in place of its message (issue 373), never as a new one.
if len(tg.sends) != 1 || len(tg.replaced) != 1 || tg.replaced[0].id != "1" ||
!strings.Contains(tg.replaced[0].m.Title, "(again, 2nd time)") {
t.Fatalf("reopened as new: sends %d, replaced %+v", len(tg.sends), tg.replaced)
}
h.Condition(EventCleared, Condition{Key: k.Key})
c.pass(11 * time.Minute)
h.Tick()
if _, kept := st.recs[k.Key]; kept {
t.Fatalf("a cleared message kept past the reopen window")
}
k.At = c.now()
h.Condition(EventRaised, k)
if len(tg.sends) != 2 {
t.Fatalf("a raise after the window is a new message: %d", len(tg.sends))
}
}
func TestASilencedConditionSendsNothing(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
k := cond("machine.ace.silent", Urgent, "silent")
k.SilencedTill = c.now().Add(2 * time.Hour)
h.Condition(EventRaised, k)
c.pass(90 * time.Minute)
h.Tick()
h.Condition(EventCleared, Condition{Key: k.Key})
if len(tg.sends)+len(dt.sends)+len(tg.edits)+len(dt.edits) != 0 {
t.Fatalf("a silenced condition said something")
}
// Silenced after it was sent: no reminder.
k2 := cond("machine.shanks.silent", Urgent, "silent")
k2.Raised = c.now()
h.Condition(EventRaised, k2)
k2.SilencedTill = c.now().Add(3 * time.Hour)
h.Condition(EventChanged, k2)
c.pass(2 * time.Hour)
h.Tick()
if len(tg.sends) != 1 {
t.Fatalf("reminded while silenced: %d", len(tg.sends))
}
}
func TestEscalationIsSaidOnce(t *testing.T) {
h, tg, dt, c, _ := newHolder(t)
k := cond("machine.novox.silent", Warning, "the anchor is silent")
h.Condition(EventRaised, k)
settle(h, c)
k.Severity = Urgent
h.Condition(EventChanged, k)
h.Condition(EventChanged, k)
settle(h, c)
// The desktop's warning is replaced by the urgent message (issue 373); Telegram, which had none, is sent one.
if len(dt.sends) != 1 || len(dt.replaced) != 1 || dt.replaced[0].id != "g14=1" ||
!strings.HasPrefix(dt.replaced[0].m.Title, "Now urgent: ") || len(tg.sends) != 1 || !strings.HasPrefix(tg.sends[0].Title, "Now urgent: ") {
t.Fatalf("desktop %d sends %d replaced, telegram %d", len(dt.sends), len(dt.replaced), len(tg.sends))
}
// Escalated while the warning still waited its window: one message, the urgent one.
k2 := cond("machine.ace.silent", Warning, "the home server is silent")
h.Condition(EventRaised, k2)
k2.Severity = Urgent
h.Condition(EventChanged, k2)
settle(h, c)
if len(dt.sends) != 2 || !strings.HasPrefix(dt.sends[1].Title, "Now urgent: ") || len(dt.replaced) != 1 {
t.Fatalf("desktop %d: %q", len(dt.sends), dt.sends[len(dt.sends)-1].Title)
}
// Escalated, then the hour of an urgent one passes since it was raised: no reminder until an hour after the
// escalation was said (issue 373: "Now urgent" and "Still open" 31 s apart).
c.pass(59 * time.Minute)
h.Tick()
settle(h, c)
if len(dt.replaced) != 1 || len(tg.replaced) != 0 {
t.Fatalf("reminded within the hour of the escalation: %+v %+v", dt.replaced, tg.replaced)
}
c.pass(2 * time.Minute)
h.Tick()
settle(h, c)
if len(tg.replaced) != 2 || len(tg.sends) != 2 {
t.Fatalf("not reminded an hour after the escalation, in place: telegram %d sends %+v", len(tg.sends), tg.replaced)
}
}
func TestAChannelThatCannotSendSaysSoAndIsTriedAgain(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
h.Desk = nil
tg.fail = errors.New("telegram sendMessage: cannot connect (dial)")
h.Condition(EventRaised, cond("machine.ace.silent", Urgent, "silent"))
st := h.Status("listening")
if !strings.HasPrefix(st.Verdict, "CANNOT SEND") || len(st.Unsent) != 1 || st.Channels[0].LastError == "" {
t.Fatalf("status: %+v", st)
}
tg.fail = nil
h.Flush()
if len(tg.sends) != 0 {
t.Fatalf("tried again before a minute")
}
c.pass(RetryEvery)
h.Tick()
if len(tg.sends) != 1 || h.Status("listening").Verdict != "ok" {
t.Fatalf("not retried: %d, %s", len(tg.sends), h.Status("listening").Verdict)
}
}
func TestNothingConfiguredIsSaidInTheStatus(t *testing.T) {
h, tg, dt, _, _ := newHolder(t)
tg.notReady = errors.New("no bot token")
dt.notReady = errors.New("no machine")
st := h.Status("listening")
if !strings.HasPrefix(st.Verdict, "CANNOT SEND") || st.Channels[0].NotReady != "no bot token" {
t.Fatalf("status: %+v", st)
}
}
func TestARestartForgetsNothing(t *testing.T) {
h, tg, _, c, st := newHolder(t)
h.Desk = nil
k := cond("machine.ace.silent", Urgent, "silent")
k.Raised = c.now()
h.Condition(EventRaised, k)
again := &Holder{Away: tg, Store: st, Now: c.now, Logf: t.Logf}
if err := again.Load(); err != nil {
t.Fatal(err)
}
again.Condition(EventRaised, k)
if len(tg.sends) != 1 {
t.Fatalf("a restart sent it again")
}
again.Condition(EventCleared, Condition{Key: k.Key})
third := &Holder{Away: tg, Store: st, Now: c.now, Logf: t.Logf}
if err := third.Load(); err != nil {
t.Fatal(err)
}
c.pass(ClearSettle)
third.Tick() // a clearing not said yet before a restart is said after it
if len(tg.edits) != 1 {
t.Fatalf("a restart lost the message to edit")
}
}
func TestAnUnreadableEventIsToldOnceAnHour(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
h.Desk = nil
h.Unreadable("mesh-controller.condition-raised", errors.New("no severity"))
h.Unreadable("mesh-controller.condition-raised", errors.New("no severity"))
settle(h, c)
if len(tg.sends) != 1 || h.Status("listening").Unreadable != 2 {
t.Fatalf("sends %d", len(tg.sends))
}
c.pass(61 * time.Minute)
h.Unreadable("mesh-controller.condition-raised", errors.New("no severity"))
settle(h, c)
if len(tg.sends) != 2 {
t.Fatalf("not said again after an hour")
}
}
func TestNotifyIsKeptApartFromConditions(t *testing.T) {
h, tg, _, c, _ := newHolder(t)
h.Desk = nil
out, err := h.Notify("backup.ace.failed", Warning, "last night's backup of the home server failed", "backup", false)
if err != nil || out["held"] != true {
t.Fatalf("%v %v", out, err)
}
settle(h, c)
if err != nil || out["key"] != "notify.backup.ace.failed" || len(tg.sends) != 1 {
t.Fatalf("%v %v %d", out, err, len(tg.sends))
}
if _, err := h.Notify("x", "", "s", "", false); err == nil {
t.Fatalf("no severity was not refused")
}
if _, err := h.Notify("x", Urgent, "see /var/lib/x", "", false); err != nil {
t.Fatal(err)
}
if strings.Contains(tg.sends[len(tg.sends)-1].Text(), "/var/lib") {
t.Fatalf("a path left")
}
}
func TestATestMessageRespectsTheRule(t *testing.T) {
h, tg, dt, _, _ := newHolder(t)
if out := h.Test("telegram", "see https://example.org"); out["refused"] == "" || len(tg.sends) != 0 {
t.Fatalf("%v", out)
}
if out := h.Test("", ""); out["telegram"] != "sent" || out["desktop"] != "sent" || len(dt.sends) != 1 {
t.Fatalf("%v", out)
}
}