cmd/test2json: benchmark output lines are attributed to the preceding test #49505

wkaluza · 2021-11-10T17:38:36Z

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

$ go version
go version go1.17.2 linux/amd64

Does this issue reproduce with the latest release?

Yes. (v1.17.3)

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

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/home/wkaluza/.cache/go-build"
GOENV="/home/wkaluza/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/home/wkaluza/go/pkg/mod"
GONOPROXY="github.com/wkaluza/*"
GONOSUMDB="github.com/wkaluza/*"
GOOS="linux"
GOPATH="/home/wkaluza/go"
GOPRIVATE="github.com/wkaluza/*"
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17.2"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/home/wkaluza/luks/pcspec_sda_luks/wk/dev/aaa/go.mod"
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-build2880021727=/tmp/go-build -gno-record-gcc-switches"
GOROOT/bin/go version: go version go1.17.2 linux/amd64
GOROOT/bin/go tool compile -V: compile version go1.17.2
uname -sr: Linux 5.11.0-40-generic
Distributor ID:	Ubuntu
Description:	Ubuntu 20.04.3 LTS
Release:	20.04
Codename:	focal
/lib/x86_64-linux-gnu/libc.so.6: GNU C Library (Ubuntu GLIBC 2.31-0ubuntu9.2) stable release version 2.31.
lldb --version: lldb version 10.0.0
gdb --version: GNU gdb (Ubuntu 9.2-0ubuntu1~20.04) 9.2

What did you do?

We have three files:

// go.mod
module gotest_problem

go 1.17

// pkg/example/x.go
package example

func CountToN(N int) int {
	i := 0
	for i < N {
		i++
	}

	return i
}

// pkg/example/x_test.go
package example_test

import (
	// "fmt"
	"testing"

	x "gotest_problem/pkg/example"
)

func TestCountToN(t *testing.T) {
	want := 1234
	if got := x.CountToN(want); got != want {
		t.Errorf("Expected %d, got %d instead", want, got)
	}
}

// func ExampleCountToN() {
//	r := x.CountToN(1234)
//
//	fmt.Println(r)
//	// Output: 1234
// }

func BenchmarkCountToN(b *testing.B) {
	x.CountToN(1234)
}

I executed the following: go test -json -shuffle off -bench '.+' -count 1 ./pkg/example

What did you expect to see?

A series of events in JSON format whose Test property shows the name of the test/benchmark/example being executed. The benchmark should emit events bearing the field "Test": "BenchmarkCountToN".

What did you see instead?

The events corresponding to the benchmark are marked with the name of the preceding test (here: "Test": "TestCountToN").

$ go test -json -shuffle off -bench '.+' -count 1 ./pkg/example

