From ad5d2f64fbb90dd13c4587aa5bf2ed3c86a6dec2 Mon Sep 17 00:00:00 2001 From: Russ Cox Date: Fri, 28 Oct 2022 09:19:32 -0400 Subject: [PATCH] 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 TryBot-Result: Gopher Robot Reviewed-by: Bryan Mills Auto-Submit: Russ Cox --- src/testing/testing.go | 38 ++++++++++++++++++++++++++++++++++---- 1 file 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 { -- 2.50.0