New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

cmd/go: -json test report ordering #28953

Open
sagikazarmark opened this Issue Nov 26, 2018 · 3 comments

Comments

Projects
None yet
3 participants
@sagikazarmark

sagikazarmark commented Nov 26, 2018

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 andybons added this to the Unplanned milestone Nov 26, 2018

@andybons

This comment has been minimized.

Member

andybons commented Nov 26, 2018

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

@ianlancetaylor @bcmills

@sagikazarmark

This comment has been minimized.

sagikazarmark commented Nov 26, 2018

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

@bcmills

This comment has been minimized.

Member

bcmills commented Nov 26, 2018

-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.

@bcmills bcmills modified the milestones: Unplanned, Go1.13 Nov 26, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment