"go test -v" and compile test binary outputs are inconsistent for post-completion panics

[xytan0056]

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

$ go version
go version go1.20.2 darwin/arm64

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
➜  test git:(testxml-logaftercompletion) ✗ go1.20.2 env    
GO111MODULE="on"
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/tanx/Library/Caches/go-build"
GOENV="/Users/tanx/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/tanx/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/tanx/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/tanx/sdk/go1.20.2"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/tanx/sdk/go1.20.2/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.20.2"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/tanx/go/src/test/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 -fdebug-prefix-map=/var/folders/7v/pljvd_0s45gc4gm6820jy0qr0000gn/T/go-build949117293=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

run test that panics post completion

• git clone -b testxml-logaftercompletion [email protected]:xytan0056/test.git
• run go test . -v -count=5
• run go test -c ./ then ./my_module.test -test.v -test.count=5

What did you expect to see?

output of go test ... and ./compiled_test ... should be consistent

What did you see instead?

output of go test . -v -count=5

➜  test git:(testxml-logaftercompletion) ✗ go1.20.2 test . -v -count=5 
...
--- PASS: TestFunc1 (0.00s)
PASS
panic: Log in goroutine after TestFunc1 has completed: log in go routine!


goroutine 5 [running]:
testing.(*common).logDepth(0x140000036c0, {0x14000014150, 0x13}, 0x3)
        /Users/tanx/sdk/go1.20.2/src/testing/testing.go:1003 +0x3c4
testing.(*common).log(...)
        /Users/tanx/sdk/go1.20.2/src/testing/testing.go:985
testing.(*common).Log(0x140000036c0, {0x140000457b0?, 0x0?, 0x0?})
        /Users/tanx/sdk/go1.20.2/src/testing/testing.go:1026 +0x4c
my_module.TestFunc1.func1()
        /Users/tanx/go/src/test/main_test.go:16 +0x98
created by my_module.TestFunc1
        /Users/tanx/go/src/test/main_test.go:13 +0x60
FAIL    my_module       0.115s     <------
FAIL                               <------ these lines are missing in the other case
➜  test git:(testxml-logaftercompletion) ✗ echo $?
1

output of go test -c ./ then ./my_module.test -test.v -test.count=5

➜  test git:(testxml-logaftercompletion) ✗ ./my_module.test -test.v -test.count=5
...
PASS
panic: Log in goroutine after TestFunc1 has completed: log in go routine!


goroutine 35 [running]:
testing.(*common).logDepth(0x14000116820, {0x140001220a8, 0x13}, 0x3)
        /Users/tanx/sdk/go1.20.2/src/testing/testing.go:1003 +0x3c4
testing.(*common).log(...)
        /Users/tanx/sdk/go1.20.2/src/testing/testing.go:985
testing.(*common).Log(0x14000116820, {0x1400015a7b0?, 0x0?, 0x0?})
        /Users/tanx/sdk/go1.20.2/src/testing/testing.go:1026 +0x4c
my_module.TestFunc1.func1()
        /Users/tanx/go/src/test/main_test.go:16 +0x98
created by my_module.TestFunc1
        /Users/tanx/go/src/test/main_test.go:13 +0x60
➜  test git:(testxml-logaftercompletion) ✗ echo $?                               
2

note that go test outputs FAIL ... at the end after the test completes, while executing the test binary doesn't. And their exit codes are different.

bazelbuild/rule_go relies on parsing the output of test binaries to generate junit.xml, which becomes inaccurate if the FAIL line is missing bazel-contrib/rules_go#3476.

On another note, although go test -json also contains the correct events

{"Time":"...","Action":"fail","Package":"my_module","Elapsed":0.11}

however -test.json is not recognized in generated test binary

➜  test git:(testxml-logaftercompletion) ✗ ./my_module.test -test.v -test.count=5 -test.json
flag provided but not defined: -test.json

so this statement is not really accurate

[seankhliao]

Duplicate of #23258

[xytan0056]

@seankhliao I don't think this is the duplicate of #23258.
even running in "local directory" mode, which is said to

compiles the package sources and tests found in the current directory and then runs the resultingtest binary

does not behave the same as manually compile the test binary and run test.

➜  test git:(testxml-logaftercompletion) ✗ go test -v
=== RUN   TestFunc1
=== PAUSE TestFunc1
=== CONT  TestFunc1
    main_test.go:18: log1?
--- PASS: TestFunc1 (0.00s)
PASS
panic: Log in goroutine after TestFunc1 has completed: log in go routine!


goroutine 5 [running]:
testing.(*common).logDepth(0x140000036c0, {0x140000140f0, 0x13}, 0x3)
        /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:894 +0x3c0
testing.(*common).log(...)
        /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:876
testing.(*common).Log(0x140000036c0, {0x14000186fb0?, 0x0?, 0x0?})
        /opt/homebrew/Cellar/go/1.19.4/libexec/src/testing/testing.go:917 +0x4c
my_module.TestFunc1.func1()
        /Users/tanx/go/src/test/main_test.go:16 +0xa0
created by my_module.TestFunc1
        /Users/tanx/go/src/test/main_test.go:13 +0x64
exit status 2
FAIL    my_module       0.127s

The problem is compiled binary doesn't output test summary line, nor does it respect -test.json flag, which is contradictory to what the document says

[seankhliao]

The docs say

... go test prints a summary line
showing the test status ('ok' or 'FAIL'), package name, and elapsed
time.

The summary line is a property of go test, not the test binary.

It also says

In addition to the build flags, the flags handled by 'go test' itself are:

...

-json

[xytan0056]

regardless of what mode go test runs in. The summary line is printed, but not test binary. This needs to be explicitly called out, because the rest of the doc gives an impression that running binary is the same.
go help testflag

Each of these flags is also recognized with an optional 'test.' prefix, as in -test.v. When invoking the generated test binary (the result of 'go test -c') directly, however, the prefix is mandatory.

For instance, the command

go test -v -args -x -v

will compile the test binary and then run it as

pkg.test -test.v -x -v

I'd understand if it's by design that "they are supposed to behave differently". But shouldn't these inconsistencies be addressed eventually?