mesh-sdk/go/buildstep/gotest.go

package buildstep

// The reader of `go test -json` (moved whole from mesh-catalog's mesh-build-go, issue 1901's thorough fix): per package
// what ran and for how long, and each failure under the contract (failure.go), its real cause too when the failure is no
// test's assertion (a panic, a timeout, a build error, an exit, a kill, a race).

import (
	"bufio"
	"encoding/json"
	"fmt"
	"regexp"
	"slices"
	"strings"
)

// GoPackage is one package's part of a Go test level.
type GoPackage struct {
	Dir     string  `json:"dir"`
	Package string  `json:"package"`
	Passed  bool    `json:"passed"`
	Elapsed float64 `json:"elapsed"`
	Tests   int     `json:"tests"`
	// Skipped is how many of the package's tests skipped.
	Skipped int `json:"skipped,omitempty"`
	// NoTests is a package with no test files (at this level: a file with the other level's build tag is none).
	NoTests bool `json:"no_tests,omitempty"`
}

// TestTime is one test and the seconds it took.
type TestTime struct {
	Package string  `json:"package"`
	Test    string  `json:"test"`
	Elapsed float64 `json:"elapsed"`
}

// GoTest is what one go.mod directory's `go test -json` said.
type GoTest struct {
	Packages []GoPackage
	Tests    int
	Skipped  int
	Times    []TestTime
	Failed   []Failure
	// Elapsed is the slowest package's running time in seconds.
	Elapsed float64
	// Noise is the lines that were no event: what go said when it could not run the tests at all.
	Noise []string
}

// ReadGoTest reads the output of `go test -json` run in the go.mod directory dir.
func ReadGoTest(out, dir string) GoTest {
	r := &goReader{dir: dir, pkgs: map[string]*GoPackage{}, builds: map[string][]string{}, pkgOut: map[string][]string{},
		testOut: map[string][]string{}, causes: map[string]string{}, failedIn: map[string]bool{},
		running: map[string][]string{}, passed: map[string]bool{}, built: map[string]bool{}}
	sc := bufio.NewScanner(strings.NewReader(out))
	sc.Buffer(make([]byte, 1<<20), 1<<26)
	for sc.Scan() {
		var ev goEvent
		if err := json.Unmarshal(sc.Bytes(), &ev); err != nil {
			if l := strings.TrimSpace(sc.Text()); l != "" {
				r.res.Noise = append(r.res.Noise, l)
			}
			continue
		}
		r.event(ev)
	}
	r.finish()
	return r.res
}

// goEvent is one line of `go test -json` (test2json, and the build events go test adds).
type goEvent struct {
	Action      string
	Package     string
	Test        string
	Output      string
	OutputType  string // "error" for a t.Error or t.Fatal message, "error-continue" for its further lines
	ImportPath  string
	FailedBuild string
	Elapsed     float64
}

type goReader struct {
	res      GoTest
	dir      string
	pkgs     map[string]*GoPackage
	order    []string
	builds   map[string][]string // build output by import path
	pkgOut   map[string][]string
	testOut  map[string][]string // by package + "\x00" + test
	causes   map[string]string   // the first error line of a test, by the same key
	failedIn map[string]bool     // packages with a failed test
	// running is the tests that started and have not ended, by package, in the order they started: when a package
	// fails with no failed test, these were running when its test program stopped.
	running map[string][]string
	// passed says a package's test program printed "PASS" before it failed; built says it failed to build.
	passed, built map[string]bool
}

func (r *goReader) pkg(name string) *GoPackage {
	p := r.pkgs[name]
	if p == nil {
		p = &GoPackage{Dir: r.dir, Package: name}
		r.pkgs[name] = p
		r.order = append(r.order, name)
	}
	return p
}

func keepLine(lines []string, out string) []string {
	if t := strings.TrimRight(out, "\r\n"); t != "" && !strings.HasPrefix(t, "=== ") {
		lines = append(lines, t)
	}
	return lines
}

