@bcmills

@davidvanlaatum, could you provide the corresponding snippet of the JSON output?

CC @ianlancetaylor @jadekler

[11:29:34 david@MacBook-Pro tmp]# docker build -t gotestissue . && while docker run -v $(pwd):/out --rm gotestissue;do true;done
Sending build context to Docker daemon  14.85kB
Step 1/4 : FROM golang:latest
 ---> baaca3151cdb
Step 2/4 : RUN go version
 ---> Using cache
 ---> 01a9e374a96e
Step 3/4 : ADD . .
 ---> d57c5aab134c
Step 4/4 : CMD ./run.sh
 ---> Running in bdc51bfce7b0
Removing intermediate container bdc51bfce7b0
 ---> dda9fe26e1ea
Successfully built dda9fe26e1ea
Successfully tagged gotestissue:latest
+ go version
go version go1.14.7 linux/amd64
+ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/root/.cache/go-build"
GOENV="/root/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD=""
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build412486303=/tmp/go-build -gno-record-gcc-switches"
+ go test -test.count=1 -json ./...
+ tee /out/output.json
+ go run ./bla.go
TestABC2/#8937 TestABC1/#9993
{"Time":"2020-08-16T01:59:48.796983636Z","Action":"output","Package":"_/go/test","Test":"TestABC2/#8937","Output":"    bla_test.go:23: XYZ TestABC1/#9993\n"}
exit status 1

on a new macbook so can't get as many failures as before but on multiple runs with a single failure like above I see similar to

{"Time":"2020-08-16T01:59:48.796929968Z","Action":"run","Package":"_/go/test","Test":"TestABC2/#8937"}
{"Time":"2020-08-16T01:59:48.796932057Z","Action":"output","Package":"_/go/test","Test":"TestABC2/#8937","Output":"=== RUN   TestABC2/#8937\n"}
{"Time":"2020-08-16T01:59:48.796934445Z","Action":"cont","Package":"_/go/test","Test":"TestABC1/#9993"}
{"Time":"2020-08-16T01:59:48.796936531Z","Action":"output","Package":"_/go/test","Test":"TestABC1/#9993","Output":"=== CONT  TestABC1/#9993\n"}
{"Time":"2020-08-16T01:59:48.79693893Z","Action":"output","Package":"_/go/test","Test":"TestABC2/#8937","Output":"=== PAUSE TestABC2/#8937\n"}
{"Time":"2020-08-16T01:59:48.796979675Z","Action":"pause","Package":"_/go/test","Test":"TestABC2/#8937"}
{"Time":"2020-08-16T01:59:48.796983636Z","Action":"output","Package":"_/go/test","Test":"TestABC2/#8937","Output":"    bla_test.go:23: XYZ TestABC1/#9993\n"}

ie TestABC1/#9993 outputs === CONT TestABC1/#9993
TestABC2/#8937 outputs === PAUSE TestABC2/#8937
TestABC1/#9993 outputs bla_test.go:23: XYZ TestABC1/#9993

so looks like TestABC2/#8937 manages to send the pause message in between TestABC1/#9993 CONT and output and thus screws up the tracking of the current test

output.json.zip

Thanks, that's helpful. This looks like a mismatch between the assumptions of the testing package and cmd/test2json: the testing package assumes that === PAUSE lines do not indicate the currently-running test (since they indicate that the named test is not actively running), whereas cmd/test2json assumes that they do indicate the currently-running test.

We could fix this by making the testing package log redundant === CONT lines, or by making cmd/test2json no longer assume that == PAUSE indicates that the output that follows is from the now-paused test, or perhaps both.

Here is a reduced test case that demonstrates the unusual === PAUSE / output sequencing, and reproduces the test2json issue:

example.com$ go test -json | grep 'outer again'
{"Time":"2020-08-17T17:21:22.050534953-04:00","Action":"output","Package":"example.com","Test":"TestWeirdTiming/pauser","Output":"    example_test.go:13: logging to outer again\n"}

Change https://golang.org/cl/248727 mentions this issue: testing: treat PAUSE lines as changing the active test name

@gopherbot, please backport to 1.14 and 1.15: this is likely a regression from the original 1.14 release.

Backport issue(s) opened: #40848 (for 1.14), #40849 (for 1.15).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

Change https://golang.org/cl/249097 mentions this issue: [release-branch.go1.15] testing: treat PAUSE lines as changing the active test name

Change https://golang.org/cl/249098 mentions this issue: [release-branch.go1.14] testing: treat PAUSE lines as changing the active test name