testing: duplicate "pass" action from TestFlag/-test.v=test2json when run with go test -json

[dmitshur]

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

$ go version
go version devel go1.21-ac881545ce Tue Mar 21 12:44:04 2023 -0400 darwin/arm64

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="arm64"
GOBIN=""
GOCACHE="/Users/dmitshur/Library/Caches/go-build"
GOENV="/Users/dmitshur/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/dmitshur/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/dmitshur/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/dmitshur/gotip"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/dmitshur/gotip/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="devel go1.21-ac881545ce Tue Mar 21 12:44:04 2023 -0400"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/dmitshur/gotip/src/go.mod"
GOWORK=""
CGO_CFLAGS="-O2 -g"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-O2 -g"
CGO_FFLAGS="-O2 -g"
CGO_LDFLAGS="-O2 -g"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/s_/5sjqzr0j6xggz_xtzmq_8r4m00jwcj/T/go-build2300515905=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

When testing the entire standard library with -json flag, one of the tests produces a "pass" action event twice rather than the usual one time maximum.

This can be reproduced with:

go test -json -run='TestFlag' testing | grep '"Action":"pass","Package":"testing","Test":"TestFlag"' | wc -l

It also seems to reproduce if invoking the test binary and test2json manually:

go test -c testing -o /tmp/testing.test && /tmp/testing.test -test.run='TestFlag' -test.v=test2json | go tool test2json | grep '"Action":"pass","Test":"TestFlag"' | wc -l

What did you expect to see?

1

What did you see instead?

2

---

I'm not definitively sure that it is a bug for a pass action to be emitted more than once for the same package/test, but it seems unexpected. This came up from #37486, and out of all the packages and tests in the standard library, it happens only with this one.

As a quick investigation note, the 'TestFlag/-test.v=test2json' test in testing package (i.e., go test -v -run='TestFlag/-test.v=test2json' testing) seems to emit 0x16 bytes, which test2json also uses, and that may contribute to its confusion.

It seems like a minor issue given I haven't yet encountered any tools that this causes a serious problem in, and in tools one has control over it's easy to work around by ignoring it, but reporting it anyway.

CC @bcmills, @matloob.

[gopherbot]

Change https://go.dev/cl/479035 mentions this issue: testing: quote -test.v=test2json output when logging it