testing: stdout output with no newline produces confusing/corrupt -v output

[neild]

package out_test

import (
	"fmt"
	"testing"
)

func TestOut(t *testing.T) { fmt.Print("TestOut") }

$ go test .
ok  	testout	0.016s
$ go test . -v
=== RUN   TestOut
Test--- PASS: TestOut (0.00s)
PASS
ok  	testout	0.017s

Output to stdout during tests is captured and printed along with t.Logf et al. output when -v is supplied. If the output doesn't end with a newline, the output is as above.

We have some tools that parse test output which get confused in this situation. It's easy enough to avoid (just print a newline in your test) but it would also be pretty trivial for the testing package could add a newline when one is missing.

[mvdan]

This does seem like something to fix, but note that you should be running go test -json to parse the test results.

[agnivade]

There are some tools like https://github.com/rakyll/gotest which parses command line go test output. This will break those I believe.

[mvdan]

The plaintext output has already been changed in the past, for example in 3a8b9cf. And now that there is go test -json, I'd imagine that it's less of a problem to make small changes to the plaintext output.

[neild]

I don't think we should change anything other than, possibly, adding a newline at the end of the test output when one isn't present. I'd be surprised if anything depends on the current behavior. e.g., https://github.com/rakyll/gotest will fail to parse test output that doesn't end in a newline.

I actually didn't know about go test -json! That's definitely a better approach for automated parsing. I lean towards saying we should add that missing newline in the text output anyway when needed; I can't imagine anyone actually wants to see the output in the example above.

[neild]

Heh. So it turns out go test -json works by parsing the normal text output...and it gets just as confused by this case.

{"Time":"2018-07-11T09:30:22.855058114-07:00","Action":"run","Package":"_/tmp/testout","Test":"TestOut"}
{"Time":"2018-07-11T09:30:22.855222613-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"=== RUN   TestOut\n"}
{"Time":"2018-07-11T09:30:22.855255176-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"Out--- PASS: TestOut (0.00s)\n"}
{"Time":"2018-07-11T09:30:22.855268402-07:00","Action":"output","Package":"_/tmp/testout","Output":"PASS\n"}
{"Time":"2018-07-11T09:30:22.855331884-07:00","Action":"output","Package":"_/tmp/testout","Output":"ok  \t_/tmp/testout\t0.011s\n"}
{"Time":"2018-07-11T09:30:22.856056764-07:00","Action":"pass","Package":"_/tmp/testout","Elapsed":0.012}

Contrast to the same test with a newline in the output, which correctly includes a "pass" action for the TestOut test:

{"Time":"2018-07-11T09:30:54.037472791-07:00","Action":"run","Package":"_/tmp/testout","Test":"TestOut"}
{"Time":"2018-07-11T09:30:54.037651722-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"=== RUN   TestOut\n"}
{"Time":"2018-07-11T09:30:54.037666684-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"Out\n"}
{"Time":"2018-07-11T09:30:54.037685506-07:00","Action":"output","Package":"_/tmp/testout","Test":"TestOut","Output":"--- PASS: TestOut (0.00s)\n"}
{"Time":"2018-07-11T09:30:54.037695155-07:00","Action":"pass","Package":"_/tmp/testout","Test":"TestOut","Elapsed":0}
{"Time":"2018-07-11T09:30:54.037708614-07:00","Action":"output","Package":"_/tmp/testout","Output":"PASS\n"}
{"Time":"2018-07-11T09:30:54.037761824-07:00","Action":"output","Package":"_/tmp/testout","Output":"ok  \t_/tmp/testout\t0.011s\n"}
{"Time":"2018-07-11T09:30:54.038279369-07:00","Action":"pass","Package":"_/tmp/testout","Elapsed":0.011}

[suzmue]

Could the start of the line requirement be removed when parsing the output?

This will introduce new false positives, but the current implementation is not protected from false positives if the program prints a matching string to os.Stdout.

The consumers of go test -json are likely tools, which could also be built to handle multiple "pass"/"fail"/"skip" events and update its status if it receives more than one (eg the last one is the result). Sending too few events prevents tools from recovering without having to parse every output themselves, which defeats the point of using go test -json.

This does not address the issues with interleaving output presented in other issues, but is an easy change that does not prevent fixing these other changes in the future.

[jayconrod]

+1 to @suzmue's suggestion, we should look at whether this is feasible.

We're always going to have false positives and negatives parsing test output, as long as test messages are sent on os.Stdout with arbitrary user data. If we drop the requirement for starting newlines, that seems like a better point on the tradeoff than when we are now though.

[junedev]

We at exercism.org (official GoBridge/GDN mentoring platform) are also affected by this bug. Students can solve Go exercises in a web editor and we run their solutions against a set of test cases on a server and present them the results. For debugging, they can add fmt.Print... statements. Currently, if they don't use Println and no trailing line break, they don't get any proper test results because the JSON we are trying to parse for that part of the code does not make sense anymore.

TLDR: +1 for @suzmue's suggestion

[MisterSquishy]

we should look at whether this is feasible.

@jayconrod is this being done? is there any way i can help move it forward? this issue is making it extremely difficult to understand test failures in one of my projects.

i threw together a POC; it may be oversimplified but it seems like it'd be fairly straightforward to implement this change, and it would benefit a lot of folks.

[suzmue]

No one is currently working on this, but I believe we would accept a CL for this fix.

cc @bcmills

[MisterSquishy]

👍 ill get my change polished up and submit a PR in the next couple of days

[gopherbot]

Change https://go.dev/cl/413616 mentions this issue: cmd/test2json: parse entire output lines for pass/fail/other update messages

[gopherbot]

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies