From aed7e0c96887344950886a14d58393bfbcb247bf Mon Sep 17 00:00:00 2001 From: jochen Date: Mon, 12 Oct 2026 16:16:04 +0200 Subject: [PATCH] Read the mesh's comment verdicts as approvals, and warn on no fix timed from the log (issue 403, review 69) The forge refuses an approval of one's own pull request, so the independent reviews are comment reviews opening with "Verdict: approve at "; read only APPROVED, the review phase was never measured. A fix whose start was read back from the log was fixed before fix times were measured: it is kept and shown, never warned on. A carried value at fixing after one at diagnosing starts at its worker's active (the move), not its since (the diagnosis). --- modules/mesh-issues/README.md | 9 +- .../mesh-issues/cmd/mesh-issues/fixtime.go | 94 ++++++++++++++----- .../cmd/mesh-issues/fixtime_test.go | 92 +++++++++++++++++- 3 files changed, 168 insertions(+), 27 deletions(-) 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) }