mirror of
https://github.com/hanzoai/tasks.git
synced 2026-10-04 02:04:03 +00:00
Write test results reports in between runs to preserve on crash (#9692)
## What changed? testrunner writes intermediate JUnit XML reports after each completed test attempt and enforces its own total deadline derived from the go test -timeout flag. ## Why? When a test run exceeds the GitHub Actions job timeout (40 min), the entire process group is killed before the testrunner can write its final merged XML, producing a synthetic junit.crash.xml showing `functional-test (crash)`, with no visibility into actual test failures. [Sample run](https://github.com/temporalio/temporal/actions/runs/23567876357) that actually had 108 failures on manual inspection There are two distinct failure modes this addresses: 1. Killed between attempts — attempt 1 completes with failures, the process is killed during attempt 2. Previously: no XML on disk. Now: attempt 1's results survive in the intermediate file. 2. Go test timeout doesn't fire — the test binary hangs past its own `-timeout=35m` (e.g. deadlocked goroutines). Previously: GitHub kills at 40 min with no XML. Now: the testrunner enforces the same 35m deadline itself, kills `gotestsum`, extracts any `--- FAIL:` lines captured from stdout, writes a report, and exits cleanly within the 5-minute buffer before GitHub's kill. ## How did you test it? - [X] built - [ ] run locally and tested manually - [ ] covered by existing tests - [X] added new unit test(s) - [ ] added new functional test(s) ## Potential risks The testrunner's context deadline fires at the same time as go test's own -timeout. If both fire simultaneously, parseTestTimeouts (existing path) and the new `ctx.Err()` check (new path) can both trigger. The `ctx.Err()` check is guarded to only activate if the normal timeout-panic path didn't already break the loop, so there is no double-processing.
This commit is contained in:
@@ -333,3 +333,21 @@ func isTestResultBoundary(line string) bool {
|
||||
func shouldStopOnTestBoundary(line string, _ int, _ int) bool {
|
||||
return isTestResultBoundary(line)
|
||||
}
|
||||
|
||||
// parseFailedTestsFromOutput extracts failing test names from gotestsum stdout.
|
||||
// It looks for "--- FAIL: TestName" lines produced as tests complete, and is
|
||||
// used when the test binary was killed externally before producing a JUnit XML.
|
||||
func parseFailedTestsFromOutput(stdout string) []string {
|
||||
var failed []string
|
||||
seen := make(map[string]struct{})
|
||||
for _, line := range strings.Split(strings.ReplaceAll(stdout, "\r\n", "\n"), "\n") {
|
||||
line = strings.TrimSpace(line)
|
||||
if !strings.HasPrefix(line, "--- FAIL: ") {
|
||||
continue
|
||||
}
|
||||
if name, ok := parseTripleDashTestName(line); ok {
|
||||
addUniqueTest(&failed, seen, name)
|
||||
}
|
||||
}
|
||||
return failed
|
||||
}
|
||||
|
||||
@@ -22,6 +22,50 @@ func TestParseTestTimeouts(t *testing.T) {
|
||||
require.Equal(t, string(logOutput), stacktrace)
|
||||
}
|
||||
|
||||
func TestParseFailedTestsFromOutput(t *testing.T) {
|
||||
t.Run("ExtractsFailedTestNames", func(t *testing.T) {
|
||||
stdout := `
|
||||
=== RUN TestFoo
|
||||
=== RUN TestFoo/SubTest1
|
||||
foo_test.go:42: assertion failed
|
||||
--- FAIL: TestFoo/SubTest1 (1.23s)
|
||||
--- FAIL: TestFoo (1.23s)
|
||||
=== RUN TestBar
|
||||
--- PASS: TestBar (0.00s)
|
||||
=== RUN TestBaz
|
||||
baz_test.go:10: something wrong
|
||||
--- FAIL: TestBaz (0.50s)
|
||||
FAIL
|
||||
`
|
||||
got := parseFailedTestsFromOutput(stdout)
|
||||
require.Equal(t, []string{"TestFoo/SubTest1", "TestFoo", "TestBaz"}, got)
|
||||
})
|
||||
|
||||
t.Run("DeduplicatesDuplicateLines", func(t *testing.T) {
|
||||
stdout := `
|
||||
--- FAIL: TestDupe (0.10s)
|
||||
--- FAIL: TestDupe (0.10s)
|
||||
--- FAIL: TestOther (0.20s)
|
||||
`
|
||||
got := parseFailedTestsFromOutput(stdout)
|
||||
require.Equal(t, []string{"TestDupe", "TestOther"}, got)
|
||||
})
|
||||
|
||||
t.Run("ReturnsEmptyWhenNoFailures", func(t *testing.T) {
|
||||
stdout := `
|
||||
=== RUN TestPass
|
||||
--- PASS: TestPass (0.01s)
|
||||
ok go.temporal.io/server/tests
|
||||
`
|
||||
got := parseFailedTestsFromOutput(stdout)
|
||||
require.Empty(t, got)
|
||||
})
|
||||
|
||||
t.Run("ReturnsEmptyOnEmptyInput", func(t *testing.T) {
|
||||
require.Empty(t, parseFailedTestsFromOutput(""))
|
||||
})
|
||||
}
|
||||
|
||||
func TestParseAlerts_DataRaceAndPanic(t *testing.T) {
|
||||
input, err := os.ReadFile("testdata/alerts-input.log")
|
||||
require.NoError(t, err)
|
||||
|
||||
@@ -13,6 +13,7 @@ import (
|
||||
"slices"
|
||||
"strconv"
|
||||
"strings"
|
||||
"time"
|
||||
|
||||
"github.com/google/uuid"
|
||||
)
|
||||
@@ -25,6 +26,11 @@ const (
|
||||
crashReportNameFlag = "--crashreportname="
|
||||
gotestsumPathFlag = "--gotestsum-path="
|
||||
|
||||
// goTestTimeoutFlag is the go test flag whose value is also used as the
|
||||
// testrunner's total-run deadline (so results are flushed before an external
|
||||
// kill such as a GitHub Actions timeout).
|
||||
goTestTimeoutFlagEq = "-timeout="
|
||||
|
||||
// fullRerunThreshold is the number of test failures above which we do a full
|
||||
// rerun instead of retrying only the failed tests.
|
||||
fullRerunThreshold = 20
|
||||
@@ -70,6 +76,7 @@ type runner struct {
|
||||
maxAttempts int
|
||||
crashName string
|
||||
alerts []alert
|
||||
totalTimeout time.Duration // derived from the -timeout go test flag
|
||||
}
|
||||
|
||||
func newRunner() *runner {
|
||||
@@ -81,6 +88,17 @@ func newRunner() *runner {
|
||||
|
||||
// nolint:revive,cognitive-complexity
|
||||
func (r *runner) sanitizeAndParseArgs(command string, args []string) ([]string, error) {
|
||||
// Pre-pass: read the go test -timeout value and use it as the testrunner's
|
||||
// total deadline so results are flushed before an external kill (e.g. GitHub
|
||||
// Actions timeout). The flag is NOT consumed — it still passes through to gotestsum.
|
||||
for _, arg := range args {
|
||||
if strings.HasPrefix(arg, goTestTimeoutFlagEq) {
|
||||
if d, err := time.ParseDuration(strings.TrimPrefix(arg, goTestTimeoutFlagEq)); err == nil {
|
||||
r.totalTimeout = d
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
var sanitizedArgs []string
|
||||
for _, arg := range args {
|
||||
if strings.HasPrefix(arg, maxAttemptsFlag) {
|
||||
@@ -189,6 +207,12 @@ func Main() {
|
||||
log.Fatalf("failed to parse command line options: %v", err)
|
||||
}
|
||||
|
||||
if r.totalTimeout > 0 {
|
||||
var cancel context.CancelFunc
|
||||
ctx, cancel = context.WithTimeout(ctx, r.totalTimeout)
|
||||
defer cancel()
|
||||
}
|
||||
|
||||
switch command {
|
||||
case testCommand:
|
||||
r.runTests(ctx, args)
|
||||
@@ -208,6 +232,30 @@ func (r *runner) reportCrash() {
|
||||
}
|
||||
}
|
||||
|
||||
// writeCurrentReport writes the merged report from all completed attempts to the
|
||||
// final output path. It is called after each attempt so that partial results
|
||||
// survive if the process is killed externally between attempts.
|
||||
// Reporting errors (e.g. unexpected missing reruns) are intentionally ignored
|
||||
// here; they are only checked for the final write at the end of runTests.
|
||||
func (r *runner) writeCurrentReport() {
|
||||
reports := r.allReports()
|
||||
if len(reports) == 0 {
|
||||
return
|
||||
}
|
||||
merged, err := mergeReports(reports)
|
||||
if err != nil {
|
||||
log.Printf("warning: failed to merge reports for intermediate write: %v", err)
|
||||
return
|
||||
}
|
||||
if len(r.alerts) > 0 {
|
||||
merged.appendAlertsSuite(r.alerts)
|
||||
}
|
||||
merged.path = r.junitOutputPath
|
||||
if err := merged.write(); err != nil {
|
||||
log.Printf("warning: failed to write intermediate report: %v", err)
|
||||
}
|
||||
}
|
||||
|
||||
func (r *runner) runTests(ctx context.Context, args []string) {
|
||||
var currentAttempt *attempt
|
||||
for a := 1; a <= r.maxAttempts; a++ {
|
||||
@@ -217,6 +265,27 @@ func (r *runner) runTests(ctx context.Context, args []string) {
|
||||
stdout, err := currentAttempt.run(ctx, args)
|
||||
// Extract prominent alerts from this attempt's output.
|
||||
r.alerts = append(r.alerts, parseAlerts(stdout)...)
|
||||
|
||||
// Check whether our total timeout fired (context deadline exceeded).
|
||||
// This happens when the go test binary hangs and never produces its own
|
||||
// "test timed out" panic. We collect whatever results are available from
|
||||
// completed attempts and from the partially-executed current attempt, then
|
||||
// flush the XML before the external kill arrives.
|
||||
if ctx.Err() != nil {
|
||||
log.Printf("total timeout reached, collecting partial results from %d completed attempt(s)", a-1)
|
||||
// Try to read whatever gotestsum managed to write before it was killed.
|
||||
if readErr := currentAttempt.junitReport.read(); readErr != nil {
|
||||
// gotestsum didn't finish writing a JUnit XML. Fall back to parsing
|
||||
// stdout for any "--- FAIL:" lines that completed before the kill.
|
||||
if failedTests := parseFailedTestsFromOutput(stdout); len(failedTests) > 0 {
|
||||
currentAttempt.junitReport = generateStatic(failedTests, "total timeout", "Timeout")
|
||||
}
|
||||
// If no failed tests are found either, the current attempt's report
|
||||
// remains empty and mergeReports will include only prior attempts.
|
||||
}
|
||||
break
|
||||
}
|
||||
|
||||
if err != nil && !errors.As(err, ¤tAttempt.exitErr) {
|
||||
log.Fatalf("test run failed with an unexpected error: %v", err)
|
||||
}
|
||||
@@ -237,6 +306,11 @@ func (r *runner) runTests(ctx context.Context, args []string) {
|
||||
log.Fatal(err)
|
||||
}
|
||||
|
||||
// Write intermediate results so they survive if we are killed externally
|
||||
// between attempts (e.g. a GitHub Actions job timeout fires after this
|
||||
// attempt but before the next one completes).
|
||||
r.writeCurrentReport()
|
||||
|
||||
// If the run completely successfull, no need to retry.
|
||||
if currentAttempt.exitErr == nil {
|
||||
break
|
||||
@@ -282,7 +356,9 @@ func (r *runner) runTests(ctx context.Context, args []string) {
|
||||
if err = mergedReport.write(); err != nil {
|
||||
log.Fatal(err)
|
||||
}
|
||||
if len(mergedReport.reportingErrs) > 0 {
|
||||
// Skip the strict rerun-coverage check when the total timeout fired: the
|
||||
// in-progress attempt was killed before it could execute all expected tests.
|
||||
if len(mergedReport.reportingErrs) > 0 && ctx.Err() == nil {
|
||||
log.Fatal(mergedReport.reportingErrs)
|
||||
}
|
||||
|
||||
|
||||
@@ -3,6 +3,7 @@ package testrunner
|
||||
import (
|
||||
"os"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/stretchr/testify/require"
|
||||
)
|
||||
@@ -35,6 +36,35 @@ func TestRunnerSanitizeAndParseArgs(t *testing.T) {
|
||||
require.Equal(t, "test.cover.out", r.coverProfilePath)
|
||||
})
|
||||
|
||||
t.Run("TotalTimeoutDerivedFromGoTestTimeout", func(t *testing.T) {
|
||||
r := newRunner()
|
||||
args, err := r.sanitizeAndParseArgs(testCommand, []string{
|
||||
"--gotestsum-path=/bin/gotestsum",
|
||||
"--junitfile=test.xml",
|
||||
"--",
|
||||
"-timeout=35m",
|
||||
"-coverprofile=test.cover.out",
|
||||
})
|
||||
require.NoError(t, err)
|
||||
// The testrunner should derive its total deadline from the go test -timeout flag.
|
||||
require.Equal(t, 35*time.Minute, r.totalTimeout)
|
||||
// The flag must still be present in the passthrough args so gotestsum/go test
|
||||
// also honour it.
|
||||
require.Contains(t, args, "-timeout=35m")
|
||||
})
|
||||
|
||||
t.Run("TotalTimeoutNotSetWhenNoGoTestTimeout", func(t *testing.T) {
|
||||
r := newRunner()
|
||||
_, err := r.sanitizeAndParseArgs(testCommand, []string{
|
||||
"--gotestsum-path=/bin/gotestsum",
|
||||
"--junitfile=test.xml",
|
||||
"--",
|
||||
"-coverprofile=test.cover.out",
|
||||
})
|
||||
require.NoError(t, err)
|
||||
require.Zero(t, r.totalTimeout)
|
||||
})
|
||||
|
||||
t.Run("GoTestSumPathMissing", func(t *testing.T) {
|
||||
r := newRunner()
|
||||
_, err := r.sanitizeAndParseArgs(testCommand, []string{
|
||||
@@ -124,6 +154,43 @@ func TestStripRunFromArgs(t *testing.T) {
|
||||
})
|
||||
}
|
||||
|
||||
func TestWriteCurrentReport(t *testing.T) {
|
||||
out, err := os.CreateTemp("", "junit-report-*.xml")
|
||||
require.NoError(t, err)
|
||||
defer func() { _ = os.Remove(out.Name()) }()
|
||||
|
||||
r := newRunner()
|
||||
r.junitOutputPath = out.Name()
|
||||
|
||||
// Simulate attempt 1 completing with failures.
|
||||
j1 := &junitReport{path: "testdata/junit-attempt-1.xml"}
|
||||
require.NoError(t, j1.read())
|
||||
a1 := r.newAttempt()
|
||||
a1.junitReport = j1
|
||||
|
||||
r.writeCurrentReport()
|
||||
|
||||
result := &junitReport{path: out.Name()}
|
||||
require.NoError(t, result.read())
|
||||
require.Equal(t, 2, result.Failures)
|
||||
require.Len(t, result.Suites, 1)
|
||||
|
||||
// Simulate attempt 2 also completing. The intermediate write should now
|
||||
// contain failures from both attempts, so that if the process is killed
|
||||
// before attempt 3 the file on disk already has the full picture.
|
||||
j2 := &junitReport{path: "testdata/junit-attempt-2.xml"}
|
||||
require.NoError(t, j2.read())
|
||||
a2 := r.newAttempt()
|
||||
a2.junitReport = j2
|
||||
|
||||
r.writeCurrentReport()
|
||||
|
||||
result2 := &junitReport{path: out.Name()}
|
||||
require.NoError(t, result2.read())
|
||||
require.Equal(t, 4, result2.Failures) // 2 from attempt 1 + 2 from attempt 2
|
||||
require.Len(t, result2.Suites, 2)
|
||||
}
|
||||
|
||||
func TestRunnerReportCrash(t *testing.T) {
|
||||
out, err := os.CreateTemp("", "junit-report-*.xml")
|
||||
require.NoError(t, err)
|
||||
|
||||
Reference in New Issue
Block a user