In the event of a timeout, the generated test.xml contains no useful information

[rickystewart]

What version of rules_go are you using?

Latest (the problem seems to go back to 0.47; the behavior at 0.46 is not ideal but much better)

What version of gazelle are you using?

Latest

What version of Bazel are you using?

7.2.1

Does this issue reproduce with the latest releases of all the above?

Yes

What operating system and processor architecture are you using?

macOS/arm64

Any other potentially useful information about your toolchain?

No

What did you do?

Run a test that times out

What did you expect to see?

While the test did not complete successfully, the .xml should show as much information as possible. Ideally, it should contain a passing testcase for every test that succeeded, and a failing or errored testcase for every test that was still running at the time the test timed out.

What did you see instead?

At the latest version of rules_go, the generated test.xml contains almost no information:

<testsuites>
	<testsuite errors="0" failures="0" skipped="0" tests="0" time="" name="repro_test"></testsuite>
</testsuites>

Note that this doesn't list any tests at all and shows 0 errors/failures/etc.

This behavior goes back to version 0.47 of rules_go. In version 0.46, the test.xml is not completely empty; it is better, shows there was an error, and contains some log output.

<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
  <testsuite name="repro_test_/repro_test" tests="1" failures="0" errors="1">
    <testcase name="repro_test_/repro_test" status="run" duration="20" time="20"><error message="exited with error code 142"></error></testcase>
      <system-out>
Generated test.log (if the file is not UTF-8, then this may be unreadable):
<![CDATA[exec ${PAGER:-/usr/bin/less} "$0" || exit 1
...

This is not perfect and could contain more useful information (for example, it could contain a testcase with the name of the timed-out test), but it is decidedly better than the state as of version 0.47.

This seems to have been regressed in #3920.

A minimal reproduction can be found in this repo on the branch timeout-behavior (bazel test :repro_test --test_timeout=5)

(This may be considered a follow-up from #3875, which originated the regressing commit in #3920)

[fmeum]

@linzhp

[yushan26]

You should be able to see the error logs on the test case level running bazel test :repro_test --test_timeout=5 --test_args=-test.v. This will provide the status/error logs of every test result on the test case level.

[rickystewart]

Even if you are doing that (or equivalently, setting GO_TEST_WRAP_TESTV=1), the behavior described above manifests. I reported this as we’re routinely encountering this issue in CI for CockroachDB where we always have that setting applied.

[yushan26]

I ran bazel test :repro_test --test_timeout=5 --test_env=GO_TEST_WRAP_TESTV=1 and I can see the test.xml output

<testsuites>
	<testsuite errors="1" failures="0" skipped="0" tests="1" time="" name="repro_test">
		<testcase classname="repro_test" name="TestRepro" time="">
			<error message="No pass/skip/fail event found for test" type="">=== RUN   TestRepro&#xA;panic: test timed out after 5s&#xA;running tests:&#xA;&#x9;TestRepro (5s)&#xA;&#xA;goroutine 19 [running]:&#xA;testing.(*M).startAlarm.func1()&#xA;&#x9;GOROOT/src/testing/testing.go:2366 +0x30c&#xA;created by time.goFunc&#xA;&#x9;GOROOT/src/time/sleep.go:177 +0x38&#xA;&#xA;goroutine 1 [chan receive]:&#xA;testing.(*T).Run(0x14000184000, {0x10437ccbf?, 0x140000efa48?}, 0x1043fc1a0)&#xA;&#x9;GOROOT/src/testing/testing.go:1750 +0x32c&#xA;testing.runTests.func1(0x14000184000)&#xA;&#x9;GOROOT/src/testing/testing.go:2161 +0x40&#xA;testing.tRunner(0x14000184000, 0x140000efb68)&#xA;&#x9;GOROOT/src/testing/testing.go:1689 +0xec&#xA;testing.runTests(0x1400000c018, {0x1044e4ab0, 0x1, 0x1}, {0x140000efc08?, 0x104245f5c?, 0x1044eea00?})&#xA;&#x9;GOROOT/src/testing/testing.go:2159 +0x3b0&#xA;testing.(*M).Run(0x1400009c1e0)&#xA;&#x9;GOROOT/src/testing/testing.go:2027 +0x5a4&#xA;main.main()&#xA;&#x9;bazel-out/darwin_arm64-fastbuild/bin/repro_test_/testmain.go:127 +0x3a8&#xA;&#xA;goroutine 5 [syscall]:&#xA;os/signal.signal_recv()&#xA;&#x9;GOROOT/src/runtime/sigqueue.go:149 +0x2c&#xA;os/signal.loop()&#xA;&#x9;GOROOT/src/os/signal/signal_unix.go:23 +0x1c&#xA;created by os/signal.Notify.func1.1 in goroutine 1&#xA;&#x9;GOROOT/src/os/signal/signal.go:151 +0x28&#xA;&#xA;goroutine 6 [sleep]:&#xA;time.Sleep(0xe8d4a51000)&#xA;&#x9;GOROOT/src/runtime/time.go:195 +0xfc&#xA;repro_test.TestRepro(0x140001841a0?)&#xA;&#x9;foo_test.go:9 +0x28&#xA;testing.tRunner(0x140001841a0, 0x1043fc1a0)&#xA;&#x9;GOROOT/src/testing/testing.go:1689 +0xec&#xA;created by testing.(*T).Run in goroutine 1&#xA;&#x9;GOROOT/src/testing/testing.go:1742 +0x318&#xA;</error>
		</testcase>
	</testsuite>
</testsuites>