search

golang / go

The Go programming language
https://go.dev
BSD 3-Clause "New" or "Revised" License
122.84k stars 17.52k forks source link

cmd/go: -json test report ordering #28953

Open sagikazarmark opened 5 years ago

sagikazarmark commented 5 years ago

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

$ go version
go version go1.11.2 darwin/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
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/me/Library/Caches/go-build"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/me/.go:/Users/mark/Projects/go"
GOPROXY=""
GORACE=""
GOROOT="/Users/me/.goenv/versions/1.11.2"
GOTMPDIR=""
GOTOOLDIR="/Users/me/.goenv/versions/1.11.2/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/mark/Projects/mine/my_pkg/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 -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/vy/hzm88gt90292ztr9f3qg9zhr0000gn/T/go-build057809249=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I ran tests for a module using the following commands:

$ go test -v ./...
$ go test -v -json ./...
$ go test -v ./... | go tool test2json

Repository: https://github.com/reproduce/golant-test-ordering-issue

What did you expect to see?

I expected to see the test events to be in the exact same order in each case

What did you see instead?

go test -v ./... Output
$ go test -v ./...
=== RUN   TestSuccess
--- PASS: TestSuccess (0.00s)
=== RUN   TestSkip
--- SKIP: TestSkip (0.00s)
    test_test.go:10: skipping test
=== RUN   TestFail
--- FAIL: TestFail (0.00s)
    test_test.go:14: failed test
=== RUN   TestMain
=== RUN   TestMain/success
=== RUN   TestMain/skip
=== RUN   TestMain/fail
--- FAIL: TestMain (0.00s)
    --- PASS: TestMain/success (0.00s)
    --- SKIP: TestMain/skip (0.00s)
        test_test.go:23: skipping test
    --- FAIL: TestMain/fail (0.00s)
        test_test.go:27: failed test
