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

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
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 (https://github.com/golang/go/issues/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.