Bring the look back for a tier the bus refused whole, clear the wait when it ends, and say the wait in plain words (issue 1334, review round 1)

cmd/mesh-controller/ask_bus_look_integration_test.go

@@ -0,0 +1,134 @@
+//go:build integration
+
+package main
+
+import (
+	"context"
+	"fmt"
+	"strings"
+	"testing"
+	"time"
+
+	"github.com/novox/mesh-controller/internal/catalogue"
+	"github.com/novox/mesh-controller/internal/inventory"
+)
+
+// Issue 1334, the look: when the bus did not answer an ask of any module of a tier, no build is in flight and no event follows,
+// so the look itself comes back (it fails, and the looker retries it), asks the modules again, and past the bound fails the plan.
+func TestALookComesBackForATierTheBusRefusedWhole(t *testing.T) {
+	open := aMesh(t)
+	ctx := t.Context()
+	inv := open.inventory
+	for _, name := range []string{"a", "b"} {
+		if err := inv.RegisterModule(ctx, catalogue.Manifest{Module: name, Version: "1"},
+			inventory.Source{Repository: "novox/" + name, Seat: "git", Ref: "main", BuiltFrom: "c0", Head: "c0"}); err != nil {
+			t.Fatal(err)
+		}
+	}
+	p := inventory.Plan{ID: "plan-bus", Repository: "novox/a", Branch: "main", Commit: "c1", Created: time.Now().UTC(),
+		State: inventory.PlanBuilding, Tiers: [][]string{{"a", "b"}}, Modules: map[string]*inventory.PlanModule{"a": {}, "b": {}}}
+	if err := inv.SavePlan(ctx, &p); err != nil {
+		t.Fatal(err)
+	}
+	bus := false
+	was := askABuild
+	askABuild = func(_ context.Context, source buildSource, _, _ string) (string, error) {
+		if !bus {
+			return "", fmt.Errorf("%w: nats: no responders available for request", inventory.ErrNoChain)
+		}
+		return "build-" + source.Repository, nil
+	}
+	t.Cleanup(func() { askABuild = was })
+	look := func() bool {
+		t.Helper()
+		release, err := inv.HoldPlans(ctx, true)
+		if err != nil {
+			t.Fatal(err)
+		}
+		defer release()
+		return advanceHeld(ctx, open)
+	}
+	read := func() inventory.Plan {
+		t.Helper()
+		got, err := inv.PlanByID(ctx, "plan-bus")
+		if err != nil {
+			t.Fatal(err)
+		}
+		return got
+	}
+
+	// Every module refused: the look says it failed, which has the looker come back; the plan is building and says why.
+	if !look() {
+		t.Fatal("a look that left the whole tier unasked for the bus did not fail, so nothing would come back to it")
+	}
+	if got := read(); got.State != inventory.PlanBuilding || !strings.Contains(got.Note, "bus did not answer") ||
+		got.Modules["a"].State != "" || got.Modules["b"].State != "" {
+		t.Fatalf("the plan after a refused tier: %s %q %+v %+v", got.State, got.Note, got.Modules["a"], got.Modules["b"])
+	}
+	// Again, still refused: the same fact is not saved again, and the look still comes back.
+	before := read().Revision
+	if !look() || read().Revision != before {
+		t.Fatalf("a second refused look failed to come back or saved the plan again (revision %d, was %d)", read().Revision, before)
+	}
+
+	// The bus answers at the next look: both are asked, and nothing waits any more.
+	bus = true
+	if look() {
+		t.Fatal("a look that asked the whole tier failed")
+	}
+	if got := read(); got.Modules["a"].State != "asked" || got.Modules["b"].State != "asked" || got.Modules["a"].BusWaitFrom != nil {
+		t.Fatalf("the tier was not asked once the bus answered: %+v %+v", got.Modules["a"], got.Modules["b"])
+	}
+}
+
+func TestALookFailsTheTierTheBusRefusedPastTheBound(t *testing.T) {
+	open := aMesh(t)
+	ctx := t.Context()
+	inv := open.inventory
+	if err := inv.RegisterModule(ctx, catalogue.Manifest{Module: "a", Version: "1"},
+		inventory.Source{Repository: "novox/a", Seat: "git", Ref: "main", BuiltFrom: "c0", Head: "c0"}); err != nil {
+		t.Fatal(err)
+	}
+	long := time.Now().UTC().Add(-busWaitBound - time.Minute)
+	p := inventory.Plan{ID: "plan-bus", Repository: "novox/a", Branch: "main", Commit: "c1", Created: time.Now().UTC(),
+		State: inventory.PlanBuilding, Tiers: [][]string{{"a"}}, Modules: map[string]*inventory.PlanModule{"a": {BusWaitFrom: &long}}}
+	if err := inv.SavePlan(ctx, &p); err != nil {
+		t.Fatal(err)
+	}
+	was := askABuild
+	askABuild = func(context.Context, buildSource, string, string) (string, error) {
+		return "", fmt.Errorf("%w: nats: no responders available for request", inventory.ErrNoChain)
+	}
+	t.Cleanup(func() { askABuild = was })
+	release, err := inv.HoldPlans(ctx, true)
+	if err != nil {
+		t.Fatal(err)
+	}
+	advanceHeld(ctx, open)
+	release()
+	got, err := inv.PlanByID(ctx, "plan-bus")
+	if err != nil {
+		t.Fatal(err)
+	}
+	if got.State != inventory.PlanFailed || !strings.Contains(got.Note, "the bus did not answer an ask for 10m0s (since ") {
+		t.Fatalf("a bus silent past its bound did not fail the plan in words: %s %q", got.State, got.Note)
+	}
+
+	// Rebuilt by hand while the bus still reloads: said as waiting, not as a failure and not with an empty reason.
+	joined, said, err := joinAPlan(ctx, open, "a")
+	if err != nil || !joined || !strings.Contains(said, "not asked yet: the bus did not answer") {
+		t.Fatalf("a rebuild left for the bus is said as %v %q %v", joined, said, err)
+	}
+	// And retried by hand: the module is named as waiting, not as asked again.
+	got, _ = inv.PlanByID(ctx, "plan-bus")
+	if got.State == inventory.PlanFailed {
+		got.Modules["a"].State, got.Modules["a"].Why = "failed", "x"
+		if err := inv.SavePlan(ctx, &got); err != nil {
+			t.Fatal(err)
+		}
+		said, err := retryPlan(ctx, open, "plan-bus")
+		if err != nil || !strings.Contains(said, "not asked yet: the bus did not answer") {
+			t.Fatalf("a retry left for the bus is said as %q %v", said, err)
+		}
+	}
+}

