Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
mafredri opened this issue Dec 14, 2022 · 4 comments
Labels
help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@mafredri
Copy link

mafredri commented Dec 14, 2022

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:

  1. The test outputs PASS but the stack trace is attributed to it after the fact ({"Test":"TestHello"})
  2. 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}
@seankhliao
Copy link
Member

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
Copy link
Author

mafredri commented Dec 14, 2022

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 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
@thanm
Copy link
Contributor

thanm commented Dec 14, 2022

@bcmills per owners.

@bcmills 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
Copy link
Contributor

bcmills commented Dec 14, 2022

See previously #35180.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
help wanted NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

4 participants