func (r *goReader) event(ev goEvent) {
	switch {
	case ev.Package == "" && ev.ImportPath != "":
		if ev.Action == "build-output" {
			r.builds[ev.ImportPath] = keepLine(r.builds[ev.ImportPath], ev.Output)
		}
	case ev.Package == "":
	case ev.Test == "":
		p := r.pkg(ev.Package)
		switch ev.Action {
		case "output":
			// go test's own summary of a package is never a failure's words: a "PASS" before a "FAIL <pkg>" says only
			// that the tests passed and the program failed after them.
			switch l := strings.TrimRight(ev.Output, "\r\n"); {
			case l == "PASS":
				r.passed[ev.Package] = true
			case goSummaryLine(l):
			default:
				r.pkgOut[ev.Package] = keepLine(r.pkgOut[ev.Package], ev.Output)
			}
		case "pass":
			p.Passed, p.Elapsed = true, ev.Elapsed
		case "fail":
			p.Passed, p.Elapsed = false, ev.Elapsed
			if ev.FailedBuild != "" {
				r.built[ev.Package] = true
				r.pkgOut[ev.Package] = append(r.builds[ev.FailedBuild], r.pkgOut[ev.Package]...)
			}
		case "skip":
			p.Passed, p.NoTests = true, true
		}
	default:
		key := ev.Package + "\x00" + ev.Test
		switch ev.Action {
		case "output":
			r.testOut[key] = keepLine(r.testOut[key], ev.Output)
			if ev.OutputType == "error" && r.causes[key] == "" {
				r.causes[key] = goErrorWords(ev.Output)
			}
		case "run":
			r.running[ev.Package] = append(r.running[ev.Package], ev.Test)
		case "pass", "fail", "skip":
			r.running[ev.Package] = slices.DeleteFunc(r.running[ev.Package], func(t string) bool { return t == ev.Test })
			p := r.pkg(ev.Package)
			p.Tests++
			r.res.Tests++
			if ev.Action == "skip" {
				r.res.Skipped++
				p.Skipped++
			}
			r.res.Times = append(r.res.Times, TestTime{Package: ev.Package, Test: ev.Test, Elapsed: ev.Elapsed})
			if ev.Action == "fail" {
				r.failedIn[ev.Package] = true
				if r.subtestFailed(ev.Package, ev.Test) {
					return // a parent failed only by its subtest is that subtest's failure, said once
				}
				if r.subtestTakesTheCause(ev.Package, ev.Test) {
					return // a subtest's panic, which go files under its parent, is said on the subtest
				}
				r.res.Failed = append(r.res.Failed, r.testFailure(ev.Package, ev.Test))
			}
		}
	}
}

// subtestFailed says a failure of test under pkg was already reported for one of its subtests (they end first), each with
// a cause of its own, and the test reported no error and no runtime cause (a subtest's panic) of its own.
func (r *goReader) subtestFailed(pkg, test string) bool {
	key := pkg + "\x00" + test
	if r.causes[key] != "" || goRuntimeCause(r.testOut[key]) != "" {
		return false
	}
	for _, f := range r.res.Failed {
		if f.Package == pkg && strings.HasPrefix(f.Test, test+"/") {
			return true
		}
	}
	return false
}

// noMessage is the cause of a test that failed and said nothing of why.
const noMessage = "the test failed without an error message (t.Fail or t.FailNow)"

// subtestTakesTheCause gives a parent's runtime cause (a subtest's panic: go test -json files its lines under the
// parent) to the subtests of that parent that failed with no message of their own, and says it did. A parent with an
// error line of its own, or whose failed subtests each said why, is reported as itself.
func (r *goReader) subtestTakesTheCause(pkg, test string) bool {
	key := pkg + "\x00" + test
	if r.causes[key] != "" {
		return false
	}
	cause := goRuntimeCause(r.testOut[key])
	if cause == "" {
		return false
	}
	took := false
	for i, f := range r.res.Failed {
		if f.Package == pkg && strings.HasPrefix(f.Test, test+"/") && f.Cause == noMessage {
			r.res.Failed[i].Cause, r.res.Failed[i].Output = cause, Clip(r.testOut[key], cause)
			took = true
		}
	}
	return took
}

// testFailure is a test that failed: its cause is its first error line, the race it ran into, the runtime's line, or
// words saying it failed without a message.
func (r *goReader) testFailure(pkg, test string) Failure {
	key := pkg + "\x00" + test
	cause := r.causes[key]
	if race := goRaceCause(r.testOut[key]); race != "" && (cause == "" || strings.HasPrefix(cause, "race detected")) {
		cause = race // the race itself, not testing's "race detected during execution of test"
	} else if cause == "" {
		cause = goRuntimeCause(r.testOut[key])
	}
	if cause == "" {
		cause = noMessage
	}
	return Failure{Package: pkg, Test: test, Output: Clip(r.testOut[key], cause), Cause: cause}
}

// goSummaryLine says a line is go test's summary of a package, in go's exact forms only: "PASS" or "FAIL" alone,
// "ok  \t<pkg>\t<time>" and "FAIL\t<pkg>\t<time>" (a line of the package's own that starts "ok " is kept).
func goSummaryLine(l string) bool {
	return l == "PASS" || l == "FAIL" || strings.HasPrefix(l, "ok  \t") || strings.HasPrefix(l, "FAIL\t")
}

// goRuntimeCause is the cause in a failure's output that is not a test's assertion: a race the race detector reported;
// else the first "panic:" line, a timeout's with the tests it names as running; else the first "fatal error:" or
// "signal:" line; "" when there is none. It reads every line, so a long goroutine dump cannot hide it. **It matches only
// lines at column 0**, where go prints the runtime's: a test's indented log line holding the same words is not the cause.
func goRuntimeCause(lines []string) string {
	if race := goRaceCause(lines); race != "" {
		return race
	}
	for _, prefix := range []string{"panic: ", "fatal error: ", "signal: "} {
		for i, l := range lines {
			l = strings.TrimRight(l, "\r\n")
			if !strings.HasPrefix(l, prefix) {
				continue
			}
			if strings.HasPrefix(l, "panic: test timed out after") {
				var names []string
				for _, n := range lines[i+1:] {
					if !strings.HasPrefix(n, "\t\t") {
						if strings.TrimSpace(n) == "running tests:" {
							continue
						}
						break
					}
					names = append(names, strings.TrimSpace(n))
				}
				if len(names) > 0 {
					l += "; running tests: " + strings.Join(names, ", ")
				}
			}
			return CutLine(l)
		}
	}
	return ""
}

