mesh-delivery: hold a stranded stop for a later merge on its way, and keep it loud (review, hq issue 474)

A stop is final, so a later merge whose queued walk would carry the modules
now holds it off; a stopped one stays in stalled until a later delivered merge
carries them. A walk counts only modules it sent, and an old walk record is read
again rather than taken as building nothing.

modules/mesh-delivery/cmd/mesh-delivery/holder.go

@@ -746,9 +746,9 @@ func (h *Holder) creditReleased(w Walk) {
 // carriedBy begins the why of a step another walk's send carried, followed by that walk's id.
 const carriedBy = "carried by "
 
-// askWalk is the ask of one walk's record by its id, once an hour while a step it carried still judges;
-// what it answers is taken as said.
-func (h *Holder) askWalk(id string, now time.Time) func() {
+// askWalk is the ask of one walk's record by its id, at most once an hour; what it answers is taken as said.
+// which says, for the log, why it is asked: what the walk is to the delivery that asks.
+func (h *Holder) askWalk(id, which string, now time.Time) func() {
 	if asked, was := h.walkAsked[id]; was && now.Sub(asked) < time.Hour {
 		return nil
 	}
@@ -758,7 +758,7 @@ func (h *Holder) askWalk(id string, now time.Time) func() {
 		h.mu.Lock()
 		defer h.mu.Unlock()
 		if err != nil {
-			h.Logf("[mesh-delivery] the walk %s, which carried a step still judging, cannot be read yet: %v", id, err)
+			h.Logf("[mesh-delivery] the walk %s, %s, cannot be read yet: %v", id, which, err)
 			h.walkAsked[id] = h.Now().Add(time.Minute - time.Hour) // asked again a minute on
 			return
 		}
@@ -916,7 +916,7 @@ func (h *Holder) plan() []func() {
 			h.settleAndKeep(d)
 			continue
 		}
-		if a := h.askWalk(d.Walk.TakenOverBy, now); a != nil {
+		if a := h.askWalk(d.Walk.TakenOverBy, "which took a delivery's walk over", now); a != nil {
 			asks = append(asks, a)
 		}
 	}
@@ -930,6 +930,20 @@ func (h *Holder) plan() []func() {
 	// grace, it is stopped saying so — never left waiting for a start that cannot come.
 	for _, d := range h.deliveries {
 		ended := d.endedUnstarted()
+		if strandedUncovered(d) {
+			// Stopped and final, but still read for a later merge that delivered its modules: until one did,
+			// `stalled` keeps listing it (review of novox/hq issue 474).
+			var ask []string
+			if d.CoveredBy, ask = h.coverOf(d); d.CoveredBy != "" {
+				h.keep(d)
+			}
+			for _, in := range ask {
+				if a := h.askContains(d, in, now); a != nil {
+					asks = append(asks, a)
+				}
+			}
+			continue
+		}
 		if d.State != Held && !h.unwalkedPast(d, now) && !ended {
 			continue
 		}
@@ -961,7 +975,7 @@ func (h *Holder) plan() []func() {
 			if s.State != StepSent && s.State != StepJudging || !strings.HasPrefix(s.Why, carriedBy) {
 				continue
 			}
-			if a := h.askWalk(strings.TrimPrefix(s.Why, carriedBy), now); a != nil {
+			if a := h.askWalk(strings.TrimPrefix(s.Why, carriedBy), "which carried a step still judging", now); a != nil {
 				asks = append(asks, a)
 			}
 		}
@@ -1001,7 +1015,7 @@ func (h *Holder) plan() []func() {
 
 	// Final deliveries past their keeping, once nothing is owed for them.
 	for id, d := range h.deliveries {
-		if d.State.Final() && len(d.Owed) == 0 && now.Sub(d.Since) > keptFinal {
+		if d.State.Final() && len(d.Owed) == 0 && now.Sub(d.Since) > keptFinal && !strandedUncovered(d) {
 			if err := h.Store.DeleteDelivery(id); err == nil {
 				delete(h.deliveries, id)
 				delete(h.written, id)
@@ -1024,8 +1038,8 @@ func (h *Holder) strand(d *Delivery, pending []string, now time.Time) func() {
 	moved, known := d.walkMovedItsModules()
 	switch {
 	case !known && d.Plan != nil:
-		return h.askWalk(d.Walk.ID, now)
-	case !known, moved, d.CoveredBy != "", len(pending) > 0, d.Stranded != "":
+		return h.askWalk(d.Walk.ID, "whose record, kept before it named the modules it built, is read again", now)
+	case !known, moved, d.CoveredBy != "", len(pending) > 0, d.Stranded != "", h.laterOnItsWay(d) != "":
 		return nil
 	}
 	ended := d.Walk.Updated
@@ -1039,12 +1053,40 @@ func (h *Holder) strand(d *Delivery, pending []string, now time.Time) func() {
 	if d.Walk.Note != "" {
 		note = " (" + d.Walk.Note + ")"
 	}
-	d.Stranded = fmt.Sprintf("its walk %s ended done before its word without building %s%s, and no later merge "+
-		"into %s that contains it delivered them: nothing delivered it (novox/hq issue 474)", d.Walk.ID,
+	d.Stranded = fmt.Sprintf("a merged change never reached the machines: its walk %s ended done before its word "+
+		"without building %s%s, and no later merge into %s that contains it delivered them (novox/hq issue 474)", d.Walk.ID,
 		strings.Join(d.notMovedBy(), ", "), note, orNone(d.Base))
 	return nil
 }
 
+// laterOnItsWay is a later merge of the same repository into the same trunk, not yet ended, whose plan moves a
+// module this delivery's walk left unbuilt — its walk queued, waiting or running — or empty when there is none
+// (review of novox/hq issue 474). A stop is final and nothing moves it to covered, so it waits for that merge:
+// once delivered, the cover test reads it; if it ends otherwise, the stop follows.
+func (h *Holder) laterOnItsWay(d *Delivery) string {
+	missing := d.notMovedBy()
+	for _, o := range h.deliveries {
+		if o.ID == d.ID || o.State.Final() || o.Plan == nil || o.MergedAs == "" || sameCommit(o.MergedAs, d.MergedAs) ||
+			!strings.EqualFold(o.Repository, d.Repository) || !strings.EqualFold(o.Base, d.Base) ||
+			!o.MergedAt.After(d.MergedAt) {
+			continue
+		}
+		for _, m := range missing {
+			if containsString(o.Plan.Moved, m) {
+				return o.ID
+			}
+		}
+	}
+	return ""
+}
+
+// strandedUncovered is whether a delivery stopped because its ended walk delivered nothing is still uncovered: a
+// merged change that never reached the machines, which `stalled` keeps listing until a later delivered merge
+// carries its modules (review of novox/hq issue 474).
+func strandedUncovered(d *Delivery) bool {
+	return d.State == Stopped && d.Stranded != "" && d.CoveredBy == ""
+}
+
 // unwalkedPast is whether a merged delivery has gone without a walk past the bound one opens within, read
 // again after it: what holds it for a person, unless something already ends it.
 func (h *Holder) unwalkedPast(d *Delivery, now time.Time) bool {

modules/mesh-delivery/cmd/mesh-delivery/issue474_test.go

@@ -80,7 +80,8 @@ func TestAMergeWhoseBatchWalkEndedIsCoveredByALaterDeliveredMerge(t *testing.T)
 }
 
 // With nothing later to carry its modules, it is stopped once the cover test says so and the walk ended past the
-// grace — saying which walk ended without moving what — and not before: a later merge may still cover it.
+// grace — saying which walk ended without moving what — and not before. Stopped, it stays loud: `stalled` lists it
+// until a later delivered merge carries its modules.
 func TestAMergeWhoseBatchWalkEndedAndNothingCoversItIsStoppedSayingWhy(t *testing.T) {
 	w := theNight(t)
 	id := IDOf(ctl474, head215)
@@ -97,43 +98,114 @@ func TestAMergeWhoseBatchWalkEndedAndNothingCoversItIsStoppedSayingWhy(t *testin
 			w.h.waitsFor(d))
 	}
 	why := d.Transitions[len(d.Transitions)-1].Why
-	for _, want := range []string{batchWalk, "build-agent", nothingNote} {
+	for _, want := range []string{"never reached the machines", batchWalk, "build-agent", nothingNote} {
 		if !strings.Contains(why, want) {
 			t.Fatalf("its stop says %q, not %q", why, want)
 		}
 	}
-	if len(w.h.Stalled()) != 0 {
-		t.Fatalf("stalled still lists %+v", w.h.Stalled())
+	lines := w.h.Stalled()
+	if len(lines) != 1 || lines[0].ID != id || !strings.Contains(lines[0].Says, "never reached the machines") {
+		t.Fatalf("stopped, it is not listed loudly: %+v", lines)
+	}
+	// A later merge that delivers build-agent ends the listing; the stop itself stays, final.
+	w.forge.contains[merge215+" in "+merge219] = true
+	deliverLater(w, ctl474, 219, "main", head219, merge219, w.now, walkDone, "build-agent")
+	w.later(2 * time.Minute)
+	w.settleAll()
+	if d := w.delivery(id); d.State != Stopped || d.CoveredBy == "" {
+		t.Fatalf("after #219 it is %s, covered by %q", d.State, d.CoveredBy)
+	}
+	if lines := w.h.Stalled(); len(lines) != 0 {
+		t.Fatalf("stalled still lists %+v", lines)
 	}
 }
 
-// A walk that ended done before a word, having built every module the merge moves, delivered it: a merge it
-// carried for a later one is covered by that one, its own merge delivered.
-func TestAMergeWhoseWalkEndedHavingMovedItsModulesIsSettledByIt(t *testing.T) {
-	for _, own := range []bool{true, false} {
+// A later merge whose walk is still queued, and whose plan moves what this one's walk left unbuilt, holds the stop
+// off: a stop is final, and that merge may yet cover it (review of issue 474).
+func TestAMergeWhoseBatchWalkEndedWaitsForALaterMergeOnItsWay(t *testing.T) {
+	w := theNight(t)
+	id := IDOf(ctl474, head215)
+	p := pr(ctl474, 219, head219, "fix/334", "internal/builder/builder.go")
+	w.h.PullUpdated(p)
+	w.h.Checked(verdictMoving(ctl474, 219, head219, "build-agent", "mesh-controller"))
+	w.later(3 * time.Minute)
+	w.h.PullMerged(mergedAt(p, merge219, w.now))
+	w.settleAll()
+	w.later(strandedAfter)
+	w.settleAll()
+	if d := w.delivery(id); d.State != Published {
+		t.Fatalf("with #219 on its way it is %s (%s)", d.State, d.Stranded)
+	}
+	// #219's walk delivers build-agent: covered.
+	w.forge.contains[merge215+" in "+merge219] = true
+	walk := aWalk(walk219, ctl474, merge219, true)
+	walk.Modules = map[string]*WalkModule{"build-agent": {}, "mesh-controller": {}}
+	w.h.WalkMoved(w.ctl.put(walk))
+	w.settleAll()
+	walk = w.ctl.walk(walk219)
+	sent := w.now
+	for m := range walk.Modules {
+		walk.Modules[m] = &WalkModule{State: "built", SentAt: &sent}
+	}
+	walk.State = walkDone
+	w.h.WalkMoved(w.ctl.put(walk))
+	w.later(2 * time.Minute)
+	w.settleAll()
+	if s := w.state(IDOf(ctl474, head219)); s != Delivered {
+		t.Fatalf("#219 is %s", s)
+	}
+	if d := w.delivery(id); d.State != Covered {
+		t.Fatalf("after #219 delivered build-agent it is %s, waiting for %q", d.State, w.h.waitsFor(d))
+	}
+}
+
+// A walk that ended before its word built nothing: a module its record names with why it was not sent is not read
+// as delivered. A merge whose plan moves nothing, answered by such a walk, is delivered.
+func TestAWalkThatEndedBeforeItsWordBuiltNothing(t *testing.T) {
+	for _, moves := range [][]string{{"build-agent"}, nil} {
 		w := newWorldOver(t, newMemStore(), newFakeController(), newFakeForge(), at215.Add(-time.Minute))
 		p := pr(ctl474, 215, head215, "fix/x", "cmd/mesh-builder/main.go")
 		w.h.PullUpdated(p)
-		w.h.Checked(verdictMoving(ctl474, 215, head215, "build-agent"))
+		w.h.Checked(verdictMoving(ctl474, 215, head215, moves...))
 		w.later(time.Minute)
 		w.h.PullMerged(mergedAt(p, merge215, at215))
-		commit, merges := merge215, []WalkMerge{{Repository: ctl474, Commit: merge215}}
-		if !own {
-			commit, merges = merge217, []WalkMerge{{Repository: ctl474, Commit: merge215, Carried: merge217}}
-		}
 		w.later(2 * time.Minute)
-		sent := w.now
-		w.h.WalkMoved(w.ctl.put(Walk{ID: batchWalk, Repository: ctl474, Branch: "main", Commit: commit, Created: w.now,
+		w.h.WalkMoved(w.ctl.put(Walk{ID: batchWalk, Repository: ctl474, Branch: "main", Commit: merge215, Created: w.now,
 			Updated: w.now, State: walkDone, Tiers: [][]string{{"build-agent"}},
-			Modules:  map[string]*WalkModule{"build-agent": {State: "built", SentAt: &sent}},
-			Delivery: &WalkDelivery{Awaits: "mesh-delivery", Merges: merges}}))
+			Modules:  map[string]*WalkModule{"build-agent": {Why: "not sent: its walk never started"}},
+			Delivery: &WalkDelivery{Awaits: "mesh-delivery", Merges: []WalkMerge{{Repository: ctl474, Commit: merge215}}}}))
 		w.settleAll()
-		want := Delivered
-		if !own {
-			want = Covered
+		d := w.delivery(IDOf(ctl474, head215))
+		want := Published
+		if len(moves) == 0 {
+			want = Delivered
 		}
-		if d := w.delivery(IDOf(ctl474, head215)); d.State != want {
-			t.Fatalf("own commit %v: it is %s, waiting for %q, not %s", own, d.State, w.h.waitsFor(d), want)
+		if d.State != want {
+			t.Fatalf("moving %v: it is %s, waiting for %q, not %s", moves, d.State, w.h.waitsFor(d), want)
 		}
 	}
 }
+
+// A walk record kept before it named the modules it built, with tiers, is not read as building nothing: the walk is
+// asked for again, and what it answers settles the delivery.
+func TestAnOldWalkRecordIsAskedForAgain(t *testing.T) {
+	w := theNight(t)
+	id := IDOf(ctl474, head215)
+	w.h.mu.Lock()
+	d := w.h.deliveries[id]
+	d.Walk.Moved, d.Walk.MovedSaid, d.Walk.Tiers = nil, false, 1
+	w.h.mu.Unlock()
+	if got := w.h.waitsFor(w.delivery(id)); !strings.Contains(got, "walk's record") {
+		t.Fatalf("an old record waits for %q", got)
+	}
+	w.later(time.Minute)
+	w.settleAll()
+	if d := w.delivery(id); !d.Walk.MovedSaid || d.Walk.Tiers != 0 {
+		t.Fatalf("the walk was not read again: %+v", d.Walk)
+	}
+	w.later(strandedAfter)
+	w.settleAll()
+	if s := w.state(id); s != Stopped {
+		t.Fatalf("read again, it is %s", s)
+	}
+}

modules/mesh-delivery/cmd/mesh-delivery/model.go

@@ -472,7 +472,7 @@ type WalkSeen struct {
 	Created time.Time `json:"created"`
 	// TakenOverBy is the walk that took a superseded one over (novox/hq ADR 0276): its deliveries follow it.
 	TakenOverBy string `json:"taken_over_by,omitempty"`
-	// Moved are the modules the walk builds, as its record names them; MovedSaid says they were read, which a
+	// Moved are the modules the walk sent, as its record names them; MovedSaid says they were read, which a
 	// record kept before novox/hq issue 474 did not. What a walk that ended before its word delivered is read
 	// from them.
 	Moved     []string `json:"moved,omitempty"`
@@ -492,8 +492,12 @@ func (w Walk) Seen() *WalkSeen {
 	s.Branch = w.Branch
 	s.Created = w.Created
 	s.TakenOverBy = w.takenOverBy()
-	for name := range w.Modules {
-		s.Moved = append(s.Moved, name)
+	// Only a module sent, or passed on its first machine, was built for the machines: one the record names with
+	// why it was not sent, or a walk that never started, built nothing (review of novox/hq issue 474).
+	for name, m := range w.Modules {
+		if m != nil && (m.SentAt != nil || m.Gate != nil && m.Gate.Verdict == "passed") {
+			s.Moved = append(s.Moved, name)
+		}
 	}
 	sort.Strings(s.Moved)
 	s.MovedSaid = true

modules/mesh-delivery/cmd/mesh-delivery/verbs.go

@@ -52,6 +52,9 @@ func (h *Holder) waitsFor(d *Delivery) string {
 		}
 		if d.endedUnstarted() {
 			// Never "its walk's start": a done walk has none (novox/hq issue 474).
+			if _, known := d.walkMovedItsModules(); !known {
+				return "its plan or its walk's record, to read what its walk " + d.Walk.ID + ", ended before its word, built"
+			}
 			return "a later delivered merge to carry " + strings.Join(d.notMovedBy(), ", ") + ": its walk " + d.Walk.ID +
 				" ended without building it, and it is stopped " + strandedAfter.String() + " after that walk ended otherwise"
 		}
@@ -197,6 +200,13 @@ func (h *Holder) Stalled() []StalledLine {
 	now := h.Now()
 	var out []StalledLine
 	for _, d := range h.deliveries {
+		if strandedUncovered(d) {
+			// Stopped, so past no bound, and still loud (review of novox/hq issue 474): listed until a later
+			// delivered merge carries its modules.
+			out = append(out, StalledLine{ID: d.ID, State: d.State, For: now.Sub(d.Since).Round(time.Second).String(),
+				Bound: "0s", H2: "none: a merge that delivers its modules ends it — the operator's", Says: d.Stranded})
+			continue
+		}
 		if !pastBound(d, now) {
 			continue
 		}