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

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
// <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"`
		} `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 <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) {
		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)
	}
}