mesh-catalog/modules/mesh-issues/cmd/mesh-issues/fixtime_test.go

package main

import (
	"encoding/json"
	"strings"
	"testing"
	"time"

	stdio "git.novox.be/novox/mesh-sdk/go"
)

// novox/hq ADR 0313 (issue 403): an issue's fix time runs from its first move to fixing to its last fix
// delivered; it is held to its class's fix budget, split into four phases that add up to it, shown in get and
// fix-times, and a fix over its budget is said on the operator's channel once final, cleared at the next of its
// class delivered within budget.

// fixClock is a harness whose clock a test moves.
type fixClock struct {
	*harness
	at time.Time
	// approvals is when each pull request was approved at its head, as the forge would say it.
	approvals map[int]time.Time
}

func newFixClock(t *testing.T) *fixClock {
	c := &fixClock{harness: newHarness(t), at: time.Date(2026, 10, 12, 9, 0, 0, 0, time.UTC), approvals: map[int]time.Time{}}
	c.Tracker.Now = func() time.Time { return c.at }
	return c
}

func (c *fixClock) approval(repository string, number int) (time.Time, bool, error) {
	a, ok := c.approvals[number]
	return a, ok, nil
}

func (c *fixClock) later(d time.Duration) time.Time { c.at = c.at.Add(d); return c.at }

// delivery says one transition of a pull request as mesh-delivery says it, with what a fix's time is read by.
func (c *fixClock) delivery(t *testing.T, number int, to, class string, opened, mergedAt *time.Time) {
	t.Helper()
	body := map[string]any{"repository": "novox/mesh-catalog", "number": number, "to": to, "at": c.at}
	if mergedAt != nil {
		body["merged_as"] = "m" + strings.Repeat("a", 11)
		body["merged_at"] = *mergedAt
	}
	if class != "" {
		body["class"] = class
	}
	if opened != nil {
		body["opened"] = *opened
	}
	raw, _ := json.Marshal(body)
	if err := c.OnTransition(stdio.Envelope{Key: "mesh-delivery.transition", Body: raw}); err != nil {
		t.Fatal(err)
	}
}

func at(t time.Time) *time.Time { return &t }

func phaseTook(t *testing.T, ft *FixTime) map[string]time.Duration {
	t.Helper()
	out := map[string]time.Duration{}
	var sum int64
	for _, p := range ft.Phases {
		out[p.Name] = time.Duration(p.TookMS) * time.Millisecond
		sum += p.TookMS
	}
	if sum != ft.TookMS {
		t.Fatalf("the phases add up to %dms, the fix time is %dms: %+v", sum, ft.TookMS, ft.Phases)
	}
	return out
}

// fixOne takes an issue through a fix: opened, moved to fixing, a pull request opened, approved, merged and
// delivered after the given spans; its fix time as kept.
func (c *fixClock) fixOne(t *testing.T, title string, pr int, class string, implementing, review, checks, running time.Duration) uint64 {
	t.Helper()
	n := c.open(t, title)
	c.fixing(t, n)
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "fix@g14", FixedBy: []string{"mesh-catalog#" + itoa(pr)}}); err != nil {
		t.Fatal(err)
	}
	opened := c.later(implementing)
	c.delivery(t, pr, "proposed", "", &opened, nil)
	approved := c.later(review)
	c.approvals[pr] = approved
	merged := c.later(checks)
	c.delivery(t, pr, "published", class, &opened, &merged)
	c.later(running)
	c.delivery(t, pr, "delivered", class, &opened, &merged)
	return n
}

func itoa(n int) string { b, _ := json.Marshal(n); return string(b) }

