Review: a blip swallows no escalation or waiting reminder; replace safely (issue 373)

- A comeback before the clearing was said rings when it is urgent now, and
  says the reminder or escalation that was waiting when it cleared.
- Comebacks never said are counted apart, so "again, Nth time" counts only
  what the operator was told; an urgent comeback after a said clearing rings
  again in place of its message.
- telegram sends the new message before deleting the earlier one, so a
  failed send leaves the operator a message.
- desk-channel keeps a machine's notification on record when its replace
  fails, and says a message shown nowhere as failed.
- A store that cannot be read sends a new message instead of holding it.
- Tests for each, and for a reminder in a burst and a clearing the channel
  could not take.

modules/messenger/cmd/messenger/holder.go

@@ -63,7 +63,7 @@ const (
 	ReopenWindow     = 10 * time.Minute
 	// ClearSettle: a clearing is said once the condition stayed cleared this long. One raised again sooner
 	// (a unit failing again after each apply, issue 373) continues its message without a word, and its
-	// clearing is never said. Once it has come back, its next clearing waits the whole ReopenWindow.
+	// clearing is never said. Once it has come back, its next clearing waits the reopen window less a minute.
 	ClearSettle  = 2 * time.Minute
 	CapPerHour   = 20
 	KeptSends    = 200
@@ -186,14 +186,19 @@ type Record struct {
 	// ClearUnsaid: cleared, and the clearing not said yet — it is said once it stays cleared ClearSettle;
 	// raised again before, the message continues as if it never cleared. ClearSilent: said only where an edit
 	// notifies nobody (it ended while this holder was away).
-	ClearUnsaid bool      `json:"clear_unsaid,omitempty"`
-	ClearSilent bool      `json:"clear_silent,omitempty"`
-	Reminded    bool      `json:"reminded,omitempty"`
-	Pending     string    `json:"pending,omitempty"` // what could not be said yet: raised, reminder, …
-	Folded      bool      `json:"folded,omitempty"`  // held by the cap
-	Cleared     time.Time `json:"cleared,omitempty"`
-	Count       int       `json:"count"`
-	Refused     string    `json:"refused,omitempty"`
+	ClearUnsaid bool `json:"clear_unsaid,omitempty"`
+	ClearSilent bool `json:"clear_silent,omitempty"`
+	// ClearHeld is what was waiting to be said of it when it cleared (a reminder, an escalation): said after
+	// all if it comes back before its clearing was said. Blips counts those comebacks, never said, so a
+	// condition that flaps is known as one and its message's "again, Nth time" counts only what was said.
+	ClearHeld string    `json:"clear_held,omitempty"`
+	Blips     int       `json:"blips,omitempty"`
+	Reminded  bool      `json:"reminded,omitempty"`
+	Pending   string    `json:"pending,omitempty"` // what could not be said yet: raised, reminder, …
+	Folded    bool      `json:"folded,omitempty"`  // held by the cap
+	Cleared   time.Time `json:"cleared,omitempty"`
+	Count     int       `json:"count"`
+	Refused   string    `json:"refused,omitempty"`
 	// History: known from the state or from an old event, and never said — not news.
 	History bool `json:"history,omitempty"`
 	// Seen is when this holder last took word of it; the open set read after it is authoritative.
@@ -481,21 +486,36 @@ func (h *Holder) raised(rec Record, quiet bool) {
 		// Cleared and raised again within ten minutes: the same message, back to open (to-be 45 §2).
 		h.mu.Lock()
 		blip := old.ClearUnsaid
+		held := old.ClearHeld
+		escalated := old.Severity == Warning && rec.Severity == Urgent
 		gone := now.Sub(old.Cleared)
 		old.Cleared = time.Time{}
-		old.ClearUnsaid, old.ClearSilent = false, false
-		old.Count++
+		old.ClearUnsaid, old.ClearSilent, old.ClearHeld = false, false, ""
+		if blip {
+			old.Blips++
+		} else {
+			old.Count++
+		}
 		old.Summary, old.Severity, old.SilencedTill = rec.Summary, rec.Severity, rec.SilencedTill
 		old.takeWords(rec)
 		old.Seen = now
 		h.mu.Unlock()
 		switch {
 		case quiet || old.silenced(now):
+		case blip && escalated:
+			// Back before its clearing was said, and urgent now: said as an escalation, which rings.
+			h.deliver(old, "escalated")
+		case blip && held != "":
+			// Back before its clearing was said: what was waiting to be said of it when it cleared is said now.
+			h.deliver(old, held)
 		case blip:
 			// Its clearing was never said (issue 373): to the operator it never ended, so nothing is said now.
 			h.Logf("[messenger] %s back %s after it cleared, which was not said yet: the same message continues, nothing said",
 				old.Key, roughly(gone))
 			h.record(Sent{At: now, Channel: "-", Key: old.Key, What: "reopened", Outcome: "quiet: back before its clearing was said"})
+		case old.told() && old.Severity == Urgent:
+			// Its end was said, and it is back: urgent, it rings again, in place of its message.
+			h.deliver(old, "reopened")
 		case old.told():
 			h.edit(old, "reopened", false)
 		case !needsNothing(old) && !h.queued(old.Key):
@@ -576,7 +596,11 @@ func (h *Holder) cleared(key string, quiet bool) {
 		h.Logf("[messenger] %s cleared and was not open here: nothing to say", key)
 		return
 	}
+	held := h.queuedWhat(key)
 	h.mu.Lock()
+	if held == "" {
+		held = old.Pending
+	}
 	old.Cleared = now
 	old.Pending = ""
 	old.Folded = false
@@ -595,7 +619,7 @@ func (h *Holder) cleared(key string, quiet bool) {
 		// Said once it stays cleared (ClearSettle; a condition that came back, ReopenWindow): a blip of a few
 		// seconds is not said at all (issue 373).
 		h.mu.Lock()
-		old.ClearUnsaid, old.ClearSilent = true, quiet
+		old.ClearUnsaid, old.ClearSilent, old.ClearHeld = true, quiet, held
 		h.mu.Unlock()
 	}
 	h.persist(old)
@@ -604,7 +628,7 @@ func (h *Holder) cleared(key string, quiet bool) {
 // clearSettle is how long a record stays cleared before its clearing is said: one that came back before
 // waits the whole reopen window, so a condition that flaps is said cleared once, when it stopped flapping.
 func clearSettle(r *Record) time.Duration {
-	if r.Count > 1 {
+	if r.Count > 1 || r.Blips > 0 {
 		return ReopenWindow - time.Minute
 	}
 	return ClearSettle

modules/messenger/cmd/messenger/holder_test.go

@@ -324,8 +324,10 @@ func TestClearedEditsTheFirstMessageAndReopenedWithinTenMinutesIsNotNew(t *testi
 	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)
-	if len(tg.sends) != 1 || !strings.Contains(tg.edits["1"].Title, "(again, 2nd time)") {
-		t.Fatalf("reopened as new: sends %d, edit %q", len(tg.sends), tg.edits["1"].Title)
+	// 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)

modules/messenger/cmd/messenger/onemessage_test.go

@@ -53,7 +53,8 @@ func TestAFlappingConditionIsSaidOnceAndItsClearingOnceWhenItStops(t *testing.T)
 	if got := saidOn(tg, dt); got != 1 {
 		t.Fatalf("a condition that flaps slower was said again: %d", got)
 	}
-	if open := h.Open(); len(open) != 1 || open[0].Count != 24 {
+	// Its comebacks were never said: the count the operator reads ("again, Nth time") does not grow with them.
+	if open := h.Open(); len(open) != 1 || open[0].Count != 1 {
 		t.Fatalf("open: %+v", open)
 	}
 	// A genuinely new problem meanwhile is said.
@@ -196,3 +197,95 @@ func TestAnEndedQuestionLeavesNoMessageOfferingItsAnswers(t *testing.T) {
 		}
 	}
 }
+
+// The review of PR 176: a comeback before the clearing was said must not swallow what changed meanwhile — a
+// warning back as urgent rings, and a reminder waiting to go out when it cleared still goes out.
+func TestABlipSwallowsNeitherAnEscalationNorAWaitingReminder(t *testing.T) {
+	h, tg, dt, c, _ := newHolder(t)
+	k := cond("machine.shanks.units", Warning, "2 failed services on shanks")
+	k.Raised = c.now()
+	h.Condition(EventRaised, k)
+	settle(h, c)
+	if len(dt.sends) != 1 || len(tg.sends) != 0 {
+		t.Fatalf("raised: desktop %d telegram %d", len(dt.sends), len(tg.sends))
+	}
+	h.Condition(EventCleared, Condition{Key: k.Key, At: c.now()})
+	c.pass(20 * time.Second)
+	k.Severity, k.At = Urgent, c.now()
+	h.Condition(EventRaised, k)
+	settle(h, c)
+	if len(tg.sends) != 1 || !strings.HasPrefix(tg.sends[0].Title, "Now urgent: ") {
+		t.Fatalf("back as urgent, and Telegram was not rung: %+v", tg.sends)
+	}
+
+	// A warning's reminder held by the desk's gentle rhythm when it cleared: said when it comes back.
+	w := cond("plan.41.stalled", Warning, "plan 41 waits")
+	w.Raised = c.now()
+	h.Condition(EventRaised, w)
+	runFor(h, c, DesktopWarningEvery+time.Minute)
+	before := len(dt.sends) + len(dt.replaced)
+	c.pass(RemindWarning)
+	h.Tick() // the reminder is due, and the desk holds it: a warning went out there less than 15 min ago
+	h.Condition(EventRaised, cond("seat.s9.silent", Warning, "s9 is silent"))
+	h.Flush()
+	h.Condition(EventCleared, Condition{Key: w.Key, At: c.now()})
+	c.pass(20 * time.Second)
+	w.At = c.now()
+	h.Condition(EventRaised, w)
+	runFor(h, c, DesktopWarningEvery+time.Minute)
+	found := false
+	for _, r := range dt.replaced {
+		found = found || strings.HasPrefix(r.m.Title, "Still open: plan 41")
+	}
+	for _, m := range dt.sends {
+		found = found || strings.Contains(m.Body, "plan 41 stalled") || strings.HasPrefix(m.Title, "Still open: plan 41")
+	}
+	if !found || len(dt.sends)+len(dt.replaced) == before {
+		t.Fatalf("the reminder waiting when it blipped was lost: sends %+v replaced %+v", dt.sends, dt.replaced)
+	}
+}
+
+// The review of PR 176: a reminder for one problem and a new problem in the same burst — the reminder goes
+// alone in place of its message, never as a digest line beside it.
+func TestAReminderInABurstReplacesItsMessageAndIsNoDigestLine(t *testing.T) {
+	h, tg, _, c, _ := newHolder(t)
+	h.Desk = nil
+	a := cond("plan.41.stalled", Warning, "plan 41 waits")
+	a.Raised = c.now()
+	h.Condition(EventRaised, a)
+	settle(h, c)
+	c.pass(RemindWarning)
+	h.Tick()
+	b := cond("seat.s9.silent", Warning, "s9 is silent")
+	b.Raised = c.now()
+	h.Condition(EventRaised, b)
+	settle(h, c)
+	for _, m := range tg.sends {
+		if strings.HasPrefix(m.Title, "Mesh: ") {
+			t.Fatalf("a reminder went into a digest: %q", m.Text())
+		}
+	}
+	if len(tg.replaced) != 1 || tg.replaced[0].id != "1" || len(tg.sends) != 2 {
+		t.Fatalf("sends %+v, replaced %+v", tg.sends, tg.replaced)
+	}
+}
+
+// The review of PR 176: a clearing the channel could not take is kept until it is said, past the reopen window.
+func TestAClearingTheChannelCouldNotTakeIsSaidLater(t *testing.T) {
+	h, tg, _, c, _ := newHolder(t)
+	h.Desk = nil
+	k := cond("machine.ace.silent", Urgent, "the home server is silent")
+	k.Raised = c.now()
+	h.Condition(EventRaised, k)
+	tg.fail = errorf("telegram is away")
+	h.Condition(EventCleared, Condition{Key: k.Key, At: c.now()})
+	runFor(h, c, ReopenWindow+2*time.Minute)
+	tg.fail = nil
+	runFor(h, c, 2*time.Minute)
+	for _, m := range tg.sends {
+		if strings.HasPrefix(m.Title, "Resolved: ") {
+			return
+		}
+	}
+	t.Fatalf("the clearing was lost: %+v", tg.sends)
+}

modules/messenger/cmd/messenger/outbox.go

@@ -104,6 +104,20 @@ func (h *Holder) unqueue(key string) int {
 	return n
 }
 
+// queuedWhat is what is held to be said of a record, not its clearing: "" when nothing is.
+func (h *Holder) queuedWhat(key string) string {
+	h.mu.Lock()
+	defer h.mu.Unlock()
+	for _, list := range h.outbox {
+		for _, it := range list {
+			if it.Msg == nil && it.Key == key && it.What != "cleared" {
+				return it.What
+			}
+		}
+	}
+	return ""
+}
+
 func (h *Holder) queued(key string) bool {
 	h.mu.Lock()
 	defer h.mu.Unlock()

modules/messenger/cmd/messenger/sync.go

@@ -68,7 +68,7 @@ func (h *Holder) Sync(open []Condition, asked time.Time) SyncResult {
 			if !old.Cleared.IsZero() {
 				// Ended here, open there: back to open, quietly — the reading is not an event.
 				old.Cleared = time.Time{}
-				old.ClearUnsaid, old.ClearSilent = false, false
+				old.ClearUnsaid, old.ClearSilent, old.ClearHeld = false, false, ""
 				old.Count++
 			}
 			old.Summary, old.Subject, old.Kind, old.SilencedTill = rec.Summary, rec.Subject, rec.Kind, rec.SilencedTill