golang/go

cmd/go: "test timed out after ... running tests: ..." attached to one of many subtests in JSON mode, can be less visible compared to non-JSON output

Open

#74,323 opened on Jun 20, 2025

View on GitHub
 (0 comments) (0 reactions) (0 assignees)Go (19,008 forks)batch import
GoCommandNeedsInvestigationhelp wanted

Repository metrics

Stars
 (133,883 stars)
PR merge metrics
 (No merged PRs in 30d)

Description

Consider the output from go test without -json flag in a situation where a test timeout happens while multiple subtests are still running (as happened in #74279):

$ go version
go version go1.25rc1 darwin/arm64

# in golang.org/x/tools/gopls/internal/test/marker package
$ go test -count=1 -timeout=20s ./... 
panic: test timed out after 20s
	running tests:
		Test/codeaction/fill_struct_resolve.txt (1s)
		Test/codeaction/issue64558.txt (0s)
		Test/codeaction/issue70268.txt (0s)
		Test/codeaction/moveparam.txt (1s)
		Test/codeaction/moveparam_issue70599.txt (1s)
		Test/codeaction/removeparam_formatting.txt (1s)
		Test/codeaction/removeparam_funcvalue.txt (1s)
		Test/codeaction/removeparam_imports.txt (1s)
		Test/codeaction/removeparam_resolve.txt (1s)
		Test/codeaction/splitlines.txt (2s)

goroutine 273028 [running]:
testing.(*M).startAlarm.func1()
	/usr/local/go/src/testing/testing.go:2679 +0x2b0
created by time.goFunc
	/usr/local/go/src/time/sleep.go:215 +0x38

goroutine 1 [chan receive]:
testing.(*T).Run(0x140003881c0, {0x104c4f030?, 0x14000045af8?}, 0x1052171d0)
	/usr/local/go/src/testing/testing.go:2002 +0x378
testing.runTests.func1(0x140003881c0)
	/usr/local/go/src/testing/testing.go:2474 +0x38
testing.tRunner(0x140003881c0, 0x14000045c28)
	/usr/local/go/src/testing/testing.go:1931 +0xc8
testing.runTests(0x140003c3a70, {0x105a54ec0, 0x1, 0x1}, {0x140004989a8?, 0x140004989d8?, 0x105a95520?})
	/usr/local/go/src/testing/testing.go:2472 +0x3b8
testing.(*M).Run(0x140003961e0)
	/usr/local/go/src/testing/testing.go:2334 +0x530
golang.org/x/tools/gopls/internal/test/marker.TestMain(0x140003961e0)
	/Users/gopher/go/src/golang.org/x/tools/gopls/internal/test/marker/marker_test.go:63 +0x54
main.main()
	_testmain.go:47 +0x88

goroutine 67 [chan receive]:
golang.org/x/tools/gopls/internal/lsprpc.(*streamServer).ServeStream(0x140000be2a0, {0x10522e850, 0x14007384b10}, {0x105233188, 0x1400758c140})
[…]
goroutine 273488 [runnable]:
golang.org/x/tools/gopls/internal/cache.execActions.func1()
	/Users/gopher/go/src/golang.org/x/tools/gopls/internal/cache/analysis.go:894
created by golang.org/x/tools/gopls/internal/cache.execActions in goroutine 273185
	/Users/gopher/go/src/golang.org/x/tools/gopls/internal/cache/analysis.go:894 +0x50
FAIL	golang.org/x/tools/gopls/internal/test/marker	20.916s
FAIL
$ echo $?
1

Compare with the output of go test in the same situation, with -json flag:

$ go test -json -count=1 -timeout=20s ./...
[…]
{"Time":"2025-06-20T12:45:40.364095-04:00","Action":"run","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt"}
[…]
{"Time":"2025-06-20T12:45:40.364106-04:00","Action":"pause","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt"}
[…]
{"Time":"2025-06-20T12:46:00.037725-04:00","Action":"cont","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt"}
{"Time":"2025-06-20T12:46:00.037727-04:00","Action":"output","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt","Output":"=== CONT  Test/codeaction/removeparam_resolve.txt\n"}
{"Time":"2025-06-20T12:46:00.168447-04:00","Action":"output","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt","Output":"panic: test timed out after 20s\n"}
{"Time":"2025-06-20T12:46:00.168471-04:00","Action":"output","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt","Output":"\trunning tests:\n"}
{"Time":"2025-06-20T12:46:00.168473-04:00","Action":"output","Package":"golang.org/x/tools/gopls/internal/test/marker","Test":"Test/codeaction/removeparam_resolve.txt","Output":"\t\tTest/codeaction/removeparam_resolve.txt (0s)\n"}
[…]
{"Time":"2025-06-20T12:46:00.248881-04:00","Action":"output","Package":"golang.org/x/tools/gopls/internal/test/marker","Output":"FAIL\tgolang.org/x/tools/gopls/internal/test/marker\t20.629s\n"}
{"Time":"2025-06-20T12:46:00.248887-04:00","Action":"fail","Package":"golang.org/x/tools/gopls/internal/test/marker","Elapsed":20.629}
$ echo $?                                  
1

Notably, the "test timed out after ... running tests: ..." message was attached to the output of a single subtest that was in the process of running, "Test/codeaction/removeparam_resolve.txt", and not anywhere else. In this particular instance, that test hadn't finished running and has no corresponding "fail" event. As things stand, when looking at a visualization of structured test output, it can be easy to miss this information, which seems to be a regression compared to the normal non-structured test output where it's quite prominent.

Perhaps there's room for improvement here. Maybe the output would be better to attach at the package-level instead of the test-level, since it refers to multiple package tests that were running, if that's viable? Maybe something else can be done?

CC @golang/command-line, @adonovan, @cherrymui.

Contributor guide