mesh-delivery/modules/mesh-delivery-builder/buildrun/asks_test.go

package buildrun

import (
	"context"
	"encoding/json"
	"errors"
	"fmt"
	"slices"
	"strings"
	"sync"
	"testing"
	"time"

	"github.com/nats-io/nats.go"

	"git.novox.be/novox/mesh-delivery/sdk/buildstep"
	"git.novox.be/novox/mesh-sdk/go/busretry"
	"git.novox.be/novox/mesh-sdk/go/health"
)

func goAsk(id string) buildstep.StepAsk {
	return buildstep.StepAsk{ID: id, Kind: buildstep.AskDelivery, Language: buildstep.AskGo, Asker: "mesh-delivery-builder", At: time.Now(),
		Build: &buildstep.BuildJob{Module: "m", Path: ".", Fetch: &buildstep.Fetch{Repository: "novox/x", Commit: strings.Repeat("a", 40)},
			Artifacts: []buildstep.AskArtifact{{Artifact: "program"}}}}
}

// 1887/A4a: an asker puts the ask once and answers the step a build node wrote for it, naming the node; one that did not
// pass is an error naming the node and why; a wait of an ask already put puts nothing.
func TestAnAskerPutsOnceAndReadsTheStep(t *testing.T) {
	f := &FakeAsks{Answer: func(a buildstep.StepAsk) buildstep.Step {
		return buildstep.Step{ID: a.ID, Node: "ace", State: buildstep.StepPassed, Result: []byte(`{"artifacts":[]}`)}
	}}
	k := Asker{Publisher: f, Waiter: f}
	var seen, also []buildstep.Step // issue 1890: a waiter that asks to see each value of the step sees it
	// Issue 1921: a second seen on the same context (a check's begin bound inside a try) is added, never in place of the first.
	both := WithStepSeen(WithStepSeen(context.Background(), func(s buildstep.Step) { seen = append(seen, s) }),
		func(s buildstep.Step) { also = append(also, s) })
	step, err := k.Ask(both, goAsk("mvl0frv18d1957"))
	if err != nil || step.Node != "ace" || len(f.Asks()) != 1 || len(seen) != 1 || seen[0].Node != "ace" || len(also) != 1 {
		t.Fatalf("step %+v, %v, asks %d, seen %+v and %+v", step, err, len(f.Asks()), seen, also)
	}
	f.Answer = func(a buildstep.StepAsk) buildstep.Step {
		return buildstep.Step{ID: a.ID, Node: "shanks", State: buildstep.StepRefused, Reason: "go 1.27 installed"}
	}
	if _, err := k.Ask(context.Background(), goAsk("mvl0frv18d1958")); err == nil || !strings.Contains(err.Error(), "shanks refused: go 1.27 installed") {
		t.Fatalf("a refused step: %v", err)
	}
	// Issue 1966 (ADR 0668 §1, §2; 1748 note 27): the put is a kept call under the ask's id, made again through a deadline and
	// no responders until the stream takes it; a refusal of the stream is not made again; a put that meets a transport fault
	// past the bound says it in buildstep.TransportFaultWords, so the key it fails is the hand tool's to build again.
	t.Cleanup(busretry.Waits(time.Second, time.Millisecond, time.Millisecond))
	for name, c := range map[string]struct {
		faults    []error
		tries     int
		transport bool
	}{
		"a deadline, then no responders, then taken": {faults: []error{context.DeadlineExceeded, nats.ErrNoResponders}, tries: 3},
		"refused by the stream":                      {faults: []error{errors.New("maximum messages exceeded")}, tries: 1},
		"a deadline past the bound":                  {faults: slices.Repeat([]error{nats.ErrTimeout}, 10000), transport: true},
	} {
		p := &faultyPuts{faults: c.faults, inner: &FakeAsks{}}
		restore := func() {}
		if c.transport {
			restore = busretry.Waits(20*time.Millisecond, time.Millisecond, time.Millisecond) // a bound this row passes
		}
		err := (Asker{Publisher: p, Waiter: p.inner}).Put(context.Background(), goAsk("mvl0frv18d1960"))
		restore()
		switch {
		case c.transport:
			if err == nil || !strings.HasPrefix(err.Error(), buildstep.TransportFaultWords) {
				t.Errorf("%s: %v, want it opens with the transport fault's words", name, err)
			}
		case c.tries == 1:
			if err == nil || p.tries != 1 || strings.Contains(err.Error(), buildstep.TransportFaultWords) {
				t.Errorf("%s: %v after %d tries, want one try and no transport fault", name, err, p.tries)
			}
		case err != nil || p.tries != c.tries || len(p.inner.Asks()) != 1 || len(p.ids) != c.tries || p.ids[0] != p.ids[len(p.ids)-1]:
			t.Errorf("%s: %v after %d tries under %v, %d asks taken, want %d tries under one id, one ask", name, err, p.tries, p.ids, len(p.inner.Asks()), c.tries)
		}
	}
	// Issue 1748 (ADR 0664 §3): a run that ended on a transport fault is no end; the next run's end is the answer, in either
	// arrival order; three runs then failed say a transport fault on 3 runs with each node; a bus that never gives the ask
	// again ends the wait saying so.
	for name, order := range map[string][]buildstep.Step{
		"again then passed": {{ID: "mvl0frv18d1971", Node: "ace", State: buildstep.StepAgain, Run: 1, AgainAt: time.Now()}, {ID: "mvl0frv18d1971", Node: "g14", State: buildstep.StepPassed, Run: 2}},
		"passed then again": {{ID: "mvl0frv18d1971", Node: "g14", State: buildstep.StepPassed, Run: 2}, {ID: "mvl0frv18d1971", Node: "ace", State: buildstep.StepAgain, Run: 1, AgainAt: time.Now()}},
	} {
		h := &FakeAsks{}
		for _, st := range order {
			h.Write(st)
		}
		if got, err := (Asker{Publisher: h, Waiter: h, Bound: time.Minute}).Wait(context.Background(), goAsk("mvl0frv18d1971")); err != nil || got.State != buildstep.StepPassed {
			t.Errorf("%s: %+v, %v", name, got, err)
		}
	}
	h := &FakeAsks{}
	for i, node := range []string{"ace", "g14", "shanks"} {
		st := buildstep.Step{ID: "mvl0frv18d1972", Node: node, State: buildstep.StepAgain, Run: i + 1, AgainAt: time.Now()}
		if i == 2 {
			st.State, st.Passing, st.Reason = buildstep.StepFailed, true, "lookup proxy: i/o timeout"
		}
		h.Write(st)
	}
	if _, err := (Asker{Publisher: h, Waiter: h, Bound: time.Minute}).Ask(context.Background(), goAsk("mvl0frv18d1972")); err == nil || !strings.Contains(err.Error(), "a transport fault on 3 runs (ace, g14, shanks): lookup proxy: i/o timeout") {
		t.Errorf("three runs then failed: %v", err)
	}
	h = &FakeAsks{}
	h.Write(buildstep.Step{ID: "mvl0frv18d1973", Node: "ace", State: buildstep.StepAgain, Run: 1, AgainAt: time.Now(), Started: time.Now()})
	if _, err := (Asker{Publisher: h, Waiter: h, Bound: 20 * time.Millisecond}).Wait(context.Background(), goAsk("mvl0frv18d1973")); err == nil || !strings.Contains(err.Error(), "given again after a transport fault") {
		t.Errorf("an ask never given again: %v", err)
	}
	// ADR 0664 §5: that ask is dropped; a wait ended by a named cause is dropped too, an ask no node took included (it waits in
	// its stream); a shutdown's plain cancel is not.
	drops := &seatDrops{}
	h = &FakeAsks{}
	h.Write(buildstep.Step{ID: "mvl0frv18d1974", Node: "ace", State: buildstep.StepAgain, Run: 1, AgainAt: time.Now(), Started: time.Now()})
	(Asker{Publisher: h, Waiter: h, Bound: 20 * time.Millisecond, Dropper: drops}).Wait(context.Background(), goAsk("mvl0frv18d1974"))
	named, stop := context.WithCancelCause(context.Background())
	h.Write(buildstep.Step{ID: "mvl0frv18d1975", Node: "g14", State: buildstep.StepRunning, Started: time.Now()})
	seenStep := WithStepSeen(named, func(buildstep.Step) { stop(Withdrawn{Why: "superseded by a newer fingerprint"}) })
	(Asker{Publisher: h, Waiter: h, Bound: time.Hour, Dropper: drops}).Wait(seenStep, goAsk("mvl0frv18d1975"))
	shut, off := context.WithCancel(context.Background())
	off()
	(Asker{Publisher: h, Waiter: h, Bound: time.Hour, Dropper: drops}).Wait(shut, goAsk("mvl0frv18d1977"))
	(Asker{Publisher: &FakeAsks{}, Waiter: &FakeAsks{}, Bound: time.Hour, Dropper: drops}).Wait(named, goAsk("mvl0frv18d1976"))
	// Review 1 (finding 1): a cause that is no withdrawal (the builder's check bound passing, which waits on) drops nothing.
	bounded, passed := context.WithCancelCause(context.Background())
	passed(errors.New("the check bound passed"))
	(Asker{Publisher: &FakeAsks{}, Waiter: &FakeAsks{}, Bound: time.Hour, Dropper: drops}).Wait(bounded, goAsk("mvl0frv18d1978"))
	if got := strings.Join(drops.got, "|"); !strings.Contains(got, "mvl0frv18d1974") || !strings.Contains(got, "mvl0frv18d1975 superseded by a newer fingerprint") || !strings.Contains(got, "mvl0frv18d1976 superseded by a newer fingerprint") || len(drops.got) != 3 {
		t.Errorf("drops %q, want the ask never given again, the superseded one and the one no node took, and no other", got)
	}
	// Review 1: a wait that starts after the first runs (a builder started again) reads the last value only, and its end still says
	// how many runs; a drop that failed is said, not discarded.
	late := &FakeAsks{}
	late.Write(buildstep.Step{ID: "mvl0frv18d1979", Node: "shanks", State: buildstep.StepFailed, Passing: true, Run: 3, Reason: "lookup proxy: i/o timeout"})
	if st, err := (Asker{Publisher: late, Waiter: late, Bound: time.Minute}).Wait(context.Background(), goAsk("mvl0frv18d1979")); err != nil || !strings.Contains(st.Reason, "a transport fault on 3 runs") {
		t.Errorf("a failed step of run 3 read alone says %q (%v), want it names 3 runs", st.Reason, err)
	}
	var said []string
	bad, off2 := context.WithCancelCause(context.Background())
	off2(Withdrawn{Why: "withdrawn"})
	(Asker{Publisher: &FakeAsks{}, Waiter: &FakeAsks{}, Bound: time.Hour, Dropper: failingDrops{}, Logf: func(f string, a ...any) { said = append(said, fmt.Sprintf(f, a...)) }}).Wait(bad, goAsk("mvl0frv18d1980"))
	if len(said) != 1 || !strings.Contains(said[0], "mvl0frv18d1980") || !strings.Contains(said[0], "no holder") {
		t.Errorf("a drop that failed said %q, want it named with its cause", said)
	}
	// review round 2 item 1: an ask that waits in its stream for a free slot is not bounded; once a node writes its step
	// running, the step is bounded from its start, and the error names the node.
	g := &FakeAsks{}
	k = Asker{Publisher: g, Waiter: g, Bound: 20 * time.Millisecond}
	waiting, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond)
	defer cancel()
	if _, err := k.Wait(waiting, goAsk("mvl0frv18d1959")); err != context.DeadlineExceeded {
		t.Fatalf("an ask no node took: %v, want it still waiting when ctx ended", err)
	}
	g.Write(buildstep.Step{ID: "mvl0frv18d1961", Node: "ace", State: buildstep.StepRunning, Started: time.Now()})
	if _, err := k.Wait(context.Background(), goAsk("mvl0frv18d1961")); err == nil || !strings.Contains(err.Error(), "on ace did not end within") {
		t.Fatalf("a step that never ends: %v", err)
	}
	if len(g.Asks()) != 0 {
		t.Fatal("a wait put an ask")
	}
	// Issue 1930: the bound is on a step that stands still, not on its age. A step past one bound from its start that entered a
	// new phase inside the bound is waited for until it ends; one that stood a whole bound in a phase fails at once, naming
	// the phase; one three bounds from its start ends, said as kept moving. The steps' own times stand for the clock, so the
	// bound is an hour no loaded machine reaches and no case waits on a pause (the check of 2026-11-02 22:35 tripped one
	// of 60 ms).
	k = Asker{Publisher: g, Waiter: g, Bound: time.Hour}
	now := time.Now()
	g.Write(buildstep.Step{ID: "mvl0frv18d1980", Node: "ace", State: buildstep.StepRunning, Started: now.Add(-90 * time.Minute), Phase: "pb", PhaseAt: now})
	g.Write(buildstep.Step{ID: "mvl0frv18d1980", Node: "ace", State: buildstep.StepPassed})
	if step, err := k.Wait(context.Background(), goAsk("mvl0frv18d1980")); err != nil || step.State != buildstep.StepPassed {
		t.Fatalf("a step that kept moving past its bound: %+v, %v", step, err)
	}
	g.Write(buildstep.Step{ID: "mvl0frv18d1981", Node: "ace", State: buildstep.StepRunning, Started: now.Add(-time.Hour), Phase: "integration: tests", PhaseAt: now.Add(-time.Hour)})
	if _, err := k.Wait(context.Background(), goAsk("mvl0frv18d1981")); err == nil || !strings.Contains(err.Error(), `stood still in "integration: tests"`) {
		t.Fatalf("a step that stood still in a phase: %v", err)
	}
	g.Write(buildstep.Step{ID: "mvl0frv18d1982", Node: "ace", State: buildstep.StepRunning, Started: now.Add(-3 * time.Hour), Phase: "qz", PhaseAt: now})
	if _, err := k.Wait(context.Background(), goAsk("mvl0frv18d1982")); err == nil || !strings.Contains(err.Error(), "kept moving") {
		t.Fatalf("a step that never stops moving: %v", err)
	}
	// Issue 734: an ask the build seat gave up on (DEAD_LETTERS keeps its copy with the ask's id) ends its wait as failed
	// with the words, though a node had taken it; under NotTakenBound one no node takes ends at the bound; a step written
	// first is answered as the node wrote it.
	dead := &DeadLetters{}
	lw := LostAskWaiter{Inner: g, Dead: dead}
	k = Asker{Publisher: g, Waiter: lw, Bound: time.Minute}
	g.Write(buildstep.Step{ID: "mvl0frv18d1970", Node: "ace", State: buildstep.StepRunning, Started: time.Now()})
	given, ok := GivenUpOf(map[string][]string{"Mesh-Dead-Msg-Id": {"mvl0frv18d1970"}, "Mesh-Dead-Deliveries": {"5"},
		"Mesh-Dead-Stream": {"SEAT_NODE_BUILD_GO"}, "Mesh-Dead-Gave-Up": {"2026-10-26T12:26:40Z"}})
	if !ok {
		t.Fatal("a dead letter's headers were not read")
	}
	go dead.Heard(given)
	step, err = k.Wait(context.Background(), goAsk("mvl0frv18d1970"))
	if err != nil || step.State != buildstep.StepFailed || !IsLost(step) ||
		!strings.Contains(step.Reason, LostWords+" after 5 deliveries at 2026-10-26T12:26:40Z") {
		t.Fatalf("a given-up ask: %+v, %v", step, err)
	}
	if _, err := k.Passed(step, nil); err == nil || !strings.Contains(err.Error(), "on "+LostNode+" failed: "+LostWords) {
		t.Fatalf("a given-up ask's error: %v", err)
	}
	step, err = k.Wait(NotTakenBound(context.Background(), 20*time.Millisecond), goAsk("mvl0frv18d1971"))
	if err != nil || !IsNotTaken(step) || IsLost(step) {
		t.Fatalf("an ask no node took: %+v, %v", step, err)
	}
	g.Write(buildstep.Step{ID: "mvl0frv18d1972", Node: "g14", State: buildstep.StepPassed})
	if step, err = k.Wait(NotTakenBound(context.Background(), time.Minute), goAsk("mvl0frv18d1972")); err != nil || step.Node != "g14" {
		t.Fatalf("a step written: %+v, %v", step, err)
	}
	// Review round 1 of issue 734: a hearing the bus refuses at start is deaf and says so, never holds the start up, and
	// tries again on the next ask waited for; heard, it says so and hands the given-up asks on.
	fol := &refusingFollower{refuse: 1}
	var mu sync.Mutex
	var told []Hearing
	hearing := NewDeadLetterHearing(context.Background(), fol, []string{buildstep.AskGo}, dead, nil,
		func(h Hearing) { mu.Lock(); told = append(told, h); mu.Unlock() })
	hearing.Wait()
	if why := hearing.Deaf(); !strings.Contains(why, "SEAT_NODE_BUILD_GO: permissions violation") {
		t.Fatalf("a refused hearing says %q", why)
	}
	k = Asker{Publisher: g, Waiter: LostAskWaiter{Inner: g, Dead: dead, Hearing: hearing}, Bound: time.Minute}
	g.Write(buildstep.Step{ID: "mvl0frv18d1973", Node: "g14", State: buildstep.StepPassed})
	if _, err := k.Wait(context.Background(), goAsk("mvl0frv18d1973")); err != nil {
		t.Fatal(err)
	}
	hearing.Wait()
	mu.Lock()
	if hearing.Deaf() != "" || len(told) != 2 || told[0].Heard || !told[1].Heard || fol.calls() != 2 {
		t.Fatalf("after an ask: deaf %q, told %+v, followed %d times", hearing.Deaf(), told, fol.calls())
	}
	mu.Unlock()
	fol.heard(GivenUp{AskID: "mvl0frv18d1974", Deliveries: 5})
	step, err = k.Wait(context.Background(), goAsk("mvl0frv18d1974"))
	if err != nil || !IsLost(step) {
		t.Fatalf("an ask heard given up after the hearing came back: %+v, %v", step, err)
	}
	// The lost check of 2026-10-28: a step whose own watch went deaf is read at the next nudge (a step of its build module
	// ended) and answered; a nudge of another build module reads nothing; a watch that closes is opened again.
	d := &FakeAsks{}
	heard := &HeardEnds{Inner: deafWatch{}, Read: d}
	k = Asker{Publisher: d, Waiter: heard, Bound: time.Minute}
	d.Write(buildstep.Step{ID: "mvl0frv18d1980", Node: "shanks", State: buildstep.StepPassed})
	got := make(chan buildstep.Step, 1)
	go func() { s, _ := k.Wait(context.Background(), goAsk("mvl0frv18d1980")); got <- s }()
	for heard.Waiting() == 0 {
		time.Sleep(time.Millisecond)
	}
	heard.Nudge(NodeBuildModule)
	select {
	case s := <-got:
		t.Fatalf("a nudge of another build module answered %+v", s)
	case <-time.After(20 * time.Millisecond):
	}
	heard.Nudge(GoBuildModule)
	if s := <-got; s.State != buildstep.StepPassed || s.Node != "shanks" {
		t.Fatalf("a step its watch never handed over: %+v", s)
	}
	closing := &HeardEnds{Inner: &closingWatch{inner: d}, Read: d}
	if s, err := (Asker{Publisher: d, Waiter: closing}).Wait(context.Background(), goAsk("mvl0frv18d1980")); err != nil || s.State != buildstep.StepPassed {
		t.Fatalf("a watch that closed once: %+v, %v", s, err)
	}
	for _, row := range []struct {
		h    *Hearing
		want string
	}{{nil, health.StateUnhealthy}, {&told[0], health.StateUnhealthy}, {&told[1], health.StateHealthy}} {
		var raw []byte
		if row.h != nil {
			raw, _ = json.Marshal(row.h)
		}
		if a := HearingHealth(raw); a.State != row.want || a.Why == "" {
			t.Errorf("health of %+v = %+v, want %s", row.h, a, row.want)
		}
	}
}

