cmd/go: go test -json splits log records

[grasparv]

I maintain a test runner tool (https://github.com/grasparv/testie).

Here is my problem:

$ go version
go version go1.14 linux/amd64
$ cat hello_test.go
package hello

import (
        "testing"
)

func TestSomething(t *testing.T) {
        t.Logf("first item\nsecond item")
        t.Logf("third item")
}
$ go test -v -json
{"Time":"2020-07-03T15:08:12.426294755+02:00","Action":"run","Package":"example","Test":"TestSomething"}
{"Time":"2020-07-03T15:08:12.426393632+02:00","Action":"output","Package":"example","Test":"TestSomething","Output":"=== RUN   TestSomething\n"}
{"Time":"2020-07-03T15:08:12.426403571+02:00","Action":"output","Package":"example","Test":"TestSomething","Output":"    TestSomething: hello_test.go:8: first item\n"}
{"Time":"2020-07-03T15:08:12.426407445+02:00","Action":"output","Package":"example","Test":"TestSomething","Output":"        second item\n"}
{"Time":"2020-07-03T15:08:12.426411074+02:00","Action":"output","Package":"example","Test":"TestSomething","Output":"    TestSomething: hello_test.go:9: third item\n"}
{"Time":"2020-07-03T15:08:12.426415993+02:00","Action":"output","Package":"example","Test":"TestSomething","Output":"--- PASS: TestSomething (0.00s)\n"}
{"Time":"2020-07-03T15:08:12.426419389+02:00","Action":"pass","Package":"example","Test":"TestSomething","Elapsed":0}
{"Time":"2020-07-03T15:08:12.426423735+02:00","Action":"output","Package":"example","Output":"PASS\n"}
{"Time":"2020-07-03T15:08:12.4264854+02:00","Action":"output","Package":"example","Output":"ok  \texample\t0.001s\n"}
{"Time":"2020-07-03T15:08:12.42649666+02:00","Action":"pass","Package":"example","Elapsed":0.001}

I expected seeing first and second item reported as a single entry (instead second entry gets its own log event). The above is an issue since it destroys information by breaking lines. For instance, my test runner tool might want to change indentation on some messages, but here it is impossible to see which log lines that actually belong together.

[dmitshur]

/cc @matloob @bcmills @jayconrod

[jayconrod]

This is a consequence of the way go test collects output from test binaries. Test binaries print output and events on stdout in a line-based text format. Tests can write directly to stdout, and there's no escaping for significant whitespace, even with t.Log, so there's no way for go test to tell whether output containing newlines came from separate writes.

There are a number of issues related to go test -v and go test -json like this. To fix them, I think we should consider sending more structured output over some other channel, like a socket or pipe passed to the test process. Or maybe tests should write logs to a file, and go test should parse that. It will be tricky finding something portable to all platforms that doesn't interfere with existing tests though.