cmd/test2json: missing pass/fail action on individual benchmark

[hugelgupf]

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

$ go version
go1.22-20230729-RC00

What operating system and processor architecture are you using (go env)?

Not relevant - omitting

What did you do?

File foo_test.go:

package foo_x_test

import (
        "testing"
)

func TestFoo(t *testing.T) {
        t.Logf("hello")
}

func fib(n int) int {
        if n < 2 {
                return n
        }
        return fib(n-1) + fib(n-2)
}

func BenchmarkFib10(b *testing.B) {
        for n := 0; n < b.N; n++ {
                fib(10)
        }
}

Run go test -json -bench=. foo_test.go

Result:

{"Time":"2023-08-04T12:37:32.630848007-07:00","Action":"start","Package":"command-line-arguments"}
{"Time":"2023-08-04T12:37:32.674050117-07:00","Action":"run","Package":"command-line-arguments","Test":"TestFoo"}
{"Time":"2023-08-04T12:37:32.674089527-07:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"=== RUN   TestFoo\n"}
{"Time":"2023-08-04T12:37:32.674121806-07:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"    foo_test.go:8: hello\n"}
{"Time":"2023-08-04T12:37:32.674136934-07:00","Action":"output","Package":"command-line-arguments","Test":"TestFoo","Output":"--- PASS: TestFoo (0.00s)\n"}
{"Time":"2023-08-04T12:37:32.674152436-07:00","Action":"pass","Package":"command-line-arguments","Test":"TestFoo","Elapsed":0}
{"Time":"2023-08-04T12:37:32.67656493-07:00","Action":"output","Package":"command-line-arguments","Output":"goos: linux\n"}
{"Time":"2023-08-04T12:37:32.676585644-07:00","Action":"output","Package":"command-line-arguments","Output":"goarch: amd64\n"}
{"Time":"2023-08-04T12:37:32.676599219-07:00","Action":"output","Package":"command-line-arguments","Output":"cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz\n"}
{"Time":"2023-08-04T12:37:32.676610204-07:00","Action":"run","Package":"command-line-arguments","Test":"BenchmarkFib10"}
{"Time":"2023-08-04T12:37:32.676619064-07:00","Action":"output","Package":"command-line-arguments","Test":"BenchmarkFib10","Output":"=== RUN   BenchmarkFib10\n"}
{"Time":"2023-08-04T12:37:32.676630118-07:00","Action":"output","Package":"command-line-arguments","Test":"BenchmarkFib10","Output":"BenchmarkFib10\n"}
{"Time":"2023-08-04T12:37:34.248814597-07:00","Action":"output","Package":"command-line-arguments","Test":"BenchmarkFib10","Output":"BenchmarkFib10-6   \t 1922632\t       602.9 ns/op\n"}
{"Time":"2023-08-04T12:37:34.248879794-07:00","Action":"output","Package":"command-line-arguments","Output":"PASS\n"}
{"Time":"2023-08-04T12:37:34.250175678-07:00","Action":"output","Package":"command-line-arguments","Output":"ok  \tcommand-line-arguments\t1.619s\n"}
{"Time":"2023-08-04T12:37:34.250212919-07:00","Action":"pass","Package":"command-line-arguments","Elapsed":1.619}

What did you expect to see?

Note that TestFoo gets a line with an individual test result --

{"Time":"2023-08-04T12:37:32.674152436-07:00","Action":"pass","Package":"command-line-arguments","Test":"TestFoo","Elapsed":0}

This is missing for BenchmarkFib10.

Expected to see:

{"Time":"<>","Action":"pass","Package":"command-line-arguments","Test":"BenchmarkFib10","Elapsed":0}

After Fib10 passes.

Really, this likely means that BenchmarkFib10 needs to be framed with a --- (PASS|SKIP|FAIL): BenchmarkFib10 (0.00s)\n at the end when -test.v=test2json is passed to the test binary as well.

(Previous work in this area fixed most of the test2json issues I've seen, cc @rsc -- https://go-review.googlesource.com/c/go/+/443596)

[dr2chase]

This might be working-as-intended. Consider the output of test -v when running a single test or a single benchmark:

go test -count=1 -v foo_test.go
=== RUN   TestFoo
    foo_test.go:8: hello
--- PASS: TestFoo (0.00s)
PASS
ok  	command-line-arguments	0.153s

and

go test -count=1 -bench=. -run=asdfasdf -v foo_test.go
goos: darwin
goarch: amd64
cpu: Intel(R) Core(TM) i5-1038NG7 CPU @ 2.00GHz
BenchmarkFib10
BenchmarkFib10-8   	 3682909	       323.3 ns/op
PASS
ok  	command-line-arguments	1.676s

Notice how there's no "PASS" printed for the benchmark itself, only the summary "PASS" at the end.

On the other hand, maybe that was a mistake, and it can be fixed in the json case.

cc @bcmills also.

[hugelgupf]

Hey David!

This is why I left the breadcrumb of https://go-review.googlesource.com/c/go/+/443596. That CL intentionally introduces the behavior that when -test.v=test2json is set, === RUN BenchmarkFib10 is emitted, but it failed to add the finishing PASS|FAIL|SKIP line for benchmarks. (I don't know what the status of fuzz tests is, I haven't tried, but they may suffer from the same?)

Try this:

$ go test -c -o foo_test foo_test.go

$ ./foo_test -test.v -test.bench=.
=== RUN   TestFoo
    foo_test.go:8: hello
--- PASS: TestFoo (0.00s)
goos: linux
goarch: amd64
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
BenchmarkFib10
BenchmarkFib10-6         1958179               601.7 ns/op
PASS

$ ./foo_test -test.v=test2json -test.bench=.
# OR evidently this works too:
$ go test -v=test2json -bench=. foo_test.go
=== RUN   TestFoo
    foo_test.go:8: hello
--- PASS: TestFoo (0.00s)
=== NAME  
goos: linux
goarch: amd64
cpu: Intel(R) Xeon(R) W-2135 CPU @ 3.70GHz
=== RUN   BenchmarkFib10
BenchmarkFib10
BenchmarkFib10-6         1920415               600.3 ns/op
=== NAME  
PASS