messenger: keep what a walk held owed in the state until its message was sent, so a restart says a held warning too (issue 538, review 39)

A warning held on purpose and lost with the walk's message at a restart was turned
into history and never told. Name the walk in the told line from its own item.

modules/messenger/README.md

@@ -186,8 +186,8 @@ The controller's `plan-moved` says each walk's start and end: `walk`, `phase` (`
 - **The end is one message:** the outcome, the modules and machines reached, how long; each held message still
   open, one line each; the ones that cleared counted. Delivered with nothing held and nothing open: one line —
   and nothing on a kind listed in the setting `only-what-needs-me`. What it carries is marked told on a kind
-  only once the message was sent there: a message lost with a restart before it was sent leaves them untold, and
-  the reading of the open conditions says them as any other.
+  only once the message was sent there. Until then each is kept owed in the state (`owed`): a message lost with a
+  restart before it was sent leaves them untold and owed, and the restarted router says each on its own.
 - **The bound:** at its start plus `bound_seconds` (900 when not given), what is held and still open is said,
   with "The walk … is still running, since HH:MM", and the cleared counted; the walk holds nothing more. A walk
   whose end never comes is forgotten a day after it started. A start heard after its end opens nothing: the

modules/messenger/cmd/messenger/holder.go

@@ -200,14 +200,17 @@ type Record struct {
 	// 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"`
+	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, …
+	// Owed is what a walk held of it and has not told yet (ADR 0308 §4, §5): kept in the state until a message
+	// carrying it was sent, so a router that restarts before says it on its own (issue 538), never history.
+	Owed    string    `json:"owed,omitempty"`
+	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.
@@ -407,6 +410,11 @@ func (h *Holder) Load() error {
 				r.History = true
 			}
 		}
