Merge pull request 'Say a build handed out again restarted: its log, the queue and the check's verdict (issue 594, part)' (#280) from fix/594-a-replaced-agent-finishes-its-build into main

internal/link/build.go

@@ -257,6 +257,10 @@ type BuildResult struct {
 	// build; then only identical artifacts make a rebuild no move.
 	SourceFingerprint string `json:"source-fingerprint,omitempty"`
 
+	// Delivery is the how-manyth time the queue handed this ask out (BuildStart.Delivery): more than 1
+	// says the outcome is from a run started again after an earlier taker left it (novox/hq issue 594).
+	Delivery int `json:"delivery,omitempty"`
+
 	// Failed is why, when it did.
 	Failed string `json:"failed,omitempty"`
 

internal/link/builds.go

@@ -92,6 +92,31 @@ type BuildStart struct {
 	Ref        string `json:"ref,omitempty"`
 	On         string `json:"on"`
 	At         string `json:"at"`
+	// Delivery is the how-manyth time the queue handed this ask out: 1 for a first start, more for one
+	// an earlier taker left unfinished — most often a build agent replaced mid-build — and started
+	// again from the beginning (novox/hq issue 594). 0 from a machine that predates it.
+	Delivery int `json:"delivery,omitempty"`
+}
+
+// Restarted is how a build handed out again says so (novox/hq issue 594), in its log and in its check's
+// report, so a second run never reads as the first. Neutral on why: a holder replaced mid-build, a paused
+// holder handing an ask back as it arrived, and a bus that held its acknowledgements past the wait all
+// count as a hand-out. Empty for a first start.
+func Restarted(delivery int) string {
+	if delivery < 2 {
+		return ""
+	}
+	return fmt.Sprintf("restarted: handed out %d times; an earlier hand-out did not finish here, so this run "+
+		"started from the beginning", delivery)
+}
+
+// RunMarker is the short form of Restarted, for a line clipped to a few words — a check's status on the
+// forge (novox/hq issue 594): "(run 2)". Empty for a first start.
+func RunMarker(delivery int) string {
+	if delivery < 2 {
+		return ""
+	}
+	return fmt.Sprintf("(run %d)", delivery)
 }
 
 // BuildLine is one thing a build said while building.

internal/link/builds_nats.go

@@ -310,7 +310,7 @@ func (m *natsMachine) Take(ctx context.Context, do func(context.Context, Build))
 			// built. A set that cannot be read is said and the ask built: a cancel is a person's
 			// exception, and a holder that refused every build while its grant was missing would
 			// stop the mesh building for it.
-			build := &natsBuild{request: request, msg: msg, on: m.on, js: m.js, seat: m.seat}
+			build := &natsBuild{request: request, msg: msg, on: m.on, js: m.js, seat: m.seat, delivery: deliveryOf(msg)}
 			if cancelled, err := IsCancelled(m.js.Conn(), m.seat, request.ID); err != nil {
 				fmt.Fprintf(os.Stderr, "could not read whether %s was cancelled, so it is built: %v\n", request.ID, err)
 			} else if cancelled {
@@ -336,6 +336,18 @@ type natsBuild struct {
 	// seat is the role this build was taken from; what the machine says about it is that role's.
 	seat string
 	seq  int
+	// delivery is the how-manyth time the queue handed this ask out (novox/hq issue 594); 0 when the
+	// server did not say.
+	delivery int
+}
+
+// deliveryOf is how many times the queue has handed this message out, this time included.
+func deliveryOf(msg *nats.Msg) int {
+	meta, err := msg.Metadata()
+	if err != nil {
+		return 0
+	}
+	return int(meta.NumDelivered)
 }
 
 func (b *natsBuild) Request() BuildRequest { return b.request }
@@ -356,6 +368,11 @@ func (b *natsBuild) Announce(ctx context.Context, result BuildResult) error {
 	if result.Failed == "" && result.Commit != "" {
 		result.Module = ModuleOf(result.Manifest)
 	}
+	// **Which run this is** (novox/hq issue 594): stamped by the transport, which alone knows, so every
+	// outcome carries it whatever the machine's code filled in.
+	if result.Delivery == 0 {
+		result.Delivery = b.delivery
+	}
 	body, err := json.Marshal(result)
 	if err != nil {
 		return err
@@ -375,11 +392,16 @@ func (b *natsBuild) Done() error { return b.msg.Ack() }
 func (b *natsBuild) Began(ctx context.Context) error {
 	body, err := json.Marshal(BuildStart{
 		ID: b.request.ID, Repository: b.request.Repository, Path: b.request.Path,
-		Ref: b.request.Ref, On: b.on, At: time.Now().UTC().Format(time.RFC3339Nano),
+		Ref: b.request.Ref, On: b.on, At: time.Now().UTC().Format(time.RFC3339Nano), Delivery: b.delivery,
 	})
 	if err != nil {
 		return err
 	}
+	// **A start that is a restart says so in the build's log** (novox/hq issue 594): a reader following
+	// the build sees why it began again, never a silent second run.
+	if said := Restarted(b.delivery); said != "" {
+		b.Say("restarted", said)
+	}
 	publish, cancel := context.WithTimeout(ctx, 30*time.Second)
 	defer cancel()
 	if _, err := b.js.Context().Publish(BuildStartedOf(b.seat), body, nats.Context(publish)); err != nil {

internal/link/builds_nats_test.go

@@ -401,3 +401,97 @@ func TestNatsAHolderSaysItTakesWorkOnceItIsBound(t *testing.T) {
 		t.Fatal("a machine that could not bind said it takes work")
 	}
 }
+
+// **An ask handed out again says so** (novox/hq issue 594). A build agent replaced mid-build leaves its
+// ask unsettled, and the queue hands it out again to start over from the beginning. That second start
+// must not look like a first one: the machine that takes it says it restarted — in its started event,
+// in the build's log and in its outcome — so the queue and the pull request can say it too.
+func TestNatsAnAskHandedOutAgainSaysItRestarted(t *testing.T) {
+	js := aBusWithTheBuildRole(t)
+	ctx, stop := context.WithCancel(context.Background())
+	defer stop()
+
+	started, err := js.Conn().SubscribeSync(BuildStarted())
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer func() { _ = started.Unsubscribe() }()
+	lines, err := js.Conn().SubscribeSync(BuildLog("b-594"))
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer func() { _ = lines.Unsubscribe() }()
+	outcomes, err := js.Conn().SubscribeSync(BuildOutcome())
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer func() { _ = outcomes.Unsubscribe() }()
+	_ = js.Conn().Flush()
+
+	body, _ := json.Marshal(BuildRequest{ID: "b-594", Repository: "/r"})
+	if _, err := js.Context().Publish(BuildWork(), body); err != nil {
+		t.Fatal(err)
+	}
+
+	machine := MachineOverNATS(js, "anchor")
+	defer machine.Close()
+	var first sync.Once
+	go func() {
+		_ = machine.Take(ctx, func(ctx context.Context, work Build) {
+			_ = work.Began(ctx)
+			handedBack := false
+			// The first time it is left unfinished — an agent replaced mid-build — and comes back.
+			first.Do(func() { _ = work.Hold(100 * time.Millisecond); handedBack = true })
+			if handedBack {
+				return
+			}
+			_ = work.Announce(ctx, BuildResult{ID: work.Request().ID, On: "anchor"})
+			_ = work.Done()
+		})
+	}()
+
+	var starts []BuildStart
+	for len(starts) < 2 {
+		msg, err := started.NextMsg(10 * time.Second)
+		if err != nil {
+			t.Fatalf("heard %d start(s) of an ask handed out twice: %v", len(starts), err)
+		}
+		var s BuildStart
+		if err := json.Unmarshal(msg.Data, &s); err != nil {
+			t.Fatal(err)
+		}
+		starts = append(starts, s)
+	}
+	if starts[0].Delivery != 1 || starts[1].Delivery != 2 {
+		t.Fatalf("the starts say deliveries %d and %d, want 1 and 2: a restart reads as a first start",
+			starts[0].Delivery, starts[1].Delivery)
+	}
+
+	msg, err := outcomes.NextMsg(10 * time.Second)
+	if err != nil {
+		t.Fatal(err)
+	}
+	var result BuildResult
+	if err := json.Unmarshal(msg.Data, &result); err != nil {
+		t.Fatal(err)
+	}
+	if result.Delivery != 2 {
+		t.Fatalf("the outcome says delivery %d, want 2: the pull request cannot say the check restarted",
+			result.Delivery)
+	}
+
+	sawRestarted := false
+	for {
+		msg, err := lines.NextMsg(time.Second)
+		if err != nil {
+			break
+		}
+		var line BuildLine
+		if json.Unmarshal(msg.Data, &line) == nil && line.Step == "restarted" {
+			sawRestarted = true
+		}
+	}
+	if !sawRestarted {
+		t.Fatal("the build's log never said it restarted")
+	}
+}

internal/link/queue.go

@@ -73,6 +73,9 @@ type QueuedAsk struct {
 	On      string    `json:"on,omitempty"`
 	Was     string    `json:"was-on,omitempty"`
 	Started time.Time `json:"started,omitempty"`
+	// Delivery is the how-manyth time the ask was handed out, as its latest start said: more than 1 is
+	// a build started again after an earlier taker left it (novox/hq issue 594).
+	Delivery int `json:"delivery,omitempty"`
 }
 
 // Queue is the seat's work queue as it stands.
@@ -162,7 +165,7 @@ func ClassifyQueue(asks []QueuedAsk, delivered uint64, ackPending int, heard Bui
 		}
 		a.State = AskDead
 		if s, ok := current[a.ID]; ok {
-			a.On, a.Started = s.On, startedAt(s)
+			a.On, a.Started, a.Delivery = s.On, startedAt(s), s.Delivery
 			running = append(running, i)
 			continue
 		}
@@ -183,7 +186,7 @@ func ClassifyQueue(asks []QueuedAsk, delivered uint64, ackPending int, heard Bui
 		for _, i := range group {
 			if slots == 0 {
 				// Past what the worker counts: handed out as often as it may be.
-				out[i].On, out[i].Started = "", time.Time{}
+				out[i].On, out[i].Started, out[i].Delivery = "", time.Time{}, 0
 				continue
 			}
 			out[i].State = AskInFlight