testing: provide additional information when test funcs panic

Flush the output log up to the root when a test panics. Prior to
this change, only the current test's output log was flushed to its
parent, resulting in no output when a subtest panics.

For the following test function:

	func Test(t *testing.T) {
		for i, test := range []int{1, 0, 2} {
			t.Run(fmt.Sprintf("%v/%v", i, test), func(t *testing.T) {
				_ = 1 / test
			})
		}
	}

Output before this change:

	panic: runtime error: integer divide by zero [recovered]
		panic: runtime error: integer divide by zero
	(stack trace follows)

Output after this change:

	--- FAIL: Test (0.00s)
	    --- FAIL: Test/1/0 (0.00s)
	panic: runtime error: integer divide by zero [recovered]
	(stack trace follows)

Fixes #32121

Change-Id: Ifee07ccc005f0493a902190a8be734943123b6b7
Reviewed-on: https://go-review.googlesource.com/c/go/+/179599
Run-TryBot: Damien Neil <[email protected]>
TryBot-Result: Gobot Gobot <[email protected]>
Reviewed-by: Ian Lance Taylor <[email protected]>

Author: neild

src/cmd/internal/test2json/testdata/panic.json

@@ -0,0 +1,19 @@
+{"Action":"output","Test":"TestPanic","Output":"--- FAIL: TestPanic (0.00s)\n"}
+{"Action":"output","Test":"TestPanic","Output":"panic: oops [recovered]\n"}
+{"Action":"output","Test":"TestPanic","Output":"\tpanic: oops\n"}
+{"Action":"output","Test":"TestPanic","Output":"\n"}
+{"Action":"output","Test":"TestPanic","Output":"goroutine 7 [running]:\n"}
+{"Action":"output","Test":"TestPanic","Output":"testing.tRunner.func1(0xc000092100)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\t/go/src/testing/testing.go:874 +0x3a3\n"}
+{"Action":"output","Test":"TestPanic","Output":"panic(0x1110ea0, 0x116aea0)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\t/go/src/runtime/panic.go:679 +0x1b2\n"}
+{"Action":"output","Test":"TestPanic","Output":"command-line-arguments.TestPanic(0xc000092100)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\ta_test.go:6 +0x39\n"}
+{"Action":"output","Test":"TestPanic","Output":"testing.tRunner(0xc000092100, 0x114f500)\n"}
+{"Action":"output","Test":"TestPanic","Output":"\tgo/src/testing/testing.go:909 +0xc9\n"}
+{"Action":"output","Test":"TestPanic","Output":"created by testing.(*T).Run\n"}
+{"Action":"output","Test":"TestPanic","Output":"\tgo/src/testing/testing.go:960 +0x350\n"}
+{"Action":"output","Test":"TestPanic","Output":"FAIL\tcommand-line-arguments\t0.042s\n"}
+{"Action":"fail","Test":"TestPanic"}
+{"Action":"output","Output":"FAIL\n"}
+{"Action":"fail"}

src/cmd/internal/test2json/testdata/panic.test

@@ -0,0 +1,17 @@
+--- FAIL: TestPanic (0.00s)
+panic: oops [recovered]
+	panic: oops
+
+goroutine 7 [running]:
+testing.tRunner.func1(0xc000092100)
+	/go/src/testing/testing.go:874 +0x3a3
+panic(0x1110ea0, 0x116aea0)
+	/go/src/runtime/panic.go:679 +0x1b2
+command-line-arguments.TestPanic(0xc000092100)
+	a_test.go:6 +0x39
+testing.tRunner(0xc000092100, 0x114f500)
+	go/src/testing/testing.go:909 +0xc9
+created by testing.(*T).Run
+	go/src/testing/testing.go:960 +0x350
+FAIL	command-line-arguments	0.042s
+FAIL

src/testing/panic_test.go

@@ -0,0 +1,83 @@
+// Copyright 2019 The Go Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package testing_test
+
+import (
+	"flag"
+	"fmt"
+	"internal/testenv"
+	"os"
+	"os/exec"
+	"regexp"
+	"strings"
+	"testing"
+)
+
+var testPanicTest = flag.String("test_panic_test", "", "TestPanic: indicates which test should panic")
+
+func TestPanic(t *testing.T) {
+	testenv.MustHaveExec(t)
+
+	testCases := []struct {
+		desc  string
+		flags []string
+		want  string
+	}{{
+		desc:  "root test panics",
+		flags: []string{"-test_panic_test=TestPanicHelper"},
+		want: `
+--- FAIL: TestPanicHelper (N.NNs)
+    panic_test.go:NNN: TestPanicHelper
+`,
+	}, {
+		desc:  "subtest panics",
+		flags: []string{"-test_panic_test=TestPanicHelper/1"},
+		want: `
+--- FAIL: TestPanicHelper (N.NNs)
+    panic_test.go:NNN: TestPanicHelper
+    --- FAIL: TestPanicHelper/1 (N.NNs)
+        panic_test.go:NNN: TestPanicHelper/1
+`,
+	}}
+	for _, tc := range testCases {
+		t.Run(tc.desc, func(t *testing.T) {
+			cmd := exec.Command(os.Args[0], "-test.run=TestPanicHelper")
+			cmd.Args = append(cmd.Args, tc.flags...)
+			cmd.Env = append(os.Environ(), "GO_WANT_HELPER_PROCESS=1")
+			b, _ := cmd.CombinedOutput()
+			got := string(b)
+			want := strings.TrimSpace(tc.want)
+			re := makeRegexp(want)
+			if ok, err := regexp.MatchString(re, got); !ok || err != nil {
+				t.Errorf("output:\ngot:\n%s\nwant:\n%s", got, want)
+			}
+		})
+	}
+}
+
+func makeRegexp(s string) string {
+	s = regexp.QuoteMeta(s)
+	s = strings.ReplaceAll(s, ":NNN:", `:\d+:`)
+	s = strings.ReplaceAll(s, "N\\.NNs", `\d*\.\d*s`)
+	return s
+}
+
+func TestPanicHelper(t *testing.T) {
+	if os.Getenv("GO_WANT_HELPER_PROCESS") != "1" {
+		return
+	}
+	t.Log(t.Name())
+	if t.Name() == *testPanicTest {
+		panic("panic")
+	}
+	for i := 0; i < 3; i++ {
+		t.Run(fmt.Sprintf("%v", i), func(t *testing.T) {
+			t.Log(t.Name())
+			if t.Name() == *testPanicTest {
+				panic("panic")
+			}
+		})
+	}
+}

src/testing/testing.go

@@ -860,7 +860,6 @@ func tRunner(t *T, fn func(t *T)) {
 			t.Errorf("race detected during execution of test")
 		}
 
-		t.duration += time.Since(t.start)
 		// If the test panicked, print any test output before dying.
 		err := recover()
 		signal := true
@@ -877,10 +876,20 @@ func tRunner(t *T, fn func(t *T)) {
 		}
 		if err != nil {
 			t.Fail()
-			t.report()
+			// Flush the output log up to the root before dying.
+			t.mu.Lock()
+			root := &t.common
+			for ; root.parent != nil; root = root.parent {
+				root.duration += time.Since(root.start)
+				fmt.Fprintf(root.parent.w, "--- FAIL: %s (%s)\n", root.name, fmtDuration(root.duration))
+				root.parent.mu.Lock()
+				io.Copy(root.parent.w, bytes.NewReader(root.output))
+			}
 			panic(err)
 		}
 
+		t.duration += time.Since(t.start)
+
 		if len(t.sub) > 0 {
 			// Run parallel subtests.
 			// Decrease the running count for this test.