Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cmd/go: go test -json splits log records #40024

Open
grasparv opened this issue Jul 3, 2020 · 2 comments
Open

cmd/go: go test -json splits log records #40024

grasparv opened this issue Jul 3, 2020 · 2 comments

Comments

@grasparv
Copy link

@grasparv grasparv commented Jul 3, 2020

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.

@cagedmantis cagedmantis changed the title bug: go test -json splits log records cmd/go: go test -json splits log records Jul 6, 2020
@dmitshur dmitshur added this to the Backlog milestone Jul 7, 2020
@dmitshur
Copy link
Member

@dmitshur dmitshur commented Jul 7, 2020

@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented Jul 7, 2020

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
3 participants
You can’t perform that action at this time.