func TestAFixTimeRunsFromTheFirstMoveToFixingAndAddsUpItsPhases(t *testing.T) {
	c := newFixClock(t)
	c.Tracker.Approval = c.approval
	note := &notified{}
	c.Notify = note.notify

	n := c.open(t, "a fix measured")
	c.later(time.Minute)
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusDiagnosing, By: "fix@g14"}); err != nil {
		t.Fatal(err)
	}
	c.later(10 * time.Minute) // finding the cause is not the fix's time
	start := c.at
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "fix@g14", FixedBy: []string{"mesh-catalog#31"}}); err != nil {
		t.Fatal(err)
	}
	c.later(30 * time.Second)
	// A take-over, and a move away and back, restart nothing.
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "other@shanks", TakeOver: "the first worker's session ended"}); err != nil {
		t.Fatal(err)
	}
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusOpen}); err != nil {
		t.Fatal(err)
	}
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "other@shanks"}); err != nil {
		t.Fatal(err)
	}
	opened := c.later(90 * time.Second) // implementing: 2m
	c.delivery(t, 31, "proposed", "", &opened, nil)
	c.approvals[31] = c.later(time.Minute) // review: 1m
	merged := c.later(3 * time.Minute)     // checks: 3m
	c.delivery(t, 31, "published", "leaf", &opened, &merged)
	if is := get(t, c.harness, n); is.FixTime != nil {
		t.Fatalf("a fix merged and not delivered has a fix time: %+v", is.FixTime)
	}
	c.later(2 * time.Minute) // merge to running: 2m
	c.delivery(t, 31, "delivered", "leaf", &opened, &merged)

	v, err := c.View(n)
	if err != nil {
		t.Fatal(err)
	}
	ft := v.FixTime
	if ft == nil {
		t.Fatalf("no fix time once the fix is delivered: %+v", v.Issue)
	}
	if !ft.From.Equal(start) || ft.TookMS != (8*time.Minute).Milliseconds() {
		t.Fatalf("fix time from %s took %s, want from %s (the first move to fixing) and 8m0s", ft.From, ft.Took, start)
	}
	got := phaseTook(t, ft)
	if got[PhaseImplementing] != 2*time.Minute || got[PhaseReview] != time.Minute || got[PhaseChecks] != 3*time.Minute ||
		got[PhaseRunning] != 2*time.Minute {
		t.Fatalf("phases %v", got)
	}
	if ft.Class != ClassLeaf || !ft.Over || ft.Budget != "5m0s" || ft.Longest != "checks 3m0s" || ft.Worker != "other@shanks" {
		t.Fatalf("class %q over %v budget %q longest %q worker %q", ft.Class, ft.Over, ft.Budget, ft.Longest, ft.Worker)
	}
	// Over its budget: said once, naming the issue, its worker and its longest phase.
	if len(note.said) != 1 || !strings.HasPrefix(note.said[0], "issue-tracker.fix.leaf.over-budget warning issue "+itoa(int(n))) ||
		!strings.Contains(note.said[0], "checks 3m0s") {
		t.Fatalf("said %q", note.said)
	}
	// Heard again: nothing new is kept or said.
	c.delivery(t, 31, "delivered", "leaf", &opened, &merged)
	if len(note.said) != 1 {
		t.Fatalf("said again: %q", note.said)
	}
}

// A phase whose end is not known is unknown and counted in the next; one that ended before the phase before it
// counts zero (a pull request opened before the move to fixing).
func TestAPhaseNotKnownIsCountedInTheNextAndOneEndedEarlyCountsZero(t *testing.T) {
	c := newFixClock(t)
	n := c.open(t, "a fix whose pull request came first")
	opened := c.at
	c.later(time.Minute)
	c.fixing(t, n)
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "fix@g14", FixedBy: []string{"mesh-catalog#32"}}); err != nil {
		t.Fatal(err)
	}
	merged := c.later(4 * time.Minute)
	c.later(time.Minute)
	c.delivery(t, 32, "delivered", "leaf", &opened, &merged)
	ft := get(t, c.harness, n).FixTime
	if ft == nil {
		t.Fatal("no fix time")
	}
	got := phaseTook(t, ft)
	if got[PhaseImplementing] != 0 || got[PhaseChecks] != 4*time.Minute || got[PhaseRunning] != time.Minute {
		t.Fatalf("phases %v", got)
	}
	for _, p := range ft.Phases {
		if p.Name == PhaseReview && (p.State != "unknown" || p.Said == "") {
			t.Fatalf("review with no approval asked: %+v", p)
		}
		if p.Name == PhaseChecks && !strings.Contains(p.Said, "review") {
			t.Fatalf("checks does not say it counts review: %+v", p)
		}
	}
	if ft.Over {
		t.Fatalf("5m of a leaf's 5m is within it: %+v", ft)
	}
}

