diff --git a/modules/mesh-issues/README.md b/modules/mesh-issues/README.md index e379c98a..33287bf0 100644 --- a/modules/mesh-issues/README.md +++ b/modules/mesh-issues/README.md @@ -146,8 +146,11 @@ its bundle cannot raise a controller condition (hq ADR 0240 rule 8, ADR 0256), s ## A fix's time (hq ADR 0313) An issue's **fix time** runs from its first move to `fixing` (kept as `fixing-from`; a take-over or a later move -back to `fixing` does not restart it, and an issue moved before the moment was kept has it read from its log) to the -moment the last of its fixes is delivered. Once every fix it names is delivered, `get` carries it as `fix-time`: +back to `fixing` does not restart it) to the moment the last of its fixes is delivered. An issue moved before the +moment was kept has it read from its log: a move's own moment, or, for a value carried into the log after one at +another status, its worker's `active` (the move), never its worker's `since`, which a diagnosis first keeps. Such a +fix time says `from-log`: it is kept and shown, and never warned on, so the first fixes heard of after the tracker +starts measuring raise no warning for work done before it. Once every fix it names is delivered, `get` carries it as `fix-time`: `from`, `end`, `took`, the issue's `class`, its **fix budget** (`budget`: five minutes for a leaf module, ten for a core one, counted from the move to `fixing`), `over`, the fix delivered last (`fix`), the `worker`, and four `phases` read from that fix, which add up to the fix time: @@ -155,7 +158,7 @@ core one, counted from the move to `fixing`), `over`, the fix delivered last (`f | phase | ends at | read from | |---|---|---| | implementing | its pull request opened | mesh-delivery's `opened` (the pull request's first head heard) | -| review | the first approval at its head | the forge's reviews (`gitea_pull_reviews`) | +| review | the first approval at its head | the forge's reviews (`gitea_pull_reviews`): the forge's own approval, or a comment review whose first line is `Verdict: approve at `, the sha the head it was posted at or a prefix of at least seven characters (the forge refuses an approval of one's own pull request, so the mesh's independent reviews are comments) | | checks | its merge, required checks and any wait for the merge included | mesh-delivery's `merged_at` | | merge to running | delivered | the delivery's `delivered` (its delivery time) | diff --git a/modules/mesh-issues/cmd/mesh-issues/fixtime.go b/modules/mesh-issues/cmd/mesh-issues/fixtime.go index 099426ab..fd078578 100644 --- a/modules/mesh-issues/cmd/mesh-issues/fixtime.go +++ b/modules/mesh-issues/cmd/mesh-issues/fixtime.go @@ -60,6 +60,10 @@ type FixTime struct { Said string `json:"said"` // Warned says the over-budget warning was said for it on the operator's channel and not cleared since. Warned bool `json:"warned,omitempty"` + // FromLog says its start was read back from the log, not kept by the move: an issue moved to fixing before the + // tracker measured fix times. Its fix time is kept and shown, and never warned on, so the first fixes heard of + // after the tracker starts measuring raise no warning for work done before it (novox/hq issue 403). + FromLog bool `json:"from-log,omitempty"` } // FixPhase is one phase of a fix time: measured, or unknown when the moment that ends it is not known — its time is @@ -144,23 +148,29 @@ func fixPhases(start time.Time, ends []struct { return out, longest } -// startOfFixing is when an issue was first moved to fixing: the earliest of what it keeps and what its log says -// (an issue moved before the tracker kept the moment is read from its log, a value carried into the log at its -// worker's since). Zero when it never was. -func (t *Tracker) startOfFixing(is *Issue) time.Time { - var start time.Time +// startOfFixing is when an issue was first moved to fixing (ADR 0313 §1), and whether that moment came from its +// log rather than from the move that kept it: the earliest of what it keeps (fixing-from, kept by the move since the +// tracker measures fix times) and what its log says. An issue moved before the moment was kept has it read from its +// log: a move's operation says its own moment. A value carried into the log, or imported, holds the issue whole and +// no moment of its own (it is stamped when it was carried); when the value before it was not at fixing it is the +// move's own write, and its worker's active is the move's moment (a move to fixing marks its worker active), not +// its worker's since, which a move from diagnosing by the same worker keeps (ADR 0284 §6). Only a first value +// already at fixing falls back to its worker's since, the best moment the log holds for it. Zero when it never was. +func (t *Tracker) startOfFixing(is *Issue) (time.Time, bool) { + var kept time.Time if is.FixingFrom != nil { - start = *is.FixingFrom + kept = is.FixingFrom.UTC() } if t.Log == nil { - return start + return kept, false } entries, err := t.readKey(is.Number, 0) if err != nil { t.Logf("[mesh-issues] the log of %d could not be read for its first move to fixing (its kept moment is used): %v", is.Number, err) - return start + return kept, false } - status := "" + var logged time.Time + status, seen := "", false for _, e := range entries { var op Operation if json.Unmarshal(e.Value, &op) != nil { @@ -170,8 +180,13 @@ func (t *Tracker) startOfFixing(is *Issue) time.Time { switch { case op.Issue != nil: became = op.Issue.Status - if op.Issue.Worker != nil && !op.Issue.Worker.Since.IsZero() { - at = op.Issue.Worker.Since + if w := op.Issue.Worker; w != nil { + switch { + case seen && status != StatusFixing && !w.Active.IsZero(): + at = w.Active + case !w.Since.IsZero(): + at = w.Since + } } case op.Set["status"] != nil: _ = json.Unmarshal(op.Set["status"], &became) @@ -179,14 +194,18 @@ func (t *Tracker) startOfFixing(is *Issue) time.Time { continue } if became == StatusFixing && status != StatusFixing && !at.IsZero() { - if start.IsZero() || at.Before(start) { - start = at.UTC() - } + logged = at.UTC() break } - status = became + status, seen = became, true } - return start + switch { + case kept.IsZero(): + return logged, !logged.IsZero() + case !logged.IsZero() && logged.Before(kept): + return logged, true + } + return kept, false } // fixTimeOf is an issue's fix time once every fix it names is delivered; nil, with why, when it is not measured. @@ -194,7 +213,7 @@ func (t *Tracker) fixTimeOf(is *Issue) (*FixTime, string) { if !allDelivered(is) { return nil, "not every fix is delivered" } - start := t.startOfFixing(is) + start, fromLog := t.startOfFixing(is) if start.IsZero() { return nil, "it was never moved to fixing" } @@ -213,7 +232,8 @@ func (t *Tracker) fixTimeOf(is *Issue) (*FixTime, string) { if end.After(start) { took = end.Sub(start) } - ft := &FixTime{From: start, End: end, TookMS: took.Milliseconds(), Took: took.Round(time.Second).String(), Fix: last.PullRequest} + ft := &FixTime{From: start, End: end, TookMS: took.Milliseconds(), Took: took.Round(time.Second).String(), Fix: last.PullRequest, + FromLog: fromLog} if is.Worker != nil { ft.Worker = is.Worker.By } else if is.FixTime != nil { @@ -274,6 +294,9 @@ func (t *Tracker) fixTimeOf(is *Issue) (*FixTime, string) { if ft.Longest != "" { said = append(said, "longest: "+ft.Longest) } + if fromLog { + said = append(said, "its start was read from its log (moved to fixing before fix times were measured), so it is never warned on") + } ft.Said = strings.Join(said, "; ") return ft, "" } @@ -351,7 +374,7 @@ func (t *Tracker) judgeFixBudgets() error { } ft := newest.FixTime if ft.Over { - if ft.Warned { + if ft.Warned || ft.FromLog { continue } worker := ft.Worker @@ -542,13 +565,18 @@ func (t *Tracker) FixTimes(days int) (*FixTimes, error) { return a, nil } -// firstApproval is when a pull request was first approved at its head among the forge's reviews: an approval -// dismissed, or of an older head, does not count. +// firstApproval is when a pull request was first approved at its head among the forge's reviews: the forge's own +// approval, or — the forge refusing an approval of one's own pull request, so the mesh's independent reviews are +// posted as comments by the account that opened it — a comment review whose first line is "Verdict: approve at +// ", the sha the head it was posted at or a prefix of it of at least seven characters. An approval dismissed, +// stale, or of an older head does not count. func firstApproval(raw json.RawMessage) (time.Time, bool, error) { var a struct { Reviews []struct { State string `json:"state"` AtHead bool `json:"at_head"` + Commit string `json:"commit"` + Body string `json:"body"` Submitted string `json:"submitted"` Stale bool `json:"stale"` Dismissed bool `json:"dismissed"` @@ -571,7 +599,16 @@ func firstApproval(raw json.RawMessage) (time.Time, bool, error) { } var first time.Time for _, r := range a.Reviews { - if r.State != "APPROVED" || !r.AtHead || r.Stale || r.Dismissed { + if !r.AtHead || r.Stale || r.Dismissed { + continue + } + switch r.State { + case "APPROVED": + case "COMMENT": + if !verdictApproves(r.Body, r.Commit) { + continue + } + default: continue } at, err := time.Parse(time.RFC3339, r.Submitted) @@ -585,6 +622,19 @@ func firstApproval(raw json.RawMessage) (time.Time, bool, error) { return first, !first.IsZero(), nil } +// verdictApproves says whether a review's body opens with the mesh's approving verdict on the commit it was posted +// at: "Verdict: approve at ", the sha that commit or a prefix of it of at least seven characters. +func verdictApproves(body, commit string) bool { + line, _, _ := strings.Cut(strings.TrimLeft(body, " \t\r\n"), "\n") + rest, ok := strings.CutPrefix(strings.TrimSpace(line), "Verdict: approve at ") + if !ok { + return false + } + sha := strings.ToLower(strings.TrimRight(strings.TrimSpace(rest), ".")) + commit = strings.ToLower(strings.TrimSpace(commit)) + return len(sha) >= 7 && commit != "" && strings.Trim(sha, "0123456789abcdef") == "" && strings.HasPrefix(commit, sha) +} + // busApproval asks the forge's reviews of a pull request over the bus (gitea_pull_reviews). func busApproval(owner func() string) Approval { return func(repository string, number int) (time.Time, bool, error) { diff --git a/modules/mesh-issues/cmd/mesh-issues/fixtime_test.go b/modules/mesh-issues/cmd/mesh-issues/fixtime_test.go index a791e1d8..23427571 100644 --- a/modules/mesh-issues/cmd/mesh-issues/fixtime_test.go +++ b/modules/mesh-issues/cmd/mesh-issues/fixtime_test.go @@ -361,9 +361,70 @@ func TestTheStartOfAnIssueMovedBeforeItWasKeptIsReadFromItsLog(t *testing.T) { 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 := c.startOfFixing(is); !got.Equal(start) { - t.Fatalf("from the log: %s, want %s", got, start) + 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 := ¬ified{} + 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) } } @@ -379,6 +440,33 @@ func TestTheReviewEndsAtTheFirstApprovalAtItsHead(t *testing.T) { 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) }