// goRaceCause is the first race the race detector reported in a failure's output, in one line: its access and the frame
// that made it, and where the goroutine that made it was created. "" when the output holds no race.
func goRaceCause(lines []string) string {
	at := -1
	for i, l := range lines {
		if strings.TrimRight(l, "\r\n") == "WARNING: DATA RACE" {
			at = i
			break
		}
	}
	if at < 0 {
		return ""
	}
	frame := func(i int) string {
		var fn, file string
		for _, l := range lines[i+1:] {
			if l = strings.TrimSpace(l); l == "" {
				break
			}
			if fn == "" {
				fn = l
				continue
			}
			file = l
			if j := strings.LastIndexByte(file, '/'); j >= 0 {
				file = file[j+1:]
			}
			if j := strings.Index(file, " +0x"); j >= 0 {
				file = file[:j]
			}
			break
		}
		if file != "" {
			return fn + " (" + file + ")"
		}
		return fn
	}
	words := "WARNING: DATA RACE"
	for i := at + 1; i < len(lines); i++ {
		l := strings.TrimSpace(lines[i])
		if l == "" || strings.HasPrefix(l, "===") {
			continue
		}
		words += ": " + strings.TrimSuffix(l, ":")
		if f := frame(i); f != "" {
			words += " in " + f
		}
		break
	}
	for i := at + 1; i < len(lines); i++ {
		l := strings.TrimSpace(lines[i])
		if strings.HasPrefix(l, "==================") {
			break
		}
		if strings.HasPrefix(l, "Goroutine ") && strings.HasSuffix(l, " created at:") {
			if f := frame(i); f != "" {
				words += "; its goroutine created at " + f
			}
			break
		}
	}
	return CutLine(words)
}

// goBuildCause is the first error line of a failed build: the first line that is not go's "# <package>" heading.
func goBuildCause(lines []string) string {
	for _, l := range lines {
		if l = strings.TrimSpace(l); l != "" && !strings.HasPrefix(l, "# ") {
			return CutLine(l)
		}
	}
	return ""
}

// goTestNames names the tests that were running, at most three, and how many more.
func goTestNames(tests []string) string {
	if len(tests) <= 3 {
		return strings.Join(tests, ", ")
	}
	return fmt.Sprintf("%s and %d more", strings.Join(tests[:3], ", "), len(tests)-3)
}

// packageFailure is a package that failed with no failed test to name it: its test program did not build, panicked,
// timed out, was killed or exited. It names the tests that were running, keeps their output with the package's, and
// says the cause.
func (r *goReader) packageFailure(name string) Failure {
	running := r.running[name]
	var lines []string
	for _, t := range running {
		lines = append(lines, r.testOut[name+"\x00"+t]...)
	}
	lines = append(lines, r.pkgOut[name]...)
	cause := goRuntimeCause(lines)
	switch {
	case cause != "":
	case r.built[name]:
		cause = goBuildCause(lines)
	case len(running) > 0:
		cause = "the test program exited while " + goTestNames(running) + " ran, with no panic: an os.Exit or a signal (go test -json reports no exit status)"
	case r.passed[name]:
		cause = "the tests passed, then the test program exited with a failure: an os.Exit or a panic in TestMain or after the tests (go test -json reports no exit status)"
	}
	if cause == "" {
		cause = "the package failed with no test to name and no panic, signal or build error in its output"
	}
	return Failure{Package: name, Test: goTestNames(running), Output: Clip(lines, cause), Cause: cause}
}

var goFileAndLine = regexp.MustCompile(`^\S+\.go:\d+: `)

// goPosition matches a line that starts with a Go file's position, as go vet and the compiler write an error.
var goPosition = regexp.MustCompile(`^\S+\.go:\d+(:\d+)?: `)

// goErrorWords is the words of an error line of a test: trimmed, without the file and line go test put before them.
func goErrorWords(out string) string {
	return strings.TrimSpace(goFileAndLine.ReplaceAllString(strings.TrimSpace(out), ""))
}

// finish moves what was read into the result: the packages in order, a failure for each failed package that has no
// failed test to name it.
func (r *goReader) finish() {
	for _, name := range r.order {
		p := r.pkgs[name]
		if !p.Passed && !r.failedIn[name] {
			r.res.Failed = append(r.res.Failed, r.packageFailure(name))
		}
		if !p.NoTests && p.Elapsed > r.res.Elapsed {
			r.res.Elapsed = p.Elapsed
		}
		r.res.Packages = append(r.res.Packages, *p)
	}
}