FAIL
FAIL    my_pkg  0.005s
?       my_pkg/pkg/no_tests [no test files]
testing: warning: no tests to run
PASS
ok      my_pkg/pkg/subpkg   0.005s [no tests to run]
go test -v -json ./... Output
$ go test -v -json ./...
{"Time":"2018-11-26T15:03:16.782812+01:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"testing: warning: no tests to run\n"}
{"Time":"2018-11-26T15:03:16.783598+01:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"PASS\n"}
{"Time":"2018-11-26T15:03:16.783605+01:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"ok  \tmy_pkg/pkg/subpkg\t(cached) [no tests to run]\n"}
{"Time":"2018-11-26T15:03:16.783614+01:00","Action":"pass","Package":"my_pkg/pkg/subpkg","Elapsed":0.001}
{"Time":"2018-11-26T15:03:17.015719+01:00","Action":"run","Package":"my_pkg","Test":"TestSuccess"}
{"Time":"2018-11-26T15:03:17.015757+01:00","Action":"output","Package":"my_pkg","Test":"TestSuccess","Output":"=== RUN   TestSuccess\n"}
{"Time":"2018-11-26T15:03:17.015786+01:00","Action":"output","Package":"my_pkg","Test":"TestSuccess","Output":"--- PASS: TestSuccess (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.015797+01:00","Action":"pass","Package":"my_pkg","Test":"TestSuccess","Elapsed":0}
{"Time":"2018-11-26T15:03:17.015804+01:00","Action":"run","Package":"my_pkg","Test":"TestSkip"}
{"Time":"2018-11-26T15:03:17.015816+01:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"=== RUN   TestSkip\n"}
{"Time":"2018-11-26T15:03:17.01583+01:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"--- SKIP: TestSkip (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.015837+01:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"    test_test.go:10: skipping test\n"}
{"Time":"2018-11-26T15:03:17.015848+01:00","Action":"skip","Package":"my_pkg","Test":"TestSkip","Elapsed":0}
{"Time":"2018-11-26T15:03:17.015854+01:00","Action":"run","Package":"my_pkg","Test":"TestFail"}
{"Time":"2018-11-26T15:03:17.015859+01:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"=== RUN   TestFail\n"}
{"Time":"2018-11-26T15:03:17.015864+01:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"--- FAIL: TestFail (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.01587+01:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"    test_test.go:14: failed test\n"}
{"Time":"2018-11-26T15:03:17.015883+01:00","Action":"fail","Package":"my_pkg","Test":"TestFail","Elapsed":0}
{"Time":"2018-11-26T15:03:17.015888+01:00","Action":"run","Package":"my_pkg","Test":"TestMain"}
{"Time":"2018-11-26T15:03:17.015942+01:00","Action":"output","Package":"my_pkg","Test":"TestMain","Output":"=== RUN   TestMain\n"}
{"Time":"2018-11-26T15:03:17.015956+01:00","Action":"run","Package":"my_pkg","Test":"TestMain/success"}
{"Time":"2018-11-26T15:03:17.015963+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/success","Output":"=== RUN   TestMain/success\n"}
{"Time":"2018-11-26T15:03:17.015969+01:00","Action":"run","Package":"my_pkg","Test":"TestMain/skip"}
{"Time":"2018-11-26T15:03:17.015974+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"=== RUN   TestMain/skip\n"}
{"Time":"2018-11-26T15:03:17.015984+01:00","Action":"run","Package":"my_pkg","Test":"TestMain/fail"}
{"Time":"2018-11-26T15:03:17.01599+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"=== RUN   TestMain/fail\n"}
{"Time":"2018-11-26T15:03:17.015996+01:00","Action":"output","Package":"my_pkg","Test":"TestMain","Output":"--- FAIL: TestMain (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.016019+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/success","Output":"    --- PASS: TestMain/success (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.016026+01:00","Action":"pass","Package":"my_pkg","Test":"TestMain/success","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016037+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"    --- SKIP: TestMain/skip (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.016042+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"        test_test.go:23: skipping test\n"}
{"Time":"2018-11-26T15:03:17.016049+01:00","Action":"skip","Package":"my_pkg","Test":"TestMain/skip","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016054+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"    --- FAIL: TestMain/fail (0.00s)\n"}
{"Time":"2018-11-26T15:03:17.01606+01:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"        test_test.go:27: failed test\n"}
{"Time":"2018-11-26T15:03:17.016088+01:00","Action":"fail","Package":"my_pkg","Test":"TestMain/fail","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016094+01:00","Action":"fail","Package":"my_pkg","Test":"TestMain","Elapsed":0}
{"Time":"2018-11-26T15:03:17.016099+01:00","Action":"output","Package":"my_pkg","Output":"FAIL\n"}
{"Time":"2018-11-26T15:03:17.016309+01:00","Action":"output","Package":"my_pkg","Output":"FAIL\tmy_pkg\t0.005s\n"}
{"Time":"2018-11-26T15:03:17.016339+01:00","Action":"fail","Package":"my_pkg","Elapsed":0.006}
{"Time":"2018-11-26T15:03:17.017209+01:00","Action":"output","Package":"my_pkg/pkg/no_tests","Output":"?   \tmy_pkg/pkg/no_tests\t[no test files]\n"}
{"Time":"2018-11-26T15:03:17.017238+01:00","Action":"skip","Package":"my_pkg/pkg/no_tests","Elapsed":0}
go test -v ./... | go tool test2json Output
$ go test -v ./... | go tool test2json
{"Action":"run","Test":"TestSuccess"}
{"Action":"output","Test":"TestSuccess","Output":"=== RUN   TestSuccess\n"}
{"Action":"output","Test":"TestSuccess","Output":"--- PASS: TestSuccess (0.00s)\n"}
{"Action":"pass","Test":"TestSuccess"}
{"Action":"run","Test":"TestSkip"}
{"Action":"output","Test":"TestSkip","Output":"=== RUN   TestSkip\n"}
{"Action":"output","Test":"TestSkip","Output":"--- SKIP: TestSkip (0.00s)\n"}
{"Action":"output","Test":"TestSkip","Output":"    test_test.go:10: skipping test\n"}
{"Action":"skip","Test":"TestSkip"}
{"Action":"run","Test":"TestFail"}
{"Action":"output","Test":"TestFail","Output":"=== RUN   TestFail\n"}
{"Action":"output","Test":"TestFail","Output":"--- FAIL: TestFail (0.00s)\n"}
{"Action":"output","Test":"TestFail","Output":"    test_test.go:14: failed test\n"}
{"Action":"fail","Test":"TestFail"}
{"Action":"run","Test":"TestMain"}
{"Action":"output","Test":"TestMain","Output":"=== RUN   TestMain\n"}
{"Action":"run","Test":"TestMain/success"}
{"Action":"output","Test":"TestMain/success","Output":"=== RUN   TestMain/success\n"}
{"Action":"run","Test":"TestMain/skip"}
{"Action":"output","Test":"TestMain/skip","Output":"=== RUN   TestMain/skip\n"}
{"Action":"run","Test":"TestMain/fail"}
{"Action":"output","Test":"TestMain/fail","Output":"=== RUN   TestMain/fail\n"}
{"Action":"output","Test":"TestMain","Output":"--- FAIL: TestMain (0.00s)\n"}
{"Action":"output","Test":"TestMain/success","Output":"    --- PASS: TestMain/success (0.00s)\n"}
{"Action":"pass","Test":"TestMain/success"}
{"Action":"output","Test":"TestMain/skip","Output":"    --- SKIP: TestMain/skip (0.00s)\n"}
{"Action":"output","Test":"TestMain/skip","Output":"        test_test.go:23: skipping test\n"}
{"Action":"skip","Test":"TestMain/skip"}
{"Action":"output","Test":"TestMain/fail","Output":"    --- FAIL: TestMain/fail (0.00s)\n"}
{"Action":"output","Test":"TestMain/fail","Output":"        test_test.go:27: failed test\n"}
{"Action":"fail","Test":"TestMain/fail"}
{"Action":"fail","Test":"TestMain"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"output","Output":"FAIL\tmy_pkg\t0.006s\n"}
{"Action":"output","Output":"?   \tmy_pkg/pkg/no_tests\t[no test files]\n"}
{"Action":"output","Output":"testing: warning: no tests to run\n"}
{"Action":"output","Output":"PASS\n"}
{"Action":"output","Output":"ok  \tmy_pkg/pkg/subpkg\t(cached) [no tests to run]\n"}
{"Action":"pass"}

As per https://golang.org/cmd/test2json I expect to see the events to be in the exact same order:

With that one exception, the concatenation of the Output fields of all output events is the exact output of the test execution.

But they are not. This causes a problem when one would like to get a json output for some kind of reporting purpose, but still want to display the regular test report to the user.

andybons commented 5 years ago

@sagikazarmark do you know if this is modules-specific?

@ianlancetaylor @bcmills

sagikazarmark commented 5 years ago

Haven't tried, but can be easily tested by cloning the repo into GOPATH. I'd be surprised though if it would be.

bcmills commented 5 years ago

-v and test2json will probably be changing soon anyway for #24929. I suggest that we wait until that settles and see if it's still a problem.

sagikazarmark commented 3 years ago

As far as I can tell, this still occurs on Go 1.15:

go test -v ./... Output
$ go test -v ./...
=== RUN   TestSuccess
--- PASS: TestSuccess (0.00s)
=== RUN   TestSkip
    test_test.go:10: skipping test
--- SKIP: TestSkip (0.00s)
=== RUN   TestFail
    test_test.go:14: failed test
--- FAIL: TestFail (0.00s)
=== RUN   TestMain
=== RUN   TestMain/success
=== RUN   TestMain/skip
    test_test.go:23: skipping test
=== RUN   TestMain/fail
    test_test.go:27: failed test
--- FAIL: TestMain (0.00s)
    --- PASS: TestMain/success (0.00s)
    --- SKIP: TestMain/skip (0.00s)
    --- FAIL: TestMain/fail (0.00s)
FAIL
FAIL    my_pkg  0.636s
?       my_pkg/pkg/no_tests [no test files]
testing: warning: no tests to run
PASS
ok      my_pkg/pkg/subpkg   0.467s [no tests to run]
FAIL
go test -v -json ./... Output
$ go test -v -json ./...
{"Time":"2020-09-23T12:11:27.885825+02:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"testing: warning: no tests to run\n"}
{"Time":"2020-09-23T12:11:27.886975+02:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"PASS\n"}
{"Time":"2020-09-23T12:11:27.887016+02:00","Action":"output","Package":"my_pkg/pkg/subpkg","Output":"ok  \tmy_pkg/pkg/subpkg\t0.068s [no tests to run]\n"}
{"Time":"2020-09-23T12:11:27.888084+02:00","Action":"pass","Package":"my_pkg/pkg/subpkg","Elapsed":0.07}
{"Time":"2020-09-23T12:11:27.934708+02:00","Action":"run","Package":"my_pkg","Test":"TestSuccess"}
{"Time":"2020-09-23T12:11:27.93475+02:00","Action":"output","Package":"my_pkg","Test":"TestSuccess","Output":"=== RUN   TestSuccess\n"}
{"Time":"2020-09-23T12:11:27.934797+02:00","Action":"output","Package":"my_pkg","Test":"TestSuccess","Output":"--- PASS: TestSuccess (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.93481+02:00","Action":"pass","Package":"my_pkg","Test":"TestSuccess","Elapsed":0}
{"Time":"2020-09-23T12:11:27.934816+02:00","Action":"run","Package":"my_pkg","Test":"TestSkip"}
{"Time":"2020-09-23T12:11:27.934822+02:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"=== RUN   TestSkip\n"}
{"Time":"2020-09-23T12:11:27.934825+02:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"    test_test.go:10: skipping test\n"}
{"Time":"2020-09-23T12:11:27.934837+02:00","Action":"output","Package":"my_pkg","Test":"TestSkip","Output":"--- SKIP: TestSkip (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.934841+02:00","Action":"skip","Package":"my_pkg","Test":"TestSkip","Elapsed":0}
{"Time":"2020-09-23T12:11:27.934843+02:00","Action":"run","Package":"my_pkg","Test":"TestFail"}
{"Time":"2020-09-23T12:11:27.934846+02:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"=== RUN   TestFail\n"}
{"Time":"2020-09-23T12:11:27.934849+02:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"    test_test.go:14: failed test\n"}
{"Time":"2020-09-23T12:11:27.934852+02:00","Action":"output","Package":"my_pkg","Test":"TestFail","Output":"--- FAIL: TestFail (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.934855+02:00","Action":"fail","Package":"my_pkg","Test":"TestFail","Elapsed":0}
{"Time":"2020-09-23T12:11:27.934857+02:00","Action":"run","Package":"my_pkg","Test":"TestMain"}
{"Time":"2020-09-23T12:11:27.93486+02:00","Action":"output","Package":"my_pkg","Test":"TestMain","Output":"=== RUN   TestMain\n"}
{"Time":"2020-09-23T12:11:27.934942+02:00","Action":"run","Package":"my_pkg","Test":"TestMain/success"}
{"Time":"2020-09-23T12:11:27.93495+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/success","Output":"=== RUN   TestMain/success\n"}
{"Time":"2020-09-23T12:11:27.934957+02:00","Action":"run","Package":"my_pkg","Test":"TestMain/skip"}
{"Time":"2020-09-23T12:11:27.934961+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"=== RUN   TestMain/skip\n"}
{"Time":"2020-09-23T12:11:27.934968+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"    test_test.go:23: skipping test\n"}
{"Time":"2020-09-23T12:11:27.93498+02:00","Action":"run","Package":"my_pkg","Test":"TestMain/fail"}
{"Time":"2020-09-23T12:11:27.934986+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"=== RUN   TestMain/fail\n"}
{"Time":"2020-09-23T12:11:27.934991+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"    test_test.go:27: failed test\n"}
{"Time":"2020-09-23T12:11:27.935026+02:00","Action":"output","Package":"my_pkg","Test":"TestMain","Output":"--- FAIL: TestMain (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.935036+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/success","Output":"    --- PASS: TestMain/success (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.935041+02:00","Action":"pass","Package":"my_pkg","Test":"TestMain/success","Elapsed":0}
{"Time":"2020-09-23T12:11:27.935051+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/skip","Output":"    --- SKIP: TestMain/skip (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.935057+02:00","Action":"skip","Package":"my_pkg","Test":"TestMain/skip","Elapsed":0}
{"Time":"2020-09-23T12:11:27.93506+02:00","Action":"output","Package":"my_pkg","Test":"TestMain/fail","Output":"    --- FAIL: TestMain/fail (0.00s)\n"}
{"Time":"2020-09-23T12:11:27.935063+02:00","Action":"fail","Package":"my_pkg","Test":"TestMain/fail","Elapsed":0}
{"Time":"2020-09-23T12:11:27.935134+02:00","Action":"fail","Package":"my_pkg","Test":"TestMain","Elapsed":0}
{"Time":"2020-09-23T12:11:27.935144+02:00","Action":"output","Package":"my_pkg","Output":"FAIL\n"}
{"Time":"2020-09-23T12:11:27.935298+02:00","Action":"output","Package":"my_pkg","Output":"FAIL\tmy_pkg\t0.115s\n"}
{"Time":"2020-09-23T12:11:27.93531+02:00","Action":"fail","Package":"my_pkg","Elapsed":0.116}
{"Time":"2020-09-23T12:11:27.93585+02:00","Action":"output","Package":"my_pkg/pkg/no_tests","Output":"?   \tmy_pkg/pkg/no_tests\t[no test files]\n"}
{"Time":"2020-09-23T12:11:27.935859+02:00","Action":"skip","Package":"my_pkg/pkg/no_tests","Elapsed":0}
go test -v ./... | go tool test2json Output
$ go test -v ./... | go tool test2json
{"Action":"run","Test":"TestSuccess"}
{"Action":"output","Test":"TestSuccess","Output":"=== RUN   TestSuccess\n"}
{"Action":"output","Test":"TestSuccess","Output":"--- PASS: TestSuccess (0.00s)\n"}
{"Action":"pass","Test":"TestSuccess"}
{"Action":"run","Test":"TestSkip"}
{"Action":"output","Test":"TestSkip","Output":"=== RUN   TestSkip\n"}
{"Action":"output","Test":"TestSkip","Output":"    test_test.go:10: skipping test\n"}
{"Action":"output","Test":"TestSkip","Output":"--- SKIP: TestSkip (0.00s)\n"}
{"Action":"skip","Test":"TestSkip"}
{"Action":"run","Test":"TestFail"}
{"Action":"output","Test":"TestFail","Output":"=== RUN   TestFail\n"}
{"Action":"output","Test":"TestFail","Output":"    test_test.go:14: failed test\n"}
{"Action":"output","Test":"TestFail","Output":"--- FAIL: TestFail (0.00s)\n"}
{"Action":"fail","Test":"TestFail"}
{"Action":"run","Test":"TestMain"}
{"Action":"output","Test":"TestMain","Output":"=== RUN   TestMain\n"}
{"Action":"run","Test":"TestMain/success"}
{"Action":"output","Test":"TestMain/success","Output":"=== RUN   TestMain/success\n"}
{"Action":"run","Test":"TestMain/skip"}
{"Action":"output","Test":"TestMain/skip","Output":"=== RUN   TestMain/skip\n"}
{"Action":"output","Test":"TestMain/skip","Output":"    test_test.go:23: skipping test\n"}
{"Action":"run","Test":"TestMain/fail"}
{"Action":"output","Test":"TestMain/fail","Output":"=== RUN   TestMain/fail\n"}
{"Action":"output","Test":"TestMain/fail","Output":"    test_test.go:27: failed test\n"}
{"Action":"output","Test":"TestMain","Output":"--- FAIL: TestMain (0.00s)\n"}
{"Action":"output","Test":"TestMain/success","Output":"    --- PASS: TestMain/success (0.00s)\n"}
{"Action":"pass","Test":"TestMain/success"}
{"Action":"output","Test":"TestMain/skip","Output":"    --- SKIP: TestMain/skip (0.00s)\n"}
{"Action":"skip","Test":"TestMain/skip"}
{"Action":"output","Test":"TestMain/fail","Output":"    --- FAIL: TestMain/fail (0.00s)\n"}
{"Action":"fail","Test":"TestMain/fail"}
{"Action":"fail","Test":"TestMain"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"output","Output":"FAIL\tmy_pkg\t0.070s\n"}
{"Action":"output","Output":"?   \tmy_pkg/pkg/no_tests\t[no test files]\n"}
{"Action":"output","Output":"testing: warning: no tests to run\n"}
{"Action":"output","Output":"PASS\n"}
{"Action":"output","Output":"ok  \tmy_pkg/pkg/subpkg\t(cached) [no tests to run]\n"}
{"Action":"output","Output":"FAIL\n"}
{"Action":"fail"}