summary: mitigate test2json bug causing missing test output

See golang/go#29755.

If a test fails, and there is no test output (other than framing), then
print all the test output for the entire test case.

This won't fix the issue if the test which failed had some output, but
well behaved tests generally shouldn't non-failure message output, so
hopefully this case is rare.

internal/junitxml/report.go

@@ -155,14 +155,16 @@ func packageTestCases(pkg *testjson.Package, formatClassname FormatFunc) []JUnit
 		jtc := newJUnitTestCase(tc, formatClassname)
 		jtc.Failure = &JUnitFailure{
 			Message:  "Failed",
-			Contents: pkg.Output(tc.Test),
+			Contents: strings.Join(pkg.OutputLines(tc), ""),
 		}
 		cases = append(cases, jtc)
 	}
 
 	for _, tc := range pkg.Skipped {
 		jtc := newJUnitTestCase(tc, formatClassname)
-		jtc.SkipMessage = &JUnitSkipMessage{Message: pkg.Output(tc.Test)}
+		jtc.SkipMessage = &JUnitSkipMessage{
+			Message: strings.Join(pkg.OutputLines(tc), ""),
+		}
 		cases = append(cases, jtc)
 	}
 

testjson/execution.go

@@ -109,19 +109,59 @@ func (p Package) TestCases() []TestCase {
 }
 
 // Output returns the full test output for a test.
+//
+// Unlike OutputLines() it does not return any extra lines in some cases.
 func (p Package) Output(test string) string {
 	root, sub := splitTestName(test)
 	return strings.Join(p.output[root][sub], "")
 }
 
+// OutputLines returns the full test output for a test as a slice of strings.
+//
+// As a workaround for test output being attributed to the wrong subtest, if:
+//   - the requested test output only contains framing lines (ex: --- FAIL: ), and
+//   - the TestCase is a root TestCase (not a subtest), and
+//   - the TestCase has no subtest failures;
+// then all output for every subtest under the root test is returned.
+// See https://github.com/golang/go/issues/29755.
+func (p Package) OutputLines(tc TestCase) []string {
+	root, sub := splitTestName(tc.Test)
+	lines := p.output[root][sub]
+	// every test will have 2 framing lines, === RUN, and --- {PASS,FAIL}
+	if len(lines) > 2 {
+		return lines
+	}
+
+	// If this is a subtest, or a root test case with subtest failures the
+	// subtest failure output should contain the relevant lines, so we don't need
+	// extra lines.
+	if sub != "" || tc.subTestFailed {
+		return lines
+	}
+	//
+	result := make([]string, 0, len(p.output[root])*2)
+	for _, sub := range testNamesSorted(p.output[root]) {
+		result = append(result, p.output[root][sub]...)
+	}
+	return result
+}
+
+func testNamesSorted(subs map[string][]string) []string {
+	names := make([]string, 0, len(subs))
+	for name := range subs {
+		names = append(names, name)
+	}
+	sort.Strings(names)
+	return names
+}
+
 func (p Package) addOutput(test string, output string) {
 	root, sub := splitTestName(test)
 	if p.output[root] == nil {
 		p.output[root] = make(map[string][]string)
 	}
 	// TODO: limit size of buffered test output
 	p.output[root][sub] = append(p.output[root][sub], output)
-
 }
 
 // splitTestName into root test name and any subtest names.