cmd/mesh-controller/ask_bus_moment_test.go

@@ -84,6 +84,38 @@ func TestABusSilentForTenMinutesFailsTheTierAsBefore(t *testing.T) {
 	if p.State != inventory.PlanFailed || p.Modules["a"].State != "failed" {
 		t.Fatalf("a bus silent past its bound did not fail the plan: %s %+v", p.State, p.Modules["a"])
 	}
+	// Said in plain words: the bus, the wait, and since when.
+	want := "a could not be asked for: the bus did not answer an ask for 10m0s (since " + long.UTC().Format(time.RFC3339) +
+		"): this kind of record lives on the bus"
+	if !strings.HasPrefix(p.Note, want) || p.Modules["a"].Why != strings.TrimPrefix(want, "a could not be asked for: ")+p.Note[len(want):] {
+		t.Fatalf("the plan says %q, not words starting %q", p.Note, want)
+	}
+	// The wait has ended: a Retry made while the bus still reloads waits again, and does not fail at its first refusal.
+	if p.Modules["a"].BusWaitFrom != nil {
+		t.Fatalf("a failed module still holds the start of its wait: %v", p.Modules["a"].BusWaitFrom)
+	}
+	p.State = inventory.PlanBuilding
+	askModule(t.Context(), p, "a", byName)
+	if p.State != inventory.PlanBuilding || p.Modules["a"].State != "" || p.Modules["a"].BusWaitFrom == nil {
+		t.Fatalf("a retry made while the bus is silent did not wait afresh: %s %+v", p.State, p.Modules["a"])
+	}
+}
+
+func TestAPlanWithAModuleWaitingForTheBusIsOneTheLookComesBackTo(t *testing.T) {
+	p, _ := aTierOfThree()
+	if busWaiting(*p) {
+		t.Fatal("a plan whose modules are not asked yet waits for the bus")
+	}
+	now := time.Now()
+	p.Modules["b"] = &inventory.PlanModule{BusWaitFrom: &now}
+	p.Modules["a"] = &inventory.PlanModule{State: "asked"}
+	if got := busWaitingIn(*p); len(got) != 1 || got[0] != "b" {
+		t.Fatalf("the modules waiting for the bus are %v, not b", got)
+	}
+	p.State = inventory.PlanFailed
+	if busWaiting(*p) {
+		t.Fatal("a plan that is not open is waited for")
+	}
 }
 
 func TestAModulesOwnFaultStillFailsThePlan(t *testing.T) {

cmd/mesh-controller/ask_bus_wait.go

@@ -3,6 +3,8 @@ package main
 import (
 	"errors"
 	"fmt"
+	"slices"
+	"sort"
 	"strings"
 	"time"
 
@@ -46,3 +48,40 @@ func waitForTheBus(p *inventory.Plan, state *inventory.PlanModule, name string,
 		p.Tier, name, firstLine(err.Error()), busWaitBound)
 	return true
 }
+
+// busWaiting says an open plan has a module of its current tier that the bus did not answer an ask of: the look must come back
+// for it, as nothing else will when no build of the tier is in flight (issue 1334).
+func busWaiting(p inventory.Plan) bool {
+	return len(busWaitingIn(p)) > 0
+}
+
+// busWaitingIn are the modules of the plan's current tier left unasked because the bus did not answer, sorted.
+func busWaitingIn(p inventory.Plan) []string {
+	if !p.Open() || p.Tier >= len(p.Tiers) {
+		return nil
+	}
+	var out []string
+	for _, m := range p.Tiers[p.Tier] {
+		if s := p.Modules[m]; s != nil && s.State == "" && s.BusWaitFrom != nil {
+			out = append(out, m)
+		}
+	}
+	sort.Strings(out)
+	return out
+}
+
+// busWaitWords is how a verb says modules are waiting for the bus: not asked yet, and asked again by the plan at its next look.
+func busWaitWords(p inventory.Plan, modules []string) string {
+	return fmt.Sprintf("%s not asked yet: the bus did not answer; %s asks again at its next look", strings.Join(modules, ", "), p.ID)
+}
+
+// slicesWithout is names without those in drop, in order.
+func slicesWithout(names, drop []string) []string {
+	var out []string
+	for _, n := range names {
+		if !slices.Contains(drop, n) {
+			out = append(out, n)
+		}
+	}
+	return out
+}

cmd/mesh-controller/plan_retry.go

@@ -406,15 +406,23 @@ func retryPlan(ctx context.Context, open *stores, id string) (string, error) {
 			asked = append(asked, m+" as "+s.Build)
 		}
 	}
