test: test timed out after 10m0s even with GO_TEST_TIMEOUT_SCALE=10

[4a6f656c]

With Go tip I'm no longer able to get ./all.bash to pass on a SiFive HiFive Unleashed board (linux/riscv64), even with GO_TEST_TIMEOUT_SCALE=10 exported the ../test now fails consistently with:

...

##### Testing cgo
ok      cmd/cgo/internal/test   3.377s
ok      cmd/cgo/internal/testtls        0.045s
ok      cmd/cgo/internal/testtls        0.021s
ok      cmd/cgo/internal/testnocgo      0.024s
ok      cmd/cgo/internal/testnocgo      0.022s
ok      cmd/cgo/internal/test   4.830s
ok      cmd/cgo/internal/test   3.014s
ok      cmd/cgo/internal/test   3.190s
ok      cmd/cgo/internal/testtls        0.023s
ok      cmd/cgo/internal/testnocgo      0.021s
...
##### ../test
panic: test timed out after 10m0s
running tests:
        Test (10m0s)
        Test/printbig.go (1s)
        Test/recover.go (2s)
        Test/rotate0.go (32s)
        Test/rotate1.go (46s)
goroutine 7219 [running]:
panic({0x16fda0?, 0x3f74b00640?})
        /home/joel/src/go/src/runtime/panic.go:1017 +0x3a0 fp=0x3f7412ef10 sp=0x3f7412ee60 pc=0x47170
testing.(*M).startAlarm.func1()
        /home/joel/src/go/src/testing/testing.go:2259 +0x304 fp=0x3f7412efd8 sp=0x3f7412ef10 pc=0xed65c
runtime.goexit()
        /home/joel/src/go/src/runtime/asm_riscv64.s:512 +0x4 fp=0x3f7412efd8 sp=0x3f7412efd8 pc=0x7b004
created by time.goFunc
        /home/joel/src/go/src/time/sleep.go:176 +0x50
...
[another 2000 lines of goroutine traces]

Contrary to this, an ./all.bash run with Go 1.21.6 passes successfully.

I'm not currently sure if GO_TEST_TIMEOUT_SCALE is no longer being correctly honoured, or if the tests being run have now tipped over some threshold. Either way, not being able to run ./all.bash to completion is not an ideal situation...

[4a6f656c]

Looks like the same issue occurs on openbsd/arm, which means its not platform specific.

I'm slowly bisecting, however my current guess is it relates to commit 7a0799b.

[bcmills]

I'm not currently sure if GO_TEST_TIMEOUT_SCALE is no longer being correctly honoured

The fact that the test timed out after 10m0s suggests that it is not.

It looks like the goTest registration for ../test is not setting the timeout field:
https://cs.opensource.google/go/go/+/refs/heads/master:src/cmd/dist/test.go;l=822-828;drc=5fe3f0a265c90a9c0346403742c6cafeb154503b

If it is not set, the -timeout flag is not passed to go test at all:
https://cs.opensource.google/go/go/+/refs/heads/master:src/cmd/dist/test.go;l=405-408;drc=5fe3f0a265c90a9c0346403742c6cafeb154503b

And the default timeout for go test is 10 minutes, which matches the timeout observed in your test log.

Probably we should treat a missing opts.timeout as 10 minutes instead of “omit flag”. 🤔

(CC @aclements @dmitshur)

[bcmills]

Contrary to this, an ./all.bash run with Go [1.20.6?] passes successfully.

my current guess is it relates to commit 7a0799b.

That makes sense too: prior to that change, the ../test phase ran the binary built from test/run.go directly, which would not have had a default timeout at all.

[dmitshur]

Thanks for reporting, I'll look.

[gopherbot]

Change https://go.dev/cl/511567 mentions this issue: cmd/dist: apply timeout scale even if timeout isn't overridden

[gopherbot]

Change https://go.dev/cl/511976 mentions this issue: [release-branch.go1.21] cmd/dist: apply timeout scale even if timeout isn't overridden

[gopherbot]

Closed by merging b36e555 to release-branch.go1.21.