cmd/test2json: go test -bench -json -count output is inconsistent

[FiloSottile]

Go version

go version go1.22.2 darwin/arm64

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/filippo/Library/Caches/go-build'
GOENV='/Users/filippo/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/filippo/pkg/mod'
GONOPROXY='github.com/FiloSottile/*,filippo.io/*'
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/filippo'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org'
GOROOT='/Users/filippo/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.2.darwin-arm64'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/Users/filippo/pkg/mod/golang.org/toolchain@v0.0.1-go1.22.2.darwin-arm64/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.2'
GCCGO='gccgo'
AR='ar'
CC='clang'
CXX='clang++'
CGO_ENABLED='1'
GOMOD='/Users/filippo/src/filippo.io/mlkem768/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 -ffile-prefix-map=/var/folders/_j/hq4ytn1n4b94fhrpvvb9tktr0000gn/T/go-build3229174055=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

$ go test -run ^$ -bench BenchmarkKeyGen -count 2 -json

What did you see happen?

{"Time":"2024-04-14T18:19:51.384784+02:00","Action":"start","Package":"filippo.io/mlkem768"}
{"Time":"2024-04-14T18:19:51.637613+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"goos: darwin\n"}
{"Time":"2024-04-14T18:19:51.637714+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"goarch: arm64\n"}
{"Time":"2024-04-14T18:19:51.637721+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"pkg: filippo.io/mlkem768\n"}
{"Time":"2024-04-14T18:19:51.637745+02:00","Action":"run","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen"}
{"Time":"2024-04-14T18:19:51.63775+02:00","Action":"output","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen","Output":"=== RUN   BenchmarkKeyGen\n"}
{"Time":"2024-04-14T18:19:51.637758+02:00","Action":"output","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen","Output":"BenchmarkKeyGen\n"}
{"Time":"2024-04-14T18:19:53.222257+02:00","Action":"output","Package":"filippo.io/mlkem768","Test":"BenchmarkKeyGen","Output":"BenchmarkKeyGen-8   \t   28196\t     40652 ns/op\n"}
{"Time":"2024-04-14T18:19:54.824157+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"BenchmarkKeyGen-8   \t   28791\t     40964 ns/op\n"}
{"Time":"2024-04-14T18:19:54.824209+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"PASS\n"}
{"Time":"2024-04-14T18:19:54.824632+02:00","Action":"output","Package":"filippo.io/mlkem768","Output":"ok  \tfilippo.io/mlkem768\t3.440s\n"}
{"Time":"2024-04-14T18:19:54.824673+02:00","Action":"pass","Package":"filippo.io/mlkem768","Elapsed":3.44}

Note how the first timing output line has the Test field, and the second one doesn't.

What did you expect to see?

Either both output events having the Test field set (which is what makes more sense to me and would make it easier to extract the data I am looking for, since without Test field I have to manually filter out metadata and result option lines), or neither (which curiously is what go doc test2json claims).

When a benchmark runs, it typically produces a single line of output giving timing results. That line is reported in an event with Action == "output" and no Test field.

[cherrymui]

cc @aclements

[pohly]

Let me piggy-back on this issue as it nicely shows another problem. I can also create a separate one, if that's preferred.

The problem is that there is a run line for BenchmarkKeyGen, but no corresponding pass. For unit tests, each run is matched by one pass or failed. The missing pass causes gotestsum to treat the benchmark as failed.

This run for benchmarks was added in Go 1.20.