-	resumed(&p, fmt.Sprintf("tier %d retried by hand: %s asked again", p.Tier, strings.Join(failed, ", ")))
+	waiting := busWaitingIn(p)
+	resumed(&p, fmt.Sprintf("tier %d retried by hand: %s asked again", p.Tier, strings.Join(slicesWithout(failed, waiting), ", ")))
+	if len(waiting) > 0 {
+		p.Note += "; " + busWaitWords(p, waiting)
+	}
 	if err := inv.SavePlan(ctx, &p); err != nil {
 		return "", err
 	}
 	if p.State != inventory.PlanBuilding {
 		return "", fmt.Errorf("%s could not be resumed: %s", p.ID, p.Note)
 	}
-	return fmt.Sprintf("%s retried at tier %d of %d: asked %s; the plan goes on from there as any plan does",
+	said := fmt.Sprintf("%s retried at tier %d of %d: asked %s; the plan goes on from there as any plan does",
-		p.ID, p.Tier, len(p.Tiers), strings.Join(asked, ", ")), nil
+		p.ID, p.Tier, len(p.Tiers), strings.Join(asked, ", "))
+	if len(waiting) > 0 {
+		said += "; " + busWaitWords(p, waiting)
+	}
+	return said, nil
 }
 
 // joinAPlan asks a module again for the plan that holds it unbuilt or failed, if one does: open plans
@@ -460,6 +468,9 @@ func joinAPlan(ctx context.Context, open *stores, module string) (bool, string,
 	if err := inv.SavePlan(ctx, &p); err != nil {
 		return false, "", err
 	}
+	if s.State == "" && s.BusWaitFrom != nil {
+		return true, busWaitWords(p, []string{module}), nil
+	}
 	if s.State != "asked" {
 		return true, "", fmt.Errorf("%s could not be asked for %s: %s", module, p.ID, s.Why)
 	}

cmd/mesh-controller/release_plan.go

@@ -582,13 +582,20 @@ func askModule(ctx context.Context, p *inventory.Plan, name string, byName map[s
 	if err != nil {
 		// **A bus that does not answer for a moment is not a failed build** (issue 1334): the module stays unasked and the
 		// tier's next look asks it again. A fault of the module's own fails the plan at once, as does a bus silent too long.
-		if busDidNotAnswer(err) && waitForTheBus(p, state, name, err, now) {
+		reason := err.Error()
+		if busDidNotAnswer(err) {
+			if waitForTheBus(p, state, name, err, now) {
 				return
 			}
+			reason = fmt.Sprintf("the bus did not answer an ask for %s (since %s): %s", busWaitBound,
+				state.BusWaitFrom.UTC().Format(time.RFC3339), firstLine(err.Error()))
+		}
+		// The wait has ended: a Retry or a rebuild waits for the bus afresh.
+		state.BusWaitFrom = nil
 		state.State = "failed"
-		state.Why = err.Error()
+		state.Why = reason
 		p.State = inventory.PlanFailed
-		p.Note = fmt.Sprintf("%s could not be asked for: %v", name, err)
+		p.Note = fmt.Sprintf("%s could not be asked for: %s", name, reason)
 		return
 	}
 	state.BusWaitFrom = nil
@@ -816,6 +823,11 @@ func advanceHeld(ctx context.Context, open *stores) (failed bool) {
 			if p.State == inventory.PlanFailed {
 				sayUnsent(p, rollsOut)
 			}
+			// A module the bus did not answer an ask of is asked again by a look, and no event may bring one (a tier all
+			// refused has no build in flight): the look fails, so the looker retries it from five seconds (issue 1334).
+			if busWaiting(*p) {
+				failed = true
+			}
 			if planSnapshot(*p) != before {
 				if err := inv.SavePlan(ctx, p); err != nil {
 					fmt.Printf("%s: cannot keep the plan: %v\n", p.ID, err)