cmd/go: go test -json outputs too verbose

[hyangah]

Without -json

golang.org/x/sync$ go test ./...
ok      golang.org/x/sync/errgroup      (cached)
ok      golang.org/x/sync/semaphore     (cached)
ok      golang.org/x/sync/singleflight  (cached)
ok      golang.org/x/sync/syncmap       (cached)

With -json

golang.org/x/sync$ go test -json ./...
{"Time":"2020-08-05T10:45:49.695703-04:00","Action":"run","Package":"golang.org/x/sync/semaphore","Test":"TestWeighted"}
{"Time":"2020-08-05T10:45:49.698457-04:00","Action":"output","Package":"golang.org/x/sync/semaphore","Test":"TestWeighted","Output":"=== RUN   TestWeighted\n"}
{"Time":"2020-08-05T10:45:49.69849-04:00","Action":"output","Package":"golang.org/x/sync/semaphore","Test":"TestWeighted","Output":"=== PAUSE TestWeighted\n"}
...
{"Time":"2020-08-05T10:57:34.15016-04:00","Action":"output","Package":"golang.org/x/sync/syncmap","Test":"TestConcurrentRange","Output":"--- PASS: TestConcurrentRange (0.34s)\n"}
{"Time":"2020-08-05T10:57:34.150165-04:00","Action":"pass","Package":"golang.org/x/sync/syncmap","Test":"TestConcurrentRange","Elapsed":0.34}
{"Time":"2020-08-05T10:57:34.150172-04:00","Action":"output","Package":"golang.org/x/sync/syncmap","Output":"PASS\n"}
{"Time":"2020-08-05T10:57:34.150176-04:00","Action":"output","Package":"golang.org/x/sync/syncmap","Output":"ok  \tgolang.org/x/sync/syncmap\t(cached)\n"}
{"Time":"2020-08-05T10:57:34.150855-04:00","Action":"pass","Package":"golang.org/x/sync/syncmap","Elapsed":0.006}

Recently vscode-go switched to use go test -json and outputs Output field, but found this is too verbose (more like -v mode).

[gopherbot]

Change https://golang.org/cl/246918 mentions this issue: src/testUtil.ts: switch to -json mode only if -v is set

[jayconrod]

Could you be more specific about what should and should not be printed? Why did vscode-go switch to -json? Can it filter the output on its own instead?

When the -json flag is passed to go test, it passes -test.v to test processes, so they generate verbose output, and testing.Verbose() returns true, which may affect test behavior. -json causes go test to reformat that output as JSON (using code based on cmd/test2json). The content is generally the same though.

Changing -json output tends to be a very delicate operation. Code that depends on it tends to be very tightly coupled, so almost any change is a breaking change.

[hyangah]

For example, the followings are 'output' type Action but these lines wouldn't appear in the non-verbose mode output.
Non-verbose mode outputs include only a single line result per package if tests are successful,
and the details will be printed only for failed tests.

{"Time":"2020-08-05T10:57:34.15016-04:00","Action":"output","Package":"golang.org/x/sync/syncmap","Test":"TestConcurrentRange","Output":"--- PASS: TestConcurrentRange (0.34s)\n"}
{"Time":"2020-08-05T10:57:34.150165-04:00","Action":"pass","Package":"golang.org/x/sync/syncmap","Test":"TestConcurrentRange","Elapsed":0.34}

vscode-go has to rewrite the the file names printed in the log messages to the absolute paths. Without knowing the package path of the test, we can't do this rewrite. Unfortunately, in the normal test output, the package path is printed at the end. For example,

$ go test ./... -v
=== RUN   TestParseLine
--- PASS: TestParseLine (0.00s)
=== RUN   TestParseSet
--- PASS: TestParseSet (0.00s)
=== RUN   TestString
=== RUN   TestString/nsTest
    TestString/nsTest: parse_test.go:206: assume it's failed: nsTest
=== RUN   TestString/mbTest
    TestString/mbTest: parse_test.go:206: assume it's failed: mbTest
=== RUN   TestString/allocatedBytesTest
    TestString/allocatedBytesTest: parse_test.go:206: assume it's failed: allocatedBytesTest
=== RUN   TestString/allocsTest
    TestString/allocsTest: parse_test.go:206: assume it's failed: allocsTest
--- FAIL: TestString (0.00s)
    --- FAIL: TestString/nsTest (0.00s)
    --- FAIL: TestString/mbTest (0.00s)
    --- FAIL: TestString/allocatedBytesTest (0.00s)
    --- FAIL: TestString/allocsTest (0.00s)
FAIL
FAIL    golang.org/x/tools/benchmark/parse      0.022s

We can't rewirte parse_test.go to its full path until we see the last line FAIL golang.org/x/tools/benchmark/parse ....
Previously, we were buffering the test output until we get the last line in addition to various hacks to parse this unstructured test output. But that made the recent test output streaming feature (available go1.14?) not very useful.

[jayconrod]

cc @bcmills @matloob

I don't think we can drop those lines though. It may break other tools that depend on them to reconstruct the complete output of the test. Can vscode-go filter them out?

[hyangah]

@jayconrod Filtering was what i initially attempted to do to fix our regression bug, and it's harder than I thought. Can it add an extra field or some sign whether the Output is for verbose or not?

Currently we switched back not to use -json if users didn't set -v. It's sad that we can't utilize it even though this -json output was introduced to ease integration with other tools including IDEs.

[jayconrod]

Can it add an extra field or some sign whether the Output is for verbose or not?

Maybe... I think all the messages from the test process to go test start with something like ^\s*(---|===) , plus the lines that start with PASS or FAIL at the end. go test reads those, but the output is mixed together with the test's own output, so doing anything with it is pretty error-prone.

We have a lot of open issues related to this actually, and I wonder if we need a more complete redesign for this mechanism.

[gopherbot]

Change https://golang.org/cl/247017 mentions this issue: [release] src/testUtil.ts: switch to -json mode only if -v is set

[dnephin]

If you are looking to emulate the non-verbose (I call it quiet) go test output from the json output, I have done that here: https://github.com/gotestyourself/gotestsum/blob/83c209d7c72e6c0889f40e965d71647fd6ea6600/testjson/format.go#L29-L38. You may be able to do the same.

Edit: (to respond to the below comment without creating too much noise on this thread)

There is preprocessing that happens in gotestsum, but none of it is required for this function (*Execution is not used). The linked function, plus the two small helpers it calls, are the only logic required to emulate the standard quiet format.

[hyangah]

Thanks @dnephin. I see the code and it assumes some preprocessing and filtering of the test events before the standard quiet formatter is applied. So, I assume majority of the heuristic is outside of the linked function.

Currently we are working around by simply not using -json if -v isn't set, which turned out to be noticeably faster in our specific case.

[rsc]

The design of -json fundamentally requires -v. Otherwise we can't associated prints on standard output to the running test. I don't believe there's anything we can change for this issue.

[bcmills]

In theory we could restructure go test -json so that the test binary itself emits the JSON output (perhaps to a pipe attached to an extra file descriptor, or perhaps to stdout with the os.Stdout variable redirected to an intra-process pipe).

That would be a fairly large project, but it doesn't seem implausible to me.