Panic stack trace from go test -timeout=X is ignored when timeout happens right after a test passes

[mafredri]

This seems like a bug in go test -json, so I've opened the following issue over there: golang/go#57305

However, this is still relevant for gotestsum since previous Go versions are affected.

The following visual should give an idea of what's wrong:

❯ gotestsum --jsonfile=trace-missing.json -- . -timeout=1s
✖  test (1.012s)

=== Failed
=== FAIL: test  (0.00s)
FAIL	github.com/mafredri/test	1.012s

DONE 1 tests, 1 failure in 1.323s

Something went wrong, but we simply don't know what. With parallel tests this is even more confusing:

❯ gotestsum --jsonfile=parallel-trace-missing.json -- . -timeout=1s
✖  test (1.008s)

=== Failed
=== FAIL: test TestWorld (unknown)

DONE 2 tests, 1 failure in 1.326s

The test fails with (unknown), but no explanation.

When this edge case isn't hit we see the proper output:

❯ gotestsum --jsonfile=trace-valid.json -- . -timeout=1s
✖  test (1.01s)

=== Failed
=== FAIL: test TestWorld (unknown)
panic: test timed out after 1s
running tests:
	TestWorld (0s)

goroutine 5 [running]:
[...]

DONE 2 tests, 1 failure in 1.317s

The json payloads are available at golang/go#57305, but for context, this is the significant portion:

{"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"}

What's going on here is that the test outputs PASS, relied on by gotestsum to ignore future output from that test. However, go test considers that test to be running still for a brief moment and attributes the panic stack trace to it.

[dnephin]

Thanks for the bug report! It seems like the Go team has confirmed this is a bug in go test, but I can see that gotestsum makes it worse by hiding the output. I'd like to fix the gotestsum output.

I guess we can detect this in gotestsum by checking if the TestEvent is for a test in Package.running. If we get output for a test that isn't running then maybe we send that output to Package.Output[""] (where package-level output is stored) instead of a storing it as output for a specific test. I'm hoping that will be enough to fix the issue. We can use the json payloads in a test case to confirm the fix.

[mafredri]

@dnephin I think that would work out great 👍🏻. It would catch the behavior as I've observed it.

I've implemented the following check in CI:

for testWithStack in $(grep 'panic: test timed out' gotestsum.json | grep -E -o '("Test":[^,}]*)'); do
  if [ -n "$testWithStack" ] && grep -q "${testWithStack}.*PASS" gotestsum.json; then
    echo "Conditions met for gotestsum stack trace missing bug, outputting panic trace:"
    grep -A 999999 "${testWithStack}.*panic: test timed out" gotestsum.json
  fi
done

And have yet to observe any exceptions to the rule.

[dnephin]

The test2json output was not exactly what I was expecting, but I think I found a way to work around the problem anyway.

Could you try the changes in #298 to see if that works for you?