cmd/internal/test2json: test timeout panic trace is attributed to the running test, even if the test just passed #57305

mafredri · 2022-12-14T11:02:00Z

What version of Go are you using (`go version`)?

go version go1.20rc1 linux/amd64
go version go1.19.4 linux/amd64

Does this issue reproduce with the latest release?

Yes.

What operating system and processor architecture are you using (`go env`)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/mafredri/.cache/go-build"
GOENV="/home/mafredri/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/mafredri/.local/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/mafredri/.local/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/home/mafredri/sdk/go1.20rc1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/home/mafredri/sdk/go1.20rc1/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.20rc1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/mafredri/src/test/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build4075746849=/tmp/go-build -gno-record-gcc-switches"

What did you do?

I ran go test with json output and a timeout which occurs right as one test is passing.

With the following test file:

package main

import (
	"testing"
	"time"
)

func TestHello(t *testing.T) {
	time.Sleep(1 * time.Second)
	t.Log("Hello")
}

func TestWorld(t *testing.T) {
	time.Sleep(2 * time.Second)
	t.Log("World")
}

Running go test . -json -timeout=1s reproduces the problem sporadically. The behavior is racy. Sometimes the test timeout panic trace is attributed to a test, other times not. And occasionally it's attributed to a test that passed.

What did you expect to see?

I wanted to see the test timeout panic output not attributed to any particular test (no {"Test":"TestHello"}) since there could be multiple tests running.

go test . -json -timeout=1s Output