// The class is the slowest-budgeted of the fixes'; a fix that moves no module has no budget and is never warned
// on; one whose class is not said has none either.
func TestAnIssuesClassIsItsSlowestFixAndOneMovingNothingHasNoBudget(t *testing.T) {
	c := newFixClock(t)
	note := &notified{}
	c.Notify = note.notify

	n := c.open(t, "two fixes, one core")
	c.fixing(t, n)
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "fix@g14", FixedBy: []string{"mesh-catalog#41", "mesh-catalog#42"}}); err != nil {
		t.Fatal(err)
	}
	merged := c.later(time.Minute)
	c.delivery(t, 41, "delivered", "leaf", nil, &merged)
	if get(t, c.harness, n).FixTime != nil {
		t.Fatal("a fix time before the last fix is delivered")
	}
	c.later(7 * time.Minute)
	c.delivery(t, 42, "delivered", "core", nil, &merged)
	ft := get(t, c.harness, n).FixTime
	if ft == nil || ft.Class != ClassCore || ft.Over || ft.Fix != "mesh-catalog#42" {
		t.Fatalf("8m of a core fix: %+v", ft)
	}

	none := c.fixOne(t, "a fix in hq alone", 43, ClassNone, time.Minute, time.Minute, 10*time.Minute, time.Second)
	ft = get(t, c.harness, none).FixTime
	if ft == nil || ft.Class != ClassNone || ft.Over || ft.BudgetMS != 0 || !strings.Contains(ft.Said, "no fix budget") {
		t.Fatalf("a fix moving nothing: %+v", ft)
	}
	unknown := c.fixOne(t, "a fix whose class is not said", 44, "", time.Minute, time.Minute, 10*time.Minute, time.Second)
	ft = get(t, c.harness, unknown).FixTime
	if ft == nil || ft.Class != "" || ft.Over || !strings.Contains(ft.Said, "no fix budget") {
		t.Fatalf("a fix of no known class: %+v", ft)
	}
	if len(note.said) != 0 {
		t.Fatalf("warned on a fix with no budget: %q", note.said)
	}
}

// Nothing is said while a fix is undelivered, however long; once delivered over budget it is said; the next leaf
// fix delivered within budget clears it.
func TestAFixOverItsBudgetIsSaidOnceFinalAndClearedByTheNextWithin(t *testing.T) {
	c := newFixClock(t)
	c.Tracker.Approval = c.approval
	note := &notified{}
	c.Notify = note.notify

	n := c.open(t, "a slow fix")
	c.fixing(t, n)
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "fix@g14", FixedBy: []string{"mesh-catalog#51"}}); err != nil {
		t.Fatal(err)
	}
	merged := c.later(20 * time.Minute)
	c.delivery(t, 51, "published", "leaf", nil, &merged)
	if _, err := c.Sweep(); err != nil {
		t.Fatal(err)
	}
	if len(note.said) != 0 {
		t.Fatalf("said while undelivered: %q", note.said)
	}
	c.later(time.Minute)
	c.delivery(t, 51, "delivered", "leaf", nil, &merged)
	if len(note.said) != 1 || !strings.HasPrefix(note.said[0], fixOverKey(ClassLeaf)+" warning") {
		t.Fatalf("said %q", note.said)
	}
	if !get(t, c.harness, n).FixTime.Warned {
		t.Fatal("not marked said")
	}
	// A core fix within its budget clears nothing of the leaf's.
	c.fixOne(t, "a quick core fix", 52, ClassCore, time.Minute, time.Minute, time.Minute, time.Minute)
	if len(note.clear) != 0 {
		t.Fatalf("cleared by another class: %q", note.clear)
	}
	c.fixOne(t, "a quick leaf fix", 53, ClassLeaf, time.Minute, 30*time.Second, time.Minute, time.Minute)
	if len(note.clear) != 1 || note.clear[0] != fixOverKey(ClassLeaf) {
		t.Fatalf("cleared %q", note.clear)
	}
	if get(t, c.harness, n).FixTime.Warned {
		t.Fatal("still marked said after the clear")
	}
	if _, err := c.Sweep(); err != nil {
		t.Fatal(err)
	}
	if len(note.said) != 1 || len(note.clear) != 1 {
		t.Fatalf("the sweep said again: %q, cleared %q", note.said, note.clear)
	}
}