+		if r.Owed != "" && r.Cleared.IsZero() {
+			// Held from the operator on purpose and not told yet: said on its own, as the next tick tries what is
+			// unsent (issue 538). What the operator could have heard is history; this they could not.
+			r.Pending, r.History = r.Owed, false
+		}
 		h.open[r.Key] = &r
 	}
 	if sent, err := h.Store.Recent(); err == nil {

modules/messenger/cmd/messenger/outbox.go

@@ -430,6 +430,7 @@ func (h *Holder) sendEntries(ch Channel, entries []entry, now time.Time) bool {
 		}
 		r.Pending, r.Folded, r.History = "", false, false
 		if e.it.What != "cleared" {
+			r.Owed = ""
 			if r.Sent == nil {
 				r.Sent = map[string]string{}
 			}
@@ -445,7 +446,11 @@ func (h *Holder) sendEntries(ch Channel, entries []entry, now time.Time) bool {
 			r.LastSaid = now
 		}
 	}
-	var told []*Record
+	type carried struct {
+		r    *Record
+		walk string
+	}
+	var told []carried
 	for _, e := range entries {
 		for _, key := range e.it.Carries {
 			r := h.open[key]
@@ -461,18 +466,18 @@ func (h *Holder) sendEntries(ch Channel, entries []entry, now time.Time) bool {
 			if r.FirstSent.IsZero() {
 				r.FirstSent = now
 			}
-			r.LastSaid, r.Pending, r.History = now, "", false
+			r.LastSaid, r.Pending, r.History, r.Owed = now, "", false, ""
 			if !r.Cleared.IsZero() && !r.ClearUnsaid {
 				// It cleared while the message saying it open waited: its clearing is said too.
 				r.ClearUnsaid = true
 			}
-			told = append(told, r)
+			told = append(told, carried{r, strings.TrimPrefix(e.it.Key, "walk.")})
 		}
 	}
 	h.mu.Unlock()
-	for _, r := range told {
-		h.record(Sent{At: now, Channel: name, Key: r.Key, What: "released", Outcome: "told in the message of walk " + strings.TrimPrefix(entries[0].it.Key, "walk.")})
-		h.persist(r)
+	for _, c := range told {
+		h.record(Sent{At: now, Channel: name, Key: c.r.Key, What: "released", Outcome: "told in the message of walk " + c.walk})
+		h.persist(c.r)
 	}
 	key, what := "(digest)", fmt.Sprintf("digest of %d", len(entries))
 	if len(entries) == 1 {

modules/messenger/cmd/messenger/walks.go

@@ -580,6 +580,17 @@ func (h *Holder) tellWalk(w *Walk, m Message, open []*Record, whats map[string]s
 		m = Message{Title: "A delivery ended", Body: "What it reached could not be said here: the delivery's walks say it.", Urgent: m.Urgent}
 		alone, open = open, nil
 	}
+	// Owed until a message carrying it was sent, in the state: a router that restarts first says it on its own
+	// (issue 538), whichever path below it takes.
+	h.mu.Lock()
+	for _, r := range append(append([]*Record(nil), open...), alone...) {
+		say := whats[r.Key]
+		if say == "" {
+			say = "raised"
+		}
+		r.Owed = say
+	}
+	h.mu.Unlock()
 	var to []Channel
 	if m.Urgent {
 		for _, ch := range h.channels() {
@@ -625,7 +636,8 @@ func (h *Holder) tellWalk(w *Walk, m Message, open []*Record, whats map[string]s
 		sev = Urgent
 	}
 	// What it carries is marked told on a channel once the message was sent there (outbox.go), not now: a
-	// message lost with a restart before it was sent leaves them untold, to be said as any other (issue 538 A).
+	// message lost with a restart before it was sent leaves them untold and owed, and the restarted router says
+	// each on its own (issue 538 A).
 	var carries []string
 	for _, r := range open {
 		carries = append(carries, r.Key)
@@ -635,11 +647,11 @@ func (h *Holder) tellWalk(w *Walk, m Message, open []*Record, whats map[string]s
 		h.enqueue(ch.Name(), item{Key: "walk." + w.ID, What: WalkEndWhat, Severity: sev, At: now, Msg: &msg, Carries: carries})
 	}
 	for _, r := range open {
-		if len(kept) == 0 {
-			break
+		if len(kept) > 0 {
+			h.record(Sent{At: now, Channel: "-", Key: r.Key, What: "released",
+				Outcome: "to be told in the message of walk " + w.ID + " " + what})
 		}
-		h.record(Sent{At: now, Channel: "-", Key: r.Key, What: "released",
-			Outcome: "to be told in the message of walk " + w.ID + " " + what})
+		h.persist(r) // owed, in the state, until the message was sent
 	}
 	h.flush(now, false)
 	for _, r := range alone {

modules/messenger/cmd/messenger/walks_test.go

@@ -623,13 +623,18 @@ func TestWhatAWalksPlainEndCannotCarryIsSaidOnItsOwn(t *testing.T) {
 
 // Issue 538 A: what a walk held is marked told only once the message carrying it was sent. When that message
 // could not be sent and the router restarts before its retry, the message is gone with it: what it held is not
-// marked told, and the reading of the open conditions says it at once, not its reminder hours later.
+// marked told, it stays owed in the state, and the restarted router says it — an urgent one and a warning alike,
+// once each, never left as history.
 func TestAHeldMessageIsToldOnlyOnceTheWalksMessageWasSent(t *testing.T) {
-	for _, then := range []string{"sent", "restart"} {
+	for _, then := range []string{"sent", "restart urgent", "restart warning"} {
 		t.Run(then, func(t *testing.T) {
 			h, tg, dt, c, st := newHolder(t)
+			sev := Urgent
+			if then == "restart warning" {
+				sev = Warning
+			}
 			walk(t, h, "plan-h", WalkStarted, "", c.now(), 1200, novox("mesh-tools"))
-			k := cond("machine.novox.tools-silent", Urgent, "the tools on novox are silent")
+			k := cond("machine.novox.tools-silent", sev, "the tools on novox are silent")
 			k.Raised = c.now()
 			h.Condition(EventRaised, k)
 			runFor(h, c, time.Minute)
@@ -649,9 +654,13 @@ func TestAHeldMessageIsToldOnlyOnceTheWalksMessageWasSent(t *testing.T) {
 				if !heard("Still open after it:\n- Urgent: "+headlineOf(k.Key), tg, dt) || saidOn(tg, dt) != 2 {
 					t.Fatalf("not told once in the walk's message: telegram %+v, desk %+v", tg.sends, dt.sends)
 				}
-				if r := h.open[k.Key]; r == nil || !r.told() || r.Sent["telegram"] != "" || r.Sent["desktop"] != "" {
+				if r := h.open[k.Key]; r == nil || !r.told() || r.Owed != "" || r.Sent["telegram"] != "" || r.Sent["desktop"] != "" {
 					t.Fatalf("not marked told on both channels once sent: %+v", r)
 				}
+				runFor(h, c, 10*time.Minute)
+				if saidOn(tg, dt) != 2 {
+					t.Fatalf("said again after the walk's message: telegram %+v, desk %+v", tg.sends, dt.sends)
+				}
 				return
 			}
 			again := &Holder{Away: tg, Desk: dt, Store: st, Now: c.now, Logf: t.Logf}
@@ -660,10 +669,20 @@ func TestAHeldMessageIsToldOnlyOnceTheWalksMessageWasSent(t *testing.T) {
 			}
 			again.Start()
 			again.Sync([]Condition{k}, c.now())
-			runFor(again, c, time.Minute)
+			runFor(again, c, 5*time.Minute)
 			if !heard(headlineOf(k.Key), tg, dt) {
 				t.Fatalf("what the lost message carried was not said after the restart: %v", outcomes(again, k.Key))
 			}
+			said := saidOn(tg, dt)
+			if r := again.open[k.Key]; r == nil || !r.told() || r.Owed != "" || r.Pending != "" {
+				t.Fatalf("said, and still owed or not marked told: %+v", r)
+			}
+			runFor(again, c, 20*time.Minute) // within its reminder's bound: nothing more is due
+			again.Sync([]Condition{k}, c.now())
+			runFor(again, c, time.Minute)
+			if saidOn(tg, dt) != said {
+				t.Fatalf("said again: telegram %+v, desk %+v", tg.sends, dt.sends)
+			}
 		})
 	}
 }