testing: print names of running tests on test timeout

Track the running tests and when they started,
so that we can report the running tests on a test timeout.

	% go test -timeout=5s
	panic: test timed out after 5s
	running tests:
		TestTCPSpuriousConnSetupCompletion (4s)

	... stack traces as usual ...

	% go test -run=Script -timeout=10s cmd/go
	vcs-test.golang.org rerouted to http://127.0.0.1:65168
	https://vcs-test.golang.org rerouted to https://127.0.0.1:65169
	go test proxy running at GOPROXY=http://127.0.0.1:65170/mod
	panic: test timed out after 10s
	running tests:
		TestScript (10s)
		TestScript/mod_get_patchcycle (0s)
		TestScript/mod_get_prefer_incompatible (0s)
		TestScript/mod_get_promote_implicit (0s)
		TestScript/mod_get_pseudo (0s)
		TestScript/mod_get_pseudo_other_branch (0s)
		TestScript/mod_get_pseudo_prefix (0s)
		TestScript/mod_get_test (0s)
		TestScript/mod_get_trailing_slash (0s)
		TestScript/mod_get_update_unrelated_sum (0s)
		TestScript/mod_gobuild_import (0s)
		TestScript/mod_gomodcache (0s)
		TestScript/mod_gonoproxy (0s)
		TestScript/mod_load_badchain (0s)
		TestScript/mod_overlay (0s)
		TestScript/test_fuzz_minimize (6s)
		TestScript/test_fuzz_minimize_dirty_cov (7s)

	... stack traces as usual ...

Change-Id: I3a6647c029097becc06664ebd76a2597c7ed7b8e
Reviewed-on: https://go-review.googlesource.com/c/go/+/446176
Run-TryBot: Russ Cox <rsc@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Bryan Mills <bcmills@google.com>
Auto-Submit: Russ Cox <rsc@golang.org>

1 files changed, 34 insertions, 4 deletions

diff --git a/src/testing/testing.go b/src/testing/testing.go
index 235ab0adb7..e694b6cb6b 100644
--- a/src/testing/testing.go
+++ b/src/testing/testing.go
@@ -381,6 +381,7 @@ import (
 	"runtime"
 	"runtime/debug"
 	"runtime/trace"
+	"sort"
 	"strconv"
 	"strings"
 	"sync"
@@ -477,6 +478,8 @@ var (
 	testlogFile *os.File
 
 	numFailed atomic.Uint32 // number of test failures
+
+	running sync.Map // map[string]time.Time of running, unpaused tests
 )
 
 type chattyFlag struct {
@@ -1363,6 +1366,7 @@ func (t *T) Parallel() {
 	if t.chatty != nil {
 		t.chatty.Updatef(t.name, "=== PAUSE %s\n", t.name)
 	}
+	running.Delete(t.name)
 
 	t.signal <- true   // Release calling test.
 	<-t.parent.barrier // Wait for the parent test to complete.
@@ -1371,6 +1375,7 @@ func (t *T) Parallel() {
 	if t.chatty != nil {
 		t.chatty.Updatef(t.name, "=== CONT  %s\n", t.name)
 	}
+	running.Store(t.name, time.Now())
 
 	t.start = time.Now()
 	t.raceErrors += -race.Errors()
@@ -1474,15 +1479,16 @@ func tRunner(t *T, fn func(t *T)) {
 		// complete even if a cleanup function calls t.FailNow. See issue 41355.
 		didPanic := false
 		defer func() {
+			// Only report that the test is complete if it doesn't panic,
+			// as otherwise the test binary can exit before the panic is
+			// reported to the user. See issue 41479.
 			if didPanic {
 				return
 			}
 			if err != nil {
 				panic(err)
 			}
-			// Only report that the test is complete if it doesn't panic,
-			// as otherwise the test binary can exit before the panic is
-			// reported to the user. See issue 41479.
+			running.Delete(t.name)
 			t.signal <- signal
 		}()
 
@@ -1595,6 +1601,8 @@ func (t *T) Run(name string, f func(t *T)) bool {
 	if t.chatty != nil {
 		t.chatty.Updatef(t.name, "=== RUN   %s\n", t.name)
 	}
+	running.Store(t.name, time.Now())
+
 	// Instead of reducing the running count of this test before calling the
 	// tRunner and increasing it afterwards, we rely on tRunner keeping the
 	// count correct. This ensures that a sequence of sequential tests runs
@@ -2201,11 +2209,33 @@ func (m *M) startAlarm() time.Time {
 	m.timer = time.AfterFunc(*timeout, func() {
 		m.after()
 		debug.SetTraceback("all")
-		panic(fmt.Sprintf("test timed out after %v", *timeout))
+		extra := ""
+
+		if list := runningList(); len(list) > 0 {
+			var b strings.Builder
+			b.WriteString("\nrunning tests:")
+			for _, name := range list {
+				b.WriteString("\n\t")
+				b.WriteString(name)
+			}
+			extra = b.String()
+		}
+		panic(fmt.Sprintf("test timed out after %v%s", *timeout, extra))
 	})
 	return deadline
 }
 
+// runningList returns the list of running tests.
+func runningList() []string {
+	var list []string
+	running.Range(func(k, v any) bool {
+		list = append(list, fmt.Sprintf("%s (%v)", k.(string), time.Since(v.(time.Time)).Round(time.Second)))
+		return true
+	})
+	sort.Strings(list)
+	return list
+}
+
 // stopAlarm turns off the alarm.
 func (m *M) stopAlarm() {
 	if *timeout > 0 {