testing: "=== PAUSE" lines do not change the test name for the next log line

[davidvanlaatum]

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

$ go version
go version go1.14.7 linux/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="/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-build248134951=/tmp/go-build -gno-record-gcc-switches"

What did you do?

when running tests with go1.14.6 and go1.14.7 still seeing log output of tests going to the wrong test #39308
tmp.zip
attached program runs a bunch of tests and checks for any output that went to the wrong test. It is a little random sometimes does work. Not positive but it seems to only ever be a TestABC1 & TestABC2 (or vice versa) yet to see one where it ends up on a different subtest for the some one

What did you expect to see?

no output

What did you see instead?

docker build -t gotestissue . && docker run --rm gotestissue
Sending build context to Docker daemon  13.82kB
Step 1/4 : FROM golang:latest
 ---> baaca3151cdb
Step 2/4 : RUN go version
 ---> Using cache
 ---> 01a9e374a96e
Step 3/4 : ADD . .
 ---> Using cache
 ---> af4f025e4da4
Step 4/4 : CMD ./run.sh
 ---> Using cache
 ---> e9586b093b23
Successfully built e9586b093b23
Successfully tagged gotestissue:latest
+ go version
go version go1.14.7 linux/amd64
+ go env
----------snip----------
+ go run ./bla.go
+ go test -test.count=1 -json ./...
TestABC1/#9599 TestABC2/#9750
{"Time":"2020-08-09T07:22:03.834305536Z","Action":"output","Package":"_/go/test","Test":"TestABC1/#9599","Output":"    bla_test.go:43: XYZ TestABC2/#9750\n"}
TestABC1/#9634 TestABC2/#9728
{"Time":"2020-08-09T07:22:03.836248518Z","Action":"output","Package":"_/go/test","Test":"TestABC1/#9634","Output":"    bla_test.go:43: XYZ TestABC2/#9728\n"}
TestABC1/#9635 TestABC2/#9723
{"Time":"2020-08-09T07:22:03.836452744Z","Action":"output","Package":"_/go/test","Test":"TestABC1/#9635","Output":"    bla_test.go:43: XYZ TestABC2/#9723\n"}
TestABC1/#9714 TestABC2/#9699
{"Time":"2020-08-09T07:22:03.840461239Z","Action":"output","Package":"_/go/test","Test":"TestABC1/#9714","Output":"    bla_test.go:43: XYZ TestABC2/#9699\n"}

[andybons]

@bcmills

[bcmills]

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

CC @ianlancetaylor @jadekler

[davidvanlaatum]

[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

[bcmills]

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.

[bcmills]

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"}

[gopherbot]

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

[bcmills]

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

[gopherbot]

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.

[gopherbot]

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

[gopherbot]

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