// A warning the channel did not take is said at the next sweep.
func TestAWarningNotTakenIsSaidAtTheNextSweep(t *testing.T) {
	c := newFixClock(t)
	note := &notified{err: errFake("the channel is away")}
	c.Notify = note.notify
	n := c.fixOne(t, "slow", 61, ClassLeaf, 5*time.Minute, time.Minute, time.Minute, time.Minute)
	if get(t, c.harness, n).FixTime == nil {
		t.Fatal("a fix time is kept although the warning was not taken")
	}
	note.err = nil
	if _, err := c.Sweep(); err != nil {
		t.Fatal(err)
	}
	if len(note.said) != 1 || !get(t, c.harness, n).FixTime.Warned {
		t.Fatalf("said %q", note.said)
	}
}

// fix-times answers each class's budget, the window's median and worst, and every issue over its budget with its
// longest phase; an issue delivered before the window does not count, so a lever is judged by the medians before
// and after it.
func TestFixTimesAnswersTheWindowsMedianAndWorst(t *testing.T) {
	c := newFixClock(t)
	old := c.fixOne(t, "long ago", 70, ClassLeaf, 30*time.Minute, time.Minute, time.Minute, time.Minute)
	c.later(8 * 24 * time.Hour)
	a := c.fixOne(t, "four minutes", 71, ClassLeaf, time.Minute, time.Minute, time.Minute, time.Minute)
	b := c.fixOne(t, "six minutes", 72, ClassLeaf, 3*time.Minute, time.Minute, time.Minute, time.Minute)
	c.fixOne(t, "eight minutes", 73, ClassLeaf, 5*time.Minute, time.Minute, time.Minute, time.Minute)
	c.fixOne(t, "a core fix", 74, ClassCore, time.Minute, time.Minute, time.Minute, time.Minute)
	c.fixOne(t, "hq alone", 75, ClassNone, time.Minute, time.Minute, time.Minute, time.Minute)

	out, err := c.call(t, "fix-times", map[string]any{})
	if err != nil {
		t.Fatal(err)
	}
	ft := out.(*FixTimes)
	leaf, core := ft.Classes[0], ft.Classes[1]
	if ft.Days != 7 || leaf.Class != ClassLeaf || leaf.Count != 3 || leaf.Median != "6m0s" || leaf.Worst != "8m0s" ||
		leaf.Within != 1 || leaf.Over != 2 || leaf.Budget != "5m0s" {
		t.Fatalf("leaf %+v (issue %d, delivered before the window, must not count)", leaf, old)
	}
	if core.Count != 1 || core.Median != "4m0s" || core.Within != 1 {
		t.Fatalf("core %+v", core)
	}
	if len(ft.Over) != 2 || ft.Over[0].Title != "eight minutes" || ft.Over[0].Longest != "implementing 5m0s" || ft.Over[1].Number != b {
		t.Fatalf("over %+v", ft.Over)
	}
	if len(ft.Unbudgeted) != 1 || ft.Unbudgeted[0].Title != "hq alone" {
		t.Fatalf("unbudgeted %+v", ft.Unbudgeted)
	}
	if !strings.Contains(ft.Line, "leaf: median 6m0s, worst 8m0s") {
		t.Fatalf("line %q", ft.Line)
	}
	// Wider, the old one counts and moves the median.
	out, _ = c.call(t, "fix-times", map[string]any{"days": 30})
	if l := out.(*FixTimes).Classes[0]; l.Count != 4 || l.Median != "7m0s" {
		t.Fatalf("over 30 days: %+v", l)
	}
	if _, err := c.call(t, "fix-times", map[string]any{"days": 91}); err == nil {
		t.Fatal("days 91 not refused")
	}
	_ = a
}