// Review (issue 734 path): an ask taken again by the same node (its build module replaced mid-run) is bounded from the
// new run's start, not the first run's. The steps' own times stand for the clock: the first run started now, the second a
// whole bound ago, so the wait ends at once on the second run's bound where the first run's would wait an hour; no case
// waits on a pause a loaded machine can outlast (the check of 2026-11-02 22:35 tripped one of 60 ms). The context's
// bound is reached only by a wait that kept the first run's start.
func TestARedeliveryToTheSameNodeRestartsTheBound(t *testing.T) {
	f := &FakeAsks{}
	k := Asker{Publisher: f, Waiter: f, Bound: time.Hour}
	const id = "mvl0frv18d1962"
	now := time.Now()
	f.Write(buildstep.Step{ID: id, Node: "ace", State: buildstep.StepRunning, Started: now})
	f.Write(buildstep.Step{ID: id, Node: "ace", State: buildstep.StepRunning, Started: now.Add(-time.Hour)})
	ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second)
	defer cancel()
	if _, err := k.Wait(ctx, goAsk(id)); err == nil || !strings.Contains(err.Error(), "on ace did not end within 1h0m0s of its start") {
		t.Fatalf("a redelivered run a bound old: %v, want its own bound to end the wait", err)
	}
}

// refusingFollower refuses the first `refuse` follows, as the bus does before the asker's grant is composed.
type refusingFollower struct {
	mu     sync.Mutex
	refuse int
	n      int
	hand   func(GivenUp)
}