{"Time":"2021-11-10T18:16:08.005808909+01:00","Action":"run","Package":"gotest_problem/pkg/example","Test":"TestCountToN"}
{"Time":"2021-11-10T18:16:08.005885444+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"=== RUN   TestCountToN\n"}
{"Time":"2021-11-10T18:16:08.005892398+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"--- PASS: TestCountToN (0.00s)\n"}
{"Time":"2021-11-10T18:16:08.006501248+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"goos: linux\n"}
{"Time":"2021-11-10T18:16:08.006515338+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"goarch: amd64\n"}
{"Time":"2021-11-10T18:16:08.006519266+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"pkg: gotest_problem/pkg/example\n"}
{"Time":"2021-11-10T18:16:08.006524007+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"cpu: Intel(R) Core(TM) i9-9900K CPU @ 3.60GHz\n"}
{"Time":"2021-11-10T18:16:08.006527421+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"BenchmarkCountToN\n"}
{"Time":"2021-11-10T18:16:08.00771734+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"BenchmarkCountToN-16    \t1000000000\t         0.0000005 ns/op\n"}
{"Time":"2021-11-10T18:16:08.007735128+01:00","Action":"pass","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Elapsed":0}
{"Time":"2021-11-10T18:16:08.007741942+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"PASS\n"}
{"Time":"2021-11-10T18:16:08.007980047+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"ok  \tgotest_problem/pkg/example\t0.003s\n"}
{"Time":"2021-11-10T18:16:08.007992879+01:00","Action":"pass","Package":"gotest_problem/pkg/example","Elapsed":0.003}

Uncommenting the fmt import and ExampleCountToN in pkg/example/x_test.go causes the benchmark events to be annotated as "Test": "ExampleCountToN":

$ go test -json -shuffle off -bench '.+' -count 1 ./pkg/example

{"Time":"2021-11-10T18:10:02.836068165+01:00","Action":"run","Package":"gotest_problem/pkg/example","Test":"TestCountToN"}
{"Time":"2021-11-10T18:10:02.836147595+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"=== RUN   TestCountToN\n"}
{"Time":"2021-11-10T18:10:02.836154387+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Output":"--- PASS: TestCountToN (0.00s)\n"}
{"Time":"2021-11-10T18:10:02.836157342+01:00","Action":"pass","Package":"gotest_problem/pkg/example","Test":"TestCountToN","Elapsed":0}
{"Time":"2021-11-10T18:10:02.836160553+01:00","Action":"run","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN"}
{"Time":"2021-11-10T18:10:02.836163118+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"=== RUN   ExampleCountToN\n"}
{"Time":"2021-11-10T18:10:02.836166188+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"--- PASS: ExampleCountToN (0.00s)\n"}
{"Time":"2021-11-10T18:10:02.83663875+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"goos: linux\n"}
{"Time":"2021-11-10T18:10:02.836654632+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"goarch: amd64\n"}
{"Time":"2021-11-10T18:10:02.836658125+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"pkg: gotest_problem/pkg/example\n"}
{"Time":"2021-11-10T18:10:02.83666083+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"cpu: Intel(R) Core(TM) i9-9900K CPU @ 3.60GHz\n"}
{"Time":"2021-11-10T18:10:02.836664021+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"BenchmarkCountToN\n"}
{"Time":"2021-11-10T18:10:02.83814744+01:00","Action":"output","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Output":"BenchmarkCountToN-16    \t1000000000\t         0.0000005 ns/op\n"}
{"Time":"2021-11-10T18:10:02.838161975+01:00","Action":"pass","Package":"gotest_problem/pkg/example","Test":"ExampleCountToN","Elapsed":0}
{"Time":"2021-11-10T18:10:02.838167637+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"PASS\n"}
{"Time":"2021-11-10T18:10:02.838341566+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"ok  \tgotest_problem/pkg/example\t0.003s\n"}
{"Time":"2021-11-10T18:10:02.83835485+01:00","Action":"pass","Package":"gotest_problem/pkg/example","Elapsed":0.003}

Deleting TestCountToN and ExampleCountToN and leaving only the benchmark causes the "Test" field to disappear from the output entirely:

{"Time":"2021-11-10T18:21:39.144096754+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"goos: linux\n"}
{"Time":"2021-11-10T18:21:39.14417142+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"goarch: amd64\n"}
{"Time":"2021-11-10T18:21:39.14417586+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"pkg: gotest_problem/pkg/example\n"}
{"Time":"2021-11-10T18:21:39.144181564+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"cpu: Intel(R) Core(TM) i9-9900K CPU @ 3.60GHz\n"}
{"Time":"2021-11-10T18:21:39.144185051+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"BenchmarkCountToN\n"}
{"Time":"2021-11-10T18:21:39.145592433+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"BenchmarkCountToN-16    \t1000000000\t         0.0000004 ns/op\n"}
{"Time":"2021-11-10T18:21:39.145602781+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"PASS\n"}
{"Time":"2021-11-10T18:21:39.145816225+01:00","Action":"output","Package":"gotest_problem/pkg/example","Output":"ok  \tgotest_problem/pkg/example\t0.003s\n"}
{"Time":"2021-11-10T18:21:39.145831098+01:00","Action":"pass","Package":"gotest_problem/pkg/example","Elapsed":0.003}

It appears that the Test field of the event struct is not populated at all for benchmarks, and the printer uses its last set value if one is available.

The text was updated successfully, but these errors were encountered:

cagedmantis · 2021-11-12T16:58:11Z

/cc @rsc

bcmills · 2021-11-12T19:04:50Z

I think this is pretty straightforward to fix for the typical case of a benchmark that produces no output.

If we see a --- PASS: TestCountToN line at the top level, I think we can assume that the output that follows does not belong with that test, although there are some old test outputs in cmd/internal/test2json/testdata (dating to Go 1.10) that violate that.

I suppose we need to figure out how and why those testdata outputs are structured that way.

bcmills · 2021-11-12T19:06:41Z

For future reference, here is a cmd/go test script that reproduces the above bug:

# Regression test for https://golang.org/issue/49505:
# 'go test -json' should not report benchmark output as test output.

go test -json -shuffle=off -bench=. -run='^Test' ./pkg/example
stdout '"Action":"output",.*"Output":"BenchmarkCountToN\\n"}'
! stdout 'TestCountToN.*Benchmark'

-- go.mod --
module gotest_problem

go 1.17
-- pkg/example/x.go --
package example

func CountToN(N int) int {
	i := 0
	for i < N {
		i++
	}

	return i
}
-- pkg/example/x_test.go --
package example_test

import (
	"fmt"
	"testing"

	x "gotest_problem/pkg/example"
)

func TestCountToN(t *testing.T) {
	want := 1234
	if got := x.CountToN(want); got != want {
		t.Errorf("Expected %d, got %d instead", want, got)
	}
}

func ExampleCountToN() {
	r := x.CountToN(1234)
	fmt.Println(r)

	// Output: 1234
}

func BenchmarkCountToN(b *testing.B) {
	x.CountToN(1234)
}

gopherbot · 2022-10-18T14:39:05Z

Change https://go.dev/cl/443596 mentions this issue: testing: fix many test2json inaccuracies

Test2json is parsing the output stream from the test, which includes package testing's own framing lines intermingled with other output, in particular any output printed via fmt.Printf, println, and so on. We have had recurring problems with unexpected partial output lines causing a framing line to be missed. A recent talk at GopherCon gave an example of an integration test involving Docker that happened to print \r-terminated lines instead of \n-terminated lines in some configurations, which in turn broke test2json badly. (https://www.gophercon.com/agenda/session/944259) There are also a variety of open reported issues with similar problems, which this CL also addresses. The general approach is to add a new testing flag -test.v=json that means to print additional output to help test2json. And then test2json takes advantage of that output. Among the fixes: - Identify testing framing more reliably, using ^V (golang#23036, golang#26325, golang#43683, GopherCon talk) - Test that output with \r\n endings is handled correctly (golang#43683, golang#34286) - Use === RUN in fuzz tests (golang#52636, golang#48132) - Add === RUN lines to note benchmark starts (golang#27764, golang#49505) - Print subtest --- PASS/FAIL lines as they happen (golang#29811) - Add === NAME lines to emit more test change events, such as when a subtest stops and the parent continues running. - Fix event shown in overall test failure (golang#27568) - Avoid interleaving of writes to os.Stdout and os.Stderr (golang#33419) Fixes golang#23036. Fixes golang#26325. Fixes golang#27568. Fixes golang#27764. Fixes golang#29811. Fixes golang#33419. Fixes golang#34286. Fixes golang#43683. Fixes golang#49505. Fixes golang#52636. Change-Id: Id4207b746a20693f92e52d68c6e4a7f8c41cc7c6 Reviewed-on: https://go-review.googlesource.com/c/go/+/443596 Auto-Submit: Russ Cox <rsc@golang.org> Run-TryBot: Russ Cox <rsc@golang.org> Reviewed-by: Bryan Mills <bcmills@google.com> TryBot-Result: Gopher Robot <gobot@golang.org>

bcmills changed the title ~~cmd/test: Incorrect go test -json output for benchmark~~ cmd/test2json: Incorrect go test -json output for benchmark Nov 12, 2021

cagedmantis added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 12, 2021

cagedmantis added this to the Backlog milestone Nov 12, 2021

bcmills changed the title ~~cmd/test2json: Incorrect go test -json output for benchmark~~ cmd/test2json: benchmark output lines are attributed to the preceding test Nov 12, 2021

gopherbot closed this as completed in 1c72ee7 Oct 26, 2022

dmitshur added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Nov 18, 2022

dmitshur modified the milestones: Backlog, Go1.20 Nov 18, 2022

cmd/test2json: benchmark output lines are attributed to the preceding test #49505

cmd/test2json: benchmark output lines are attributed to the preceding test #49505

wkaluza commented Nov 10, 2021

cagedmantis commented Nov 12, 2021

bcmills commented Nov 12, 2021

bcmills commented Nov 12, 2021

gopherbot commented Oct 18, 2022

cmd/test2json: benchmark output lines are attributed to the preceding test #49505

cmd/test2json: benchmark output lines are attributed to the preceding test #49505

Comments

wkaluza commented Nov 10, 2021

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

Does this issue reproduce with the latest release?

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

What did you do?

What did you expect to see?

What did you see instead?

cagedmantis commented Nov 12, 2021

bcmills commented Nov 12, 2021

bcmills commented Nov 12, 2021

gopherbot commented Oct 18, 2022

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

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