Panic when syntax error output comes after JSON output

[daenney]

We've adopted gotestfmt for Go repos in https://github.com/pion, but every now and then a test run fails with:

panic: unexpected output encountered: exit status 1 (Did you use -json on go test?)

goroutine 7 [running]:
github.com/haveyoudebuggedit/gotestfmt/v2/parser.parse(0xc000062480, 0xc0000624e0, 0xc000062540, 0xc0000625a0, 0xc000062600)
    /home/runner/go/pkg/mod/github.com/haveyoudebuggedit/gotestfmt/v2@v2.3.0/parser/parse.go:163 +0x1588
created by github.com/haveyoudebuggedit/gotestfmt/v2/parser.Parse
    /home/runner/go/pkg/mod/github.com/haveyoudebuggedit/gotestfmt/v2@v2.3.0/parser/parse.go:26 +0xf7
Error: Process completed with exit code 2.

For example:

• Failed: https://github.com/pion/dtls/runs/6061616437?check_suite_focus=true.
• Rerun: https://github.com/pion/dtls/runs/6061638237?check_suite_focus=true

The rerun is "rerun failed jobs" and then passes, no CI or code changes in between.

I suspect this is some weird interaction with go-acc but the fact that it seems to only happen about 10% of the time has me kinda stuck trying to figure this out. Any pointers or ideas would be greatly appreciated.

[ghost]

Hello @daenney thank you for this bug report. I am unable to access the artifacts generated in these runs since I'm not a member of this project. Could you please upload the JSON output of go test so I can write a test case for it?

[daenney]

It doesn't seem like I can get to the test log artifact of the failed run, seems only the one from the last attempt is kept. I'm guessing that one isn't all that useful to you, since it parsed successfully?

I'll see if I can get CI to break and grab the artifact then.

[daenney]

gotest.log

Caught one it seems: https://github.com/pion/dtls/runs/6063708502?check_suite_focus=true

panic: unexpected output encountered: # github.com/pion/dtls/v2/pkg/crypto/signaturehash [github.com/pion/dtls/v2/pkg/crypto/signaturehash.test] (Did you use -json on go test?)

goroutine 19 [running]:
github.com/haveyoudebuggedit/gotestfmt/v2/parser.parse(0xc000080480, 0xc0000804e0, 0xc000080540, 0xc0000805a0, 0xc000080600)
    /home/runner/go/pkg/mod/github.com/haveyoudebuggedit/gotestfmt/v2@v2.3.0/parser/parse.go:163 +0x1588
created by github.com/haveyoudebuggedit/gotestfmt/v2/parser.Parse
    /home/runner/go/pkg/mod/github.com/haveyoudebuggedit/gotestfmt/v2@v2.3.0/parser/parse.go:26 +0xf7
📦 github.com/pion/dtls/v2/e2e
coverage: 64.9% of statements in github.com/pion/dtls/v2, github.com/pion/dtls/v2/e2e, github.com/pion/dtls/v2/examples/dial/psk, github.com/pion/dtls/v2/examples/dial/selfsign, github.com/pion/dtls/v2/examples/dial/verify, github.com/pion/dtls/v2/examples/listen/psk, github.com/pion/dtls/v2/examples/listen/selfsign, github.com/pion/dtls/v2/examples/listen/verify, github.com/pion/dtls/v2/examples/util, github.com/pion/dtls/v2/internal/ciphersuite, github.com/pion/dtls/v2/internal/ciphersuite/types, github.com/pion/dtls/v2/internal/closer, github.com/pion/dtls/v2/internal/net/dpipe, github.com/pion/dtls/v2/internal/util, github.com/pion/dtls/v2/pkg/crypto/ccm, github.com/pion/dtls/v2/pkg/crypto/ciphersuite, github.com/pion/dtls/v2/pkg/crypto/clientcertificate, github.com/pion/dtls/v2/pkg/crypto/elliptic, github.com/pion/dtls/v2/pkg/crypto/fingerprint, github.com/pion/dtls/v2/pkg/crypto/hash, github.com/pion/dtls/v2/pkg/crypto/prf, github.com/pion/dtls/v2/pkg/crypto/selfsign, github.com/pion/dtls/v2/pkg/crypto/
signature, github.com/pion/dtls/v2/pkg/crypto/signaturehash, github.com/pion/dtls/v2/pkg/protocol, github.com/pion/dtls/v2/pkg/protocol/alert, github.com/pion/dtls/v2/pkg/protocol/extension, github.com/pion/dtls/v2/pkg/protocol/handshake, github.com/pion/dtls/v2/pkg/protocol/recordlayer
✅ TestPionE2ELossy (8.55s)

[daenney]

Piping that log through jq I actually get an error too: parse error: Invalid numeric literal at line 1527, column 2

{"Time":"2022-04-18T14:24:24.684335251Z","Action":"skip","Package":"github.com/pion/dtls/v2/pkg/crypto/signature","Elapsed":0}
# github.com/pion/dtls/v2/pkg/crypto/signaturehash [github.com/pion/dtls/v2/pkg/crypto/signaturehash.test]
pkg/crypto/signaturehash/signaturehash_go113_test.go:38:31: undefined: errors
pkg/crypto/signaturehash/signaturehash_test.go:93:31: undefined: errors
FAIL    github.com/pion/dtls/v2/pkg/crypto/signaturehash [build failed]

So I guess when a build fails, go test -json doesn't output only JSON?

[daenney]

This doesn't feel like the same thing as the first time I encountered it, since the original run I opened the ticket about didn't have a build failure.

[ghost]

Hey @daenney no worries, this seems to be a legitimate crash and it seems we are indeed not handling the case properly when there is extra non-JSON output due to syntax errors at the end. I'll take a look at it and issue a fix soon.

Is this issue blocking something right now, or are you able to work?

[ghost]

Note to self, simple example to reproduce the crash:

{"Time":"2021-11-27T10:23:01.309620888+01:00","Action":"run","Package":"github.com/haveyoudebuggedit/example/second","Test":"TestNothing"}
{"Time":"2021-11-27T10:23:01.309734731+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example/second","Test":"TestNothing","Output":"=== RUN   TestNothing\n"}
{"Time":"2021-11-27T10:23:01.3097659+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example/second","Test":"TestNothing","Output":"--- PASS: TestNothing (0.00s)\n"}
{"Time":"2021-11-27T10:23:01.309786588+01:00","Action":"pass","Package":"github.com/haveyoudebuggedit/example/second","Test":"TestNothing","Elapsed":0}
{"Time":"2021-11-27T10:23:01.309799132+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example/second","Output":"PASS\n"}
{"Time":"2021-11-27T10:23:01.309994377+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example/second","Output":"ok  \tgithub.com/haveyoudebuggedit/example/second\t0.002s\n"}
{"Time":"2021-11-27T10:23:01.310211915+01:00","Action":"pass","Package":"github.com/haveyoudebuggedit/example/second","Elapsed":0.002}
# github.com/haveyoudebuggedit/example
nothing_test.go:7:11: expected '(', found Nothing
FAIL    github.com/haveyoudebuggedit/example [setup failed]

[ghost]

Note to self: go-acc seems to output an extra line when the test fails:

exit status 2

Normal go test doesn't do that.

[ghost]

@daenney I've released the bugfix as v2.3.1. Please let me know if the error still happens.

[daenney]

Damn that was fast. Thanks so much! I'll keep an eye out on CI over the next couple of days.