diff --git a/modules/messenger/README.md b/modules/messenger/README.md index f628080c..bb915243 100644 --- a/modules/messenger/README.md +++ b/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 diff --git a/modules/messenger/cmd/messenger/holder.go b/modules/messenger/cmd/messenger/holder.go index e25866e8..2eb5676a 100644 --- a/modules/messenger/cmd/messenger/holder.go +++ b/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 { diff --git a/modules/messenger/cmd/messenger/outbox.go b/modules/messenger/cmd/messenger/outbox.go index f43fa427..7e9d2ae7 100644 --- a/modules/messenger/cmd/messenger/outbox.go +++ b/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 { diff --git a/modules/messenger/cmd/messenger/walks.go b/modules/messenger/cmd/messenger/walks.go index 3d32b957..365937f7 100644 --- a/modules/messenger/cmd/messenger/walks.go +++ b/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 { diff --git a/modules/messenger/cmd/messenger/walks_test.go b/modules/messenger/cmd/messenger/walks_test.go index 7e613d56..a7b86909 100644 --- a/modules/messenger/cmd/messenger/walks_test.go +++ b/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) + } }) } }