cmd/test2json: streamed log output not correctly associated with parallel tests

[mdwhatcott]

What version of Go are you using (go version)?

$ go version
go version go1.14.1 darwin/amd64

Does this issue reproduce with the latest release?

YES

What operating system and processor architecture are you using (go env)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/mike/Library/Caches/go-build"
GOENV="/Users/mike/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/mike"
GOPRIVATE=""
GOPROXY="direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/mike/src/github.com/mdwhatcott/parallel/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/mv/rt57xj7n1xl1wvqn5h0y2x4m0000gp/T/go-build151690166=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Working sample code: https://github.com/mdwhatcott/parallel

The sample code referenced above runs tests in parallel. I use parallel tests quite often to prove that test cases are isolated and that there are no unintended temporal couplings in the code. The purpose of this code is to illustrate a bug in the output of go test -json (as well as go tool test2json).

After upgrading to Go 1.14 I noticed that output associated with failing tests wasn't always correctly associated with the failing test. I suppose this is a consequence of the change to test output introduced in Go 1.14 which causes all output to be immediately streamed to the output rather than buffered for each test. (See the original issue (#24929) and the Go 1.14 release notes (https://golang.org/doc/go1.14#go-test).)

The repository referenced above (https://github.com/mdwhatcott/parallel) includes working tests and reference output for both Go 1.14.1 (problematic) and Go 1.13.1 (working fine).

What did you expect to see?

I expect that the output of go test -json correctly associate output of failing tests with the test that failed, not other tests (that might even have passed).

What did you see instead?

The problem is that output associated with failing tests is sometimes associated with passing tests, probably because it (the failure output) is emitted proximate to output for the passing test. This is very problematic for test runner tools found in many text editors and IDEs (issue on JetBrains GoLand issue tracker: https://youtrack.jetbrains.com/issue/GO-8985).

Here's what the errant lines look like from executing go test -json:

{"Time":"2020-03-24T12:13:53.358545-06:00","Action":"output","Package":"parallel","Test":"Test1/this_passes","Output":"        got:  [THIS WILL FAIL]\n"}
{"Time":"2020-03-24T12:13:53.358549-06:00","Action":"output","Package":"parallel","Test":"Test1/this_passes","Output":"        want: [because this is wrong]\n"}

Notice that the failure output is associated with "Test1/this_passes", which was a passing test with no output.

[andybons]

@rsc @mpvl

[vvakame]

sorry for my unclear information.
We have a similar like problems on Circle CI.
We are using t.Parallel. When test was failed, We can't see --- FAIL (and --- PASS) log about specific test case. Its vanished.
We got only FAIL log at last.
We are using golang:1.14-buster docker image on CI.
and, We can't reproduce with small sample code...

[mdwhatcott]

I have a fix almost ready to submit as a PR. The gist of the change is that the test2json converter needs to keep track of all test names in a map[string]struct{} so that when decorated test log output is emitted (at any point, thanks to #24929) it can be associated back to the originating test. Here's how I'm planning to implement the logic that is needed (at line 214):

if !ok {
    // Not a special test output line, but it may be the beginning
    // of decorated test log output and should be associated with its originating test.
    line := string(origLine)
    dedent := strings.TrimLeftFunc(line, unicode.IsSpace)
    end := strings.Index(dedent, ":")
    if end >= len("Test") {
        name := dedent[:end]
        _, found := c.testNames[name]
        if found {
            c.testName = name
        }
    }
    c.output.write(origLine)
    return
}

Here's the test case I plan on adding (straight from the sample code referenced in the description of this issue):

=== RUN   Test1
=== PAUSE Test1
=== RUN   Test2
=== PAUSE Test2
=== CONT  Test1
=== CONT  Test2
=== RUN   Test1/this_passes
=== PAUSE Test1/this_passes
=== RUN   Test1/this_will_fail
=== RUN   Test2/this_passes
=== PAUSE Test1/this_will_fail
=== CONT  Test1/this_passes
=== PAUSE Test2/this_passes
=== CONT  Test1/this_will_fail
=== RUN   Test2/this_will_fail
=== PAUSE Test2/this_will_fail
=== CONT  Test2/this_passes
    Test1/this_will_fail: parallel_test.go:40:
        got:  [THIS WILL FAIL]
        want: [because this is wrong]
=== CONT  Test2/this_will_fail
--- FAIL: Test1 (0.00s)
    --- PASS: Test1/this_passes (0.00s)
    --- FAIL: Test1/this_will_fail (0.00s)
    Test2/this_will_fail: parallel_test.go:40:
        got:  [THIS WILL FAIL]
        want: [because this is wrong]
--- FAIL: Test2 (0.00s)
    --- PASS: Test2/this_passes (0.00s)
    --- FAIL: Test2/this_will_fail (0.00s)
FAIL

And here's the expected output (made possible by the code above):

{"Action":"run","Test":"Test1"}
{"Action":"output","Test":"Test1","Output":"=== RUN   Test1\n"}
{"Action":"output","Test":"Test1","Output":"=== PAUSE Test1\n"}
{"Action":"pause","Test":"Test1"}
{"Action":"run","Test":"Test2"}
{"Action":"output","Test":"Test2","Output":"=== RUN   Test2\n"}
{"Action":"output","Test":"Test2","Output":"=== PAUSE Test2\n"}
{"Action":"pause","Test":"Test2"}
{"Action":"cont","Test":"Test1"}
{"Action":"output","Test":"Test1","Output":"=== CONT  Test1\n"}
{"Action":"cont","Test":"Test2"}
{"Action":"output","Test":"Test2","Output":"=== CONT  Test2\n"}
{"Action":"run","Test":"Test1/this_passes"}
{"Action":"output","Test":"Test1/this_passes","Output":"=== RUN   Test1/this_passes\n"}
{"Action":"output","Test":"Test1/this_passes","Output":"=== PAUSE Test1/this_passes\n"}
{"Action":"pause","Test":"Test1/this_passes"}
{"Action":"run","Test":"Test1/this_will_fail"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== RUN   Test1/this_will_fail\n"}
{"Action":"run","Test":"Test2/this_passes"}
{"Action":"output","Test":"Test2/this_passes","Output":"=== RUN   Test2/this_passes\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== PAUSE Test1/this_will_fail\n"}
{"Action":"pause","Test":"Test1/this_will_fail"}
{"Action":"cont","Test":"Test1/this_passes"}
{"Action":"output","Test":"Test1/this_passes","Output":"=== CONT  Test1/this_passes\n"}
{"Action":"output","Test":"Test2/this_passes","Output":"=== PAUSE Test2/this_passes\n"}
{"Action":"pause","Test":"Test2/this_passes"}
{"Action":"cont","Test":"Test1/this_will_fail"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"=== CONT  Test1/this_will_fail\n"}
{"Action":"run","Test":"Test2/this_will_fail"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== RUN   Test2/this_will_fail\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== PAUSE Test2/this_will_fail\n"}
{"Action":"pause","Test":"Test2/this_will_fail"}
{"Action":"cont","Test":"Test2/this_passes"}
{"Action":"output","Test":"Test2/this_passes","Output":"=== CONT  Test2/this_passes\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"    Test1/this_will_fail: parallel_test.go:40:\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"        got:  [THIS WILL FAIL]\n"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"        want: [because this is wrong]\n"}
{"Action":"cont","Test":"Test2/this_will_fail"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"=== CONT  Test2/this_will_fail\n"}
{"Action":"output","Test":"Test1","Output":"--- FAIL: Test1 (0.00s)\n"}
{"Action":"output","Test":"Test1/this_passes","Output":"    --- PASS: Test1/this_passes (0.00s)\n"}
{"Action":"pass","Test":"Test1/this_passes"}
{"Action":"output","Test":"Test1/this_will_fail","Output":"    --- FAIL: Test1/this_will_fail (0.00s)\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"    Test2/this_will_fail: parallel_test.go:40:\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"        got:  [THIS WILL FAIL]\n"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"        want: [because this is wrong]\n"}
{"Action":"fail","Test":"Test1/this_will_fail"}
{"Action":"fail","Test":"Test1"}
{"Action":"output","Test":"Test2","Output":"--- FAIL: Test2 (0.00s)\n"}
{"Action":"output","Test":"Test2/this_passes","Output":"    --- PASS: Test2/this_passes (0.00s)\n"}
{"Action":"pass","Test":"Test2/this_passes"}
{"Action":"output","Test":"Test2/this_will_fail","Output":"    --- FAIL: Test2/this_will_fail (0.00s)\n"}
{"Action":"fail","Test":"Test2/this_will_fail"}
{"Action":"fail","Test":"Test2"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"fail"}

[gopherbot]

Change https://golang.org/cl/226757 mentions this issue: test2json: associate streaming log output with the originating test

[mdwhatcott]

@andybons - Just curious, how shall I know when/whether the associated PR has been seen or reviewed, or what the next step is?

#38189

[andybons]

@bcmills mind taking a look?

[mdwhatcott]

@andybons @bcmills - Had a chance to look over the PR? #38189

[mdwhatcott]

@bcmills - Thanks for the review. Stay tuned for additional commits.

[mdwhatcott]

@bcmills - Ok, I've incorporated your suggestions, including the addition of an integration test/script.

[andybons]

@mdwhatcott please use the Gerrit UI — https://go-review.googlesource.com/c/go/+/226757 and mark comments you’ve addressed as “resolved” rather than commenting here. Thanks.

[mdwhatcott]

@andybons - Well, I definitely am new here ;)

Thanks

[mdwhatcott]

@andybons @bcmills - ok, I think I've marked all comments as resolved, so it's back in your court now.

[bcmills]

Thanks. There is some discussion of rolling back the output-format change (#38458), so this may only need to happen on the 1.14 branch.

[mdwhatcott]

@bcmills @andybons - any chance of movement on this?

[dlsniper]

I'm going to ping this one as well :)

[bcmills]

I believe that #39308 will be the fix for this in 1.14. (We'll fix the output format rather than the test2json tool.)

[mdwhatcott]

Resolved in Go1.14.6. Thanks everyone!