testing: remove tests from the running log while they are waiting on parallel subtests

The parallel subtests are themselves removed from the running map
while they are blocked on calls to t.Parallel, so it is misleading to
log their parents as if they are running when we know they cannot be
making any kind of meaningful progress.

Fixes #64404.

Change-Id: Iaad11d5d4f4c86d775d36e5285c49629dccddd74
Reviewed-on: https://go-review.googlesource.com/c/go/+/546018
Run-TryBot: Bryan Mills <bcmills@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>
Auto-Submit: Bryan Mills <bcmills@google.com>
Reviewed-by: Alan Donovan <adonovan@google.com>

src/testing/testing.go

@@ -1638,15 +1638,22 @@ func tRunner(t *T, fn func(t *T)) {
 
 		if len(t.sub) > 0 {
 			// Run parallel subtests.
-			// Decrease the running count for this test.
+
+			// Decrease the running count for this test and mark it as no longer running.
 			t.context.release()
+			running.Delete(t.name)
+
 			// Release the parallel subtests.
 			close(t.barrier)
 			// Wait for subtests to complete.
 			for _, sub := range t.sub {
 				<-sub.signal
 			}
+
+			// Run any cleanup callbacks, marking the test as running
+			// in case the cleanup hangs.
 			cleanupStart := time.Now()
+			running.Store(t.name, cleanupStart)
 			err := t.runCleanup(recoverAndReturnPanic)
 			t.duration += time.Since(cleanupStart)
 			if err != nil {
@@ -1733,11 +1740,19 @@ func (t *T) Run(name string, f func(t *T)) bool {
 	// without being preempted, even when their parent is a parallel test. This
 	// may especially reduce surprises if *parallel == 1.
 	go tRunner(t, f)
+
+	// The parent goroutine will block until the subtest either finishes or calls
+	// Parallel, but in general we don't know whether the parent goroutine is the
+	// top-level test function or some other goroutine it has spawned.
+	// To avoid confusing false-negatives, we leave the parent in the running map
+	// even though in the typical case it is blocked.
+
 	if !<-t.signal {
 		// At this point, it is likely that FailNow was called on one of the
 		// parent tests by one of the subtests. Continue aborting up the chain.
 		runtime.Goexit()
 	}
+
 	if t.chatty != nil && t.chatty.json {
 		t.chatty.Updatef(t.parent.name, "=== NAME  %s\n", t.parent.name)
 	}

src/testing/testing_test.go

@@ -6,13 +6,18 @@ package testing_test
 
 import (
 	"bytes"
+	"fmt"
 	"internal/race"
 	"internal/testenv"
 	"os"
+	"os/exec"
 	"path/filepath"
 	"regexp"
+	"slices"
+	"strings"
 	"sync"
 	"testing"
+	"time"
 )
 
 // This is exactly what a test would do without a TestMain.
@@ -636,3 +641,142 @@ func BenchmarkSubRacy(b *testing.B) {
 
 	doRace() // should be reported separately
 }
+
+func TestRunningTests(t *testing.T) {
+	t.Parallel()
+
+	// Regression test for https://go.dev/issue/64404:
+	// on timeout, the "running tests" message should not include
+	// tests that are waiting on parked subtests.
+
+	if os.Getenv("GO_WANT_HELPER_PROCESS") == "1" {
+		for i := 0; i < 2; i++ {
+			t.Run(fmt.Sprintf("outer%d", i), func(t *testing.T) {
+				t.Parallel()
+				for j := 0; j < 2; j++ {
+					t.Run(fmt.Sprintf("inner%d", j), func(t *testing.T) {
+						t.Parallel()
+						for {
+							time.Sleep(1 * time.Millisecond)
+						}
+					})
+				}
+			})
+		}
+	}
+
+	timeout := 10 * time.Millisecond
+	for {
+		cmd := testenv.Command(t, os.Args[0], "-test.run=^"+t.Name()+"$", "-test.timeout="+timeout.String(), "-test.parallel=4")
+		cmd.Env = append(cmd.Environ(), "GO_WANT_HELPER_PROCESS=1")
+		out, err := cmd.CombinedOutput()
+		t.Logf("%v:\n%s", cmd, out)
+		if _, ok := err.(*exec.ExitError); !ok {
+			t.Fatal(err)
+		}
+
+		// Because the outer subtests (and TestRunningTests itself) are marked as
+		// parallel, their test functions return (and are no longer “running”)
+		// before the inner subtests are released to run and hang.
+		// Only those inner subtests should be reported as running.
+		want := []string{
+			"TestRunningTests/outer0/inner0",
+			"TestRunningTests/outer0/inner1",
+			"TestRunningTests/outer1/inner0",
+			"TestRunningTests/outer1/inner1",
+		}
+
+		got, ok := parseRunningTests(out)
+		if slices.Equal(got, want) {
+			break
+		}
+		if ok {
+			t.Logf("found running tests:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n"))
+		} else {
+			t.Logf("no running tests found")
+		}
+		t.Logf("retrying with longer timeout")
+		timeout *= 2
+	}
+}
+
+func TestRunningTestsInCleanup(t *testing.T) {
+	t.Parallel()
+
+	if os.Getenv("GO_WANT_HELPER_PROCESS") == "1" {
+		for i := 0; i < 2; i++ {
+			t.Run(fmt.Sprintf("outer%d", i), func(t *testing.T) {
+				// Not parallel: we expect to see only one outer test,
+				// stuck in cleanup after its subtest finishes.
+
+				t.Cleanup(func() {
+					for {
+						time.Sleep(1 * time.Millisecond)
+					}
+				})
+
+				for j := 0; j < 2; j++ {
+					t.Run(fmt.Sprintf("inner%d", j), func(t *testing.T) {
+						t.Parallel()
+					})
+				}
+			})
+		}
+	}
+
+	timeout := 10 * time.Millisecond
+	for {
+		cmd := testenv.Command(t, os.Args[0], "-test.run=^"+t.Name()+"$", "-test.timeout="+timeout.String())
+		cmd.Env = append(cmd.Environ(), "GO_WANT_HELPER_PROCESS=1")
+		out, err := cmd.CombinedOutput()
+		t.Logf("%v:\n%s", cmd, out)
+		if _, ok := err.(*exec.ExitError); !ok {
+			t.Fatal(err)
+		}
+
+		// TestRunningTestsInCleanup is blocked in the call to t.Run,
+		// but its test function has not yet returned so it should still
+		// be considered to be running.
+		// outer1 hasn't even started yet, so only outer0 and the top-level
+		// test function should be reported as running.
+		want := []string{
+			"TestRunningTestsInCleanup",
+			"TestRunningTestsInCleanup/outer0",
+		}
+
+		got, ok := parseRunningTests(out)
+		if slices.Equal(got, want) {
+			break
+		}
+		if ok {
+			t.Logf("found running tests:\n%s\nwant:\n%s", strings.Join(got, "\n"), strings.Join(want, "\n"))
+		} else {
+			t.Logf("no running tests found")
+		}
+		t.Logf("retrying with longer timeout")
+		timeout *= 2
+	}
+}
+
+func parseRunningTests(out []byte) (runningTests []string, ok bool) {
+	inRunningTests := false
+	for _, line := range strings.Split(string(out), "\n") {
+		if inRunningTests {
+			if trimmed, ok := strings.CutPrefix(line, "\t"); ok {
+				if name, _, ok := strings.Cut(trimmed, " "); ok {
+					runningTests = append(runningTests, name)
+					continue
+				}
+			}
+
+			// This line is not the name of a running test.
+			return runningTests, true
+		}
+
+		if strings.TrimSpace(line) == "running tests:" {
+			inRunningTests = true
+		}
+	}
+
+	return nil, false
+}