mesh-knowledge: keep when an owed review is due, say it in the history, and tell the operator once after its last try (hq issue 497)

A failed review's try count was already kept with the version, but not when it was asked again, so a 10-minute
pause read as a review lost to a restart; and after the last try only the history and the health said so.

modules/mesh-knowledge/README.md

@@ -104,8 +104,11 @@ as text. `get` serves each, and any other field a record of hq wrote under `fiel
      Its author revises it by proposing it again, and that version is reviewed again.
    - A judgement that cannot be had (the judge unreachable, or an answer that is not `approve`, or `changes` naming
      no finding) leaves the record proposed and says so on it (`get`'s `review`). It is never taken as an
-     approval. It is asked again after 10, then 20 minutes; after 3 tries the record says its author proposes it
-     again to have it reviewed again, and the module is unhealthy, naming it, so the mesh raises a condition.
+     approval. It is owed: its try count and when it is asked again (10, then 20 minutes later) are kept with the
+     version in the store and said in its history, so the background work takes it up at that time, also after a
+     restart of the tool runner (hq issue 497). After 3 tries the record says it was the last and its author
+     proposes it again to have it reviewed again; the operator is told once on the operator's channel, and the
+     module is unhealthy, naming it, so the mesh raises a condition.
      An ask of the operator that cannot be made counts as a try the same way.
    - A review whose outcome the database refused to keep is held back for that record alone (10, then 20
      minutes, 3 tries, logged as given up), so it never blocks the records behind it.

modules/mesh-knowledge/cmd/mesh-knowledge/answers.go

@@ -770,11 +770,6 @@ func reviewSays(r *Record) string {
 	case JudgingUnproven:
 		return "not reviewed: " + j.Reason
 	}
-	s := fmt.Sprintf("not reviewed: %s (try %d of %d); it stays proposed, and no judgement that could not be had counts as an approval", j.Reason, j.Tries, MostReviewTries)
-	if j.Tries >= MostReviewTries {
-		s += "; its author proposes it again to have it reviewed again"
-	} else {
-		s += "; asked again after a pause"
-	}
-	return s
+	// When it is asked again is said, so a pause is not taken for a review lost (novox/hq issue 497).
+	return fmt.Sprintf("not reviewed: %s (%s; no judgement that could not be had counts as an approval", j.Reason, j.owedSays())
 }

modules/mesh-knowledge/cmd/mesh-knowledge/operator.go

@@ -141,13 +141,8 @@ func (k *KB) askOperator(ctx context.Context, held *Entry, w *Record, by string,
 	}
 	unasked := func(why string) (string, error) {
 		w.Ask = nil
-		w.Judging = &Judging{State: JudgingFailed, Tries: tries + 1, Reason: why, At: k.now()}
-		said := fmt.Sprintf("approved by the knowledge base's review, and %s (try %d of %d); it stays proposed", why, tries+1, MostReviewTries)
-		if tries+1 >= MostReviewTries {
-			said += ", and its author proposes it again to have it reviewed again"
-		} else {
-			said += " and is reviewed again after a pause"
-		}
+		w.Judging = failedJudging(tries+1, why, k.now())
+		said := fmt.Sprintf("approved by the knowledge base's review, and %s (%s", why, w.Judging.owedSays())
 		e, err := k.Store.Get(ctx, w.Key())
 		if err != nil || e == nil {
 			return "", fmt.Errorf("%s: %s, and that could not be kept (%v)", w.Key(), said, err)

modules/mesh-knowledge/cmd/mesh-knowledge/review.go

@@ -9,8 +9,11 @@ package main
 //   - On changes the record stays proposed, the findings kept with the version they judged, and its author revises
 //     it with a new version, which is reviewed again.
 //   - A judgement that cannot be had — the judge unreachable, or its answer unreadable — leaves the record proposed
-//     and says so on it. It is never taken as an approval. It is asked again after a pause, up to MostReviewTries;
-//     after that the record says its author proposes it again to have it reviewed again.
+//     and says so on it. It is never taken as an approval. It is owed: the try count and when the next try is due
+//     are kept with the version in the store, so the background work takes it up at that time, also after a restart
+//     of the tool runner (novox/hq issue 497), up to MostReviewTries. After the last try the record says so, its
+//     author proposes it again to have it reviewed again, the module's health names it, and the operator is told
+//     once on the operator's channel.
 //   - A record with a version whose writer the runtime did not prove is not reviewed: who wrote it cannot be told,
 //     and no one but its proven author revises it, so its author proposes it again under a new number.
 //   - On approve, a record that does not need the operator is accepted at once; one its author marked
@@ -35,6 +38,41 @@ type Judging struct {
 	Tries  int       `json:"tries,omitempty"`
 	Reason string    `json:"reason,omitempty"`
 	At     time.Time `json:"at,omitempty"`
+	// Due is when a failed review is asked again; zero after its last try. It is kept in the store with the
+	// version, so a restart of the tool runner neither loses the try nor asks it early (novox/hq issue 497).
+	Due time.Time `json:"due,omitempty"`
+}
+
+// ReviewPause is the pause after a failed try of a review, times the tries so far.
+const ReviewPause = 10 * time.Minute
+
+// failedJudging is a review that could not be had, the tries'th time: owed again at a time it keeps, unless that
+// was its last try.
+func failedJudging(tries int, reason string, now time.Time) *Judging {
+	j := &Judging{State: JudgingFailed, Tries: tries, Reason: reason, At: now}
+	if tries < MostReviewTries {
+		j.Due = now.Add(time.Duration(tries) * ReviewPause)
+	}
+	return j
+}
+
+// due is when a failed review is asked again. A version kept before the time was kept (novox/hq issue 497) has
+// none, and is due after the same pause from its last try.
+func (j *Judging) due() time.Time {
+	if !j.Due.IsZero() {
+		return j.Due
+	}
+	return j.At.Add(time.Duration(j.Tries) * ReviewPause)
+}
+
+// owedSays is what a failed try says of what follows it: when it is asked again, or that it was the last.
+func (j *Judging) owedSays() string {
+	if j.Tries >= MostReviewTries {
+		return fmt.Sprintf("try %d of %d, the last); it stays proposed and nothing of it is in force, the operator is told, "+
+			"and its author proposes it again to have it reviewed again", j.Tries, MostReviewTries)
+	}
+	return fmt.Sprintf("try %d of %d); it stays proposed, and it is asked again at %s", j.Tries, MostReviewTries,
+		j.due().UTC().Format("2006-01-02 15:04 UTC"))
 }
 
 // The states of Judging.
@@ -162,7 +200,7 @@ func (k *KB) reviewDue(e *Entry) bool {
 	case JudgingDue:
 		return true
 	case JudgingFailed:
-		return w.Judging.Tries < MostReviewTries && k.now().Sub(w.Judging.At) >= time.Duration(w.Judging.Tries)*10*time.Minute
+		return w.Judging.Tries < MostReviewTries && !k.now().Before(w.Judging.due())
 	}
 	return false
 }
@@ -218,6 +256,10 @@ func (k *KB) ReviewStep() (string, error) {
 		return "", err
 	}
 	for _, e := range all {
+		if ranOutOfTries(e.Working()) {
+			k.tellUnreviewed(e)
+			continue
+		}
 		if !k.reviewDue(e) || k.heldBack(e) {
 			continue
 		}
@@ -240,13 +282,44 @@ func Unreviewed(all []*Entry) []string {
 	var out []string
 	for _, e := range all {
 		w := e.Working()
-		if w.Status == StatusProposed && w.Judging != nil && w.Judging.State == JudgingFailed && w.Judging.Tries >= MostReviewTries {
+		if ranOutOfTries(w) {
 			out = append(out, fmt.Sprintf("%s (%s)", w.Key(), w.Judging.Reason))
 		}
 	}
 	return out
 }
 
+func ranOutOfTries(w *Record) bool {
+	return w.Status == StatusProposed && w.Judging != nil && w.Judging.State == JudgingFailed && w.Judging.Tries >= MostReviewTries
+}
+
+// tellUnreviewed tells the operator, once for each version, that a proposal ran out of review tries: a history line
+// alone is read by nobody, and a proposal never reviewed must not wait in silence (novox/hq issue 497). The store
+// keeps that it was told, so a restart does not tell it again. A tell that fails is logged; the module's health
+// still names the record, so the mesh's condition stands.
+func (k *KB) tellUnreviewed(e *Entry) {
+	if k.Notify == nil {
+		return
+	}
+	w := e.Working()
+	version := e.CurrentVersion
+	if e.Pending != nil {
+		version = e.PendingVersion
+	}
+	first, err := k.Store.Told(context.Background(), fmt.Sprintf("unreviewed %s version %d", w.Key(), version))
+	if err != nil || !first {
+		return
+	}
+	summary := fmt.Sprintf("%s was never reviewed: its review could not be had %d times (last: %s). It stays proposed, and nothing of it is in force.",
+		w.Key(), w.Judging.Tries, w.Judging.Reason)
+	explanation := "No review that could not be had counts as an approval. Its author proposes it again to have it reviewed again; " +
+		"until then the knowledge base's health names it. The knowledge base's get and history show it."
+	key := fmt.Sprintf("knowledge.unreviewed.%s-%d", w.Kind, w.Number)
+	if err := k.Notify(key, summary, "A proposal was never reviewed: "+w.Key().String(), explanation); err != nil {
+		k.logf("[mesh-knowledge] the operator could not be told that %s was never reviewed: %v; the module's health still names it", w.Key(), err)
+	}
+}
+
 // reviewOne asks the judgement on one record's working version, and acts on its verdict. The write lock is held
 // only to read and to write, never across the judgement; a record revised while it was judged is judged again.
 func (k *KB) reviewOne(key Key) (string, error) {
@@ -312,12 +385,8 @@ func (k *KB) reviewOne(key Key) (string, error) {
 	}
 	if err != nil {
 		// No verdict: the record stays proposed and says so. Never an approval.
-		w.Judging.State, w.Judging.Reason, w.Judging.At = JudgingFailed, err.Error(), k.now()
-		w.Judging.Tries++
-		why := fmt.Sprintf("not reviewed: %v (try %d of %d); it stays proposed", err, w.Judging.Tries, MostReviewTries)
-		if w.Judging.Tries >= MostReviewTries {
-			why += ", and its author proposes it again to have it reviewed again"
-		}
+		w.Judging = failedJudging(w.Judging.Tries+1, err.Error(), k.now())
+		why := fmt.Sprintf("not reviewed: %v (%s", err, w.Judging.owedSays())
 		by = ReviewBy
 		if serr := save(w, why); serr != nil {
 			return "", fmt.Errorf("%s: %s, and that could not be kept (%v)", key, why, serr)

modules/mesh-knowledge/cmd/mesh-knowledge/review_owed_test.go

@@ -0,0 +1,88 @@
+package main
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"testing"
+	"time"
+)
+
+// novox/hq issue 497: a review that could not be had is owed. What is owed is kept in the knowledge base's store,
+// with its try count and when its next try is due, so the background work takes it up after a restart of the tool
+// runner as it would have without one; the history says when it is asked again, so nobody takes a pause for a
+// loss; and after its last try the history says so and the operator is told once. It is never an approval.
+func TestAReviewOwedOutlivesARestartAndItsLastTryIsSaid(t *testing.T) {
+	eachStore(t, func(t *testing.T, s Store) {
+		w := imported(t, s)
+		n := proposed(t, w, "author@g14", false)
+		key := Key{KindDecision, n}
+		lastWhy := func() string {
+			vs, err := s.Versions(context.Background(), key)
+			if err != nil || len(vs) == 0 {
+				t.Fatalf("versions of %s: %v", key, err)
+			}
+			return vs[len(vs)-1].Why
+		}
+		var due time.Time
+		for try := 1; try <= MostReviewTries; try++ {
+			if try > 1 {
+				// The tool runner restarts: a new knowledge base over the same store, nothing of the old one's memory.
+				w = newWorld(t, s, fixture())
+				w.clock = due.Add(-time.Second)
+				if said := w.reviewAll(t); len(said) != 0 {
+					t.Fatalf("try %d asked before it was due: %v", try, said)
+				}
+				w.clock = due
+			}
+			w.judge.reviewFail = true
+			if said := w.reviewAll(t); len(said) != 1 || !strings.Contains(said[0], "not reviewed") {
+				t.Fatalf("try %d after a restart was not taken up: %v", try, said)
+			}
+			e := mustGet(t, s, key)
+			if e.Current.Status != StatusProposed || e.Current.Judging == nil || e.Current.Judging.State != JudgingFailed ||
+				e.Current.Judging.Tries != try || len(e.Current.Reviews) != 0 {
+				t.Fatalf("try %d is not counted in the store: %s, %+v", try, e.Current.Status, e.Current.Judging)
+			}
+			why := lastWhy()
+			if !strings.Contains(why, fmt.Sprintf("try %d of %d", try, MostReviewTries)) {
+				t.Fatalf("try %d: the history does not count it: %q", try, why)
+			}
+			if try < MostReviewTries {
+				due = w.clock.Add(time.Duration(try) * 10 * time.Minute)
+				when := "asked again at " + due.Format("2006-01-02 15:04 UTC")
+				if !strings.Contains(why, when) {
+					t.Fatalf("try %d: the history does not say when it is asked again (%q): %q", try, when, why)
+				}
+				if g, _ := w.k.Get(GetAsk{Number: n}); !strings.Contains(g.Review, when) {
+					t.Fatalf("try %d: get does not say when it is asked again (%q): %q", try, when, g.Review)
+				}
+				if len(w.told) != 0 {
+					t.Fatalf("try %d: the operator was told before the last try: %v", try, w.told)
+				}
+			}
+		}
+		// After its last try: the history says it was the last, and the operator is told, once.
+		if why := lastWhy(); !strings.Contains(why, "the last") || !strings.Contains(why, "the operator is told") {
+			t.Fatalf("the last try is not said in the history: %q", why)
+		}
+		if len(w.told) != 1 || !strings.Contains(w.told[0], key.String()) || !strings.Contains(w.told[0], "never reviewed") {
+			t.Fatalf("the operator is not told once of the last try: %v", w.told)
+		}
+		w.clock = w.clock.Add(24 * time.Hour)
+		if said := w.reviewAll(t); len(said) != 0 || len(w.told) != 1 {
+			t.Fatalf("after the last try: asked %v, told %v", said, w.told)
+		}
+		// Another restart neither asks it again nor tells the operator again.
+		clock := w.clock
+		w = newWorld(t, s, fixture())
+		w.clock = clock
+		if said := w.reviewAll(t); len(said) != 0 || len(w.told) != 0 {
+			t.Fatalf("after a restart past the last try: asked %v, told %v", said, w.told)
+		}
+		// Never an approval.
+		if e := mustGet(t, s, key); e.Current.Status != StatusProposed || len(w.said.of(EventAccepted)) != 0 {
+			t.Fatalf("a review never had approved it: %s", e.Current.Status)
+		}
+	})
+}

modules/mesh-knowledge/cmd/mesh-knowledge/store.go

@@ -63,7 +63,8 @@ type Store interface {
 	// SetFindings replaces the whole-set findings; Findings reads them.
 	SetFindings(ctx context.Context, f []Finding) error
 	Findings(ctx context.Context) ([]Finding, error)
-	// Told records that the operator was told about a topic's clauses, once; false when it was already.
+	// Told records that the operator was told of something, once, by its key: a topic's clauses drafted, or a
+	// version that ran out of review tries (novox/hq issue 497); false when it was already.
 	Told(ctx context.Context, topic string) (bool, error)
 }