@@ -154,6 +194,9 @@ type TestCase struct {
 	Package string
 	Test    string
 	Elapsed time.Duration
+	// subTestFailed is true when a subtest of this TestCase has failed. It is
+	// used to find root TestCases which have no failing subtests.
+	subTestFailed bool
 }
 
 func newPackage() *Package {
@@ -222,6 +265,14 @@ func (e *Execution) addTestEvent(pkg *Package, event TestEvent) {
 	switch event.Action {
 	case ActionFail:
 		pkg.Failed = append(pkg.Failed, tc)
+
+		// If this is a subtest, mark the root test as having subtests.
+		root, subTest := splitTestName(event.Test)
+		if subTest != "" {
+			rootTestCase := pkg.running[root]
+			rootTestCase.subTestFailed = true
+			pkg.running[root] = rootTestCase
+		}
 	case ActionSkip:
 		pkg.Skipped = append(pkg.Skipped, tc)
 	case ActionPass:
@@ -245,10 +296,13 @@ func isCachedOutput(output string) bool {
 	return strings.Contains(output, "\t(cached)")
 }
 
-// OutputLines returns the full test output for a test as an array of lines.
-func (e *Execution) OutputLines(pkg, test string) []string {
-	root, sub := splitTestName(test)
-	return e.packages[pkg].output[root][sub]
+// OutputLines returns the full test output for a test as an slice of lines.
+// This function is a convenient wrapper around Package.OutputLines() to
+// support the hiding of output in the summary.
+//
+// See Package.OutLines() for more details.
+func (e *Execution) OutputLines(tc TestCase) []string {
+	return e.packages[tc.Package].OutputLines(tc)
 }
 
 // Package returns the Package by name.

testjson/summary.go

@@ -143,14 +143,14 @@ func countErrors(errors []string) int {
 type executionSummary interface {
 	Failed() []TestCase
 	Skipped() []TestCase
-	OutputLines(pkg, test string) []string
+	OutputLines(TestCase) []string
 }
 
 type noOutputSummary struct {
 	Execution
 }
 
-func (s *noOutputSummary) OutputLines(_, _ string) []string {
+func (s *noOutputSummary) OutputLines(_ TestCase) []string {
 	return nil
 }
 
@@ -173,7 +173,7 @@ func writeTestCaseSummary(out io.Writer, execution executionSummary, conf testCa
 			RelativePackagePath(tc.Package),
 			tc.Test,
 			FormatDurationAsSeconds(tc.Elapsed, 2))
-		for _, line := range execution.OutputLines(tc.Package, tc.Test) {
+		for _, line := range execution.OutputLines(tc) {
 			if isRunLine(line) || conf.filter(tc.Test, line) {
 				continue
 			}

testjson/summary_test.go

@@ -229,6 +229,7 @@ func multiLine(s string) map[string][]string {
 func TestPrintSummary_MissingTestFailEvent(t *testing.T) {
 	_, reset := patchClock()
 	defer reset()
+
 	exec, err := ScanTestOutput(ScanConfig{
 		Stdout:  bytes.NewReader(golden.Get(t, "go-test-json-missing-test-fail.out")),
 		Stderr:  bytes.NewReader(nil),
@@ -250,3 +251,35 @@ func (s noopHandler) Event(TestEvent, *Execution) error {
 func (s noopHandler) Err(string) error {
 	return nil
 }
+
+func TestPrintSummary_WithMisattributedOutput(t *testing.T) {
+	_, reset := patchClock()
+	defer reset()
+
+	exec, err := ScanTestOutput(ScanConfig{
+		Stdout:  bytes.NewReader(golden.Get(t, "go-test-json-misattributed.out")),
+		Stderr:  bytes.NewBuffer(nil),
+		Handler: noopHandler{},
+	})
+	assert.NilError(t, err)
+
+	buf := new(bytes.Buffer)
+	PrintSummary(buf, exec, SummarizeAll)
+	golden.Assert(t, buf.String(), "summary-misattributed-output")
+}
+
+func TestPrintSummary_WithSubtestFailures(t *testing.T) {
+	_, reset := patchClock()
+	defer reset()
+
+	exec, err := ScanTestOutput(ScanConfig{
+		Stdout:  bytes.NewReader(golden.Get(t, "go-test-json.out")),
+		Stderr:  bytes.NewBuffer(nil),
+		Handler: noopHandler{},
+	})
+	assert.NilError(t, err)
+
+	buf := new(bytes.Buffer)
+	PrintSummary(buf, exec, SummarizeAll)
+	golden.Assert(t, buf.String(), "summary-root-test-has-subtest-failures")
+}

testjson/testdata/go-test-json-misattributed.out

@@ -0,0 +1,35 @@
+{"Action":"run","Test":"TestOutputWithSubtest"}
+{"Action":"output","Test":"TestOutputWithSubtest","Output":"=== RUN   TestOutputWithSubtest\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"=== RUN   TestOutputWithSubtest/sub_test\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test/sub2"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"=== RUN   TestOutputWithSubtest/sub_test/sub2\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test2"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"=== RUN   TestOutputWithSubtest/sub_test2\n"}
+{"Action":"run","Test":"TestOutputWithSubtest/sub_test2/sub2"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"=== RUN   TestOutputWithSubtest/sub_test2/sub2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest","Output":"--- FAIL: TestOutputWithSubtest (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"    --- PASS: TestOutputWithSubtest/sub_test (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"        foo_test.go:9: output from sub test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"        foo_test.go:11: more output from sub test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test","Output":"        foo_test.go:16: more output from sub test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"        --- PASS: TestOutputWithSubtest/sub_test/sub2 (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"            foo_test.go:14: output from sub2 test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"    foo_test.go:22: output from root test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test/sub2","Output":"    foo_test.go:27: output from root test\n"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test/sub2"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"    --- PASS: TestOutputWithSubtest/sub_test2 (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"        foo_test.go:21: output from sub test2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"        foo_test.go:23: more output from sub test2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2","Output":"        foo_test.go:28: more output from sub test2\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"        --- PASS: TestOutputWithSubtest/sub_test2/sub2 (0.00s)\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"            foo_test.go:26: output from sub2 test\n"}
+{"Action":"output","Test":"TestOutputWithSubtest/sub_test2/sub2","Output":"    foo_test.go:32: output after sub test\n"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test2/sub2"}
+{"Action":"pass","Test":"TestOutputWithSubtest/sub_test2"}
+{"Action":"fail","Test":"TestOutputWithSubtest"}
+{"Action":"output","Output":"FAIL\n"}
+{"Action":"output","Output":"FAIL\tgotest.tools/gotestsum/foo\t0.001s\n"}
+{"Action":"output","Output":"FAIL\n"}
+{"Action":"fail"}

testjson/testdata/summary-misattributed-output

@@ -0,0 +1,21 @@
+
+=== Failed
+=== FAIL:  TestOutputWithSubtest (0.00s)
+    --- PASS: TestOutputWithSubtest/sub_test (0.00s)
+        foo_test.go:9: output from sub test
+        foo_test.go:11: more output from sub test
+        foo_test.go:16: more output from sub test
+        --- PASS: TestOutputWithSubtest/sub_test/sub2 (0.00s)
+            foo_test.go:14: output from sub2 test
+    foo_test.go:22: output from root test
+    foo_test.go:27: output from root test
+    --- PASS: TestOutputWithSubtest/sub_test2 (0.00s)
+        foo_test.go:21: output from sub test2
+        foo_test.go:23: more output from sub test2
+        foo_test.go:28: more output from sub test2
+        --- PASS: TestOutputWithSubtest/sub_test2/sub2 (0.00s)
+            foo_test.go:26: output from sub2 test
+    foo_test.go:32: output after sub test
+
+
+DONE 5 tests, 1 failure in 0.000s

testjson/testdata/summary-root-test-has-subtest-failures

@@ -0,0 +1,35 @@
+
+=== Skipped
+=== SKIP: github.com/gotestyourself/gotestyourself/testjson/internal/good TestSkipped (0.00s)
+	good_test.go:23: 
+
+=== SKIP: github.com/gotestyourself/gotestyourself/testjson/internal/good TestSkippedWitLog (0.00s)
+	good_test.go:27: the skip message
+
+=== SKIP: github.com/gotestyourself/gotestyourself/testjson/internal/stub TestSkipped (0.00s)
+	stub_test.go:26: 
+
+=== SKIP: github.com/gotestyourself/gotestyourself/testjson/internal/stub TestSkippedWitLog (0.00s)
+	stub_test.go:30: the skip message
+
+
+=== Failed
+=== FAIL: github.com/gotestyourself/gotestyourself/testjson/internal/badmain  (0.00s)
+sometimes main can exit 2
+FAIL	github.com/gotestyourself/gotestyourself/testjson/internal/badmain	0.010s
+
+=== FAIL: github.com/gotestyourself/gotestyourself/testjson/internal/stub TestFailed (0.00s)
+	stub_test.go:34: this failed
+
+=== FAIL: github.com/gotestyourself/gotestyourself/testjson/internal/stub TestFailedWithStderr (0.00s)
+this is stderr
+	stub_test.go:43: also failed
+
+=== FAIL: github.com/gotestyourself/gotestyourself/testjson/internal/stub TestNestedWithFailure/c (0.00s)
+    --- FAIL: TestNestedWithFailure/c (0.00s)
+    	stub_test.go:65: failed
+
+=== FAIL: github.com/gotestyourself/gotestyourself/testjson/internal/stub TestNestedWithFailure (0.00s)
+
+
+DONE 46 tests, 4 skipped, 5 failures in 0.000s