func (f *refusingFollower) Follow(_ context.Context, _ string, _ time.Time, heard func(GivenUp)) (func(), error) {
	f.mu.Lock()
	defer f.mu.Unlock()
	f.n++
	if f.n <= f.refuse {
		return nil, errors.New("permissions violation")
	}
	f.hand = heard
	return func() {}, nil
}

func (f *refusingFollower) calls() int { f.mu.Lock(); defer f.mu.Unlock(); return f.n }

func (f *refusingFollower) heard(g GivenUp) { f.mu.Lock(); h := f.hand; f.mu.Unlock(); h(g) }

// deafWatch is a watch of an ask's step that stays open and hears nothing.
type deafWatch struct{}

func (deafWatch) WatchAsk(context.Context, string, string) (<-chan buildstep.Step, error) {
	return make(chan buildstep.Step), nil
}

// closingWatch closes its first watch at once, and hands the later ones to inner.
type closingWatch struct {
	inner  AskWaiter
	closed bool
}

func (c *closingWatch) WatchAsk(ctx context.Context, module, askID string) (<-chan buildstep.Step, error) {
	if !c.closed {
		c.closed = true
		ch := make(chan buildstep.Step)
		close(ch)
		return ch, nil
	}
	return c.inner.WatchAsk(ctx, module, askID)
}

// seatDrops keeps the asks an Asker dropped: "<id> <why>".
type seatDrops struct{ got []string }

func (d *seatDrops) DropAsk(_ context.Context, a buildstep.StepAsk, why string) error {
	if strings.Contains(why, "bound") {
		why = ""
	}
	d.got = append(d.got, strings.TrimSpace(a.ID+" "+why))
	return nil
}

// failingDrops is an AskDropper whose verb is not answered.
type failingDrops struct{}

func (failingDrops) DropAsk(context.Context, buildstep.StepAsk, string) error {
	return errors.New("no holder answered")
}

// faultyPuts fails its first puts with faults, then puts through inner (issue 1966).
type faultyPuts struct {
	mu     sync.Mutex
	faults []error
	tries  int
	ids    []string
	inner  *FakeAsks
}

func (p *faultyPuts) PublishAsk(ctx context.Context, subject, id string, data []byte) error {
	p.mu.Lock()
	p.tries++
	p.ids = append(p.ids, id)
	var err error
	if len(p.faults) > 0 {
		err, p.faults = p.faults[0], p.faults[1:]
	}
	p.mu.Unlock()
	if err != nil {
		return err
	}
	return p.inner.PublishAsk(ctx, subject, id, data)
}