// An issue moved to fixing before the tracker kept the moment has its start read from its log.
func TestTheStartOfAnIssueMovedBeforeItWasKeptIsReadFromItsLog(t *testing.T) {
	c := newFixClock(t)
	n := c.open(t, "moved to fixing long ago")
	c.later(time.Minute)
	start := c.at
	c.fixing(t, n)
	c.later(time.Hour)
	is := get(t, c.harness, n)
	if is.FixingFrom == nil || !is.FixingFrom.Equal(start) {
		t.Fatalf("fixing-from %v, want %s", is.FixingFrom, start)
	}
	if got, fromLog := c.startOfFixing(is); !got.Equal(start) || fromLog {
		t.Fatalf("kept: %s from the log %v, want %s kept by the move", got, fromLog, start)
	}
	is.FixingFrom = nil
	if got, fromLog := c.startOfFixing(is); !got.Equal(start) || !fromLog {
		t.Fatalf("from the log: %s (from the log %v), want %s", got, fromLog, start)
	}
}

// A value carried into the log holds no moment of its own: after a value at diagnosing, the first value at fixing
// is the move's own write, and its start is its worker's active (the move), not its worker's since (the start of
// the diagnosis, ADR 0313 §1). A first value already at fixing falls back to its worker's since.
func TestACarriedIssueStartsAtTheMoveNotTheDiagnosis(t *testing.T) {
	c := newFixClock(t)
	diagnosed := time.Date(2026, 10, 1, 8, 0, 0, 0, time.UTC)
	moved := diagnosed.Add(40 * time.Minute)
	carry := func(n uint64, is Issue) {
		t.Helper()
		if _, err := c.log.AppendAt(keyOf(n), Operation{Op: OpCarried, By: Seat, At: c.at, Issue: &is}, c.log.lastOf(keyOf(n))); err != nil {
			t.Fatal(err)
		}
	}
	carry(900, Issue{Number: 900, Title: "x", Status: StatusDiagnosing, Worker: &Worker{By: "fix@g14", Since: diagnosed, Active: diagnosed}})
	carry(900, Issue{Number: 900, Title: "x", Status: StatusFixing, Worker: &Worker{By: "fix@g14", Since: diagnosed, Active: moved}})
	if got, fromLog := c.startOfFixing(&Issue{Number: 900}); !got.Equal(moved) || !fromLog {
		t.Fatalf("start %s (from the log %v), want the move at %s, not the diagnosis at %s", got, fromLog, moved, diagnosed)
	}
	carry(901, Issue{Number: 901, Title: "y", Status: StatusFixing, Worker: &Worker{By: "fix@g14", Since: diagnosed, Active: moved}})
	if got, _ := c.startOfFixing(&Issue{Number: 901}); !got.Equal(diagnosed) {
		t.Fatalf("a first value at fixing: %s, want its worker's since %s", got, diagnosed)
	}
}

// An issue moved to fixing before fix times were measured gets its fix time when its fix is next heard of, with its
// start from its log; it is kept and shown, never warned on, and leaves the class's warning to a fix measured whole.
func TestAFixWhoseStartCameFromTheLogIsNeverWarnedOn(t *testing.T) {
	c := newFixClock(t)
	note := &notified{}
	c.Notify = note.notify
	n := c.open(t, "fixed before the tracker measured")
	c.fixing(t, n)
	if _, err := c.Move(MoveAsk{Number: n, Status: StatusFixing, By: "fix@g14", FixedBy: []string{"mesh-catalog#81"}}); err != nil {
		t.Fatal(err)
	}
	// As kept before this change: no fixing-from.
	if _, err := c.change(n, Act{Op: "test", By: Seat}, func(i *Issue) error { i.FixingFrom = nil; return nil }); err != nil {
		t.Fatal(err)
	}
	merged := c.later(3 * time.Hour)
	c.delivery(t, 81, "delivered", ClassLeaf, nil, &merged)
	ft := get(t, c.harness, n).FixTime
	if ft == nil || !ft.Over || !ft.FromLog || ft.Warned || ft.TookMS != (3*time.Hour).Milliseconds() {
		t.Fatalf("fix time %+v", ft)
	}
	if _, err := c.Sweep(); err != nil {
		t.Fatal(err)
	}
	if len(note.said) != 0 {
		t.Fatalf("warned on a fix whose start came from the log: %q", note.said)
	}
	// A fix measured whole after it is warned on as before.
	c.fixOne(t, "measured whole", 82, ClassLeaf, 6*time.Minute, time.Minute, time.Minute, time.Minute)
	if len(note.said) != 1 {
		t.Fatalf("said %q", note.said)
	}
}

