diff --git a/modules/messenger/cmd/messenger/holder.go b/modules/messenger/cmd/messenger/holder.go index 44a167b6..9182672c 100644 --- a/modules/messenger/cmd/messenger/holder.go +++ b/modules/messenger/cmd/messenger/holder.go @@ -321,30 +321,31 @@ type Holder struct { work sync.Mutex // one event, call or tick at a time mu sync.Mutex // what the status reads - open map[string]*Record - recent []Sent - refusals []RefusalNote - outbox map[string][]item - lastSend map[string]time.Time - lastWarn map[string]time.Time - lastTry map[string]time.Time - capSaid map[string]time.Time - chanErr map[string]string - chanErrAt map[string]time.Time - chanOK map[string]time.Time - unreadable int - lastBad string - lastBadAt time.Time - saidOnce map[string]time.Time - storeErr string - heard map[string]int - lastHeard time.Time - started time.Time - syncedAt time.Time - syncErr string - wantSync bool - history int - stale int + open map[string]*Record + recent []Sent + refusals []RefusalNote + outbox map[string][]item + lastSend map[string]time.Time + lastWarn map[string]time.Time + lastTry map[string]time.Time + capSaid map[string]time.Time + tellCapSaid map[string]time.Time + chanErr map[string]string + chanErrAt map[string]time.Time + chanOK map[string]time.Time + unreadable int + lastBad string + lastBadAt time.Time + saidOnce map[string]time.Time + storeErr string + heard map[string]int + lastHeard time.Time + started time.Time + syncedAt time.Time + syncErr string + wantSync bool + history int + stale int // tellSeq makes every tell's key its own, even when two calls land in the same instant. tellSeq int // answered is what came of each answer event, by its id: a redelivered one is acted on once. @@ -376,6 +377,7 @@ func (h *Holder) init() { h.lastWarn = map[string]time.Time{} h.lastTry = map[string]time.Time{} h.capSaid = map[string]time.Time{} + h.tellCapSaid = map[string]time.Time{} h.chanErr = map[string]string{} h.chanErrAt = map[string]time.Time{} h.chanOK = map[string]time.Time{} diff --git a/modules/messenger/cmd/messenger/holder_test.go b/modules/messenger/cmd/messenger/holder_test.go index 241b5dc2..e79286a9 100644 --- a/modules/messenger/cmd/messenger/holder_test.go +++ b/modules/messenger/cmd/messenger/holder_test.go @@ -576,6 +576,65 @@ func TestATellIsDroppedPastItsOwnHourlyCap(t *testing.T) { } } +func TestATellDoesNotCountTowardTheConditionsCap(t *testing.T) { + h, tg, _, c, _ := newHolder(t) + h.Desk = nil + // Bring conditions close to, but under, their own cap: CapPerHour-5. + for i := 0; i < CapPerHour-5; 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-5 { + t.Fatalf("sent %d conditions, want %d", len(tg.sends), CapPerHour-5) + } + // A full hour of tells: these must not be counted against the conditions' cap (ADR 0380 §8). + for i := 0; i < TellCapPerHour; i++ { + if _, err := h.Tell("mail", []string{"line"}, ""); err != nil { + t.Fatal(err) + } + } + h.Condition(EventRaised, cond("machine.mlast.silent", Urgent, "a machine is silent")) + c.pass(BurstWindow + time.Second) + h.Flush() + want := CapPerHour - 5 + TellCapPerHour + 1 + if len(tg.sends) != want { + t.Fatalf("sent %d, want %d (the condition after the tells still sent)", len(tg.sends), want) + } + if last := tg.sends[len(tg.sends)-1]; strings.HasPrefix(last.Title, "Mesh messages paused for this hour") { + t.Fatalf("the condition was held behind the tells' sends: %q", last.Title) + } +} + +func TestATellCapDropIsLoggedOnceAnHour(t *testing.T) { + h, tg, _, _, _ := newHolder(t) + h.Desk = nil + var logs []string + h.Logf = func(format string, args ...any) { logs = append(logs, fmt.Sprintf(format, args...)) } + for i := 0; i < TellCapPerHour; i++ { + if _, err := h.Tell("mail", []string{"line"}, ""); err != nil { + t.Fatal(err) + } + } + for i := 0; i < 3; i++ { + if _, err := h.Tell("mail", []string{"line"}, ""); err != nil { + t.Fatal(err) + } + } + if len(tg.sends) != TellCapPerHour { + t.Fatalf("sent %d of %d", len(tg.sends), TellCapPerHour) + } + dropLogs := 0 + for _, l := range logs { + if strings.Contains(l, "dropped") { + dropLogs++ + } + } + if dropLogs != 1 { + t.Fatalf("logged the drop %d times, want 1", dropLogs) + } +} + 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 { diff --git a/modules/messenger/cmd/messenger/outbox.go b/modules/messenger/cmd/messenger/outbox.go index 31159a63..ab11d4d3 100644 --- a/modules/messenger/cmd/messenger/outbox.go +++ b/modules/messenger/cmd/messenger/outbox.go @@ -609,7 +609,9 @@ func (h *Holder) sendNow(ch Channel, key, what string, m Message) bool { return true } -// allow says whether a channel is under its cap: messages sent in the last hour, as recorded. +// allow says whether a channel is under its cap: messages sent in the last hour, as recorded. A +// tell is not counted here: it has its own cap (TellCapPerHour) so a burst of tells cannot crowd +// out a condition or an ask (ADR 0380 §8). func (h *Holder) allow(channel string) bool { return h.sentLastHour(channel) < CapPerHour } @@ -620,7 +622,7 @@ func (h *Holder) sentLastHour(channel string) int { since := h.Now().Add(-time.Hour) n := 0 for _, s := range h.recent { - if s.Channel == channel && s.Outcome == "sent" && s.At.After(since) { + if s.Channel == channel && s.What != "tell" && s.Outcome == "sent" && s.At.After(since) { n++ } } diff --git a/modules/messenger/cmd/messenger/status.go b/modules/messenger/cmd/messenger/status.go index 17a0cab6..cc89348a 100644 --- a/modules/messenger/cmd/messenger/status.go +++ b/modules/messenger/cmd/messenger/status.go @@ -361,7 +361,16 @@ func (h *Holder) Tell(headline string, lines []string, subject string) (map[stri } if !h.allowTell(name) { dropped = append(dropped, name) - h.Logf("[messenger] a tell was dropped on %s: it is at its own cap of %d tells an hour", name, TellCapPerHour) + h.mu.Lock() + said := h.tellCapSaid[name] + sayIt := said.IsZero() || now.Sub(said) >= time.Hour + if sayIt { + h.tellCapSaid[name] = now + } + h.mu.Unlock() + if sayIt { + h.Logf("[messenger] a tell was dropped on %s: it is at its own cap of %d tells an hour", name, TellCapPerHour) + } h.record(Sent{At: now, Channel: name, Key: key, What: "tell", Outcome: fmt.Sprintf("dropped: at its own cap of %d tells an hour", TellCapPerHour)}) continue