package main // A fix's time (novox/hq ADR 0313, issue 403). An issue's fix time runs from its first move to fixing to the moment // the last of its fixes is delivered to every machine it should reach. It is held to the fix budget of its class — // five minutes for a leaf module, ten for a core one — and split into four phases read from the fix delivered // last: implementing (to its pull request opened), review (to an approval at its head), checks (to its merge) and // merge to running (to delivered, its delivery time). A fix over its budget is said on the operator's channel once // it is final, naming the issue, its worker and its longest phase; the warning clears when the next issue of that // class is delivered within its budget. `fix-times` answers the last days' median and worst per class. import ( "encoding/json" "fmt" "sort" "strings" "time" stdio "git.novox.be/novox/mesh-sdk/go" ) // The classes of a fix (ADR 0282 §1, ADR 0313 §2) and the class of a fix that moves no module. const ( ClassCore = "core" ClassLeaf = "leaf" ClassNone = "none" ) // FixBudgets are the fix budgets by class, counted from the move to fixing (ADR 0313 §2). var FixBudgets = map[string]time.Duration{ClassLeaf: 5 * time.Minute, ClassCore: 10 * time.Minute} // fixClasses in the order `fix-times` says them. var fixClasses = []string{ClassLeaf, ClassCore} // The phases of a fix time, in order (ADR 0313 §4). const ( PhaseImplementing = "implementing" PhaseReview = "review" PhaseChecks = "checks" PhaseRunning = "merge to running" ) // FixTime is an issue's fix time, kept on it once the last of its fixes is delivered. type FixTime struct { // From is the first move to fixing; End when the fix delivered last was delivered. From time.Time `json:"from"` End time.Time `json:"end"` TookMS int64 `json:"took_ms"` Took string `json:"took"` // Class is core, leaf or none; empty when a fix's class is not known. A fix of class none, or one not known, // has no budget: its time is shown and never warned on. Class string `json:"class,omitempty"` Budget string `json:"budget,omitempty"` BudgetMS int64 `json:"budget_ms,omitempty"` Over bool `json:"over,omitempty"` // Fix is the pull request delivered last, which the phases are read from; Worker who worked on the issue. Fix string `json:"fix"` Worker string `json:"worker,omitempty"` Phases []FixPhase `json:"phases"` Longest string `json:"longest,omitempty"` 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 // then counted in the phase after it, which says so. type FixPhase struct { Name string `json:"name"` State string `json:"state"` TookMS int64 `json:"took_ms"` Took string `json:"took"` Said string `json:"said,omitempty"` } // Approval is when a pull request was first approved at its head, as the forge says it; a test stubs the asking. // found is false when no approval at its head is on the forge. type Approval func(repository string, number int) (at time.Time, found bool, err error) // classOfFixes is the class of an issue's fixes: that of the slowest-budgeted module they move — core when any // moves a core module, leaf when any moves a leaf one, none when none moves a module — and empty, with why, when // a fix's class is not known and none is core. func classOfFixes(is *Issue, prs []string) (string, string) { var unknown []string leaf := false for _, pr := range prs { f := fixOf(is, pr) switch { case f == nil || f.Class == "": unknown = append(unknown, pr) case f.Class == ClassCore: return ClassCore, "" case f.Class == ClassLeaf: leaf = true } } if len(unknown) > 0 { return "", "the delivery did not say what " + strings.Join(unknown, ", ") + " moves" } if leaf { return ClassLeaf, "" } return ClassNone, "" } // fixPhases splits the span from start to the delivered moment at the moments that end each phase, in order. A // phase whose end is not known is unknown, and its time counts in the next phase known; a phase whose end came // before the end of the phase before it counts zero (ADR 0313 §4). The phases add up to the fix time. func fixPhases(start time.Time, ends []struct { name string at *time.Time why string }) ([]FixPhase, string) { var out []FixPhase prev := start var carried []string for _, e := range ends { if e.at == nil { out = append(out, FixPhase{Name: e.name, State: "unknown", Took: "0s", Said: e.why}) carried = append(carried, e.name) continue } took := time.Duration(0) if e.at.After(prev) { took = e.at.Sub(prev) prev = *e.at } p := FixPhase{Name: e.name, State: "measured", TookMS: took.Milliseconds(), Took: took.Round(time.Second).String()} if len(carried) > 0 { p.Said = "counts " + strings.Join(carried, " and ") + " too: its end is not known" carried = nil } out = append(out, p) } best := -1 for i, p := range out { if p.State == "measured" && (best < 0 || p.TookMS > out[best].TookMS) { best = i } } longest := "" if best >= 0 { longest = out[best].Name + " " + out[best].Took } return out, longest } // 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 { kept = is.FixingFrom.UTC() } if t.Log == nil { 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 kept, false } var logged time.Time status, seen := "", false for _, e := range entries { var op Operation if json.Unmarshal(e.Value, &op) != nil { continue } at, became := op.At, "" switch { case op.Issue != nil: became = op.Issue.Status 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) default: continue } if became == StatusFixing && status != StatusFixing && !at.IsZero() { logged = at.UTC() break } status, seen = became, true } 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. func (t *Tracker) fixTimeOf(is *Issue) (*FixTime, string) { if !allDelivered(is) { return nil, "not every fix is delivered" } start, fromLog := t.startOfFixing(is) if start.IsZero() { return nil, "it was never moved to fixing" } prs := liveFixes(is) var last *Fix for _, pr := range prs { if f := fixOf(is, pr); f != nil && (last == nil || f.Since.After(last.Since)) { last = f } } if last == nil { return nil, "no fix is heard of" } end := last.Since.UTC() took := time.Duration(0) 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, FromLog: fromLog} if is.Worker != nil { ft.Worker = is.Worker.By } else if is.FixTime != nil { ft.Worker = is.FixTime.Worker } class, why := classOfFixes(is, prs) ft.Class = class if b, ok := FixBudgets[class]; ok { ft.Budget, ft.BudgetMS, ft.Over = b.String(), b.Milliseconds(), took > b } // The phases, from the fix delivered last. type end_ = struct { name string at *time.Time why string } var approved *time.Time approvalWhy := "no approval at its head is on the forge: review and checks are counted together" if t.Approval != nil { repo, number, _ := strings.Cut(last.PullRequest, "#") var n int if _, err := fmt.Sscanf(number, "%d", &n); err == nil { at, found, err := t.Approval(repo, n) switch { case err != nil: approvalWhy = "the forge could not be read for its approval (" + cut(err.Error(), 200) + "): review and checks are counted together" case found: a := at.UTC() approved = &a } } } else { approvalWhy = "the forge is not asked here: review and checks are counted together" } openedWhy := "the delivery did not say when its pull request opened: implementing is counted in review" mergedWhy := "the delivery did not say when it merged: checks are counted in merge to running" ft.Phases, ft.Longest = fixPhases(start, []end_{ {PhaseImplementing, last.Opened, openedWhy}, {PhaseReview, approved, approvalWhy}, {PhaseChecks, last.MergedAt, mergedWhy}, {PhaseRunning, &end, ""}, }) var said []string said = append(said, fmt.Sprintf("fixed in %s, from the first move to fixing (%s) to %s delivered (%s)", ft.Took, start.Format(time.RFC3339), last.PullRequest, end.Format(time.RFC3339))) switch { case class == ClassNone: said = append(said, "its fixes move no module, so it has no fix budget") case class == "": said = append(said, "no fix budget: "+why) case ft.Over: said = append(said, fmt.Sprintf("over its %s fix budget of %s", class, ft.Budget)) default: said = append(said, fmt.Sprintf("within its %s fix budget of %s", class, ft.Budget)) } 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, "" } // sameFixTime says whether two fix times say the same, the warning's mark aside. func sameFixTime(a, b *FixTime) bool { if a == nil || b == nil { return a == b } x, y := *a, *b x.Warned, y.Warned = false, false ra, _ := json.Marshal(x) rb, _ := json.Marshal(y) return string(ra) == string(rb) } // timeFix keeps an issue's fix time once every fix it names is delivered, and again when a later fix moves its // end; then the warnings of its class are judged. func (t *Tracker) timeFix(n uint64) error { is, _, err := read(t.Store, n) if err != nil { return err } ft, _ := t.fixTimeOf(is) if ft == nil || sameFixTime(ft, is.FixTime) { return nil } if _, err := t.change(n, Act{Op: "fix-time", By: Seat}, func(i *Issue) error { if i.FixTime != nil { ft.Warned = i.FixTime.Warned } i.FixTime = ft return nil }); err != nil { return err } if err := t.judgeFixBudgets(); err != nil { t.Logf("[mesh-issues] a fix over its budget could not be said or cleared on the operator's channel (tried again at the next sweep): %v", err) } return nil } // fixOverKey is the warning a fix over its class's budget raises (ADR 0313 §6). func fixOverKey(class string) string { return "issue-tracker.fix." + class + ".over-budget" } // judgeFixBudgets says or clears each class's warning by the newest fix time of the class (ADR 0313 §6): the newest // over its budget and not yet said is said; the newest within its budget clears what was said for the class. Run // after every fix time kept and at every sweep, so a warning that failed is said, or cleared, at the next. func (t *Tracker) judgeFixBudgets() error { if t.Notify == nil { return nil } all, err := t.allIssues() if err != nil { return err } var firstErr error for _, class := range fixClasses { var newest *Issue var warned []uint64 for _, is := range all { ft := is.FixTime if ft == nil || ft.Class != class { continue } if ft.Warned { warned = append(warned, is.Number) } if newest == nil || ft.End.After(newest.FixTime.End) || (ft.End.Equal(newest.FixTime.End) && is.Number > newest.Number) { newest = is } } if newest == nil { continue } ft := newest.FixTime if ft.Over { if ft.Warned || ft.FromLog { continue } worker := ft.Worker if worker == "" { worker = "nobody named" } longest := ft.Longest if longest == "" { longest = "not known" } if err := t.Notify(fixOverKey(class), "warning", fmt.Sprintf("issue %d: fixed in %s, over its %s fix budget of %s (longest: %s)", newest.Number, ft.Took, class, ft.Budget, longest), fmt.Sprintf("A fix took longer than its budget (issue %d)", newest.Number), fmt.Sprintf("Issue %d was fixed in %s, from %s's move to fixing to its last fix delivered, over the %s fix "+ "budget of %s. Its longest phase was %s. Nothing is needed from you: it says where fixes lose time. "+ "It clears when the next %s fix is delivered within its budget.", newest.Number, ft.Took, worker, class, ft.Budget, longest, class), "", false); err != nil { if firstErr == nil { firstErr = err } continue } if _, err := t.change(newest.Number, Act{Op: "warned", By: Seat}, func(i *Issue) error { if i.FixTime != nil { i.FixTime.Warned = true } return nil }); err != nil && firstErr == nil { firstErr = err } continue } if len(warned) == 0 || ft.BudgetMS == 0 { continue } if err := t.Notify(fixOverKey(class), "", "", "", "", fmt.Sprintf("issue %d's fix was delivered within its %s fix budget (%s of %s)", newest.Number, class, ft.Took, ft.Budget), true); err != nil { if firstErr == nil { firstErr = err } continue } sort.Slice(warned, func(i, j int) bool { return warned[i] < warned[j] }) for _, n := range warned { if _, err := t.change(n, Act{Op: "warned", By: Seat}, func(i *Issue) error { if i.FixTime != nil { i.FixTime.Warned = false } return nil }); err != nil && firstErr == nil { firstErr = err } } } return firstErr } // FixTimesClass is one class's line of `fix-times`. type FixTimesClass struct { Class string `json:"class"` Budget string `json:"budget"` BudgetMS int64 `json:"budget_ms"` Count int `json:"count"` Within int `json:"within"` Over int `json:"over"` Median string `json:"median,omitempty"` MedianMS int64 `json:"median_ms,omitempty"` Worst string `json:"worst,omitempty"` WorstMS int64 `json:"worst_ms,omitempty"` // WorstIssue is the issue whose fix took the worst time. WorstIssue uint64 `json:"worst_issue,omitempty"` } // FixTimesRow is an issue as `fix-times` names it. type FixTimesRow struct { Number uint64 `json:"number"` Title string `json:"title"` Class string `json:"class,omitempty"` Took string `json:"took"` TookMS int64 `json:"took_ms"` Budget string `json:"budget,omitempty"` Longest string `json:"longest,omitempty"` Worker string `json:"worker,omitempty"` Delivered string `json:"delivered"` } // FixTimes is the answer of `fix-times`. type FixTimes struct { Days int `json:"days"` Since string `json:"since"` Line string `json:"line"` Classes []FixTimesClass `json:"classes"` // Over is every issue over its budget in the window, newest first, with its longest phase. Over []FixTimesRow `json:"over,omitempty"` // Unbudgeted are the issues fixed in the window with no fix budget: their fixes move no module, or what they // move is not known. Unbudgeted []FixTimesRow `json:"unbudgeted,omitempty"` } // MostFixTimesDays is the longest window `fix-times` reads. const MostFixTimesDays = 90 // FixTimes is the `fix-times` verb: each class's fix budget, the last days' median and worst fix time, and every // issue over its budget with its longest phase (ADR 0313 §5, §7). An issue counts in the window its last fix was // delivered in. func (t *Tracker) FixTimes(days int) (*FixTimes, error) { if days <= 0 { days = 7 } if days > MostFixTimesDays { return nil, fmt.Errorf("days %d is more than the %d fix-times reads", days, MostFixTimesDays) } all, err := t.allIssues() if err != nil { return nil, err } since := t.now().Add(-time.Duration(days) * 24 * time.Hour) a := &FixTimes{Days: days, Since: since.Format(time.RFC3339)} byClass := map[string][]*Issue{} row := func(is *Issue) FixTimesRow { ft := is.FixTime return FixTimesRow{Number: is.Number, Title: is.Title, Class: ft.Class, Took: ft.Took, TookMS: ft.TookMS, Budget: ft.Budget, Longest: ft.Longest, Worker: ft.Worker, Delivered: ft.End.Format(time.RFC3339)} } for _, is := range all { ft := is.FixTime if ft == nil || ft.End.Before(since) { continue } if _, ok := FixBudgets[ft.Class]; !ok { a.Unbudgeted = append(a.Unbudgeted, row(is)) continue } byClass[ft.Class] = append(byClass[ft.Class], is) if ft.Over { a.Over = append(a.Over, row(is)) } } newestFirst := func(rows []FixTimesRow) { sort.Slice(rows, func(i, j int) bool { if rows[i].Delivered != rows[j].Delivered { return rows[i].Delivered > rows[j].Delivered } return rows[i].Number > rows[j].Number }) } newestFirst(a.Over) newestFirst(a.Unbudgeted) var line []string for _, class := range fixClasses { b := FixBudgets[class] c := FixTimesClass{Class: class, Budget: b.String(), BudgetMS: b.Milliseconds()} is := byClass[class] sort.Slice(is, func(i, j int) bool { if is[i].FixTime.TookMS != is[j].FixTime.TookMS { return is[i].FixTime.TookMS < is[j].FixTime.TookMS } return is[i].Number < is[j].Number }) c.Count = len(is) for _, i := range is { if i.FixTime.Over { c.Over++ } else { c.Within++ } } if n := len(is); n > 0 { ms := is[n/2].FixTime.TookMS if n%2 == 0 { ms = (is[n/2-1].FixTime.TookMS + is[n/2].FixTime.TookMS) / 2 } med := time.Duration(ms) * time.Millisecond c.MedianMS, c.Median = ms, med.Round(time.Second).String() worst := is[n-1] c.WorstMS, c.Worst, c.WorstIssue = worst.FixTime.TookMS, worst.FixTime.Took, worst.Number line = append(line, fmt.Sprintf("%s: median %s, worst %s (issue %d), %d of %d within %s", class, c.Median, c.Worst, c.WorstIssue, c.Within, c.Count, c.Budget)) } else { line = append(line, fmt.Sprintf("%s: no issue fixed", class)) } a.Classes = append(a.Classes, c) } a.Line = fmt.Sprintf("fix time over the last %d day(s), from the move to fixing to delivered — %s", days, strings.Join(line, "; ")) if len(a.Unbudgeted) > 0 { a.Line += fmt.Sprintf("; %d fixed with no fix budget", len(a.Unbudgeted)) } return a, nil } // 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"` } `json:"reviews"` } var s string if json.Unmarshal(raw, &s) == nil { raw = json.RawMessage(s) } var wrapped struct { Content []struct { Text string `json:"text"` } `json:"content"` } if json.Unmarshal(raw, &wrapped) == nil && len(wrapped.Content) > 0 { raw = json.RawMessage(wrapped.Content[0].Text) } if err := json.Unmarshal(raw, &a); err != nil || a.Reviews == nil { return time.Time{}, false, fmt.Errorf("the forge's gitea_pull_reviews answered no reviews: %.200s", raw) } var first time.Time for _, r := range a.Reviews { 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) if err != nil { continue } if first.IsZero() || at.Before(first) { first = at } } 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) { raw, err := stdio.Ask("gitea.gitea_pull_reviews", map[string]any{"owner": owner(), "repo": repository, "number": number}) if err != nil { return time.Time{}, false, err } return firstApproval(raw) } }