// The forge's reviews: the first approval at the head, never one dismissed, stale or of an older head.
func TestTheReviewEndsAtTheFirstApprovalAtItsHead(t *testing.T) {
	raw := json.RawMessage(`{"reviews":[
		{"state":"APPROVED","at_head":false,"submitted":"2026-10-12T09:01:00Z"},
		{"state":"REQUEST_CHANGES","at_head":true,"submitted":"2026-10-12T09:02:00Z"},
		{"state":"APPROVED","at_head":true,"dismissed":true,"submitted":"2026-10-12T09:03:00Z"},
		{"state":"APPROVED","at_head":true,"submitted":"2026-10-12T09:05:00Z"},
		{"state":"APPROVED","at_head":true,"submitted":"2026-10-12T09:04:00Z"}]}`)
	at, found, err := firstApproval(raw)
	if err != nil || !found || at.Format(time.RFC3339) != "2026-10-12T09:04:00Z" {
		t.Fatalf("%s %v %v", at, found, err)
	}
	// The mesh's own reviews: comments by the account that opened the pull request, whose first line is the verdict.
	head := "43df7ebc5aa21c0bceacd1580f01f67d83d3495d"
	comments := json.RawMessage(`{"reviews":[
		{"state":"COMMENT","at_head":true,"commit":"` + head + `","body":"Verdict: request changes at ` + head + `\n\nBlocking: …","submitted":"2026-10-12T09:01:00Z"},
		{"state":"COMMENT","at_head":true,"commit":"` + head + `","body":"Looks fine. Verdict: approve at ` + head + `","submitted":"2026-10-12T09:02:00Z"},
		{"state":"COMMENT","at_head":true,"commit":"` + head + `","body":"Verdict: approve at 43df7eb\n\nAll clauses hold.","submitted":"2026-10-12T09:07:00Z"},
		{"state":"COMMENT","at_head":true,"commit":"` + head + `","body":"Verdict: approve at ` + head + `\n\nAgain.","submitted":"2026-10-12T09:08:00Z"}]}`)
	at, found, err = firstApproval(comments)
	if err != nil || !found || at.Format(time.RFC3339) != "2026-10-12T09:07:00Z" {
		t.Fatalf("a comment's verdict: %s %v %v", at, found, err)
	}
	for _, c := range []struct {
		body, commit string
		approves     bool
	}{
		{"Verdict: approve at " + head, head, true},
		{"Verdict: approve at 43df7eb", head, true},
		{"Verdict: approve at 43df7e", head, false},            // shorter than seven characters
		{"Verdict: approve at 0123456789", head, false},        // another commit
		{"Verdict: request changes at " + head, head, false},   // not an approval
		{"Not yet.\nVerdict: approve at " + head, head, false}, // not the first line
		{"Verdict: approve at 43df7ebc", "", false},            // no commit to hold it to
	} {
		if got := verdictApproves(c.body, c.commit); got != c.approves {
			t.Errorf("%q at %q approves %v, want %v", c.body, c.commit, got, c.approves)
		}
	}
	if _, found, err := firstApproval(json.RawMessage(`{"reviews":[]}`)); err != nil || found {
		t.Fatalf("no reviews: %v %v", found, err)
	}
	if _, _, err := firstApproval(json.RawMessage(`"nothing"`)); err == nil {
		t.Fatal("an answer with no reviews read as none")
	}
}

type errFake string

func (e errFake) Error() string { return string(e) }