$ go test . -json -timeout=1s
{"Time":"2022-12-14T09:52:45.610058332Z","Action":"start","Package":"github.com/mafredri/test"}
{"Time":"2022-12-14T09:52:45.6149067Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:52:45.614981514Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== RUN   TestHello\n"}
{"Time":"2022-12-14T09:52:46.615047173Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"    main_test.go:11: Hello\n"}
{"Time":"2022-12-14T09:52:46.615171408Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"--- PASS: TestHello (1.00s)\n"}
{"Time":"2022-12-14T09:52:46.615193059Z","Action":"pass","Package":"github.com/mafredri/test","Test":"TestHello","Elapsed":1}
{"Time":"2022-12-14T09:52:46.618346351Z","Action":"output","Package":"github.com/mafredri/test","Output":"panic: test timed out after 1s\n"}
{"Time":"2022-12-14T09:52:46.618364203Z","Action":"output","Package":"github.com/mafredri/test","Output":"running tests:\n"}
{"Time":"2022-12-14T09:52:46.618374523Z","Action":"output","Package":"github.com/mafredri/test","Output":"\tTestHello (1s)\n"}
{"Time":"2022-12-14T09:52:46.618384492Z","Action":"output","Package":"github.com/mafredri/test","Output":"\n"}
{"Time":"2022-12-14T09:52:46.618399382Z","Action":"output","Package":"github.com/mafredri/test","Output":"goroutine 19 [running]:\n"}
{"Time":"2022-12-14T09:52:46.618410087Z","Action":"output","Package":"github.com/mafredri/test","Output":"testing.(*M).startAlarm.func1()\n"}
{"Time":"2022-12-14T09:52:46.618421931Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2240 +0x3b9\n"}
{"Time":"2022-12-14T09:52:46.618438976Z","Action":"output","Package":"github.com/mafredri/test","Output":"created by time.goFunc\n"}
{"Time":"2022-12-14T09:52:46.618450138Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/time/sleep.go:176 +0x32\n"}
{"Time":"2022-12-14T09:52:46.618461896Z","Action":"output","Package":"github.com/mafredri/test","Output":"\n"}
{"Time":"2022-12-14T09:52:46.618475653Z","Action":"output","Package":"github.com/mafredri/test","Output":"goroutine 1 [runnable]:\n"}
{"Time":"2022-12-14T09:52:46.618498327Z","Action":"output","Package":"github.com/mafredri/test","Output":"testing.(*T).Run(0xc000102d00, {0x5be895?, 0x4ce6c5?}, 0x6072a8)\n"}
{"Time":"2022-12-14T09:52:46.618525401Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1606 +0xf8\n"}
{"Time":"2022-12-14T09:52:46.618551729Z","Action":"output","Package":"github.com/mafredri/test","Output":"testing.runTests.func1(0x7438e0?)\n"}
{"Time":"2022-12-14T09:52:46.618574979Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2035 +0x45\n"}
{"Time":"2022-12-14T09:52:46.618602505Z","Action":"output","Package":"github.com/mafredri/test","Output":"testing.tRunner(0xc000102d00, 0xc0002dfc88)\n"}
{"Time":"2022-12-14T09:52:46.618624326Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b\n"}
{"Time":"2022-12-14T09:52:46.618709789Z","Action":"output","Package":"github.com/mafredri/test","Output":"testing.runTests(0xc000134500?, {0x739320, 0x2, 0x2}, {0x20?, 0x100c00011d6c8?, 0x743080?})\n"}
{"Time":"2022-12-14T09:52:46.618764825Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2033 +0x489\n"}
{"Time":"2022-12-14T09:52:46.618785284Z","Action":"output","Package":"github.com/mafredri/test","Output":"testing.(*M).Run(0xc000134500)\n"}
{"Time":"2022-12-14T09:52:46.618807928Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1905 +0x63a\n"}
{"Time":"2022-12-14T09:52:46.618823424Z","Action":"output","Package":"github.com/mafredri/test","Output":"main.main()\n"}
{"Time":"2022-12-14T09:52:46.618843647Z","Action":"output","Package":"github.com/mafredri/test","Output":"\t_testmain.go:49 +0x1aa\n"}
{"Time":"2022-12-14T09:52:46.619974338Z","Action":"output","Package":"github.com/mafredri/test","Output":"FAIL\tgithub.com/mafredri/test\t1.010s\n"}
{"Time":"2022-12-14T09:52:46.62000331Z","Action":"fail","Package":"github.com/mafredri/test","Elapsed":1.01}

When adding t.Parallel() to both tests:

go test . -json -timeout=1s Output (parallel)

$ go test . -json -timeout=1s
{"Time":"2022-12-14T09:55:35.246489093Z","Action":"start","Package":"github.com/mafredri/test"}
{"Time":"2022-12-14T09:55:35.251424026Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:55:35.251518839Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== RUN   TestHello\n"}
{"Time":"2022-12-14T09:55:35.25157982Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== PAUSE TestHello\n"}
{"Time":"2022-12-14T09:55:35.251589952Z","Action":"pause","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:55:35.251599969Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestWorld"}
{"Time":"2022-12-14T09:55:35.251607407Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"=== RUN   TestWorld\n"}
{"Time":"2022-12-14T09:55:35.251616616Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"=== PAUSE TestWorld\n"}
{"Time":"2022-12-14T09:55:35.251623729Z","Action":"pause","Package":"github.com/mafredri/test","Test":"TestWorld"}
{"Time":"2022-12-14T09:55:35.251632215Z","Action":"cont","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:55:35.251640566Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== CONT  TestHello\n"}
{"Time":"2022-12-14T09:55:35.2516486Z","Action":"cont","Package":"github.com/mafredri/test","Test":"TestWorld"}
{"Time":"2022-12-14T09:55:35.251655697Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"=== CONT  TestWorld\n"}
{"Time":"2022-12-14T09:55:36.253661037Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"panic: test timed out after 1s\n"}
{"Time":"2022-12-14T09:55:36.253687981Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"running tests:\n"}
{"Time":"2022-12-14T09:55:36.253692302Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\tTestHello (1s)\n"}
{"Time":"2022-12-14T09:55:36.253698479Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\tTestWorld (1s)\n"}
{"Time":"2022-12-14T09:55:36.253701688Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\n"}
{"Time":"2022-12-14T09:55:36.253704985Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"goroutine 33 [running]:\n"}
{"Time":"2022-12-14T09:55:36.253711078Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.(*M).startAlarm.func1()\n"}
{"Time":"2022-12-14T09:55:36.253714256Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2240 +0x3b9\n"}
{"Time":"2022-12-14T09:55:36.253721132Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"created by time.goFunc\n"}
{"Time":"2022-12-14T09:55:36.253725321Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/time/sleep.go:176 +0x32\n"}
{"Time":"2022-12-14T09:55:36.253734038Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\n"}
{"Time":"2022-12-14T09:55:36.253746746Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"goroutine 1 [chan receive]:\n"}
{"Time":"2022-12-14T09:55:36.253792636Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.tRunner.func1()\n"}
{"Time":"2022-12-14T09:55:36.253810139Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1541 +0x4a5\n"}
{"Time":"2022-12-14T09:55:36.253850313Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.tRunner(0xc000083040, 0xc00025fc88)\n"}
{"Time":"2022-12-14T09:55:36.253871049Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1581 +0x144\n"}
{"Time":"2022-12-14T09:55:36.25395494Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.runTests(0xc0000c0500?, {0x739320, 0x2, 0x2}, {0xc0000b2878?, 0x100c00025fd10?, 0x743080?})\n"}
{"Time":"2022-12-14T09:55:36.253970468Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2033 +0x489\n"}
{"Time":"2022-12-14T09:55:36.253985066Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.(*M).Run(0xc0000c0500)\n"}
{"Time":"2022-12-14T09:55:36.254008048Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1905 +0x63a\n"}
{"Time":"2022-12-14T09:55:36.254021094Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"main.main()\n"}
{"Time":"2022-12-14T09:55:36.254039749Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t_testmain.go:49 +0x1aa\n"}
{"Time":"2022-12-14T09:55:36.254048086Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\n"}
{"Time":"2022-12-14T09:55:36.254062038Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"goroutine 20 [sleep]:\n"}
{"Time":"2022-12-14T09:55:36.254081672Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"time.Sleep(0x3b9aca00)\n"}
{"Time":"2022-12-14T09:55:36.254104512Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/time.go:195 +0x135\n"}
{"Time":"2022-12-14T09:55:36.254120657Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"github.com/mafredri/test.TestHello(0xc0000831e0)\n"}
{"Time":"2022-12-14T09:55:36.254144276Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/src/mafredri/test/main_test.go:10 +0x28\n"}
{"Time":"2022-12-14T09:55:36.25415969Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.tRunner(0xc0000831e0, 0x607340)\n"}
{"Time":"2022-12-14T09:55:36.254174687Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b\n"}
{"Time":"2022-12-14T09:55:36.254182297Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"created by testing.(*T).Run\n"}
{"Time":"2022-12-14T09:55:36.254206658Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1628 +0x3ea\n"}
{"Time":"2022-12-14T09:55:36.254211849Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\n"}
{"Time":"2022-12-14T09:55:36.254223182Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"goroutine 21 [sleep]:\n"}
{"Time":"2022-12-14T09:55:36.254236017Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"time.Sleep(0x77359400)\n"}
{"Time":"2022-12-14T09:55:36.254251193Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/time.go:195 +0x135\n"}
{"Time":"2022-12-14T09:55:36.254262497Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"github.com/mafredri/test.TestWorld(0xc000083520)\n"}
{"Time":"2022-12-14T09:55:36.254282952Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/src/mafredri/test/main_test.go:16 +0x28\n"}
{"Time":"2022-12-14T09:55:36.254305717Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"testing.tRunner(0xc000083520, 0x607348)\n"}
{"Time":"2022-12-14T09:55:36.254328602Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b\n"}
{"Time":"2022-12-14T09:55:36.254339528Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"created by testing.(*T).Run\n"}
{"Time":"2022-12-14T09:55:36.254364553Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1628 +0x3ea\n"}
{"Time":"2022-12-14T09:55:36.254978551Z","Action":"output","Package":"github.com/mafredri/test","Output":"FAIL\tgithub.com/mafredri/test\t1.008s\n"}
{"Time":"2022-12-14T09:55:36.255018826Z","Action":"fail","Package":"github.com/mafredri/test","Elapsed":1.009}

Note that I'm unsure if removing {"Test":"TestWorld"} would be problematic in this case, or break any existing tools, but it doesn't intuitively make sense to me that any one test would be attributed this output.

What did you see instead?

I saw two things:

The test outputs PASS but the stack trace is attributed to it after the fact ({"Test":"TestHello"})
The test outputs PASS but Go 1.20rc1 considers it to be running still.

The first case is problematic since tools like gotestsum rely on PASS to ignore future output from a test. The second is more of an inconvenience, however, if tools relied on the output to distinguish problematic tests, the statistics would be skewed.

{"Time":"2022-12-14T09:49:02.56982657Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"--- PASS: TestHello (1.00s)\n"}
{"Time":"2022-12-14T09:49:02.572963923Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"panic: test timed out after 1s\n"}
{"Time":"2022-12-14T09:49:02.572982687Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"running tests:\n"}
{"Time":"2022-12-14T09:49:02.572992095Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestHello (1s)\n"}

go test . -json -timeout=1s Output

$ go test . -json -timeout=1s
{"Time":"2022-12-14T09:49:01.562401799Z","Action":"start","Package":"github.com/mafredri/test"}
{"Time":"2022-12-14T09:49:01.569546938Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:49:01.569700427Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== RUN   TestHello\n"}
{"Time":"2022-12-14T09:49:02.569759117Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"    main_test.go:11: Hello\n"}
{"Time":"2022-12-14T09:49:02.56982657Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"--- PASS: TestHello (1.00s)\n"}
{"Time":"2022-12-14T09:49:02.572963923Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"panic: test timed out after 1s\n"}
{"Time":"2022-12-14T09:49:02.572982687Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"running tests:\n"}
{"Time":"2022-12-14T09:49:02.572992095Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestHello (1s)\n"}
{"Time":"2022-12-14T09:49:02.573000907Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
{"Time":"2022-12-14T09:49:02.573019868Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 33 [running]:\n"}
{"Time":"2022-12-14T09:49:02.573029067Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*M).startAlarm.func1()\n"}
{"Time":"2022-12-14T09:49:02.573038878Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2240 +0x3b9\n"}
{"Time":"2022-12-14T09:49:02.573064315Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"created by time.goFunc\n"}
{"Time":"2022-12-14T09:49:02.573079975Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/time/sleep.go:176 +0x32\n"}
{"Time":"2022-12-14T09:49:02.573097493Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
{"Time":"2022-12-14T09:49:02.573119064Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 1 [runnable]:\n"}
{"Time":"2022-12-14T09:49:02.573141104Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*T).Run(0xc000083040, {0x5be88c?, 0x4ce6c5?}, 0x6072a0)\n"}
{"Time":"2022-12-14T09:49:02.573162696Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1629 +0x405\n"}
{"Time":"2022-12-14T09:49:02.573178743Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.runTests.func1(0x7438e0?)\n"}
{"Time":"2022-12-14T09:49:02.573203585Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2035 +0x45\n"}
{"Time":"2022-12-14T09:49:02.57321895Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.tRunner(0xc000083040, 0xc00025fc88)\n"}
{"Time":"2022-12-14T09:49:02.573239542Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b\n"}
{"Time":"2022-12-14T09:49:02.573342015Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.runTests(0xc0000c0500?, {0x739320, 0x2, 0x2}, {0x0?, 0x100c0000ab938?, 0x743080?})\n"}
{"Time":"2022-12-14T09:49:02.573376752Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2033 +0x489\n"}
{"Time":"2022-12-14T09:49:02.573403856Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*M).Run(0xc0000c0500)\n"}
{"Time":"2022-12-14T09:49:02.573433691Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1905 +0x63a\n"}
{"Time":"2022-12-14T09:49:02.573456763Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"main.main()\n"}
{"Time":"2022-12-14T09:49:02.573483156Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t_testmain.go:49 +0x1aa\n"}
{"Time":"2022-12-14T09:49:02.573503088Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
{"Time":"2022-12-14T09:49:02.573520911Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 20 [runnable]:\n"}
{"Time":"2022-12-14T09:49:02.573539195Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"runtime.goexit1()\n"}
{"Time":"2022-12-14T09:49:02.573576101Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/proc.go:3616 +0x54\n"}
{"Time":"2022-12-14T09:49:02.573596375Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"runtime.goexit()\n"}
{"Time":"2022-12-14T09:49:02.573620424Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/asm_amd64.s:1599 +0x6\n"}
{"Time":"2022-12-14T09:49:02.573637148Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"created by testing.(*T).Run\n"}
{"Time":"2022-12-14T09:49:02.573690092Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1628 +0x3ea\n"}
{"Time":"2022-12-14T09:49:02.574702109Z","Action":"pass","Package":"github.com/mafredri/test","Test":"TestHello","Elapsed":1}
{"Time":"2022-12-14T09:49:02.57473959Z","Action":"output","Package":"github.com/mafredri/test","Output":"FAIL\tgithub.com/mafredri/test\t1.012s\n"}
{"Time":"2022-12-14T09:49:02.574754586Z","Action":"fail","Package":"github.com/mafredri/test","Elapsed":1.012}

When adding t.Parallel() to both tests:

{"Time":"2022-12-14T09:55:14.438107688Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"--- PASS: TestHello (1.00s)\n"}
{"Time":"2022-12-14T09:55:14.440255876Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"panic: test timed out after 1s\n"}
{"Time":"2022-12-14T09:55:14.440265298Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"running tests:\n"}
{"Time":"2022-12-14T09:55:14.440268652Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestHello (1s)\n"}
{"Time":"2022-12-14T09:55:14.440271669Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestWorld (1s)\n"}

go test . -json -timeout=1s Output (parallel)

$ go test . -json -timeout=1s
{"Time":"2022-12-14T09:55:13.434571388Z","Action":"start","Package":"github.com/mafredri/test"}
{"Time":"2022-12-14T09:55:13.43773263Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:55:13.437785391Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== RUN   TestHello\n"}
{"Time":"2022-12-14T09:55:13.437810964Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== PAUSE TestHello\n"}
{"Time":"2022-12-14T09:55:13.437814886Z","Action":"pause","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:55:13.437818949Z","Action":"run","Package":"github.com/mafredri/test","Test":"TestWorld"}
{"Time":"2022-12-14T09:55:13.437821771Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"=== RUN   TestWorld\n"}
{"Time":"2022-12-14T09:55:13.437825158Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"=== PAUSE TestWorld\n"}
{"Time":"2022-12-14T09:55:13.437832833Z","Action":"pause","Package":"github.com/mafredri/test","Test":"TestWorld"}
{"Time":"2022-12-14T09:55:13.437836266Z","Action":"cont","Package":"github.com/mafredri/test","Test":"TestHello"}
{"Time":"2022-12-14T09:55:13.437838918Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"=== CONT  TestHello\n"}
{"Time":"2022-12-14T09:55:13.437843993Z","Action":"cont","Package":"github.com/mafredri/test","Test":"TestWorld"}
{"Time":"2022-12-14T09:55:13.437846615Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestWorld","Output":"=== CONT  TestWorld\n"}
{"Time":"2022-12-14T09:55:14.438061577Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"    main_test.go:11: Hello\n"}
{"Time":"2022-12-14T09:55:14.438107688Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"--- PASS: TestHello (1.00s)\n"}
{"Time":"2022-12-14T09:55:14.440255876Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"panic: test timed out after 1s\n"}
{"Time":"2022-12-14T09:55:14.440265298Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"running tests:\n"}
{"Time":"2022-12-14T09:55:14.440268652Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestHello (1s)\n"}
{"Time":"2022-12-14T09:55:14.440271669Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\tTestWorld (1s)\n"}
{"Time":"2022-12-14T09:55:14.440278625Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
{"Time":"2022-12-14T09:55:14.440282363Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 17 [running]:\n"}
{"Time":"2022-12-14T09:55:14.440301449Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*M).startAlarm.func1()\n"}
{"Time":"2022-12-14T09:55:14.440328262Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2240 +0x3b9\n"}
{"Time":"2022-12-14T09:55:14.440345871Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"created by time.goFunc\n"}
{"Time":"2022-12-14T09:55:14.440377095Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/time/sleep.go:176 +0x32\n"}
{"Time":"2022-12-14T09:55:14.440386657Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
{"Time":"2022-12-14T09:55:14.440401693Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 1 [chan receive]:\n"}
{"Time":"2022-12-14T09:55:14.44043358Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.tRunner.func1()\n"}
{"Time":"2022-12-14T09:55:14.440460579Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1541 +0x4a5\n"}
{"Time":"2022-12-14T09:55:14.440490626Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.tRunner(0xc000007ba0, 0xc00025fc88)\n"}
{"Time":"2022-12-14T09:55:14.440516299Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1581 +0x144\n"}
{"Time":"2022-12-14T09:55:14.440631272Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.runTests(0xc000110500?, {0x739320, 0x2, 0x2}, {0x0?, 0x100c00010f098?, 0x743080?})\n"}
{"Time":"2022-12-14T09:55:14.440659038Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:2033 +0x489\n"}
{"Time":"2022-12-14T09:55:14.440688016Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.(*M).Run(0xc000110500)\n"}
{"Time":"2022-12-14T09:55:14.440716982Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1905 +0x63a\n"}
{"Time":"2022-12-14T09:55:14.440734567Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"main.main()\n"}
{"Time":"2022-12-14T09:55:14.440795664Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t_testmain.go:49 +0x1aa\n"}
{"Time":"2022-12-14T09:55:14.440804655Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\n"}
{"Time":"2022-12-14T09:55:14.440822033Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"goroutine 7 [sleep]:\n"}
{"Time":"2022-12-14T09:55:14.440845811Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"time.Sleep(0x77359400)\n"}
{"Time":"2022-12-14T09:55:14.440873545Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/runtime/time.go:195 +0x135\n"}
{"Time":"2022-12-14T09:55:14.440892453Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"github.com/mafredri/test.TestWorld(0xc0002801a0)\n"}
{"Time":"2022-12-14T09:55:14.440928546Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/src/mafredri/test/main_test.go:16 +0x28\n"}
{"Time":"2022-12-14T09:55:14.440978215Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"testing.tRunner(0xc0002801a0, 0x607348)\n"}
{"Time":"2022-12-14T09:55:14.440996639Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1575 +0x10b\n"}
{"Time":"2022-12-14T09:55:14.441008328Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"created by testing.(*T).Run\n"}
{"Time":"2022-12-14T09:55:14.441045254Z","Action":"output","Package":"github.com/mafredri/test","Test":"TestHello","Output":"\t/home/mafredri/sdk/go1.20rc1/src/testing/testing.go:1628 +0x3ea\n"}
{"Time":"2022-12-14T09:55:14.441926648Z","Action":"pass","Package":"github.com/mafredri/test","Test":"TestHello","Elapsed":1}
{"Time":"2022-12-14T09:55:14.441961258Z","Action":"output","Package":"github.com/mafredri/test","Output":"FAIL\tgithub.com/mafredri/test\t1.007s\n"}
{"Time":"2022-12-14T09:55:14.441978318Z","Action":"fail","Package":"github.com/mafredri/test","Elapsed":1.007}

The text was updated successfully, but these errors were encountered:

seankhliao · 2022-12-14T14:07:00Z

I think the attribution may be correct with the test runner still processing the first test, but there's a race between PASS and timeout?

mafredri · 2022-12-14T14:38:51Z

I think the attribution may be correct with the test runner still processing the first test, but there's a race between PASS and timeout?

Yeah, there's a race between printing PASS and the test actually exiting which affects the timeout result. But re: attribution, I would argue that when using t.Parallel() and there are multiple tests running, attributing it to a single test is incorrect. And by that reasoning, it should never be attributed to a specific test (IMO). That would match the behavior of hitting the timeout just right between a test PASSing and the next starting (there is no attribution since no test is considered to be running in that gap).

thanm · 2022-12-14T16:47:07Z

@bcmills per owners.

bcmills · 2022-12-14T17:32:01Z

See previously #35180.

See golang/go#57305

See golang/go/issues/57305

mafredri mentioned this issue Dec 14, 2022

Panic stack trace from go test -timeout=X is ignored when timeout happens right after a test passes gotestyourself/gotestsum#292

Closed

thanm added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 14, 2022

bcmills changed the title ~~testing: test timeout panic trace is attributed to the running test, even if the test just passed~~ cmd/internal/test2json: test timeout panic trace is attributed to the running test, even if the test just passed Dec 14, 2022

bcmills added this to the Backlog milestone Dec 14, 2022

bcmills added the help wanted label Dec 14, 2022

dnephin added a commit to gotestyourself/gotestsum that referenced this issue Jan 8, 2023

Workaround for a race in test2json with test timeout

8e53273

See golang/go#57305

dnephin added a commit to gotestyourself/gotestsum that referenced this issue Jan 8, 2023

Workaround for a race in test2json with test timeout

ec2b0f7

See golang/go#57305

dnephin mentioned this issue Jan 8, 2023

Print the test timeout panic as package output gotestyourself/gotestsum#298

Merged

dnephin added a commit to gotestyourself/gotestsum that referenced this issue Jan 8, 2023

Workaround for a race in test2json with test timeout

2fe7769

See golang/go/issues/57305

thanm mentioned this issue Feb 22, 2023

testing: data race is attributed to wrong test in -json formatting #58634

Open

dnephin mentioned this issue Aug 12, 2023

Include timeout errors in junit reports. gotestyourself/gotestsum#349

Closed

seankhliao mentioned this issue Jun 15, 2024

testing: timeout failure text attributed to irrelevant, passing test #67705

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cmd/internal/test2json: test timeout panic trace is attributed to the running test, even if the test just passed #57305

cmd/internal/test2json: test timeout panic trace is attributed to the running test, even if the test just passed #57305

mafredri commented Dec 14, 2022 •

edited

Loading

seankhliao commented Dec 14, 2022

mafredri commented Dec 14, 2022 •

edited

Loading

thanm commented Dec 14, 2022

bcmills commented Dec 14, 2022

cmd/internal/test2json: test timeout panic trace is attributed to the running test, even if the test just passed #57305

cmd/internal/test2json: test timeout panic trace is attributed to the running test, even if the test just passed #57305

Comments

mafredri commented Dec 14, 2022 • edited Loading

What version of Go are you using (go version)?

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

seankhliao commented Dec 14, 2022

mafredri commented Dec 14, 2022 • edited Loading

thanm commented Dec 14, 2022

bcmills commented Dec 14, 2022

mafredri commented Dec 14, 2022 •

edited

Loading

What version of Go are you using (`go version`)?

What operating system and processor architecture are you using (`go env`)?

mafredri commented Dec 14, 2022 •

edited

Loading