Read the mesh's comment verdicts as approvals, and warn on no fix timed from the log (issue 403, review 69)
mesh/delivery-group group fix/403-fix-time checking: composed check out of date: novox/mesh-controller@7ca5a45ecc5a was judged against trunk ?, the trunk is no…
mesh/merge-gate out of date: judged against trunk 2fe5601397ae, the trunk is now 0863ec2a059d; judged again on a recheck or when it is merged
mesh/repo-check out of date: judged against trunk 2fe5601397ae, the trunk is now 0863ec2a059d; judged again on a recheck or when it is merged
mesh/delivery superseded: a newer head of the same pull request

The forge refuses an approval of one's own pull request, so the independent
reviews are comment reviews opening with "Verdict: approve at <sha>"; 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).
This commit is contained in:
jochen
2026-10-12 16:16:04 +02:00
parent 43df7ebc5a
commit aed7e0c968
3 changed files with 168 additions and 27 deletions
+72 -22
View File
@@ -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
// <sha>", 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 <sha>", 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) {
@@ -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 := &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)
}
}
@@ -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)
}