Potential issue when running go test -json

[mfridman]

Hey Mat, long time. Ran into a curious issue worth filing.

Summary

Running go test -json ... and using this package reports incorrect test names in JSON events. This could very well be a bug in Go (test2json), but figured I'd start here because if I remove is and use regular std. lib primitives it reports the correct thing.

Reproducible example

I noticed this happening in https://github.com/pressly/goose and put together a PR to showcase the problem.

In this commit I purposefully changed a test to trigger a failure. Note the name of the test is TestNotAllowMissing.

pressly/goose@9b7c732#diff-080f0d7ba408eaf6181e1f61388995ebcd57fdd1468ffafffbf789176531418fR30

When I run go test -v -json -count=1 ./tests/e2e -dialect=postgres I happily get JSON output. But, the test name in the JSON event doesn't line up with the Output.

I was expecting Output that is prints to be associated with test named TestNotAllowMissing, but instead it was associated with another test named TestMigrateFull. (the name is non-deterministic, it changes between runs).

The raw output can be found here . But I've copied and trimmed the relevant bits:

{"Test":"TestMigrateFull","Output":"\t\u001b[90mallow_missing_test.go:30: \u001b[39m7 != 8\n"}
{"Test":"TestNotAllowMissing","Output":"--- FAIL: TestNotAllowMissing (3.73s)\n"}

The first JSON event refers to allow_missing_test.go:30, in the code base the call site on line 30 is located within the test named: TestNotAllowMissing, but the test name is TestMigrateFull.

The second JSON event correctly outputs the failure under the test named TestNotAllowMissing.

This could very well be a bug in how go test prints JSON events, but I suspect it may be something within this library. I say this because if I remove is from that specific test (TestNotAllowMissing) I see the expected output associated with the correct Test name:

Raw output can be found here

{"Test":"TestNotAllowMissing","Output":"    allow_missing_test.go:35: got 7: want: 8\n"}
{"Test":"TestNotAllowMissing","Output":"--- FAIL: TestNotAllowMissing (2.81s)\n"}

[flowchartsman]

This is a known issue with running tests with -json, since test2json parses the output of Go tests, and direct outputs to stdout and stderr can cause this to become jumbled. The well-behaved way to make this work correctly is to use t.Log[F]. I have tested a fix to this using terminal dectection with a fallback to t.Log, and the judicious use of t.Helper(), and it seems to work now.

I'll have to see how invasive the PR is to fix this, but hopefully it won't be too bad.

{"Time":"2023-03-13T22:42:07.551054-04:00","Action":"output","Package":"github.com/pressly/goose/v3/tests/e2e","Test":"TestNotAllowMissing","Output":"    allow_missing_test.go:30: \t\u001b[02mallow_missing_test.go:30: \u001b[00m7 != 8\n"}

[flowchartsman]

Tentatively, a fix for this would involve retrofitting is.I to ditch taking function references to t.Fail and t.FailNow in favor of calling them directly with the log message, and adding i.t.Helper() guards where appropriate to ensure that failures show the correct location. In theory, this would make detecting a terminal or falling back to t.Log() unnecessary, but messages would then be subject to the normal rules about printing failures, which might defer them until after test has failed, unless -v is used. To me, that would be an acceptable tradeoff, but I'm curious what @breml and @matryer think. I'm happy to start a PR.

[flowchartsman]

To avoid breaking pre-1.7 compatibility (if we really care about going that far back), it would probably also be a good idea to denormalize the pre-1.7 code into a single file and EOL it. I might even go so far as to print a warning, but that's just me ;)

[breml]

Tentatively, a fix for this would involve retrofitting is.I to ditch taking function references to t.Fail and t.FailNow in favor of calling them directly with the log message, and adding i.t.Helper() guards where appropriate to ensure that failures show the correct location. In theory, this would make detecting a terminal or falling back to t.Log() unnecessary, but messages would then be subject to the normal rules about printing failures, which might defer them until after test has failed, unless -v is used. To me, that would be an acceptable tradeoff, but I'm curious what @breml and @matryer think. I'm happy to start a PR.

Currently, I don't see, what the difference is between "... taking function references to ..." and "... calling them directly ...". But maybe this would become more clear from a concrete PR. In regards to calling i.t.Helper(), I am clearly in favor of this. I think we should avoid changing the T interface but instead perform a type assertion in New and NewRelaxed to figure out, if the t T we got, actually does implement Helper or not. If it does, it is used. If not, a dummy implementation (no-op) is used instead.

To avoid breaking pre-1.7 compatibility (if we really care about going that far back), it would probably also be a good idea to denormalize the pre-1.7 code into a single file and EOL it. I might even go so far as to print a warning, but that's just me ;)

I think, this call is on @matryer. For me personally, it would be ok to ditch Go 1.7 support.