diff --git a/internal/measurements/measurements.go b/internal/measurements/measurements.go new file mode 100644 index 000000000..7423c9214 --- /dev/null +++ b/internal/measurements/measurements.go @@ -0,0 +1,1478 @@ +// Package measurements keeps a run's own timings so a report cannot invent them. +// +// THE FAILURE THIS EXISTS FOR. A measured run finished a benchmark and reported +// a table of test timings that no command in the session had produced. The same +// test read 0.86s in one paste and 4.20s in the next with nothing said about the +// difference, a -race overhead moved from +3.7% to +133% between two tellings of +// the same result, and the column summed to an exact total no real transcript +// lands on. A prompt rule — "re-run every command before you paste it" — is the +// obvious answer and the weak one: a model that is willing to write numbers it +// did not measure is equally willing to say it re-ran them. +// +// The harness is not. Every command's output passed through this process and was +// written to the session log, so the run's real numbers are already here. This +// package reads them back and compares them against what the answer claims, +// which is the one check a model cannot satisfy by asserting harder. +// +// DELIBERATELY LOOSE. Timings vary between runs for honest reasons — a loaded +// machine, a warm cache, a different -count. The tolerance below is a 50% band, +// which lets ordinary variation through and catches 0.86s reported as 4.20s. The +// cost of a false positive is high (a tripwire that cries wolf is turned off, and +// then it catches nothing), and the cost of a false negative is one uncaught +// number, so this errs firmly toward silence. +package measurements + +import ( + "encoding/json" + "math" + "sort" + "strconv" + "strings" + "sync" + "unicode/utf8" +) + +// Measurement is one timing a command reported: what was measured, and how long +// it took in seconds. +type Measurement struct { + Name string + Package string + Test string + Seconds float64 +} + +type measurementID struct { + Package string + Test string +} + +func (m Measurement) identity() measurementID { + if m.Test != "" { + return measurementID{Package: m.Package, Test: m.Test} + } + return measurementID{Package: m.Name} +} + +// Conflict is a number an answer states that the session never recorded. +type Conflict struct { + Name string + // Claimed is the value the answer gave, in seconds. + Claimed float64 + // Recorded is every value this session actually observed for Name UNDER THE + // SAME RUN, sorted. + Recorded []float64 + // Run is the command those values came from. + Run Run +} + +// Run is the command a set of timings came from. +// +// TIMINGS FROM DIFFERENT COMMANDS ARE DIFFERENT MEASUREMENTS. Everything used to +// pool into map[name][]seconds, so a claim about an ordinary run was satisfied by +// a value only the -race run ever produced — and -race is routinely several times +// slower, which is exactly the size of discrepancy this package exists to catch. +// The pooling made the check agree with a number the stated command never +// printed, silently, which is the failure mode that is hardest to notice. +// +// A zero Run is a legitimate value meaning "this caller does not distinguish +// runs"; everything it records and asks about lives in one group, which is how +// this behaved before provenance existed. +type Run struct { + Command string + Args []string + Dir string +} + +// key identifies the run for grouping. Args are joined with a separator that +// cannot appear inside a single argument boundary ambiguously, so ["a b"] and +// ["a","b"] are different runs rather than the same one. +func (r Run) key() string { + var b strings.Builder + writeKeyField := func(value string) { + b.WriteString(strconv.Itoa(len(value))) + b.WriteByte(':') + b.WriteString(value) + } + writeKeyField(r.Dir) + writeKeyField(r.Command) + b.WriteString(strconv.Itoa(len(r.Args))) + b.WriteByte(':') + for _, arg := range r.Args { + writeKeyField(arg) + } + return b.String() +} + +// snapshot severs the caller's ownership of argument backing storage. A Run is +// retained as provenance, so it must remain the same identity that produced the +// key even when a command builder reuses its argument slice for a later run. +func (r Run) snapshot() Run { + r.Args = append([]string(nil), r.Args...) + return r +} + +// quoteRunPart keeps ordinary command lines readable while making argument +// boundaries unambiguous whenever whitespace, quotes, shell expansion, or +// control bytes would otherwise collapse two different argv values into the +// same label. +func quoteRunPart(part string) string { + if part == "" { + return strconv.Quote(part) + } + for _, r := range part { + switch { + case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9': + case strings.ContainsRune("_./-:@%+=,", r): + default: + return strconv.Quote(part) + } + } + return part +} + +// Label renders the run for a reader. Empty for the zero Run, so a caller that +// does not distinguish runs gets the same wording it always had. +func (r Run) Label() string { + if r.Command == "" && len(r.Args) == 0 && r.Dir == "" { + return "" + } + parts := make([]string, 0, len(r.Args)+1) + if r.Command != "" { + parts = append(parts, quoteRunPart(r.Command)) + } + for _, arg := range r.Args { + parts = append(parts, quoteRunPart(arg)) + } + label := strings.Join(parts, " ") + if r.Dir != "" { + if label != "" { + label += " " + } + label += "(dir " + quoteRunPart(r.Dir) + ")" + } + return label +} + +// ── one authoritative duration token ──────────────────────────────────────── +// +// THREE UNANCHORED SEARCHES WERE THE ROOT CAUSE. Each regex hunted for its own +// suffix with no shared left boundary, so a failed outer match simply restarted +// inside the same token: ".86s" was read as 86s, ".5m" as 300s, "1,200ms" as +// 0.2s, and the valid Go compounds "1m10ms" and "1h1m500ms" fell through to their +// millisecond tails as 0.01s and 0.5s. Every one of those turns an honest claim +// into a fabricated correction, which is the single failure this package exists +// to prevent. Reported by @jatmn. +// +// A token is now recognised WHOLE or not at all, and one scanner answers for both +// callers — parseClaimedDuration and the clause scan — so the two can no longer +// disagree about what counts as a duration. + +// durationUnits are ordered longest-first: "ms" has to be tried before "m", or +// every millisecond figure reads as minutes. +var durationUnits = []struct { + suffix string + seconds float64 +}{ + {"ms", 0.001}, + {"h", 3600}, + {"m", 60}, + {"s", 1}, +} + +// tokenLeftBoundary reports whether a duration may BEGIN at index. +// +// A digit, letter, dot or comma before the figure means this is the middle of +// something else — the fractional tail of ".86s", the grouped remainder of +// "1,200ms", or an identifier. None of those is a duration this package can read, +// and reading part of one is how a truthful sentence acquired a number it never +// contained. +func tokenLeftBoundary(text string, index int) bool { + if index == 0 { + return true + } + previous, _ := utf8.DecodeLastRuneInString(text[:index]) + switch { + case previous >= '0' && previous <= '9': + return false + case previous >= 'a' && previous <= 'z', previous >= 'A' && previous <= 'Z': + return false + case previous == '.', previous == ',': + return false + case previous == '+', previous == '-', previous == '−': + // A signed number is a delta or another numeric expression, not an + // unsigned elapsed-time claim. Starting at the digit would discard the + // sign and turn "improved by -4.20s" into a claim that the test took + // positive 4.20 seconds. + return false + default: + return true + } +} + +// tokenRightBoundary reports whether a duration may END at index. +func tokenRightBoundary(text string, index int) bool { + if index >= len(text) { + return true + } + switch next := text[index]; { + case next >= '0' && next <= '9': + return false + case next >= 'a' && next <= 'z', next >= 'A' && next <= 'Z': + return false + case next == '.': + // A sentence-ending dot is a boundary; a decimal point is not. Only a + // digit after it makes it part of a number. + return index+1 >= len(text) || text[index+1] < '0' || text[index+1] > '9' + default: + return true + } +} + +// scanNumber reads a plain or decimal figure at index, returning its end offset. +func scanNumber(text string, index int) int { + at := index + for at < len(text) && text[at] >= '0' && text[at] <= '9' { + at++ + } + if at == index { + return index + } + if at < len(text) && text[at] == '.' { + fraction := at + 1 + for fraction < len(text) && text[fraction] >= '0' && text[fraction] <= '9' { + fraction++ + } + if fraction > at+1 { + at = fraction + } + } + return at +} + +// durationTokenAt reads a complete duration token beginning at index. +// +// Every component must be a figure followed by a unit, and the whole run must sit +// between token boundaries. A partial parse yields nothing rather than a +// second-best reading: an unsupported form is not evidence, and guessing at one +// is exactly how a fabricated number reaches the model. +func durationTokenAt(text string, index int) (end int, seconds float64, unitCount int, ok bool) { + if !tokenLeftBoundary(text, index) { + return 0, 0, 0, false + } + at := index + for { + numberEnd := scanNumber(text, at) + if numberEnd == at { + break + } + matched := false + for _, unit := range durationUnits { + if !strings.HasPrefix(text[numberEnd:], unit.suffix) { + continue + } + value, err := strconv.ParseFloat(text[at:numberEnd], 64) + if err != nil { + return 0, 0, 0, false + } + seconds += value * unit.seconds + at = numberEnd + len(unit.suffix) + unitCount++ + matched = true + break + } + if !matched { + // A figure with no unit, or an unsupported one. The token is not a + // duration, and no prefix of it is either. + return 0, 0, 0, false + } + } + if unitCount == 0 || !tokenRightBoundary(text, at) { + return 0, 0, 0, false + } + return at, seconds, unitCount, true +} + +// nextDurationToken finds the next complete duration token at or after start. +func nextDurationToken(text string, start int) (begin, end int, seconds float64, unitCount int, ok bool) { + for at := start; at < len(text); at++ { + if text[at] < '0' || text[at] > '9' { + continue + } + if finish, value, units, valid := durationTokenAt(text, at); valid { + return at, finish, value, units, true + } + // Skip the rest of this numeric run rather than re-entering it one digit + // later, which is precisely how ".86s" became "86s". + for at < len(text) && ((text[at] >= '0' && text[at] <= '9') || text[at] == '.' || text[at] == ',') { + at++ + } + } + return 0, 0, 0, 0, false +} + +// ParseGoTest pulls timings only from structured `go test -json` result events. +// +// Plain `go test -v` output is deliberately not accepted. The test process and +// the Go runner share that text stream, so a test can print a line shaped like +// `--- PASS: TestName (99.00s)` before the runner prints the real result. Under +// -json, test stdout is wrapped in an "output" event; only pass/fail/skip events +// contribute timings. A package-level `(cached)` output marker makes every +// timing event for that package inadmissible: cmd/go replays per-test pass +// events with zero elapsed before it announces the cache hit. Malformed or +// ordinary-text lines are silence, not evidence. +func ParseGoTest(text string) []Measurement { + if strings.TrimSpace(text) == "" { + return nil + } + type event struct { + Action string `json:"Action"` + Package string `json:"Package"` + Test string `json:"Test"` + Output string `json:"Output"` + Elapsed *float64 `json:"Elapsed"` + } + cachedPackages := make(map[string]struct{}) + var out []Measurement + for _, line := range strings.Split(text, "\n") { + var item event + if err := json.Unmarshal([]byte(line), &item); err != nil { + continue + } + item.Test = strings.TrimSpace(item.Test) + item.Package = strings.TrimSpace(item.Package) + if item.Action == "output" && item.Test == "" && cachedGoTestPackageOutput(item.Output, item.Package) { + cachedPackages[item.Package] = struct{}{} + } + if item.Elapsed == nil { + continue + } + switch item.Action { + case "pass", "fail", "skip": + default: + continue + } + name := item.Test + if name == "" { + name = item.Package + } + if name == "" || math.IsNaN(*item.Elapsed) || math.IsInf(*item.Elapsed, 0) || *item.Elapsed < 0 { + continue + } + out = append(out, Measurement{Name: name, Package: item.Package, Test: item.Test, Seconds: *item.Elapsed}) + } + if len(cachedPackages) == 0 { + return out + } + kept := out[:0] + for _, measurement := range out { + if _, cached := cachedPackages[measurement.Package]; cached { + continue + } + kept = append(kept, measurement) + } + return kept +} + +func cachedGoTestPackageOutput(output, packageName string) bool { + fields := strings.Fields(output) + if packageName == "" || len(fields) < 3 || fields[1] != packageName { + return false + } + for _, field := range fields[2:] { + if field == "(cached)" { + return true + } + } + return false +} + +// RecordedRun is an immutable identity returned by Record. Keep it for later +// per-run checks; the command builder's Run may be reused or changed meanwhile. +// A zero handle, or a handle from another ledger, cannot select observations. +type RecordedRun struct { + ledger *Ledger + key string +} + +// Ledger is every timing this run observed, and which conflicts it has already +// raised. +// +// A nil Ledger is a working no-op, so a caller that does not want the check +// holds nil and still calls every method unconditionally. +type Ledger struct { + mu sync.Mutex + // observed is keyed by run FIRST, so a lookup can only ever see the values + // the asked-about command produced. Making that structural rather than a + // filter applied at read time means a future caller cannot reintroduce the + // pooling by forgetting to pass the run. + observed map[string]map[measurementID][]float64 + runs map[string]Run + // raised keys on the name AND the value that was wrong, not the name alone. + // Keying on the name switched the check off for that name permanently: after + // one bad 4.20s, a later, differently wrong 9.90s for the same test was + // silent. The point of the dedupe is that re-reading the SAME answer says + // nothing twice, which per-value still gives, while a new wrong number is a + // new thing to say. + raised map[raisedKey]bool +} + +// raisedKey identifies one conflict already reported: which name, and which +// claimed value. The value is rounded to milliseconds so that re-stating the +// same number in a different precision is still the same conflict. +type raisedKey struct { + run string + // acrossRuns separates the two entry points' bookkeeping. A cross-run report + // is not about any single run, so keying it on one was wrong twice over: the + // run it picked came from map iteration, which Go randomises, so the SAME + // conflict was reported again on a later pass one time in four — and the + // dedupe exists precisely so a correction fed back to the model cannot loop. + acrossRuns bool + name string + claimedMilli int64 +} + +func newRaisedKey(run Run, name string, claimed float64) raisedKey { + return raisedKey{run: run.key(), name: name, claimedMilli: claimedMilli(claimed)} +} + +// newAcrossRunsKey identifies a conflict raised against every run at once. +// Independent of which run the report happens to quote, and in its own namespace +// so the two entry points cannot suppress each other's reports — they answer +// different questions, and a caller uses one or the other. +func newAcrossRunsKey(name string, claimed float64) raisedKey { + return raisedKey{acrossRuns: true, name: name, claimedMilli: claimedMilli(claimed)} +} + +func claimedMilli(claimed float64) int64 { + return int64(math.Round(claimed * 1000)) +} + +func NewLedger() *Ledger { + return &Ledger{ + observed: map[string]map[measurementID][]float64{}, + runs: map[string]Run{}, + raised: map[raisedKey]bool{}, + } +} + +// ensureMaps makes a zero-value Ledger behave like a constructed one. +// +// ONE PLACE, NOT THREE. The nil receiver is handled separately, but a Ledger +// that was DECLARED rather than built by NewLedger reached the map writes with +// nil maps and panicked. The first attempt at this fixed the two maps Record +// touches and missed `raised`, which only Conflicts and ConflictsAcrossRuns +// write — and they write it exclusively on the contradiction path, so a test +// asking an agreeing claim never reached it. Reported by @jatmn. +// +// Every caller that can write a map calls this, and the field list lives beside +// NewLedger's, so a fourth map added later is a compile-time-visible omission in +// one spot rather than a panic in whichever entry point forgot it. +// +// Callers hold l.mu; this only fills nil fields, so a constructed Ledger pays +// three nil checks and nothing else. +func (l *Ledger) ensureMaps() { + if l.observed == nil { + l.observed = map[string]map[measurementID][]float64{} + } + if l.runs == nil { + l.runs = map[string]Run{} + } + if l.raised == nil { + l.raised = map[raisedKey]bool{} + } +} + +// Record reads any timings out of a command's output and remembers them against +// the run that produced it. Returns its immutable identity and the number of +// timings accepted. Repeated records of the same command retain the existing +// grouping; changing the command builder produces a different identity. +// +// Pass the command actually executed. A zero Run says this caller does not +// distinguish runs, which is a legitimate answer — but it is now said out loud at +// the call site rather than being the only thing the type could express. +func (l *Ledger) Record(run Run, text string) (RecordedRun, int) { + if l == nil { + return RecordedRun{}, 0 + } + run = run.snapshot() + key := run.key() + handle := RecordedRun{ledger: l, key: key} + found := ParseGoTest(text) + if len(found) == 0 { + return handle, 0 + } + l.mu.Lock() + defer l.mu.Unlock() + l.ensureMaps() + byName := l.observed[key] + if byName == nil { + byName = map[measurementID][]float64{} + l.observed[key] = byName + l.runs[key] = run + } + for _, m := range found { + id := m.identity() + byName[id] = append(byName[id], m.Seconds) + } + return handle, len(found) +} + +// tolerance reports whether two timings are close enough to be the same result +// measured twice. A 50% band with a small absolute floor: ordinary variation and +// sub-centisecond jitter pass, a fivefold difference does not. +func tolerance(a, b float64) bool { + spread := math.Max(math.Abs(a), math.Abs(b)) * 0.5 + if spread < 0.05 { + spread = 0.05 + } + return math.Abs(a-b) <= spread +} + +func measurementDisplayNames(observed map[measurementID][]float64) (map[measurementID]string, map[string][]float64) { + testOwners := map[string]int{} + for id := range observed { + if id.Test != "" { + testOwners[id.Test]++ + } + } + candidates := make(map[measurementID]string, len(observed)) + owners := make(map[string]int, len(observed)) + for id := range observed { + name := id.Package + if id.Test != "" { + name = id.Test + if testOwners[id.Test] > 1 { + name = id.Package + "." + id.Test + } + } + if name == "" { + continue + } + candidates[id] = name + owners[name]++ + } + names := make(map[measurementID]string, len(candidates)) + known := make(map[string][]float64, len(candidates)) + for id, name := range candidates { + // Package results and package-qualified test results occupy distinct + // identities but can render to the same text (package "example/a.TestFoo" + // versus TestFoo in package "example/a"). Such a claim has no unique + // owner, so fail silent rather than pooling values or emitting two + // incompatible corrections. + if owners[name] != 1 { + continue + } + names[id] = name + known[name] = append(known[name], observed[id]...) + } + return names, known +} + +// Conflicts reports numbers in claim that contradict what this session recorded. +// +// ONLY NAMES THE LEDGER ALREADY KNOWS are considered, and only when the claim +// puts a duration next to one on the same line. An answer that mentions a test +// without timing it, or that reports something never measured here, produces +// nothing — this check exists to catch a number that DISAGREES with the +// transcript, not to demand that every number have one. +// +// Each name AND CLAIMED VALUE is reported at most once per Ledger. A second pass +// over the same answer is silent, so the caller can feed a correction back to the +// model without the possibility of a loop — while a differently wrong number for +// the same name is a new thing to say and is reported. +func (l *Ledger) Conflicts(handle RecordedRun, claim string) []Conflict { + if l == nil || handle.ledger != l || strings.TrimSpace(claim) == "" { + return nil + } + l.mu.Lock() + l.ensureMaps() + defer l.mu.Unlock() + + // ONLY THIS RUN'S VALUES. A claim about `go test ./...` is not answered by a + // number that only `go test -race ./...` ever printed. + key := handle.key + observed := l.observed[key] + if len(observed) == 0 { + return nil + } + // Use the immutable provenance retained at Record time. A command builder + // may reuse the caller's argv backing array after this method returns; a + // later Nudge must still name the command that produced these observations. + attributedRun, ok := l.runs[key] + if !ok { + return nil + } + run := attributedRun + names, known := measurementDisplayNames(observed) + var out []Conflict + for id, recorded := range observed { + name := names[id] + if name == "" { + continue + } + if len(recorded) == 0 { + continue + } + // EVERY MENTION, not the first that parsed. An agreeing occurrence used to + // return before any later one was examined, so a fabricated second value + // went unseen — and the per-value dedupe below exists precisely because + // two different wrong numbers for one name are two findings. + // ONE FINDING PER DISTINCT VALUE, within this call as well as across + // calls. The ledger's dedupe is keyed on the value for a reason: the + // same wrong number said twice is one thing to correct, while two + // different wrong numbers are two. + seenThisCall := map[int64]bool{} + for _, claimed := range claimedSecondsAllFor(claim, name, known) { + if l.raised[newRaisedKey(run, name, claimed)] || seenThisCall[claimedMilli(claimed)] { + continue + } + seenThisCall[claimedMilli(claimed)] = true + agrees := false + for _, seen := range recorded { + if tolerance(claimed, seen) { + agrees = true + break + } + } + if agrees { + continue + } + values := append([]float64(nil), recorded...) + sort.Float64s(values) + out = append(out, Conflict{Name: name, Claimed: claimed, Recorded: values, Run: attributedRun}) + } + } + // Deterministic order: this text reaches a model, and a set that reshuffles + // between identical runs is a diff nobody can read. + sort.Slice(out, func(i, j int) bool { + if out[i].Name != out[j].Name { + return out[i].Name < out[j].Name + } + return out[i].Claimed < out[j].Claimed + }) + for _, conflict := range out { + l.raised[newRaisedKey(run, conflict.Name, conflict.Claimed)] = true + } + return out +} + +// firstDurationEnd returns the offset just past the first duration token in the +// clause, or len(clause) when there is none. +func firstDurationEnd(clause string) int { + if _, end, _, _, ok := nextDurationToken(clause, 0); ok { + return end + } + return len(clause) +} + +// claimedSecondsAllFor returns EVERY value the claim attributes to name, in the +// order they appear. +// +// THE SCALAR CONTRACT WAS THE DEFECT. Returning at the first occurrence that +// parsed meant an agreeing mention shielded every later one, so +// "TestFoo took 1.00s; TestFoo later took 9.00s" produced no conflict against a +// recorded 1s — the fabricated 9s was never examined. That also contradicted the +// ledger's per-VALUE dedupe, which exists precisely so two different wrong +// numbers for one name are two findings. +// +// Comparison and dedupe belong to the caller, which is why this returns values +// rather than a verdict: "later" is not a special case, and neither are two wrong +// values, repeated equivalent spellings, or more than two mentions. Reported by +// @jatmn. +func claimedSecondsAllFor(claim, name string, known map[string][]float64) []float64 { + var values []float64 + for _, line := range strings.Split(claim, "\n") { + for start := 0; start < len(line); { + index := strings.Index(line[start:], name) + if index < 0 { + break + } + absolute := start + index + end := absolute + len(name) + start = absolute + 1 + if !nameBoundary(line, absolute, end) { + continue + } + // A quoted transcript or example is evidence being discussed, not a + // result the report itself asserts. Requiring an unquoted name keeps an + // otherwise valid-looking "took 9s" inside prose or a code span from + // becoming a correction. + clauseFrom := end + if insideASCIIQuote(line, absolute) { + var formatted bool + clauseFrom, formatted = formattedNameEnd(line, absolute, end) + if !formatted { + continue + } + } + clause := line[clauseFrom:clauseEnd(line, clauseFrom, known)] + // TWO DURATIONS IN ONE CLAUSE MEANS OWNERSHIP IS UNCLEAR, so the + // clause yields nothing. + // + // Position is not ownership. "nearest duration" was standing in for + // "the duration asserted as this test's result", and the two part + // company the moment a budget is stated first: with 0.86s recorded, + // "TestQuick stayed under the 10s timeout and completed in 0.86s" was + // reported as claiming 10s — a completely truthful sentence receiving + // the exact fabricated correction this package exists to prevent. + // + // Deliberately NOT a "timeout" keyword exception: the same structure + // arrives as deadlines, limits, budgets, targets and baselines, and a + // word list would reopen the class at the next synonym. An ambiguous + // clause is silent, which fails toward a miss rather than an + // accusation. Reported by @jatmn. + if _, _, _, _, second := nextDurationToken(clause, firstDurationEnd(clause)); second { + continue + } + if value, ok := elapsedClaimedDuration(clause); ok { + values = append(values, value) + } + } + } + return values +} + +// clauseEnd returns the offset in line at which this name's clause stops. +// +// Three bounds, whichever comes first: +// +// - the next RECORDED name, as a whole token. Every recorded name is +// considered, including the one being searched for: a second mention starts +// a second clause, and the caller's loop visits it on its own turn. +// - the next name-SHAPED token, recorded or not. Cutting only at names the +// ledger knows left "TestFoo passed; TestUnrecorded took 4.20s" fabricating +// a conflict for TestFoo, because the neighbour holding the number was never +// recorded and so never bounded anything. Whether a number belongs to this +// name cannot depend on whether some OTHER name happened to be measured. +// - a clause separator. "and", a semicolon or a comma end the clause as surely +// as a new name does, and catch the neighbours that are not name-shaped. +// +// All three only ever SHORTEN the search, so each can cost a detection but none +// can invent one — the right direction for a check whose worst failure is +// accusing a correct number of being wrong. +func clauseEnd(line string, from int, known map[string][]float64) int { + cut := len(line) + consider := func(at int) { + if at >= 0 && at < cut { + cut = at + } + } + for other := range known { + if other == "" { + continue + } + for start := from; start < len(line); { + index := strings.Index(line[start:], other) + if index < 0 { + break + } + absolute := start + index + start = absolute + 1 + if !nameBoundary(line, absolute, absolute+len(other)) { + continue + } + consider(absolute) + break + } + } + if at := nextNameShaped(line, from); at >= 0 { + consider(at) + } + for _, separator := range clauseSeparators { + index := strings.Index(line[from:], separator) + if index < 0 { + continue + } + // A SEPARATOR BREAKS THE CLAUSE ONLY WHEN A NEW SUBJECT FOLLOWS IT. + // Punctuation alone does not decide: "TestFoo (9.99s)", + // "TestFoo passed - 9.99s" and "TestFoo passed, 9.99s" are all ways of + // stating THIS test's own number, and bounding at the punctuation would + // cut the number off from the name it belongs to and silence a real + // fabrication. What makes it a break is a subject named after it — + // "TestFoo passed (the suite took 34.249s)" — so the test is whether any + // word appears between the separator and the next duration. + after := line[from+index+len(separator):] + if !separatorBreaksClause(after) { + continue + } + consider(from + index) + } + consider(sentenceEnd(line, from)) + return cut +} + +// elapsedClaimedDuration reads a duration only when its local syntax says that +// it is this name's elapsed result. A duration is not a claim by proximity: it +// may be a timeout, budget, bound, count, quotation, or another subject's value. +// +// The grammar is intentionally small and affirmative. It recognizes the result +// forms this package has direct evidence for: "took D", a completed action "in +// D", a presentation-owned "Name (D)"/"Name passed, D", and "D elapsed". A +// miss is cheaper than inventing a correction, so every other role is silent. +func elapsedClaimedDuration(text string) (float64, bool) { + begin, end, _, _, ok := nextDurationToken(text, 0) + if !ok { + return 0, false + } + if !durationHasElapsedRole(text, begin, end) { + return 0, false + } + // parseClaimedDuration remains the single authority for whether the token is + // a complete duration rather than an ambiguous count such as "5m rows". + return parseClaimedDuration(text) +} + +func durationHasElapsedRole(text string, begin, end int) bool { + if insideASCIIQuote(text, begin) { + return false + } + before := strings.TrimSpace(text[:begin]) + after := text[end:] + if elapsedFollowsDuration(after) && (before == "" || presentationOwnsDuration(before)) { + return true + } + + lead, last := popLastASCIIWord(before) + if last == "took" && affirmativeCueLead(lead) { + return true + } + if last == "in" { + lead, verb := popLastASCIIWord(lead) + switch verb { + case "passed", "completed", "finished", "ran": + return affirmativeCueLead(lead) + } + } + return presentationOwnsDuration(before) && !containsLetter(after[:segmentEnd(after)]) +} + +// affirmativeCueLead binds the result verb to the measured name. These are the +// only modifiers exercised by the package's established result fixtures. An +// arbitrary noun phrase, negation, modal, or quoted example therefore cannot +// borrow a later "took"/"finished in" substring as its own timing assertion. +func affirmativeCueLead(text string) bool { + switch strings.ToLower(strings.TrimSpace(text)) { + case "", "actually", "later": + return true + default: + return false + } +} + +func presentationOwnsDuration(before string) bool { + before = strings.ToLower(strings.TrimSpace(before)) + for _, prefix := range []string{"", "passed"} { + punctuation := strings.TrimSpace(strings.TrimPrefix(before, prefix)) + if prefix != "" && punctuation == before { + continue + } + switch punctuation { + case "(", "-", "—", "–", "|", ",", ":": + return true + } + } + return false +} + +func popLastASCIIWord(text string) (string, string) { + text = strings.TrimSpace(text) + end := len(text) + start := end + for start > 0 { + c := text[start-1] + if (c < 'a' || c > 'z') && (c < 'A' || c > 'Z') { + break + } + start-- + } + if start == end { + return text, "" + } + return strings.TrimSpace(text[:start]), strings.ToLower(text[start:end]) +} + +func elapsedFollowsDuration(after string) bool { + after = strings.TrimSpace(after) + if len(after) < len("elapsed") || !strings.EqualFold(after[:len("elapsed")], "elapsed") { + return false + } + if len(after) > len("elapsed") { + next := after[len("elapsed")] + if (next >= 'a' && next <= 'z') || (next >= 'A' && next <= 'Z') { + return false + } + } + rest := after[len("elapsed"):] + return !containsLetter(rest[:segmentEnd(rest)]) +} + +func insideASCIIQuote(text string, at int) bool { + var double, backtick bool + escaped := false + for index := 0; index < at; index++ { + switch c := text[index]; { + case escaped: + escaped = false + case c == '\\': + escaped = true + case c == '"': + double = !double + case c == '`': + backtick = !backtick + } + } + return double || backtick +} + +// formattedNameEnd accepts a quote pair only when it wraps the matched name +// itself. Markdown commonly writes "`TestX` took 9s"; that is an assertion with +// a formatted subject, unlike "`TestX took 9s`", whose duration remains inside +// the quoted example and must stay silent. +func formattedNameEnd(text string, begin, end int) (int, bool) { + if begin == 0 || end >= len(text) || insideASCIIQuote(text, begin-1) { + return end, false + } + delimiter := text[begin-1] + if (delimiter != '`' && delimiter != '"') || text[end] != delimiter { + return end, false + } + return end + 1, true +} + +// separatorBreaksClause reports whether the text after a separator names a new +// subject, rather than simply carrying the preceding name's own number. +// +// A word beside the next duration means something else is being talked about. No +// word — just the number — means the punctuation was only presentation, which is +// how a table, a bullet list or an aside states one test's timing. +// +// BESIDE, NOT BEFORE. The scan used to look only at what came ahead of the +// number, so a subject that trailed its own figure was invisible and the +// separator read as presentation: +// +// recorded: TestFoo 0.10s +// claim: "TestFoo passed; 4.20s was the whole suite." +// -> [{Name:TestFoo Claimed:4.2 Recorded:[0.1]}] +// +// Every word of that claim is true and 4.20s belongs to the suite named directly +// after it. Which side of the figure its subject sits on says nothing about who +// owns it, so both sides are scanned. +// +// The trailing scan stops at the end of the figure's OWN segment, or ordinary +// layouts would break themselves: the words after "| 4.20s |" belong to the next +// cell, and the ones after ", 9.99s." to the next sentence. +func separatorBreaksClause(after string) bool { + start, stop := nextDurationSpan(after) + if start < 0 { + // No duration after the separator at all, so there is no figure for a + // word to sit beside: any word is a new subject. + start, stop = len(after), len(after) + } + if containsLetter(after[:start]) { + return true + } + tail := after[stop:] + segment := tail[:segmentEnd(tail)] + if elapsedFollowsDuration(segment) { + return false + } + return containsLetter(segment) +} + +// segmentEnd returns the offset at which text stops belonging to the segment it +// starts — the first clause separator or sentence terminator, or the whole +// string when it holds neither. +func segmentEnd(text string) int { + end := len(text) + for _, separator := range clauseSeparators { + if index := strings.Index(text, separator); index >= 0 && index < end { + end = index + } + } + if index := sentenceEnd(text, 0); index >= 0 && index < end { + end = index + } + return end +} + +func containsLetter(text string) bool { + for index := 0; index < len(text); index++ { + if c := text[index]; (c >= 'a' && c <= 'z') || (c >= 'A' && c <= 'Z') { + return true + } + } + return false +} + +// nextDurationSpan returns the bounds of the first duration in text that this +// package would actually read, or -1 when there is none. +// +// EVERY FORM THE PARSER READS, AND NO FORM IT REFUSES. Without the hour form this +// scan could not locate "9h" as a duration, so it read the "h" as the first +// letter of a new subject and turned the punctuation into a clause boundary, +// cutting a test's own number off from its name — "TestVerySlow - 9h", +// "…passed - 9h", "…(9h)" and "…: 9h" were all missed that way. The ambiguous +// bare unit below is the same requirement from the other side: a token +// parseClaimedDuration will not read is not a duration here either, or the two +// again disagree about where a clause ends. +// +// Only the leftmost match of each form is considered, so an ambiguous "5m" +// hides any later minute figure. That can only push the span later, which +// lengthens the scan and shortens the clause — the direction every bound here +// takes. +func nextDurationSpan(text string) (int, int) { + // THE SAME SCANNER THE PARSER USES. These were separate heuristics, so a token + // the parser refused could still bound a clause and vice versa — the two + // disagreeing about what a duration is was its own defect class. + begin, end, _, units, ok := nextDurationToken(text, 0) + if !ok { + return -1, -1 + } + if units == 1 && bareUnitFollowedByWord(text, begin, end) { + return -1, -1 + } + return begin, end +} + +// clauseSeparators end a measurement clause without starting a new name. +// +// CLAUSE PUNCTUATION IS A CLOSED SET, which is what makes enumerating it +// finishable — unlike the ways a person can phrase an admission. Walking the +// shapes rather than guessing found five that leaked, not one: the plain hyphen +// everyone types, both typographic dashes, a parenthetical and a pipe. Each let +// a following clause's number be charged to the name in front of it. +var clauseSeparators = []string{ + ";", ":", ",", "(", "|", "—", "–", + " - ", " -- ", + " and ", " but ", " while ", " whereas ", " though ", +} + +// sentenceEnd returns the offset of the first sentence terminator at or after +// from, or -1. +// +// A FULL STOP ENDS A CLAUSE. The separator list had none, so when the next +// sentence's subject was an ordinary noun phrase — not a recorded name and not +// name-shaped — nothing bounded the clause and its number was charged to the +// previous sentence's test: +// +// "TestNested is green. The full run took 34.249s." +// -> [{Name:TestNested Claimed:34.249 Recorded:[0.03]}] +// +// Both sentences are true, both numbers were really measured, and the writer +// attached each to the right subject. Accusing a correct report is the failure +// that gets a tripwire switched off. +// +// A decimal point is not a terminator, and neither is the dot inside an import +// path: a terminator is followed by whitespace or the end of the line, and never +// sits between two digits. +func sentenceEnd(line string, from int) int { + for index := from; index < len(line); index++ { + switch line[index] { + case '.', '!', '?': + default: + continue + } + if line[index] == '.' && index > 0 && index+1 < len(line) && + isDigitByte(line[index-1]) && isDigitByte(line[index+1]) { + continue + } + if index+1 >= len(line) || line[index+1] == ' ' || line[index+1] == '\t' { + return index + } + } + return -1 +} + +func isDigitByte(b byte) bool { return b >= '0' && b <= '9' } + +// nextNameShaped returns the offset of the next token that looks like a name +// `go test` would print a timing for — a Test, Benchmark, Fuzz or Example +// function — or -1. +// +// SHAPE, not membership. The ledger only knows what this session measured, and a +// claim may name a test that was never run; that name still ends the clause it +// starts, because the number after it belongs to it and not to the name before. +// +// THE PREFIXES ARE CAPITALISED, and the first version's were not. Nothing here +// lowercases the claim — unlike the guardrails, this package compares against +// recorded names and must preserve their case — so "test" never matched +// "TestUnrecorded" and this function returned -1 for every realistic input. The +// tests that were supposed to cover it all contained a comma or a semicolon, so +// the clause-separator bound caught them and the dead branch looked alive. A +// bleed with no separator at all went straight through. +// +// The character after the prefix must be uppercase, a digit or an underscore, +// which is how `go test` spells these names and what separates TestFoo from the +// ordinary words "test", "testing" and "tested". +func nextNameShaped(line string, from int) int { + for index := from; index < len(line); index++ { + if index > from && !isNameSeparator(line[index-1]) { + continue + } + rest := line[index:] + for _, prefix := range []string{"Test", "Benchmark", "Fuzz", "Example"} { + if len(rest) <= len(prefix) || !strings.HasPrefix(rest, prefix) { + continue + } + if next := rest[len(prefix)]; !isNameContinuation(next) { + continue + } + return index + } + if packagePathAt(line, index) { + return index + } + } + return -1 +} + +// packagePathAt reports whether a package path begins at index. +// +// A PACKAGE IS A MEASUREMENT SUBJECT TOO, and it used to be recognised only when +// that exact package had already been recorded. So a truthful +// "github.com/x/first passed github.com/x/unrecorded took 4.20s" charged the +// second package's figure backwards to the first, because the unrecorded +// neighbour did not bound the clause — while an unrecorded TEST-shaped name +// always did. Whether a neighbouring subject ends a clause cannot depend on +// whether that neighbour happened to produce a parseable timing. Reported by +// @jatmn. +// +// Deliberately narrow: at least one slash, and every segment made of the +// characters an import path may contain. Prose rarely looks like this, and the +// consequence of a miss is the pre-existing behaviour rather than a new one. +func packagePathAt(line string, index int) bool { + end := index + slashes := 0 + for end < len(line) { + c := line[end] + switch { + case c >= 'a' && c <= 'z', c >= 'A' && c <= 'Z', c >= '0' && c <= '9', + c == '.', c == '-', c == '_': + case c == '/': + slashes++ + default: + goto done + } + end++ + } +done: + if slashes == 0 || end == index { + return false + } + // A trailing dot is sentence punctuation, not part of the path. + segment := line[index:end] + return !strings.HasPrefix(segment, "/") && !strings.HasSuffix(segment, "/") +} + +// isNameContinuation reports whether b continues a go test name rather than +// ending the word. +func isNameContinuation(b byte) bool { + return (b >= 'A' && b <= 'Z') || (b >= '0' && b <= '9') || b == '_' +} + +func isNameSeparator(b byte) bool { + switch b { + case ' ', '\t', ';', ',', '(', ')', '[', ']', '`', '"', '\'', '-', '*': + return true + } + return false +} + +// nameBoundary reports whether line[from:to] is a whole token rather than the +// head of a longer one. +// +// A raw substring search made an HONEST report look like a fabrication whenever +// one recorded name is a prefix of another, which `go test -v` guarantees: it +// prints the parent above every subtest and the ledger records both, so a +// truthful "TestParent/subcase took 0.02s" matched the ledger entry for +// TestParent and was told it invented the number. Package names collide the same +// way with no subtests at all — internal/agent is a prefix of internal/agentinit, +// and this repo has several such pairs. A tripwire that accuses honest reports is +// one that gets switched off, and then it catches nothing. +// +// "/" and "." continue a name rather than ending it, so TestParent does not match +// inside TestParent/subcase and internal/agent does not match inside +// internal/agentinit. +func nameBoundary(line string, from, to int) bool { + continues := func(r rune) bool { + // Test names are Go identifiers and may contain Unicode letters and + // digits. Conservatively treating every non-ASCII rune (including invalid + // UTF-8 decoded as RuneError) as a continuation makes an uncertain match + // fail silent rather than attributing a longer foreign name to an ASCII + // prefix. + if r >= utf8.RuneSelf { + return true + } + switch { + case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9': + return true + case r == '_', r == '/', r == '.', r == '-', r == '#': + return true + } + return false + } + if from > 0 { + before, _ := utf8.DecodeLastRuneInString(line[:from]) + if continues(before) { + return false + } + } + if to < len(line) { + after, _ := utf8.DecodeRuneInString(line[to:]) + if continues(after) { + return false + } + } + return true +} + +// parseClaimedDuration reads the FIRST duration in tail, in seconds. +// +// MINUTES COUNT. The pattern was ms-or-s only, so "1m10s" failed on "1m", the +// scan moved on, and "10s" won: a truthful restatement of a recorded 70 seconds +// was reported as a conflict, and the nudge then quoted 10s back at the model — a +// number its answer never contained. Anything over a minute is ordinary in this +// repo's own suite. +// +// POSITION DECIDES, NOT PATTERN ORDER. Trying the minute form over the whole +// tail first reached past a nearer seconds figure to claim a later one: +// +// "took 0.86s (package total 1m20s)" -> 80, not 0.86 +// +// The claim being checked is the test's own 0.86s; 1m20s is the package total +// that happens to trail it. Reading the far number as the claim invented a +// conflict against a number the model got right, which is the one failure this +// package must never produce. Both patterns are located, and the minute form +// wins only when it starts no later than the seconds form. +// +// AND POSITION IS ONLY WORTH DECIDING BETWEEN REAL DURATIONS. A bare "5m" or "9h" +// carrying a word — "handled 5m rows" — may be a count rather than a duration, +// and winning on position is exactly how it took precedence over the timing +// beside it. bareUnitIsAmbiguous holds that shape back, and its clause then +// reports nothing at all rather than a guess. +func parseClaimedDuration(tail string) (float64, bool) { + begin, end, seconds, units, ok := nextDurationToken(tail, 0) + if !ok { + return 0, false + } + // AMBIGUITY IS STILL SILENCE, NOT A SECOND-BEST READING. A bare "5m" or "9h" + // with a word directly after it may be a count rather than a duration + // ("handled 5m rows"), and reaching past it to a later figure would answer the + // same question by guessing. + if units == 1 && bareUnitFollowedByWord(tail, begin, end) { + return 0, false + } + return seconds, true +} + +// bareUnitFollowedByWord reports whether a single-component token is the +// ambiguous count shape: one figure, one unit letter, and a word beside it. A +// compound form cannot be a count, and a bare figure with nothing after it has no +// noun to be counting. +func bareUnitFollowedByWord(text string, begin, end int) bool { + if end-begin == 0 { + return false + } + switch text[end-1] { + case 'm', 'h': + default: + return false + } + if end >= len(text) { + return false + } + at := end + switch text[at] { + case '-', '_', '.': + // A connector only forms a count when word material follows it + // immediately. In particular, a sentence-ending dot in "took 5m. The" + // must not make the duration ambiguous. + at++ + default: + for at < len(text) && text[at] == ' ' { + at++ + } + if at == end { + return false + } + } + if at >= len(text) { + return false + } + letter := text[at] + return (letter >= 'a' && letter <= 'z') || (letter >= 'A' && letter <= 'Z') +} + +// sortedRunKeys walks the recorded runs in an order that does not depend on how +// the map was built. +// +// THE RUN QUOTED IS CHOSEN DETERMINISTICALLY. Map iteration order is randomised +// per range, and a merged sighting keeps the first run that recorded the name, so +// taking whichever came first made the nudge name a different command between +// identical passes — and this text reaches a model, where a message that +// reshuffles is the same problem the sorted output exists to avoid. The lowest +// run key wins, which is stable. +// +// NOTHING DOWNSTREAM CAN SEE THIS ORDER TODAY, and that is why it is a named +// function. A name recorded by several runs has its label dropped as untrue of +// any one of them, and a name recorded by one run has a single candidate, so the +// choice is forced either way and every assertion about it passes whatever this +// returns — removing the sort entirely leaves the suite green. A bound with no +// live witness is the shape that rots, so it is tested here directly instead of +// being certified by accident. +func sortedRunKeys(observed map[string]map[measurementID][]float64) []string { + keys := make([]string, 0, len(observed)) + for key := range observed { + keys = append(keys, key) + } + sort.Strings(keys) + return keys +} + +// ConflictsAcrossRuns reports numbers in claim that contradict EVERY run this +// session recorded. +// +// For a caller that cannot say which run a claim is about — the agent loop +// checking a final answer that may summarise several commands — this is the +// honest question to ask. A value the model could have read off any of them is +// not evidence of invention, and accusing it of inventing a number one of the +// commands really printed is the failure this package must never produce. +// +// Callers that DO know the command should use Conflicts, which holds the claim +// to that run's own numbers: a claim about an ordinary run is not answered by a +// value only `go test -race` printed. The difference between the two is not a +// convenience, it is how much the caller actually knows, so it is two functions +// rather than a flag. +// +// The Conflict reports the run whose values it quotes, picking the run with a +// recording for that name so the nudge names a command the model can repeat. +func (l *Ledger) ConflictsAcrossRuns(claim string) []Conflict { + if l == nil || strings.TrimSpace(claim) == "" { + return nil + } + l.mu.Lock() + l.ensureMaps() + defer l.mu.Unlock() + + // Names are gathered across runs first, so a name recorded by two commands + // is considered once against everything either of them saw. + type sighting struct { + values []float64 + run Run + runs int + } + keys := sortedRunKeys(l.observed) + + merged := map[measurementID]*sighting{} + for _, key := range keys { + for id, values := range l.observed[key] { + seen := merged[id] + if seen == nil { + seen = &sighting{run: l.runs[key]} + merged[id] = seen + } + seen.values = append(seen.values, values...) + seen.runs++ + } + } + mergedValues := make(map[measurementID][]float64, len(merged)) + for id, seen := range merged { + mergedValues[id] = seen.values + } + displayNames, known := measurementDisplayNames(mergedValues) + + var out []Conflict + for id, seen := range merged { + name := displayNames[id] + if name == "" { + continue + } + // EVERY MENTION, for the same reason as the per-run path above. + seenThisCall := map[int64]bool{} + for _, claimed := range claimedSecondsAllFor(claim, name, known) { + if l.raised[newAcrossRunsKey(name, claimed)] || seenThisCall[claimedMilli(claimed)] { + continue + } + seenThisCall[claimedMilli(claimed)] = true + agrees := false + for _, value := range seen.values { + if tolerance(claimed, value) { + agrees = true + break + } + } + if agrees { + continue + } + values := append([]float64(nil), seen.values...) + sort.Float64s(values) + // NAME A COMMAND ONLY WHEN ONE COMMAND PRINTED ALL OF THESE. Merging two + // runs' values and then labelling the union with one of them said that + // command reported a number it never printed: + // + // `go test ./a` in this session reported 0.1s, 0.2s + // + // where 0.2s came only from ./b. Choosing the run deterministically fixed + // the reshuffling and left the attribution just as untrue. With more than + // one run behind the values the label is dropped, and Nudge falls back to + // naming the session rather than a command. + attributed := seen.run + if seen.runs > 1 { + attributed = Run{} + } + out = append(out, Conflict{Name: name, Claimed: claimed, Recorded: values, Run: attributed}) + } + } + sort.Slice(out, func(i, j int) bool { + if out[i].Name != out[j].Name { + return out[i].Name < out[j].Name + } + return out[i].Claimed < out[j].Claimed + }) + for _, conflict := range out { + l.raised[newAcrossRunsKey(conflict.Name, conflict.Claimed)] = true + } + return out +} + +// Nudge renders conflicts as the correction a model is asked to act on. Empty +// when there is nothing to say, so the caller can test the string itself. +func Nudge(conflicts []Conflict) string { + if len(conflicts) == 0 { + return "" + } + var b strings.Builder + if len(conflicts) == 1 { + b.WriteString("One number in your answer does not match what this session recorded.\n") + } else { + b.WriteString("Some numbers in your answer do not match what this session recorded.\n") + } + for _, conflict := range conflicts { + b.WriteString(" - ") + b.WriteString(conflict.Name) + b.WriteString(": your answer says ") + b.WriteString(formatSeconds(conflict.Claimed)) + b.WriteString("; ") + if label := conflict.Run.Label(); label != "" { + b.WriteString("`") + b.WriteString(label) + b.WriteString("` in this session reported ") + } else { + b.WriteString("the commands actually run in this session reported ") + } + for i, value := range conflict.Recorded { + if i > 0 { + b.WriteString(", ") + } + b.WriteString(formatSeconds(value)) + } + b.WriteString(".\n") + } + b.WriteString("Re-run the command and report what it prints. If both numbers are real, give both and say what changed between them — " + + "do not replace one with the other silently. If the number was not measured in this session, say so plainly instead of stating it as a result.") + return b.String() +} + +func formatSeconds(value float64) string { + return strconv.FormatFloat(value, 'f', -1, 64) + "s" +} diff --git a/internal/measurements/measurements_test.go b/internal/measurements/measurements_test.go new file mode 100644 index 000000000..a91d35071 --- /dev/null +++ b/internal/measurements/measurements_test.go @@ -0,0 +1,1717 @@ +package measurements + +import ( + "encoding/json" + "fmt" + "regexp" + "sort" + "strconv" + "strings" + "sync" + "testing" +) + +var ( + legacyPackageResult = regexp.MustCompile(`(?m)^(ok|FAIL)\s+(\S+)\s+([0-9]+(?:\.[0-9]+)?)s(?:\s|$)`) + legacyTestResult = regexp.MustCompile(`(?m)^\s*--- (PASS|FAIL|SKIP):\s+(\S+)\s+\(([0-9]+(?:\.[0-9]+)?)s\)`) +) + +// goTestJSON keeps the conflict-classifier fixtures concise while feeding the +// production parser only the trusted event shape emitted by `go test -json`. +// Parser trust-boundary behavior itself is tested directly below. +func goTestJSON(legacy string) string { + type event struct { + Action string `json:"Action"` + Package string `json:"Package,omitempty"` + Test string `json:"Test,omitempty"` + Elapsed float64 `json:"Elapsed"` + } + var lines []string + appendEvent := func(item event) { + encoded, err := json.Marshal(item) + if err != nil { + panic(err) + } + lines = append(lines, string(encoded)) + } + for _, match := range legacyPackageResult.FindAllStringSubmatch(legacy, -1) { + seconds, _ := strconv.ParseFloat(match[3], 64) + action := "pass" + if match[1] == "FAIL" { + action = "fail" + } + appendEvent(event{Action: action, Package: match[2], Elapsed: seconds}) + } + for _, match := range legacyTestResult.FindAllStringSubmatch(legacy, -1) { + seconds, _ := strconv.ParseFloat(match[3], 64) + appendEvent(event{Action: strings.ToLower(match[1]), Package: "example.test", Test: match[2], Elapsed: seconds}) + } + return strings.Join(lines, "\n") +} + +func recordGoTest(ledger *Ledger, run Run, legacy string) int { + _, count := ledger.Record(run, goTestJSON(legacy)) + return count +} + +// Parser fixtures query a known, unchanged command. Identity/lifecycle tests +// below retain the handle returned with the actual observations instead. +func recordedRun(ledger *Ledger, run Run) RecordedRun { + handle, _ := ledger.Record(run, "") + return handle +} + +const goTestOutput = ` +ok github.com/Gitlawb/zero/internal/specialist 8.337s +FAIL github.com/Gitlawb/zero/internal/cli 34.249s +ok github.com/Gitlawb/zero/internal/config 20.047s coverage: 61.2% of statements +ok github.com/Gitlawb/zero/internal/minify (cached) +--- PASS: TestChattyChild (0.86s) +--- FAIL: TestWallBackstop (1.00s) +--- PASS: TestNested (0.03s) + --- PASS: TestNested/subcase (0.02s) +` + +// THE PARENT LINE ABOVE IS NOT OPTIONAL. go test -v always prints a parent +// before its subtests, and the earlier fixture omitted it — a shape the tool +// never emits. That single omission hid a whole class: with only the subtest +// present, no ledger name was ever a strict prefix of another, so the raw +// substring match in claimedSecondsFor looked correct. A fixture has to be the +// output a real run produced, because the trimming is where the bug lives. + +func TestParseGoTestReadsBothLineShapes(t *testing.T) { + got := ParseGoTest(goTestJSON(goTestOutput)) + byName := map[string]float64{} + for _, m := range got { + byName[m.Name] = m.Seconds + } + + for name, want := range map[string]float64{ + "github.com/Gitlawb/zero/internal/specialist": 8.337, + "github.com/Gitlawb/zero/internal/cli": 34.249, + // A trailing coverage suffix must not stop the line being read. + "github.com/Gitlawb/zero/internal/config": 20.047, + "TestChattyChild": 0.86, + "TestWallBackstop": 1.00, + // Indented subtests count: they are what a per-test table is built from. + "TestNested/subcase": 0.02, + // And the parent alongside it. The subtest alone left the prefix-trimming + // unpinned from this side: a change that dropped parent lines, or folded + // the parent's time into the child, passed every assertion here. + "TestNested": 0.03, + } { + if byName[name] != want { + t.Errorf("%s = %v, want %v", name, byName[name], want) + } + } + // A cached package reports no duration, so there is nothing to record — and + // inventing a zero for it would make every later claim look like a conflict. + if _, present := byName["github.com/Gitlawb/zero/internal/minify"]; present { + t.Error("a (cached) package was recorded with a duration it never reported") + } +} + +func TestTestStdoutCannotBecomeTimingEvidence(t *testing.T) { + const stream = "" + + `{"Action":"output","Package":"example.test","Test":"TestSpoofed","Output":"--- PASS: TestSpoofed (99.00s)\\n"}` + "\n" + + `{"Action":"pass","Package":"example.test","Test":"TestSpoofed","Elapsed":1}` + "\n" + ledger := NewLedger() + if _, n := ledger.Record(Run{}, stream); n != 1 { + t.Fatalf("recorded %d events, want only the runner result", n) + } + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestSpoofed took 99s") + if len(conflicts) != 1 || len(conflicts[0].Recorded) != 1 || conflicts[0].Recorded[0] != 1 { + t.Fatalf("test stdout satisfied a fabricated claim: %+v", conflicts) + } + if got := ParseGoTest("--- PASS: TestSpoofed (99.00s)\nok example.test 99.00s\n"); len(got) != 0 { + t.Fatalf("plain mixed-origin output became evidence: %+v", got) + } +} + +func TestCachedPackageProducesNoTimingEvidence(t *testing.T) { + // These are reduced captures from two real cached commands run against + // internal/minify. Timestamps and unrelated test events are omitted; the + // event order and cmd/go output strings are preserved. + for _, tc := range []struct { + name string + stream string + }{ + { + name: "plain", + stream: "" + + `{"Action":"run","Package":"github.com/Gitlawb/zero/internal/minify","Test":"TestStripC"}` + "\n" + + `{"Action":"output","Package":"github.com/Gitlawb/zero/internal/minify","Test":"TestStripC","Output":"--- PASS: TestStripC (0.00s)\n"}` + "\n" + + `{"Action":"pass","Package":"github.com/Gitlawb/zero/internal/minify","Test":"TestStripC","Elapsed":0}` + "\n" + + `{"Action":"output","Package":"github.com/Gitlawb/zero/internal/minify","Output":"PASS\n"}` + "\n" + + `{"Action":"output","Package":"github.com/Gitlawb/zero/internal/minify","Output":"ok \tgithub.com/Gitlawb/zero/internal/minify\t(cached)\n"}` + "\n" + + `{"Action":"pass","Package":"github.com/Gitlawb/zero/internal/minify","Elapsed":0}` + "\n", + }, + { + name: "cover", + stream: "" + + `{"Action":"pass","Package":"github.com/Gitlawb/zero/internal/minify","Test":"TestStripC","Elapsed":0}` + "\n" + + `{"Action":"output","Package":"github.com/Gitlawb/zero/internal/minify","Output":"coverage: 79.0% of statements\n"}` + "\n" + + `{"Action":"output","Package":"github.com/Gitlawb/zero/internal/minify","Output":"ok \tgithub.com/Gitlawb/zero/internal/minify\t(cached)\tcoverage: 79.0% of statements\n"}` + "\n" + + `{"Action":"pass","Package":"github.com/Gitlawb/zero/internal/minify","Elapsed":0}` + "\n", + }, + } { + t.Run(tc.name, func(t *testing.T) { + if got := ParseGoTest(tc.stream); len(got) != 0 { + t.Fatalf("cached package events became timing evidence: %+v", got) + } + ledger := NewLedger() + if _, n := ledger.Record(Run{}, tc.stream); n != 0 { + t.Fatalf("recorded %d cached timings, want none", n) + } + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestStripC took 0.86s"); len(conflicts) != 0 { + t.Fatalf("cache metadata caused a false conflict: %+v", conflicts) + } + }) + } + + const fresh = "" + + `{"Action":"pass","Package":"github.com/Gitlawb/zero/internal/minify","Test":"TestStripC","Elapsed":0.86}` + "\n" + + `{"Action":"output","Package":"github.com/Gitlawb/zero/internal/minify","Output":"ok \tgithub.com/Gitlawb/zero/internal/minify\t1.234s\n"}` + "\n" + + `{"Action":"pass","Package":"github.com/Gitlawb/zero/internal/minify","Elapsed":1.234}` + "\n" + ledger := NewLedger() + if _, n := ledger.Record(Run{}, fresh); n != 2 { + t.Fatalf("recorded %d fresh timings, want test and package", n) + } + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestStripC took 9s"); len(conflicts) != 1 || conflicts[0].Claimed != 9 { + t.Fatalf("fresh-run fabrication stopped being detected: %+v", conflicts) + } + + const mixed = "" + + `{"Action":"pass","Package":"example/cached","Test":"TestCached","Elapsed":0}` + "\n" + + `{"Action":"output","Package":"example/cached","Output":"ok \texample/cached\t(cached)\n"}` + "\n" + + `{"Action":"pass","Package":"example/cached","Elapsed":0}` + "\n" + + `{"Action":"pass","Package":"example/fresh","Test":"TestFresh","Elapsed":0.5}` + "\n" + + `{"Action":"pass","Package":"example/fresh","Elapsed":0.75}` + "\n" + got := ParseGoTest(mixed) + if len(got) != 2 || got[0].Package != "example/fresh" || got[1].Package != "example/fresh" { + t.Fatalf("cache suppression escaped its package: %+v", got) + } +} + +func TestSameNamedTestsKeepTheirPackageIdentity(t *testing.T) { + const stream = "" + + `{"Action":"pass","Package":"example/a","Test":"TestFoo","Elapsed":1}` + "\n" + + `{"Action":"pass","Package":"example/b","Test":"TestFoo","Elapsed":9}` + "\n" + run := Run{Command: "go", Args: []string{"test", "-json", "./..."}} + + wrong := NewLedger() + wrong.Record(run, stream) + conflicts := wrong.Conflicts(recordedRun(wrong, run), "example/a.TestFoo took 9s") + if len(conflicts) != 1 || conflicts[0].Name != "example/a.TestFoo" || conflicts[0].Recorded[0] != 1 { + t.Fatalf("a same-named test in another package satisfied the claim: %+v", conflicts) + } + + honest := NewLedger() + honest.Record(run, stream) + if conflicts := honest.Conflicts(recordedRun(honest, run), "example/a.TestFoo took 1s"); len(conflicts) != 0 { + t.Fatalf("the owning package value was rejected: %+v", conflicts) + } + + ambiguous := NewLedger() + ambiguous.Record(run, stream) + if conflicts := ambiguous.Conflicts(recordedRun(ambiguous, run), "TestFoo took 9s"); len(conflicts) != 0 { + t.Fatalf("an unqualified ambiguous test borrowed a package identity: %+v", conflicts) + } +} + +func TestPackageAndQualifiedTestDisplayCollisionFailsSilent(t *testing.T) { + const stream = "" + + `{"Action":"pass","Package":"example/a.TestFoo","Elapsed":1}` + "\n" + + `{"Action":"pass","Package":"example/a","Test":"TestFoo","Elapsed":9}` + "\n" + + `{"Action":"pass","Package":"example/b","Test":"TestFoo","Elapsed":2}` + "\n" + run := Run{Command: "go", Args: []string{"test", "-json", "./..."}} + + for _, entry := range []struct { + name string + check func(*Ledger, string) []Conflict + }{ + {"per-run", func(ledger *Ledger, claim string) []Conflict { + return ledger.Conflicts(recordedRun(ledger, run), claim) + }}, + {"across-runs", func(ledger *Ledger, claim string) []Conflict { return ledger.ConflictsAcrossRuns(claim) }}, + } { + t.Run(entry.name, func(t *testing.T) { + ledger := NewLedger() + ledger.Record(run, stream) + if conflicts := entry.check(ledger, "example/a.TestFoo took 30s"); len(conflicts) != 0 { + t.Fatalf("ambiguous package/test display identity produced conflicts: %+v", conflicts) + } + + // The collision is local to example/a.TestFoo. A distinct qualified + // identity must remain enforceable rather than disabling the detector. + if conflicts := entry.check(ledger, "example/b.TestFoo took 30s"); len(conflicts) != 1 || conflicts[0].Name != "example/b.TestFoo" { + t.Fatalf("non-colliding qualified test stopped being checked: %+v", conflicts) + } + }) + } +} + +// THE FAILURE THIS WAS BUILT FOR: the same test reported at 0.86s in one paste +// and 4.20s in the next, with nothing said about the difference. +func TestAClaimThatContradictsTheTranscriptIsCaught(t *testing.T) { + ledger := NewLedger() + if n := recordGoTest(ledger, Run{}, goTestOutput); n == 0 { + t.Fatal("nothing was recorded, so no conflict could ever be found") + } + + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "| TestChattyChild | 4.20s | passes |") + if len(conflicts) != 1 { + t.Fatalf("got %d conflicts, want 1: %+v", len(conflicts), conflicts) + } + if conflicts[0].Name != "TestChattyChild" || conflicts[0].Claimed != 4.20 { + t.Fatalf("wrong conflict: %+v", conflicts[0]) + } + if len(conflicts[0].Recorded) != 1 || conflicts[0].Recorded[0] != 0.86 { + t.Fatalf("the recorded value is not carried back to the reader: %+v", conflicts[0]) + } +} + +// ...and the honest cases stay silent. A tripwire that fires on ordinary +// variation gets switched off, and then it catches nothing at all. +func TestHonestReportingProducesNoConflict(t *testing.T) { + for name, claim := range map[string]string{ + "the number as recorded": "TestChattyChild took 0.86s.", + "ordinary run-to-run variation": "TestChattyChild took 0.91s.", + "a package line restated": "ok github.com/Gitlawb/zero/internal/specialist 8.4s", + "sub-centisecond jitter": "TestNested/subcase (0.03s)", + "named without a timing": "TestChattyChild passes.", + "a name this session never ran": "TestSomethingElse took 99.0s.", + "the same value in milliseconds": "TestChattyChild took 860ms.", + } { + fresh := NewLedger() + recordGoTest(fresh, Run{}, goTestOutput) + if got := fresh.Conflicts(recordedRun(fresh, Run{}), claim); len(got) != 0 { + t.Errorf("%s produced a false conflict: %+v", name, got) + } + } +} + +// A NUMBER THREE PARAGRAPHS AWAY IS NOT THIS NAME'S TIMING. Pairing across lines +// would invent disagreements rather than find them. +func TestADurationOnAnotherLineIsNotPairedWithTheName(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, goTestOutput) + + claim := "TestChattyChild is the one to look at.\n\nSeparately, the whole suite took 4.20s." + if got := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(got) != 0 { + t.Errorf("a duration from an unrelated line was attributed to the test: %+v", got) + } +} + +// EACH NAME IS RAISED ONCE. The caller feeds this back to the model, so a second +// pass over an uncorrected answer has to be silent or the loop never ends. +func TestAConflictIsRaisedOnlyOnce(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, goTestOutput) + claim := "TestChattyChild took 4.20s." + + if got := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(got) != 1 { + t.Fatalf("first pass found %d conflicts, want 1", len(got)) + } + if got := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(got) != 0 { + t.Fatalf("the same conflict was raised twice, so an unchanged answer would loop: %+v", got) + } +} + +// A test run twice legitimately has two timings, and matching EITHER is honest. +func TestMatchingAnyRecordedValueIsEnough(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFlaky (0.10s)\n") + recordGoTest(ledger, Run{}, "--- PASS: TestFlaky (9.90s)\n") + + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFlaky took 9.90s."); len(got) != 0 { + t.Errorf("matching the second of two recorded runs was called a conflict: %+v", got) + } + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFlaky took 45.0s."); len(got) != 1 { + t.Errorf("a value matching neither run was not caught: %+v", got) + } +} + +// The nudge has to name the number, the recorded value, and what to do — a +// warning a model cannot act on is a warning it will not act on. +func TestTheNudgeNamesBothNumbersAndTheRemedy(t *testing.T) { + nudge := Nudge([]Conflict{{Name: "TestChattyChild", Claimed: 4.2, Recorded: []float64{0.86}}}) + for _, required := range []string{"TestChattyChild", "4.2s", "0.86s", "Re-run the command", "give both"} { + if !strings.Contains(nudge, required) { + t.Errorf("the nudge does not contain %q:\n%s", required, nudge) + } + } + if Nudge(nil) != "" { + t.Error("an empty conflict set must render nothing") + } +} + +// A nil Ledger is a working no-op: the loop calls these unconditionally and only +// holds a real ledger under the posture. +func TestANilLedgerIsSafe(t *testing.T) { + var ledger *Ledger + if got := recordGoTest(ledger, Run{}, goTestOutput); got != 0 { + t.Errorf("Record on a nil ledger returned %d", got) + } + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestChattyChild took 4.20s."); got != nil { + t.Errorf("Conflicts on a nil ledger returned %+v", got) + } + // BOTH entry points, since the loop calls this one and not the other. + if got := ledger.ConflictsAcrossRuns("TestChattyChild took 4.20s."); got != nil { + t.Errorf("ConflictsAcrossRuns on a nil ledger returned %+v", got) + } +} + +// Tool results arrive from concurrently executed tool calls, so recording races +// against recording and against the final check. +func TestTheLedgerIsSafeUnderConcurrentRecording(t *testing.T) { + ledger := NewLedger() + var wait sync.WaitGroup + for i := 0; i < 16; i++ { + wait.Add(1) + go func() { + defer wait.Done() + recordGoTest(ledger, Run{}, goTestOutput) + ledger.Conflicts(recordedRun(ledger, Run{}), "nothing to see") + }() + } + wait.Wait() + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestChattyChild took 4.20s."); len(got) != 1 { + t.Fatalf("got %d conflicts after concurrent recording, want 1", len(got)) + } +} + +// An HONEST report must not be called a fabrication because one recorded name is +// a prefix of another. go test -v guarantees the collision: it prints the parent +// above every subtest and the ledger records both, so a truthful subtest claim +// matched the parent's entry and was told it invented the number. Package names +// collide with no subtests at all — internal/agent is a prefix of +// internal/agentinit, and this repo has several such pairs. +func TestAPrefixNameDoesNotAccuseAnHonestClaim(t *testing.T) { + ledger := NewLedger() + // Exactly what go test -v emits: parent first, subtest indented under it. + // + // THE TWO DURATIONS MUST BE FAR APART. At 0.03s and 0.01s they sit inside + // tolerance of each other, so a subtest claim matching the PARENT's entry + // reads as agreement and this test passes whether or not the prefix boundary + // works — it certified nothing. Five seconds against a hundredth cannot be + // confused for the same measurement. + recordGoTest(ledger, Run{}, "--- PASS: TestNested (5.00s)\n --- PASS: TestNested/subcase (0.01s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestNested/subcase took 0.01s"); len(conflicts) != 0 { + t.Errorf("an honest subtest claim was reported as a conflict: %+v", conflicts) + } + + packages := NewLedger() + recordGoTest(packages, Run{}, "ok \tgithub.com/Gitlawb/zero/internal/agent\t35.58s\nok \tgithub.com/Gitlawb/zero/internal/agentinit\t1.66s\n") + if conflicts := packages.Conflicts(recordedRun(packages, Run{}), "github.com/Gitlawb/zero/internal/agentinit took 1.66s"); len(conflicts) != 0 { + t.Errorf("an honest package claim was reported as a conflict: %+v", conflicts) + } + + // And the check still bites: a genuinely wrong subtest number is caught, and + // attributed to the subtest rather than to its parent. + caught := NewLedger() + recordGoTest(caught, Run{}, "--- PASS: TestNested (5.00s)\n --- PASS: TestNested/subcase (0.01s)\n") + conflicts := caught.Conflicts(recordedRun(caught, Run{}), "TestNested/subcase took 4.20s") + if len(conflicts) != 1 || conflicts[0].Name != "TestNested/subcase" { + t.Errorf("a fabricated subtest number was not caught against its own name: %+v", conflicts) + } +} + +func TestAUnicodeSuffixDoesNotBelongToTheASCIIName(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (1.00s)\n") + + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFooΩ took 9.00s"); len(conflicts) != 0 { + t.Fatalf("a Unicode-suffixed name was attributed to its ASCII prefix: %+v", conflicts) + } + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "ΩTestFoo took 9.00s"); len(conflicts) != 0 { + t.Fatalf("a name after a Unicode continuation was treated as a standalone token: %+v", conflicts) + } + + wrong := NewLedger() + recordGoTest(wrong, Run{}, "--- PASS: TestFoo (1.00s)\n") + if conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestFoo took 9.00s"); len(conflicts) != 1 || conflicts[0].Name != "TestFoo" || conflicts[0].Claimed != 9 { + t.Fatalf("an exact-name fabricated duration stopped being caught: %+v", conflicts) + } +} + +// A duration carrying a minute component must be read whole. The pattern was +// ms-or-s only, so "1m10s" failed on "1m" and "10s" won — a truthful restatement +// of a recorded 70 seconds became a conflict, and the nudge quoted 10s back at +// the model, a number its answer never contained. +func TestAMinuteDurationIsReadWhole(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestSlow (70.00s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestSlow took 1m10s"); len(conflicts) != 0 { + t.Errorf("an honest 1m10s claim was reported as a conflict: %+v", conflicts) + } + + bare := NewLedger() + recordGoTest(bare, Run{}, "--- PASS: TestTwoMinutes (120.00s)\n") + if conflicts := bare.Conflicts(recordedRun(bare, Run{}), "TestTwoMinutes took 2m"); len(conflicts) != 0 { + t.Errorf("an honest bare-minute claim was reported as a conflict: %+v", conflicts) + } + + // Still caught when the minutes really disagree. + wrong := NewLedger() + recordGoTest(wrong, Run{}, "--- PASS: TestSlow (70.00s)\n") + conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestSlow took 5m00s") + if len(conflicts) != 1 || conflicts[0].Claimed != 300 { + t.Errorf("a fabricated 5m00s was not caught as 300s: %+v", conflicts) + } +} + +// The nearest duration is the claim, whichever form it is written in. Every case +// above puts the minute figure FIRST, so trying that pattern over the whole tail +// ahead of the seconds pattern passed them all while reaching past a nearer +// seconds figure to claim a later one — inventing a conflict against a number the +// model had right, the one failure this package must never produce. +func TestTheNearestDurationIsTheClaim(t *testing.T) { + honest := NewLedger() + recordGoTest(honest, Run{}, "--- PASS: TestChattyChild (0.86s)\n") + // The package total trails the test's own timing, exactly as `go test` prints it. + if conflicts := honest.Conflicts(recordedRun(honest, Run{}), "TestChattyChild took 0.86s (package total 1m20s)"); len(conflicts) != 0 { + t.Errorf("a correct 0.86s claim was reported as a conflict because a later 1m20s was read instead: %+v", conflicts) + } + + ms := NewLedger() + recordGoTest(ms, Run{}, "--- PASS: TestQuick (0.45s)\n") + if conflicts := ms.Conflicts(recordedRun(ms, Run{}), "TestQuick took 450ms, well under the 2m budget"); len(conflicts) != 0 { + t.Errorf("a correct 450ms claim was reported as a conflict: %+v", conflicts) + } + + // And a seconds figure sitting nearby does not rescue a wrong minute claim + // when the minute figure is the one being stated. + wrong := NewLedger() + recordGoTest(wrong, Run{}, "--- PASS: TestSlow (70.00s)\n") + conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestSlow took 5m00s, not the 70s you might expect") + if len(conflicts) != 1 || conflicts[0].Claimed != 300 { + t.Errorf("a fabricated 5m00s was not caught as 300s: %+v", conflicts) + } +} + +// A NAME'S DURATION IS THE ONE IN ITS OWN CLAUSE. +// +// Searching the whole remainder of the line let one name take another's number: +// with TestFoo at 0.10s and TestBar at 4.20s recorded, the entirely truthful +// "TestFoo passed; TestBar took 4.20s" reported TestFoo as claiming 4.2. Every +// word of that sentence is correct, and the check called it a fabrication. +func TestADurationBelongsToTheNameBesideIt(t *testing.T) { + honest := NewLedger() + recordGoTest(honest, Run{}, "--- PASS: TestFoo (0.10s)\n--- PASS: TestBar (4.20s)\n") + for _, claim := range []string{ + "TestFoo passed; TestBar took 4.20s", + "TestFoo was fine, TestBar took 4.20s", + "TestFoo and TestBar both ran; TestBar took 4.20s", + } { + if conflicts := honest.Conflicts(recordedRun(honest, Run{}), claim); len(conflicts) != 0 { + t.Errorf("a truthful claim was reported as a conflict: %q -> %+v", claim, conflicts) + } + } + + // The name's OWN number is still read, and a wrong one still caught. + caught := NewLedger() + recordGoTest(caught, Run{}, "--- PASS: TestFoo (0.10s)\n--- PASS: TestBar (4.20s)\n") + conflicts := caught.Conflicts(recordedRun(caught, Run{}), "TestFoo took 9.90s; TestBar took 4.20s") + if len(conflicts) != 1 || conflicts[0].Name != "TestFoo" || conflicts[0].Claimed != 9.9 { + t.Errorf("a fabricated TestFoo timing beside an honest TestBar one was not caught: %+v", conflicts) + } +} + +// A SECOND, DIFFERENT WRONG NUMBER IS A SECOND THING TO SAY. +// +// Suppressing by name alone switched the check off for that test permanently: +// after one bad 4.20s, a later and differently bad 9.90s was silent. Re-reading +// the same answer must still say nothing, which is what the dedupe is for. +func TestEachWrongValueIsReportedOnce(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFoo took 4.20s"); len(got) != 1 { + t.Fatalf("the first wrong value was not reported: %+v", got) + } + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFoo took 9.90s"); len(got) != 1 || got[0].Claimed != 9.9 { + t.Errorf("a second, differently wrong value was swallowed: %+v", got) + } + // The SAME wrong value again says nothing, so feeding a correction back + // cannot loop. + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFoo took 4.20s"); len(got) != 0 { + t.Errorf("the same conflict was raised twice: %+v", got) + } +} + +// TIMINGS FROM DIFFERENT COMMANDS ARE DIFFERENT MEASUREMENTS. +// +// Pooling every value under the name alone let a claim about an ordinary run be +// satisfied by a number only the -race run produced — and -race is routinely +// several times slower, which is the size of discrepancy this package exists to +// catch. +func TestAClaimIsCheckedAgainstItsOwnRun(t *testing.T) { + plain := Run{Command: "go", Args: []string{"test", "./..."}} + race := Run{Command: "go", Args: []string{"test", "-race", "./..."}} + + ledger := NewLedger() + recordGoTest(ledger, plain, "--- PASS: TestSlow (1.00s)\n") + recordGoTest(ledger, race, "--- PASS: TestSlow (9.00s)\n") + + // The race value must not excuse a plain-run claim of 9s. + conflicts := ledger.Conflicts(recordedRun(ledger, plain), "TestSlow took 9.00s") + if len(conflicts) != 1 { + t.Fatalf("a plain-run claim borrowed the -race value: %+v", conflicts) + } + if len(conflicts[0].Recorded) != 1 || conflicts[0].Recorded[0] != 1.00 { + t.Errorf("the conflict quoted values from another run: %+v", conflicts[0].Recorded) + } + // And the same number IS right for the run that produced it. + if got := ledger.Conflicts(recordedRun(ledger, race), "TestSlow took 9.00s"); len(got) != 0 { + t.Errorf("a truthful -race claim was reported as a conflict: %+v", got) + } + + // The nudge names the command, so the model is told which run to re-run. + nudge := Nudge(conflicts) + if !strings.Contains(nudge, "go test ./...") { + t.Errorf("the nudge does not name the run it is about: %q", nudge) + } + // A ledger that never distinguishes runs reads exactly as before. + if label := (Run{}).Label(); label != "" { + t.Errorf("the zero Run has a label: %q", label) + } +} + +func TestRunProvenanceIsSnapshottedAtRecordTime(t *testing.T) { + args := []string{"test", "./a"} + ledger := NewLedger() + recordGoTest(ledger, Run{Command: "go", Args: args, Dir: "/workspace/a"}, "--- PASS: TestSlow (1.00s)\n") + + // Command builders commonly reuse an argv slice for the next invocation. + args[1] = "./b" + conflicts := ledger.ConflictsAcrossRuns("TestSlow took 9.00s") + if len(conflicts) != 1 { + t.Fatalf("conflicts = %+v, want one", conflicts) + } + if got := conflicts[0].Run.Label(); got != "go test ./a (dir /workspace/a)" { + t.Fatalf("retained run label = %q, want original command", got) + } + if nudge := Nudge(conflicts); !strings.Contains(nudge, "go test ./a (dir /workspace/a)") || strings.Contains(nudge, "./b") { + t.Fatalf("nudge lost immutable provenance: %q", nudge) + } +} + +func TestStrictConflictKeepsRecordedRunAfterQueryArgsMutate(t *testing.T) { + args := []string{"test", "./a"} + run := Run{Command: "go", Args: args, Dir: "/workspace/a"} + ledger := NewLedger() + handle, _ := ledger.Record(run, goTestJSON("--- PASS: TestSlow (1.00s)\n")) + args[1] = "./b" + run.Dir = "/workspace/b" + + conflicts := ledger.Conflicts(handle, "TestSlow took 9.00s") + if len(conflicts) != 1 { + t.Fatalf("conflicts = %+v, want one", conflicts) + } + nudge := Nudge(conflicts) + if !strings.Contains(nudge, "go test ./a (dir /workspace/a)") || strings.Contains(nudge, "./b") { + t.Fatalf("strict conflict retained mutable query provenance: %q", nudge) + } +} + +func TestRecordedIdentitySurvivesBuilderReuse(t *testing.T) { + ledger := NewLedger() + args := []string{"test", "./a"} + run := Run{Command: "go", Args: args, Dir: "/workspace/a"} + first, count := ledger.Record(run, goTestJSON("--- PASS: TestSlow (1.00s)\n")) + if count != 1 { + t.Fatalf("first record accepted %d timings", count) + } + args[1] = "./b" + run.Dir = "/workspace/b" + second, _ := ledger.Record(run, goTestJSON("--- PASS: TestSlow (9.00s)\n")) + args[1] = "./c" + if got := ledger.Conflicts(first, "TestSlow took 9s"); len(got) != 1 || got[0].Run.Label() != "go test ./a (dir /workspace/a)" { + t.Fatalf("first record identity changed with builder: %+v", got) + } + if got := ledger.Conflicts(second, "TestSlow took 9s"); len(got) != 0 { + t.Fatalf("second record mixed with first: %+v", got) + } + if got := ledger.Conflicts(second, "TestSlow took 1s"); len(got) != 1 || got[0].Run.Label() != "go test ./b (dir /workspace/b)" { + t.Fatalf("second record lost its own identity: %+v", got) + } + other := NewLedger() + other.Record(run, goTestJSON("--- PASS: TestSlow (2.00s)\n")) + for _, invalid := range []RecordedRun{{}, first} { + if got := other.Conflicts(invalid, "TestSlow took 99s"); len(got) != 0 { + t.Fatalf("invalid handle selected evidence: %+v", got) + } + } +} + +func TestRunKeyPreservesArgumentCardinalityAndContents(t *testing.T) { + noArgs := Run{Command: "tool"} + emptyArg := Run{Command: "tool", Args: []string{""}} + if noArgs.key() == emptyArg.key() { + t.Fatal("no argv and one explicit empty argv value have the same run key") + } + if (Run{Command: "tool", Args: []string{"a\x00b"}}).key() == + (Run{Command: "tool", Args: []string{"a", "b"}}).key() { + t.Fatal("an embedded NUL collapsed distinct argv values") + } + + ledger := NewLedger() + recordGoTest(ledger, noArgs, "--- PASS: TestSlow (1.00s)\n") + recordGoTest(ledger, emptyArg, "--- PASS: TestSlow (9.00s)\n") + conflicts := ledger.Conflicts(recordedRun(ledger, noArgs), "TestSlow took 9.00s") + if len(conflicts) != 1 || len(conflicts[0].Recorded) != 1 || conflicts[0].Recorded[0] != 1 { + t.Fatalf("the empty-argument run satisfied the no-argument claim: %+v", conflicts) + } + if got := ledger.Conflicts(recordedRun(ledger, emptyArg), "TestSlow took 9.00s"); len(got) != 0 { + t.Fatalf("the empty-argument run rejected its own value: %+v", got) + } +} + +func TestRunLabelPreservesDirectoryAndArgumentBoundaries(t *testing.T) { + spaced := Run{Command: "go", Args: []string{"test", "a b"}, Dir: "/workspace/one"}.Label() + separate := Run{Command: "go", Args: []string{"test", "a", "b"}, Dir: "/workspace/two"}.Label() + if spaced != `go test "a b" (dir /workspace/one)` { + t.Fatalf("space-containing argument label = %q", spaced) + } + if separate != "go test a b (dir /workspace/two)" { + t.Fatalf("separate argument label = %q", separate) + } + if spaced == separate { + t.Fatal("distinct run identities rendered identically") + } +} + +// A CALLER THAT CANNOT NAME THE RUN ASKS A DIFFERENT QUESTION. +// +// The agent loop checks a final answer that may summarise several commands, so +// it has no single run to hold the claim to. Quoting a number one of those +// commands really printed is not invention, and accusing it would be the false +// accusation this package must never produce — so across runs, a value that +// matches ANY of them agrees. +func TestAcrossRunsAcceptsAValueAnyRunPrinted(t *testing.T) { + plain := Run{Command: "go", Args: []string{"test", "./..."}} + race := Run{Command: "go", Args: []string{"test", "-race", "./..."}} + + ledger := NewLedger() + recordGoTest(ledger, plain, "--- PASS: TestSlow (1.00s)\n") + recordGoTest(ledger, race, "--- PASS: TestSlow (9.00s)\n") + + // Either number is one this session really printed. + if got := ledger.ConflictsAcrossRuns("TestSlow took 9.00s"); len(got) != 0 { + t.Errorf("a value the -race run printed was called a fabrication: %+v", got) + } + if got := ledger.ConflictsAcrossRuns("TestSlow took 1.00s"); len(got) != 0 { + t.Errorf("a value the plain run printed was called a fabrication: %+v", got) + } + // A number NO run printed is still caught, and both runs' values are quoted. + conflicts := ledger.ConflictsAcrossRuns("TestSlow took 45.00s") + if len(conflicts) != 1 { + t.Fatalf("a number no run printed was not caught: %+v", conflicts) + } + if len(conflicts[0].Recorded) != 2 { + t.Errorf("the conflict quoted %v; both runs' values belong in it", conflicts[0].Recorded) + } + + // THE SAME CONFLICT IS RAISED ONCE, however the map happened to iterate. + // + // The dedupe key was built from whichever run map iteration picked first, and + // Go randomises that per range, so a name recorded under two commands was + // re-reported on a later pass one time in four. The agent loop feeds this + // back to the model as a correction; raising it again is how that loops. + // + // Repeated 200 times because a key that depends on map order fails + // intermittently, and a single pass would call it fixed. + for attempt := 0; attempt < 200; attempt++ { + repeat := NewLedger() + recordGoTest(repeat, plain, "--- PASS: TestSlow (1.00s)\n") + recordGoTest(repeat, race, "--- PASS: TestSlow (9.00s)\n") + if first := repeat.ConflictsAcrossRuns("TestSlow took 45.00s"); len(first) != 1 { + t.Fatalf("attempt %d: the first pass did not report: %+v", attempt, first) + } + if again := repeat.ConflictsAcrossRuns("TestSlow took 45.00s"); len(again) != 0 { + t.Fatalf("attempt %d: the same conflict was raised twice: %+v", attempt, again) + } + } + + // AND THE RUN IT QUOTES IS THE ONE THAT RECORDED THE NAME, named here rather + // than checked for being non-empty. + // + // THIS IS NOT THE DETERMINISM CHECK, though it used to be dressed as one: + // 200 identical passes collected the label into a set and required the set to + // hold one entry. TestOnlyPlain is recorded by a single run, so a single + // candidate exists however the map iterates and the set could not hold two. + // It was vacuous by accident before that — the same name under both runs + // makes the report a merged one, and merged reports drop the label, so it + // watched an empty string — and vacuous by construction after the repair. + // Determinism is asserted where something can actually reshuffle, in + // TestTheReportIsIdenticalBetweenIdenticalPasses. + stable := NewLedger() + recordGoTest(stable, plain, "--- PASS: TestOnlyPlain (1.00s)\n") + recordGoTest(stable, race, "--- PASS: TestOnlyRace (9.00s)\n") + reported := stable.ConflictsAcrossRuns("TestOnlyPlain took 45.00s") + if len(reported) != 1 || reported[0].Run.Label() != "go test ./..." { + t.Fatalf("a single-run conflict must quote the command that recorded it: %+v", reported) + } + + // THE TWO ENTRY POINTS KEEP SEPARATE BOOKS, deliberately. They answer + // different questions, so neither suppresses the other — asking both on one + // ledger reports the same number twice, once per question. No caller does: + // the agent loop and the specialist each use ConflictsAcrossRuns, and the + // per-run form is for a caller that knows its command. Pinned because it is a + // real consequence of the split rather than an accident. + shared := NewLedger() + recordGoTest(shared, plain, "--- PASS: TestSlow (1.00s)\n") + if got := shared.Conflicts(recordedRun(shared, plain), "TestSlow took 45.00s"); len(got) != 1 { + t.Errorf("the per-run question was not answered: %+v", got) + } + if got := shared.ConflictsAcrossRuns("TestSlow took 45.00s"); len(got) != 1 { + t.Errorf("the cross-run question was suppressed by the per-run one: %+v", got) + } + + // And the strict, per-run check still holds a claim to its own run — that is + // the whole difference between the two entry points. + strict := NewLedger() + recordGoTest(strict, plain, "--- PASS: TestSlow (1.00s)\n") + recordGoTest(strict, race, "--- PASS: TestSlow (9.00s)\n") + if got := strict.Conflicts(recordedRun(strict, plain), "TestSlow took 9.00s"); len(got) != 1 { + t.Errorf("the per-run check accepted another run's value: %+v", got) + } +} + +// A NEIGHBOUR BOUNDS THE CLAUSE WHETHER OR NOT IT WAS MEASURED. +// +// Cutting only at names the ledger knows left an unrecorded neighbour holding +// the number, and the name before it took the blame: +// +// recorded: TestFoo 0.10s +// claim: "TestFoo passed; TestUnrecorded took 4.20s" +// -> [{Name:TestFoo Claimed:4.2 Recorded:[0.1]}] +// +// Whether a number belongs to a name cannot depend on whether some OTHER name +// happened to be measured this session. Name shape and clause separators bound +// it too, and all three only ever shorten the search — each can cost a +// detection, none can invent one. +func TestAnUnrecordedNeighbourStillEndsTheClause(t *testing.T) { + for _, claim := range []string{ + "TestFoo passed; TestUnrecorded took 4.20s", + "TestFoo passed and TestUnrecorded took 4.20s", + "TestFoo was fine, BenchmarkThing took 4.20s", + // Not name-shaped at all — the separator is what ends this one. + "TestFoo passed, the suite took 4.20s", + // NO SEPARATOR ANYWHERE. These can only be stopped by the name-shape + // bound, which is the point: every case above contains a comma, a + // semicolon or an " and ", so they all passed while nextNameShaped was + // returning -1 for every realistic input and the dead branch looked + // alive. A bound that only its neighbours can certify is not covered. + "TestFoo passed TestUnrecorded took 4.20s", + "TestFoo was fine BenchmarkThing took 4.20s", + "TestFoo ok FuzzParse took 4.20s", + "TestFoo ok Example_usage took 4.20s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("a truthful claim was blamed for a neighbour's number: %q -> %+v", claim, conflicts) + } + } + + // The name's own number is still read, with a neighbour present and without. + for _, claim := range []string{ + "TestFoo took 9.90s", + "TestFoo took 9.90s and TestBar took 1.00s", + "TestFoo took 9.90s; TestUnrecorded took 4.20s", + "TestFoo took 9.90s TestBar took 1.00s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim) + if len(conflicts) != 1 || conflicts[0].Claimed != 9.9 { + t.Errorf("a fabricated number beside a neighbour was not caught: %q -> %+v", claim, conflicts) + } + } + + // "testing", "tested" and a bare "test" are ordinary words, not names, and + // must not cut the clause short. + for _, claim := range []string{ + "TestFoo took 9.90s after testing the parser", + "TestFoo took 9.90s, tested twice", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 1 { + t.Errorf("an ordinary word beginning with a name prefix ended the clause: %q -> %+v", claim, conflicts) + } + } + + // A package name is a name too, and its own claim still lands. + packages := NewLedger() + recordGoTest(packages, Run{}, "ok \tgithub.com/x/y\t8.00s\n") + if conflicts := packages.Conflicts(recordedRun(packages, Run{}), "github.com/x/y took 30.00s"); len(conflicts) != 1 { + t.Errorf("a package claim stopped being read: %+v", conflicts) + } +} + +// A FULL STOP ENDS A CLAUSE. +// +// The separator list had no sentence terminator, so when the next sentence's +// subject was an ordinary noun phrase — not a recorded name, not name-shaped — +// nothing bounded the clause and its number was charged to the previous +// sentence's test. Both sentences true, both numbers really measured, each +// attached by the writer to the right subject, and the report accused of +// fabricating one of them. +func TestASentenceTerminatorEndsTheClause(t *testing.T) { + for _, claim := range []string{ + "TestNested is green. The full run took 34.249s.", + "TestNested passed! The full run took 34.249s.", + "TestNested is green? The full run took 34.249s.", + "TestNested ok: package total 34.249s.", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestNested (0.03s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("the next sentence's number was charged to this test: %q -> %+v", claim, conflicts) + } + } + + // A DECIMAL POINT IS NOT A TERMINATOR, and neither is the dot in an import + // path — otherwise this bound would silence every claim it is meant to read. + for _, tc := range []struct { + recorded, claim string + want float64 + }{ + {"--- PASS: TestNested (0.03s)\n", "TestNested took 9.90s.", 9.9}, + {"--- PASS: TestNested (0.03s)\n", "TestNested took 9.90s. The full run took 34.249s.", 9.9}, + {"ok \tgithub.com/x/y\t8.00s\n", "github.com/x/y took 30.00s.", 30}, + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, tc.recorded) + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), tc.claim) + if len(conflicts) != 1 || conflicts[0].Claimed != tc.want { + t.Errorf("a fabricated number stopped being read: %q -> %+v", tc.claim, conflicts) + } + } + + // The first duration in the clause still wins, so an honest report that gives + // its own timing before the total is untouched. + honest := NewLedger() + recordGoTest(honest, Run{}, "--- PASS: TestNested (0.03s)\n") + if conflicts := honest.Conflicts(recordedRun(honest, Run{}), "TestNested passed in 0.03s. The full run took 34.249s."); len(conflicts) != 0 { + t.Errorf("an honest report carrying both numbers was flagged: %+v", conflicts) + } +} + +// A COMMAND IS NAMED ONLY WHEN THAT COMMAND PRINTED ALL OF THESE VALUES. +// +// ConflictsAcrossRuns merges every run's values for a name. Labelling that union +// with one run said the command reported a number it never printed — +// "`go test ./a` in this session reported 0.1s, 0.2s" where 0.2s came only from +// ./b. Choosing the run deterministically fixed the reshuffling and left the +// attribution just as untrue. +func TestAMergedResultIsNotAttributedToOneCommand(t *testing.T) { + merged := NewLedger() + recordGoTest(merged, Run{Command: "go", Args: []string{"test", "./a"}}, "--- PASS: TestFoo (0.10s)\n") + recordGoTest(merged, Run{Command: "go", Args: []string{"test", "./b"}}, "--- PASS: TestFoo (0.20s)\n") + conflicts := merged.ConflictsAcrossRuns("TestFoo took 9.90s") + if len(conflicts) != 1 { + t.Fatalf("expected one conflict, got %+v", conflicts) + } + if label := conflicts[0].Run.Label(); label != "" { + t.Errorf("values from two runs were attributed to %q", label) + } + if nudge := Nudge(conflicts); strings.Contains(nudge, "go test ./a") || strings.Contains(nudge, "go test ./b") { + t.Errorf("the nudge names one command for a merged set: %q", nudge) + } + + // One run behind the values keeps the label, which is the useful case: the + // model is told exactly which command to re-run. + single := NewLedger() + recordGoTest(single, Run{Command: "go", Args: []string{"test", "./a"}}, "--- PASS: TestFoo (0.10s)\n") + one := single.ConflictsAcrossRuns("TestFoo took 9.90s") + if len(one) != 1 || one[0].Run.Label() != "go test ./a" { + t.Errorf("a single-run result lost its command label: %+v", one) + } +} + +// CLAUSE PUNCTUATION IS A CLOSED SET, and the plain hyphen was missing from it. +// +// Walking the shapes rather than reasoning about them found five that leaked, +// not one: the ASCII hyphen everyone types, both typographic dashes, a +// parenthetical and a pipe. Each let a following clause's number be charged to +// the name in front of it. +func TestEveryClausePunctuationEndsTheClause(t *testing.T) { + for _, claim := range []string{ + "TestChattyChild passed. the suite took 34.249s.", + "TestChattyChild passed; the suite took 34.249s.", + "TestChattyChild passed: the suite took 34.249s.", + "TestChattyChild passed, the suite took 34.249s.", + "TestChattyChild passed - the suite took 34.249s.", + "TestChattyChild passed -- the suite took 34.249s.", + "TestChattyChild passed — the suite took 34.249s.", + "TestChattyChild passed – the suite took 34.249s.", + "TestChattyChild passed (the suite took 34.249s)", + "TestChattyChild passed | suite 34.249s", + "TestChattyChild - the suite took 34.249s.", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestChattyChild (0.86s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("a following clause's number was charged to this test: %q -> %+v", claim, conflicts) + } + } +} + +// PUNCTUATION ALONE DOES NOT END A CLAUSE — A NEW SUBJECT DOES. +// +// Treating the punctuation itself as the boundary cuts a test's own number away +// from its name, which silences a real fabrication. "TestFoo (9.99s)" and +// "TestFoo passed - 9.99s" are ordinary ways of stating one test's timing; what +// makes the same punctuation a break is a subject named after it. +// +// The last two were MISSED before this rule existed, because the comma and colon +// were already unconditional separators — so this recovers detections rather than +// only adding bounds. +func TestPunctuationCarryingThisTestsOwnNumberIsNotABoundary(t *testing.T) { + for _, claim := range []string{ + "TestChattyChild (9.99s)", + "TestChattyChild - 9.99s", + "TestChattyChild — 9.99s", + "TestChattyChild | 9.99s", + "TestChattyChild took 9.99s", + "TestChattyChild passed in 9.99s", + "TestChattyChild passed (9.99s)", + "TestChattyChild passed - 9.99s", + "TestChattyChild passed, 9.99s", + "TestChattyChild passed: 9.99s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestChattyChild (0.86s)\n") + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim) + if len(conflicts) != 1 || conflicts[0].Claimed != 9.99 { + t.Errorf("a test's own number stopped being read: %q -> %+v", claim, conflicts) + } + } +} + +// HOURS COUNT, for the reason minutes did one round earlier. Without an hour +// form "1h10m0s" matched only its minute remainder and read as 600s, so a +// truthful restatement of a recorded 4200s was reported as a fabrication. +// +// The hour form is its OWN pattern rather than an optional prefix on the minute +// one: making every part optional lets the expression match the EMPTY string, +// which regexp finds at offset 0 ahead of any real duration — that version read +// "1h10m0s" as 0s, which is worse than the bug it was fixing. +func TestAnHourDurationIsReadWhole(t *testing.T) { + for claim, want := range map[string]float64{ + " took 1h10m0s": 4200, + " took 1h": 3600, + " took 2h30m": 9000, + " took 1h30s": 3630, + " took 1h2m3s": 3723, + // The forms that already worked must keep working — an hour pattern that + // swallows these would trade one fabrication for another. + " took 1m10s": 70, + " took 2m": 120, + " took 0.86s": 0.86, + " took 450ms": 0.45, + " took 34.249s": 34.249, + } { + if got, ok := parseClaimedDuration(claim); !ok || got != want { + t.Errorf("parseClaimedDuration(%q) = %v, %v; want %v", claim, got, ok, want) + } + } + + honest := NewLedger() + recordGoTest(honest, Run{}, "--- PASS: TestVerySlow (4200.00s)\n") + if conflicts := honest.Conflicts(recordedRun(honest, Run{}), "TestVerySlow took 1h10m0s"); len(conflicts) != 0 { + t.Errorf("a truthful 1h10m0s claim was reported as a conflict: %+v", conflicts) + } + wrong := NewLedger() + recordGoTest(wrong, Run{}, "--- PASS: TestVerySlow (4200.00s)\n") + if conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestVerySlow took 9h"); len(conflicts) != 1 || conflicts[0].Claimed != 32400 { + t.Errorf("a fabricated 9h was not caught as 32400s: %+v", conflicts) + } +} + +// A DURATION THIS PACKAGE CAN PARSE MUST BE ONE THE CLAUSE SCAN CAN SEE. +// +// separatorBreaksClause locates the next duration to decide whether a separator +// introduces a new subject, and it did not know the hour form. So it read the +// "h" of "9h" as the first letter of a new subject, turned the punctuation into +// a clause boundary, and cut the test's own number away from its name. Four +// ordinary spellings were missed; only the separator-free "took 9h" survived. +func TestTheClauseScanSeesTheHourForm(t *testing.T) { + for _, claim := range []string{ + "TestVerySlow - 9h", + "TestVerySlow passed - 9h", + "TestVerySlow (9h)", + "TestVerySlow: 9h", + "TestVerySlow took 9h", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestVerySlow (4200.00s)\n") + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim) + if len(conflicts) != 1 || conflicts[0].Claimed != 32400 { + t.Errorf("a fabricated hour figure was not read: %q -> %+v", claim, conflicts) + } + } + + // And the bounds still bind: an hour figure belonging to another subject + // stays that subject's, and a truthful hour restatement is not a conflict. + bleed := NewLedger() + recordGoTest(bleed, Run{}, "--- PASS: TestVerySlow (4200.00s)\n") + if conflicts := bleed.Conflicts(recordedRun(bleed, Run{}), "TestVerySlow passed - the whole suite took 9h"); len(conflicts) != 0 { + t.Errorf("another subject's hour figure was charged to this test: %+v", conflicts) + } + honest := NewLedger() + recordGoTest(honest, Run{}, "--- PASS: TestVerySlow (4200.00s)\n") + if conflicts := honest.Conflicts(recordedRun(honest, Run{}), "TestVerySlow - 1h10m0s"); len(conflicts) != 0 { + t.Errorf("a truthful 1h10m0s restatement was reported as a conflict: %+v", conflicts) + } +} + +// A DECIMAL DURATION IS ONE NUMBER, NOT ITS REMAINDER. The minute and hour +// components accepted integers only, so neither pattern could match "1.5m" at +// the digit it starts on — the leftmost match began after the point instead and +// read the claim as 5 minutes. "0.5m", half a minute, read as five, and "10.25h" +// as twenty-five hours. +// +// That is the exact failure this package exists to prevent, in its own parser: a +// model that truthfully restated a recorded 90s as "1.5m" was accused of +// fabricating a number, and the nudge quoted 300s back at it — a figure nothing +// in the run ever produced. +func TestADecimalDurationIsReadWhole(t *testing.T) { + for _, c := range []struct { + recorded string + seconds float64 + claim string + }{ + {"--- PASS: TestNinety (90.00s)\n", 90, "TestNinety took 1.5m"}, + {"--- PASS: TestHalf (30.00s)\n", 30, "TestHalf took 0.5m"}, + {"--- PASS: TestLong (5400.00s)\n", 5400, "TestLong took 1.5h"}, + {"--- PASS: TestVeryLong (36900.00s)\n", 36900, "TestVeryLong took 10.25h"}, + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, c.recorded) + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), c.claim); len(conflicts) != 0 { + t.Errorf("an honest claim %q against %vs was reported as a conflict: %+v", c.claim, c.seconds, conflicts) + } + } + + // AND THE UNITS THAT WERE ALREADY RIGHT STAY RIGHT. "1.5ms" must not become + // a minute claim: the word boundary after "m" is what kept milliseconds out + // of the minute pattern, and widening the number must not cost that. + milli := NewLedger() + recordGoTest(milli, Run{}, "--- PASS: TestQuick (0.0015s)\n") + if conflicts := milli.Conflicts(recordedRun(milli, Run{}), "TestQuick took 1.5ms"); len(conflicts) != 0 { + t.Errorf("an honest 1.5ms claim was read as minutes: %+v", conflicts) + } + + // STILL CAUGHT WHEN A DECIMAL CLAIM REALLY DISAGREES, and reported as the + // number that was written. 4.5m is 270s; under the old patterns it matched + // its remainder and came back as 300, so asserting the reported value — not + // merely that something was reported — is what distinguishes a whole read + // from a lucky one. (2.5m would also disagree, but 150s against a recorded + // 90s sits inside the deliberate 50% tolerance band and is not a conflict.) + wrong := NewLedger() + recordGoTest(wrong, Run{}, "--- PASS: TestNinety (90.00s)\n") + if conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestNinety took 4.5m"); len(conflicts) != 1 || conflicts[0].Claimed != 270 { + t.Errorf("a fabricated 4.5m was not caught as 270s: %+v", conflicts) + } +} + +// A Ledger that was declared rather than constructed still has to behave. The +// nil receiver is already handled; a zero value got past that guard and panicked +// with "assignment to entry in nil map" on its first Record. +func TestAZeroValueLedgerRecordsWithoutPanicking(t *testing.T) { + var ledger Ledger + if n := recordGoTest(&ledger, Run{}, "--- PASS: TestSomething (1.25s)\n"); n != 1 { + t.Errorf("a zero-value ledger recorded %d measurements, want 1", n) + } + if conflicts := ledger.Conflicts(recordedRun(&ledger, Run{}), "TestSomething took 1.25s"); len(conflicts) != 0 { + t.Errorf("a zero-value ledger reported a conflict against its own record: %+v", conflicts) + } +} + +// THE AGREEING CLAIM ABOVE NEVER REACHES THE MAP THAT PANICS. `raised` is +// written only when a contradiction is actually found — it is the dedupe that +// stops the same wrong number being reported twice — so a test that asks a +// truthful claim returns early and proves nothing about it. The first fix for +// the zero-value Ledger initialised the two maps Record touches and left +// `raised` nil, and this test passed anyway. Reported by @jatmn. +// +// Both conflict entry points are covered: they write different key shapes into +// the same map, so one of them holding says nothing about the other. +func TestAZeroValueLedgerSurvivesAContradiction(t *testing.T) { + var single Ledger + recordGoTest(&single, Run{}, "--- PASS: TestSomething (1.25s)\n") + conflicts := single.Conflicts(recordedRun(&single, Run{}), "TestSomething took 99s") + if len(conflicts) != 1 || conflicts[0].Claimed != 99 { + t.Errorf("a zero-value ledger did not report the contradiction: %+v", conflicts) + } + // And the dedupe it just wrote actually works, which is what that map is for. + if again := single.Conflicts(recordedRun(&single, Run{}), "TestSomething took 99s"); len(again) != 0 { + t.Errorf("the same wrong number was reported twice: %+v", again) + } + + var across Ledger + recordGoTest(&across, Run{}, "--- PASS: TestSomething (1.25s)\n") + if conflicts := across.ConflictsAcrossRuns("TestSomething took 99s"); len(conflicts) != 1 { + t.Errorf("a zero-value ledger did not report the contradiction across runs: %+v", conflicts) + } +} + +// DETERMINISM IS ASSERTED WHERE SOMETHING CAN ACTUALLY RESHUFFLE. +// +// Both entry points build their report by ranging over maps, and Go randomises +// that order per range, so the sort at the end of each is the only thing keeping +// two identical passes from producing two different texts. This text reaches a +// model, where a message that reshuffles between passes is a diff nobody can +// read — the reason the sorts are there at all. +// +// Nothing observed them. The assertion that claimed to was written against a +// name only one run had recorded, which leaves one candidate however the map +// iterates; deleting BOTH sorts left the whole suite green over twenty runs. One +// name cannot catch an ordering, so this uses four and pins the exact report: +// name, value, quoted command and recorded values, in order. +func TestTheReportIsIdenticalBetweenIdenticalPasses(t *testing.T) { + plain := Run{Command: "go", Args: []string{"test", "./..."}} + race := Run{Command: "go", Args: []string{"test", "-race", "./..."}} + const fromPlain = "--- PASS: TestAlpha (1.00s)\n--- PASS: TestBravo (2.00s)\n--- PASS: TestShared (1.00s)\n" + const fromRace = "--- PASS: TestCharlie (3.00s)\n--- PASS: TestShared (9.00s)\n" + // Put TestAlpha's claims in descending order. The report contract sorts the + // values independently of claim order, so a Name-only comparator cannot pass + // this case by merely preserving the adjacent inputs. + const claim = "TestAlpha took 49.00s; TestAlpha took 45.00s; TestBravo took 46.00s; TestCharlie took 47.00s; TestShared took 48.00s" + + report := func(conflicts []Conflict) string { + var b strings.Builder + for _, conflict := range conflicts { + fmt.Fprintf(&b, "%s=%v@%q%v|", conflict.Name, conflict.Claimed, conflict.Run.Label(), conflict.Recorded) + } + return b.String() + } + + // TestShared is recorded by BOTH runs deliberately: its label is dropped as + // untrue of either one, so the ordering has a fourth distinct rendering to + // get wrong rather than three that differ only in their command. + const wantAcross = `TestAlpha=45@"go test ./..."[1]|TestAlpha=49@"go test ./..."[1]|TestBravo=46@"go test ./..."[2]|TestCharlie=47@"go test -race ./..."[3]|TestShared=48@""[1 9]|` + const wantPerRun = `TestAlpha=45@"go test ./..."[1]|TestAlpha=49@"go test ./..."[1]|TestBravo=46@"go test ./..."[2]|TestShared=48@"go test ./..."[1]|` + + // A fresh ledger each pass: the dedupe is per-Ledger, so a reused one would + // report nothing after the first attempt and the loop would assert on empty. + for attempt := 0; attempt < 200; attempt++ { + across := NewLedger() + recordGoTest(across, plain, fromPlain) + recordGoTest(across, race, fromRace) + if got := report(across.ConflictsAcrossRuns(claim)); got != wantAcross { + t.Fatalf("attempt %d: the cross-run report is not what identical passes must produce:\n got %s\nwant %s", attempt, got, wantAcross) + } + + perRun := NewLedger() + recordGoTest(perRun, plain, fromPlain) + recordGoTest(perRun, race, fromRace) + if got := report(perRun.Conflicts(recordedRun(perRun, plain), claim)); got != wantPerRun { + t.Fatalf("attempt %d: the per-run report is not what identical passes must produce:\n got %s\nwant %s", attempt, got, wantPerRun) + } + } +} + +// THE ORDER THE MERGE WALKS IS PINNED HERE BECAUSE NOTHING DOWNSTREAM CAN SEE IT. +// +// sortedRunKeys decides which run a merged sighting keeps. A name recorded by +// several runs has its label dropped as untrue of any one of them, and a name +// recorded by one run has a single candidate, so every assertion about the +// report passes whatever order this returns — reversing it, or deleting the sort +// inside it, leaves the suite green. That is the shape of bound this package has +// already shipped twice: alive-looking and certifying nothing. It is asserted +// directly instead, so it stays true for the next caller that does depend on it. +func TestTheRunOrderTheMergeWalksIsStable(t *testing.T) { + runs := []Run{ + {}, + {Command: "go", Args: []string{"test", "-race", "./..."}}, + {Command: "go", Args: []string{"test", "./..."}}, + {Command: "go", Args: []string{"test", "./internal/agent"}}, + {Command: "go", Args: []string{"test", "./..."}, Dir: "/w"}, + } + observed := map[string]map[measurementID][]float64{} + for _, run := range runs { + observed[run.key()] = map[measurementID][]float64{{Test: "TestFoo"}: {1}} + } + want := []string{ + runs[0].key(), runs[1].key(), runs[2].key(), runs[3].key(), runs[4].key(), + } + sort.Strings(want) + + for attempt := 0; attempt < 200; attempt++ { + got := sortedRunKeys(observed) + if len(got) != len(want) { + t.Fatalf("attempt %d: got %d keys, want %d", attempt, len(got), len(want)) + } + for i := range want { + if got[i] != want[i] { + t.Fatalf("attempt %d: key %d is %q, want %q — the merge walks the runs in map order", attempt, i, got[i], want[i]) + } + } + } +} + +// A SUBJECT THAT FOLLOWS ITS OWN NUMBER STILL OWNS IT. +// +// The subject rule scanned only what came BEFORE the next duration, so a +// separator with the figure first and its subject second looked like plain +// presentation — the shape a table or an aside uses for a test's own timing — and +// the neighbouring number was charged to the name in front of it: +// +// recorded: TestFoo 0.10s +// claim: "TestFoo passed; 4.20s was the whole suite." +// -> [{Name:TestFoo Claimed:4.2 Recorded:[0.1]}] +// +// Every word of that claim is true, and 4.20s belongs to the suite named +// immediately after it. Which side of a figure its subject sits on says nothing +// about who owns it. +func TestASubjectFollowingItsNumberEndsTheClause(t *testing.T) { + for _, claim := range []string{ + "TestFoo passed; 4.20s was the whole suite.", + "TestFoo passed - 4.20s was the package total", + "TestFoo passed | 4.20s for the whole package", + "TestFoo ok: 4.20s across every package", + "TestFoo passed (4.20s for the suite)", + "TestFoo was fine, 4.20s covered every package", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("a following subject's number was charged to this test: %q -> %+v", claim, conflicts) + } + } + + // AND THE PRESENTATION FORMS STILL READ, which is what the trailing scan + // stopping at the end of the figure's own segment buys: the words in the next + // table cell and the next sentence are not that figure's subject, and cutting + // there would silence a real fabrication. + for _, claim := range []string{ + "TestFoo (9.90s)", + "TestFoo passed, 9.90s", + "| TestFoo | 9.90s | passes |", + "TestFoo passed, 9.90s. The suite took 34.249s.", + "TestFoo passed (9.90s) and the suite took 34.249s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim) + if len(conflicts) != 1 || conflicts[0].Claimed != 9.9 { + t.Errorf("a test's own number stopped being read: %q -> %+v", claim, conflicts) + } + } +} + +// AN "m" THAT IS NOT A DURATION IS NOT MINUTES. +// +// The minute pattern matches any figure with an "m" and a word boundary after +// it, and position decides between the forms, so a count of rows won over the +// timing standing beside it: +// +// recorded: TestParseCorpus 0.86s +// claim: "TestParseCorpus handled 5m rows in 0.86s" +// -> [{Name:TestParseCorpus Claimed:300 Recorded:[0.86]}] +// +// The report is truthful and the nudge quotes 300s back at it, a number its +// answer never contained — this package's own failure mode, in its own parser. +// +// An ambiguous bare unit now reports NOTHING rather than a second-choice figure, +// because reaching past it would decide the same question by guessing. The cost +// is asserted below too: "took 2m to finish" is unreadable, and a figure +// fabricated in that spelling goes uncaught. +func TestANonDurationUnitIsNotReadAsMinutes(t *testing.T) { + for _, claim := range []string{ + "TestParseCorpus handled 5m rows in 0.86s", + "TestParseCorpus processed 5m tokens", + "TestParseCorpus scanned 12m records and passed", + "TestParseCorpus walked 5m lines", + "TestParseCorpus walked 5m-row corpus", + "TestParseCorpus walked 5m_rows", + "TestParseCorpus walked 5m.rows", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestParseCorpus (0.86s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("a count was read as minutes and a truthful report accused of it: %q -> %+v", claim, conflicts) + } + } + + // The exact readings, so a change that trades one wrong number for another + // cannot pass. A compound form cannot be a count and a bare figure with no + // word after it has no noun to be counting, so both still read. + for _, c := range []struct { + tail string + seconds float64 + ok bool + }{ + {" handled 5m rows in 0.86s", 0, false}, + {" 5m rows", 0, false}, + {" walked 5m-row corpus", 0, false}, + {" walked 5m_rows", 0, false}, + {" walked 5m.rows", 0, false}, + {" 9h of wall time", 0, false}, + {" took 2m to finish", 0, false}, + {" took 2m", 120, true}, + {" took 5m.", 300, true}, + {" (5m)", 300, true}, + {" | 2m |", 120, true}, + {" took 1m10s to finish", 70, true}, + {" took 2h30m of wall time", 9000, true}, + {" took 0.86s over 5m rows", 0.86, true}, + } { + got, ok := parseClaimedDuration(c.tail) + if got != c.seconds || ok != c.ok { + t.Errorf("parseClaimedDuration(%q) = %v, %v; want %v, %v", c.tail, got, ok, c.seconds, c.ok) + } + } + + // And a minute figure that really is one is still caught, whole. + caught := NewLedger() + recordGoTest(caught, Run{}, "--- PASS: TestSlow (70.00s)\n") + if conflicts := caught.Conflicts(recordedRun(caught, Run{}), "TestSlow took 5m"); len(conflicts) != 1 || conflicts[0].Claimed != 300 { + t.Errorf("a bare minute figure with no word after it stopped being read: %+v", conflicts) + } +} + +// AND THE CLAUSE SCAN REFUSES WHAT THE PARSER REFUSES. +// +// The scan locates the next duration to decide whether a separator introduces a +// new subject, so the two have to agree about what a duration is — the hour form +// was added to it for that reason, and an ambiguous bare unit is the same +// requirement from the other side. While the scan still counted "5m" as a +// duration, it found no word before it, read the punctuation as presentation, +// and handed the count to the name in front as a timing the parser itself would +// have refused: +// +// recorded: TestFoo 0.10s +// claim: "TestFoo passed; 5m and the suite took 4.20s" +// -> [{Name:TestFoo Claimed:300 Recorded:[0.1]}] +// +// A conjunction directly after the figure is what exposes it: the trailing scan +// stops at that separator, so the words beyond it cannot end the clause either, +// and the ambiguous token is the only thing standing between the name and a +// number that is not its own. +func TestTheClauseScanRefusesWhatTheParserRefuses(t *testing.T) { + for _, claim := range []string{ + "TestFoo passed; 5m and the suite took 4.20s", + "TestFoo passed, 5m and the whole run took 4.20s", + "TestFoo passed: 5m but the suite took 4.20s", + "TestFoo passed | 5m while the suite took 4.20s", + "TestFoo passed (5m and the suite took 4.20s)", + "TestFoo passed; 5m though the suite took 4.20s", + // The hour form the same way, at 32400s rather than 300s. + "TestFoo ok; 9h and the suite took 4.20s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (0.10s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("the clause scan read a token the parser refuses: %q -> %+v", claim, conflicts) + } + } +} + +// A DURATION IS READ WHOLE OR NOT AT ALL. +// +// Three unanchored regexes each hunted for their own suffix with no shared left +// boundary, so a failed outer match restarted inside the same token. Every one of +// these was a truthful claim turned into a fabricated correction — the single +// failure this package exists to prevent. Reported by @jatmn. +func TestADurationTokenIsReadWholeOrRefused(t *testing.T) { + for _, honest := range []struct { + recorded string + claim string + }{ + {"--- PASS: TestQ (0.86s)\n", "TestQ took .86s"}, // was read as 86s + {"--- PASS: TestQ (90.00s)\n", "TestQ took .5m"}, // was read as 300s + {"--- PASS: TestQ (1.20s)\n", "TestQ took 1,200ms"}, // was read as 0.2s + {"--- PASS: TestQ (60.01s)\n", "TestQ took 1m10ms"}, // was read as 0.01s + {"--- PASS: TestQ (3660.50s)\n", "TestQ took 1h1m500ms"}, // was read as 0.5s + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, honest.recorded) + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), honest.claim); len(conflicts) != 0 { + t.Errorf("an honest claim %q was accused: %+v", honest.claim, conflicts) + } + } + + if got, ok := parseClaimedDuration("1m10ms"); !ok || got != 60.01 { + t.Fatalf("1m10ms parsed as (%v, %v), want exactly (60.01, true)", got, ok) + } + + // AND THE FORMS THAT DO PARSE STILL PARSE, so refusing partial tokens has not + // simply made the detector blind. + for _, readable := range []struct { + recorded string + claim string + }{ + {"--- PASS: TestQ (0.86s)\n", "TestQ took 0.86s"}, + {"--- PASS: TestQ (70.00s)\n", "TestQ took 1m10s"}, + {"--- PASS: TestQ (0.05s)\n", "TestQ took 50ms"}, + {"--- PASS: TestQ (4200.00s)\n", "TestQ took 1h10m0s"}, + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, readable.recorded) + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), readable.claim); len(conflicts) != 0 { + t.Errorf("a valid duration %q stopped being read: %+v", readable.claim, conflicts) + } + } + + // A real fabrication is still caught. + wrong := NewLedger() + recordGoTest(wrong, Run{}, "--- PASS: TestQ (0.86s)\n") + if conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestQ took 9.00s"); len(conflicts) != 1 || conflicts[0].Claimed != 9 { + t.Errorf("a fabricated 9.00s was not caught as 9: %+v", conflicts) + } +} + +func TestSignedTimingDeltaIsNotElapsedTimeEvidence(t *testing.T) { + for _, claim := range []string{ + "TestFoo improved by -4.20s", + "TestFoo regressed by +4.20s", + "TestFoo changed by −4.20s", + } { + for _, entry := range []struct { + name string + check func(*Ledger) []Conflict + }{ + {"per-run", func(ledger *Ledger) []Conflict { return ledger.Conflicts(recordedRun(ledger, Run{}), claim) }}, + {"across-runs", func(ledger *Ledger) []Conflict { return ledger.ConflictsAcrossRuns(claim) }}, + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (1.00s)\n") + if conflicts := entry.check(ledger); len(conflicts) != 0 { + t.Errorf("%s treated signed delta as elapsed time: %q -> %+v", entry.name, claim, conflicts) + } + } + } + + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (1.00s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestFoo took 4.20s"); len(conflicts) != 1 || conflicts[0].Claimed != 4.2 { + t.Fatalf("unsigned elapsed-time fabrication stopped being detected: %+v", conflicts) + } +} + +// EVERY TIMED MENTION IS CHECKED, not the first that parsed. +// +// claimedSecondsFor returned at its first successful occurrence, so an agreeing +// mention shielded every later one and "TestFoo took 1.00s; TestFoo later took +// 9.00s" reported nothing against a recorded 1s. That also contradicted the +// ledger's per-VALUE dedupe, which exists so two different wrong numbers are two +// findings. Reported by @jatmn. +func TestEveryTimedMentionOfANameIsChecked(t *testing.T) { + for _, c := range []struct { + label string + claim string + want []float64 + }{ + {"agreeing then wrong", "TestFoo took 1.00s; TestFoo later took 9.00s", []float64{9}}, + {"wrong then agreeing", "TestFoo took 9.00s; TestFoo actually took 1.00s", []float64{9}}, + {"two distinct wrong", "TestFoo took 9.00s; TestFoo took 20.00s", []float64{9, 20}}, + {"repeated equivalent", "TestFoo took 9.00s; TestFoo took 9.00s", []float64{9}}, + {"all agreeing", "TestFoo took 1.00s; TestFoo took 1.00s", nil}, + } { + for _, entry := range []struct { + name string + run func(*Ledger) []Conflict + }{ + {"per-run", func(l *Ledger) []Conflict { return l.Conflicts(recordedRun(l, Run{}), c.claim) }}, + {"across-runs", func(l *Ledger) []Conflict { return l.ConflictsAcrossRuns(c.claim) }}, + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestFoo (1.00s)\n") + got := entry.run(ledger) + if len(got) != len(c.want) { + t.Errorf("%s/%s: %d conflicts, want %d: %+v", entry.name, c.label, len(got), len(c.want), got) + continue + } + for i, want := range c.want { + if got[i].Claimed != want { + t.Errorf("%s/%s: conflict %d claimed %v, want %v", entry.name, c.label, i, got[i].Claimed, want) + } + } + } + } +} + +func TestAConjunctionSeparatedThresholdIsNotTheResult(t *testing.T) { + for _, claim := range []string{ + "TestQuick stayed under the 10s timeout and completed in 0.86s", + "TestQuick met the 10s budget and actually ran in 0.86s", + "TestQuick stayed under the 10s cap and completed in 0.86s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestQuick (0.86s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("threshold/result wording produced a false conflict: %q -> %+v", claim, conflicts) + } + } + + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestQuick (0.86s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestQuick completed in 9.00s"); len(conflicts) != 1 || conflicts[0].Claimed != 9 { + t.Fatalf("an unambiguous wrong result stopped being detected: %+v", conflicts) + } +} + +func TestAStandaloneThresholdIsNotTheResult(t *testing.T) { + for _, claim := range []string{ + "TestQuick stayed under the 10s timeout", + "TestQuick has a 10s budget", + "TestQuick has a 10s cap", + "TestQuick must finish within 10s", + "TestQuick is limited to at most 10s", + "TestQuick's budget is 10s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestQuick (0.86s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("standalone threshold became a result: %q -> %+v", claim, conflicts) + } + } +} + +func TestReviewedThresholdRolesDoNotBecomeElapsedClaims(t *testing.T) { + for _, claim := range []string{ + "TestQuick stayed under the 10s maximum and completed in 0.86s", + "TestQuick has a 10s maximum", + "TestQuick finished in less than 10s", + "TestQuick has a minimum of 10s", + } { + t.Run(claim, func(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "--- PASS: TestQuick (0.86s)\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("bound became an elapsed claim: %+v", conflicts) + } + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestQuick completed in 9.00s"); len(conflicts) != 1 || conflicts[0].Claimed != 9 { + t.Errorf("fabrication control = %+v, want 9s conflict", conflicts) + } + }) + } +} + +// AN ELAPSED RESULT NEEDS AN AFFIRMATIVE ROLE, not merely a duration somewhere +// after the test name. A deny-list of threshold nouns made a duration an +// elapsed claim by default, so each unlisted spelling of the same bound reopened +// the package's worst failure: a truthful report received a fabricated +// correction. None of these bounds owns the 10s as TestX's measured result. +func TestOnlyAffirmativeElapsedRolesBecomeClaims(t *testing.T) { + for _, claim := range []string{ + "TestX is capped at 10s; it took 0.86s.", + "TestX has a 10s ceiling and took 0.86s.", + "TestX must not exceed 10s; it took 0.86s.", + "TestX finished in no more than 10s.", + "TestX is allowed 10s and took 0.86s.", + "TestX is limited to 10s; it took 0.86s.", + "TestX never took 9s.", + "TestX never reached 9s elapsed.", + "TestX should have completed in 9s.", + `TestX's documentation says "took 9s" is an example.`, + `"TestX took 9s" is an example, not a result.`, + "`TestX took 9s` is an example, not a result.", + `TestX documentation gives "9s elapsed" as a counterexample.`, + } { + t.Run("silent/"+claim, func(t *testing.T) { + ledger := NewLedger() + handle, _ := ledger.Record(Run{}, goTestJSON("--- PASS: TestX (0.86s)\n")) + if conflicts := ledger.Conflicts(handle, claim); len(conflicts) != 0 { + t.Errorf("non-result duration became an elapsed claim: %+v", conflicts) + } + }) + } + + for _, claim := range []string{ + "TestX took 9s.", + "TestX finished in 9s.", + "TestX (9s).", + "TestX 9s elapsed.", + "TestX passed, 9s elapsed.", + "`TestX` took 9s.", + `"TestX" took 9s.`, + } { + t.Run("conflict/"+claim, func(t *testing.T) { + ledger := NewLedger() + handle, _ := ledger.Record(Run{}, goTestJSON("--- PASS: TestX (0.86s)\n")) + conflicts := ledger.Conflicts(handle, claim) + if len(conflicts) != 1 || conflicts[0].Claimed != 9 { + t.Errorf("affirmative elapsed claim = %+v, want one 9s conflict", conflicts) + } + }) + } +} + +func TestPackageCacheMarkerSuppressesEveryStatus(t *testing.T) { + // Defensive event fixtures: Go currently caches only successful test runs. + // The ingestion contract rejects package cache markers independently of the + // result status, even if a replay source supplies a failed cached result. + for _, status := range []string{"ok", "FAIL", "future-status"} { + stream := `{"Action":"pass","Package":"example/p","Test":"TestX","Elapsed":0}` + "\n" + + fmt.Sprintf(`{"Action":"output","Package":"example/p","Output":%q}`, status+"\texample/p\t(cached)\n") + "\n" + + `{"Action":"fail","Package":"example/p","Elapsed":0}` + if got := ParseGoTest(stream); len(got) != 0 { + t.Errorf("%s cache replay produced timing evidence: %+v", status, got) + } + ledger := NewLedger() + ledger.Record(Run{}, stream) + if got := ledger.Conflicts(recordedRun(ledger, Run{}), "TestX took 0.86s"); len(got) != 0 { + t.Errorf("%s cache replay accused truthful report: %+v", status, got) + } + } +} + +func TestGeneratedDuplicateSubtestSuffixBelongsToTheName(t *testing.T) { + ledger := NewLedger() + recordGoTest(ledger, Run{}, strings.Join([]string{ + "--- PASS: TestParent/sub (0.10s)", + "--- PASS: TestParent/sub#01 (4.20s)", + "", + }, "\n")) + + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "TestParent/sub#01 took 4.20s"); len(conflicts) != 0 { + t.Fatalf("suffixed subtest was attributed to its unsuffixed sibling: %+v", conflicts) + } + + wrong := NewLedger() + recordGoTest(wrong, Run{}, strings.Join([]string{ + "--- PASS: TestParent/sub (0.10s)", + "--- PASS: TestParent/sub#01 (4.20s)", + "", + }, "\n")) + conflicts := wrong.Conflicts(recordedRun(wrong, Run{}), "TestParent/sub#01 took 9.00s") + if len(conflicts) != 1 || conflicts[0].Name != "TestParent/sub#01" || conflicts[0].Claimed != 9 { + t.Fatalf("wrong suffixed result was not attributed to the suffixed name: %+v", conflicts) + } +} + +// AN UNRECORDED PACKAGE BOUNDS A CLAUSE, exactly as an unrecorded test-shaped +// name already did. +// +// Package neighbours were only recognised when that package had itself been +// recorded, so a truthful sentence charged an unrecorded neighbour's figure +// backwards to the first package. Whether a neighbouring subject ends a clause +// cannot depend on whether that neighbour happened to produce a parseable +// timing. Reported by @jatmn. +func TestAnUnrecordedPackageNeighbourBoundsTheClause(t *testing.T) { + for _, claim := range []string{ + "github.com/x/first passed github.com/x/unrecorded took 4.20s", + "github.com/x/first passed, github.com/x/unrecorded took 4.20s", + "github.com/x/first ok; github.com/x/unrecorded took 4.20s", + } { + ledger := NewLedger() + recordGoTest(ledger, Run{}, "ok \tgithub.com/x/first\t0.10s\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), claim); len(conflicts) != 0 { + t.Errorf("a neighbour's figure was charged to the first package: %q -> %+v", claim, conflicts) + } + } + // THE CONTROL: when the duration really is the first package's, it still reads. + ledger := NewLedger() + recordGoTest(ledger, Run{}, "ok \tgithub.com/x/first\t0.10s\n") + if conflicts := ledger.Conflicts(recordedRun(ledger, Run{}), "github.com/x/first took 4.20s"); len(conflicts) != 1 { + t.Errorf("a genuine package fabrication stopped being caught: %+v", conflicts) + } +}