issue 797: tells no longer eat the conditions'/notify's cap, and a dropped tell is logged once an hour

Review round 1 of mesh-catalog found sentLastHour counting tells
against CapPerHour (ADR 0380 §8 says tells keep their own cap, never
shared), and the drop log firing on every drop instead of once an
hour per channel as the comment already said.

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{}

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 {

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++
 		}
 	}

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