testing: report non-zero exit status in -json output

[goto1134]

I have the following test file sample_test.go:

package main

import (
	"os"
	"testing"
)

func Test(t *testing.T) {
	t.Run("1", func(t *testing.T) {
		t.Run("1.1", func(t *testing.T) {
			os.Exit(2)
                         // os.Exit(0)
		})
	})
}

If I use go test on that file, I get the exit code in the output as expected:

$ go test -json -test.paniconexit0 -test.run Test .      
{"Time":"2023-08-08T16:09:56.448232+02:00","Action":"start","Package":"awesomeProject3"}
{"Time":"2023-08-08T16:09:56.611997+02:00","Action":"run","Package":"awesomeProject3","Test":"Test"}
{"Time":"2023-08-08T16:09:56.612096+02:00","Action":"output","Package":"awesomeProject3","Test":"Test","Output":"=== RUN   Test\n"}
{"Time":"2023-08-08T16:09:56.612131+02:00","Action":"run","Package":"awesomeProject3","Test":"Test/1"}
{"Time":"2023-08-08T16:09:56.612133+02:00","Action":"output","Package":"awesomeProject3","Test":"Test/1","Output":"=== RUN   Test/1\n"}
{"Time":"2023-08-08T16:09:56.612136+02:00","Action":"run","Package":"awesomeProject3","Test":"Test/1/1.1"}
{"Time":"2023-08-08T16:09:56.612138+02:00","Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"=== RUN   Test/1/1.1\n"}
{"Time":"2023-08-08T16:09:56.61243+02:00","Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"exit status 2\n"}
{"Time":"2023-08-08T16:09:56.612473+02:00","Action":"output","Package":"awesomeProject3","Output":"FAIL\tawesomeProject3\t0.164s\n"}
{"Time":"2023-08-08T16:09:56.612476+02:00","Action":"fail","Package":"awesomeProject3","Elapsed":0.164}

If I use go test2json instead, I will get no exit code in the output at all.

$ go test -c -o awesomeProject3 ./...
$ go tool test2json -t ./awesomeProject3 -test.v -test.run Test       
{"Time":"2023-08-08T16:12:00.158467+02:00","Action":"start"}
{"Time":"2023-08-08T16:12:00.47165+02:00","Action":"run","Test":"Test"}
{"Time":"2023-08-08T16:12:00.471757+02:00","Action":"output","Test":"Test","Output":"=== RUN   Test\n"}
{"Time":"2023-08-08T16:12:00.471767+02:00","Action":"run","Test":"Test/1"}
{"Time":"2023-08-08T16:12:00.47177+02:00","Action":"output","Test":"Test/1","Output":"=== RUN   Test/1\n"}
{"Time":"2023-08-08T16:12:00.471773+02:00","Action":"run","Test":"Test/1/1.1"}
{"Time":"2023-08-08T16:12:00.471775+02:00","Action":"output","Test":"Test/1/1.1","Output":"=== RUN   Test/1/1.1\n"}
{"Time":"2023-08-08T16:12:00.472018+02:00","Action":"fail","Test":"Test/1/1.1","Elapsed":0.314}

Try the same commands with the zero exit code and you will see a detailed panic message in both cases.

---

1. Consider panicking on any non-zero exit code as well.
2. Consider showing the non-zero exit code in the text2json output as well.

[bcmills]

If I use go test on that file, I get the exit code in the output as expected:

The exit code in the output is not “as expected“. We normally only log the exit status if there is no other output to explain the failure:
https://cs.opensource.google/go/go/+/master:src/cmd/go/internal/test/test.go;l=1462-1466;drc=a3093eca64f9efc830c153c835291d751ea167f9

What you are seeing here is a subtle (and unfortunate) combination of factors.

• You are passing the flag -test.paniconexit0 explicitly, but that flag is for internal use and not intentionally supported by go test:
  https://cs.opensource.google/go/go/+/refs/heads/master:src/cmd/go/internal/test/flagdefs.go;l=11;drc=aca6577196d61073a74c2ba791aa89c166db9521

• That causes the go test flag parser to enter the “unknown flag” state and assume that the arguments that follow (including the trailing .) are not package paths:
  https://cs.opensource.google/go/go/+/refs/heads/master:src/cmd/go/internal/test/testflag.go;l=294-323;drc=c6b5dce0d1ef35c1c35ab14f3e32ad55d7f83818

• The lack of a package argument causes the test to run in “local directory mode”, which bypasses output buffering:
  https://cs.opensource.google/go/go/+/refs/heads/master:src/cmd/go/internal/test/test.go;l=1263-1268;drc=a3093eca64f9efc830c153c835291d751ea167f9

• The lack of buffering causes go test to be uncertain about whether the test actually generated any output, so it logs the exit status just to be sure.

[bcmills]

That said: I think it would be reasonable to explicitly include the exit status in the JSON output when known.
(That information could be added by the (*cmd/internal/test2json.Converter.Exited method.)

However, it should not be logged as an "Output" event, since it is not output logged by the test itself.

[goto1134]

Thank you for clarifying that!

However, it should not be logged as an "Output" event, since it is not output logged by the test itself.

Does this mean that for the exit status we will need a new action type? Or maybe adding another field to the fail action makes sense to clarify the reason?

It might be helpful to panic in case of an exit code to highlight the termination stack trace. What do you think about that?

[bcmills]

Does this mean that for the exit status we will need a new action type? Or maybe adding another field to the fail action makes sense to clarify the reason?

Either of those seems reasonable to me.

It might be helpful to panic in case of an exit code to highlight the termination stack trace. What do you think about that?

Unfortunately that would be a backward-incompatible change: some existing tests already use -test.run and environment variables to execute themselves as subprocesses, and those subprocesses may have interesting Exit behavior.

It might be feasible for the specific case when -test.paniconexit0 is set, though. 🤔

[goto1134]

It might be feasible for the specific case when -test.paniconexit0 is set, though. 🤔

Indeed. For example, in GoLand, the flag -test.paniconexit0 is provided to the tests to help users to navigate to the sources easily: https://youtrack.jetbrains.com/issue/GO-10324. The same approach should work for non-zero exit codes.

[goto1134]

You are passing the flag -test.paniconexit0 explicitly, but that flag is for internal use and not intentionally supported by go test:
https://cs.opensource.google/go/go/+/refs/heads/master:src/cmd/go/internal/test/flagdefs.go;l=11;drc=aca6577196d61073a74c2ba791aa89c166db9521

By the way, is the flag -test.paniconexit0 enabled by default for go test? I tried to run the following code with default arguments and got the panic about the zero code:

func Test(t *testing.T) {
	println(1)
	os.Exit(0)
}

$ go test .
1
--- FAIL: Test (0.00s)
panic: unexpected call to os.Exit(0) during test [recovered]
        panic: unexpected call to os.Exit(0) during test

goroutine 6 [running]:
testing.tRunner.func1.2({0x100d715c0, 0x100d93f88})
        /opt/homebrew/opt/go/libexec/src/testing/testing.go:1526 +0x1c8
testing.tRunner.func1()
        /opt/homebrew/opt/go/libexec/src/testing/testing.go:1529 +0x384
panic({0x100d715c0, 0x100d93f88})
        /opt/homebrew/opt/go/libexec/src/runtime/panic.go:884 +0x204
os.Exit(0x0)
        /opt/homebrew/opt/go/libexec/src/os/proc.go:67 +0x58
awesomeProject3.Test(0x0?)
        /Users/Andrei.Efanov/Projects/chore/awesomeProject3/sample_test.go:10 +0x34
testing.tRunner(0x14000003a00, 0x100d939d8)
        /opt/homebrew/opt/go/libexec/src/testing/testing.go:1576 +0x10c
created by testing.(*T).Run
        /opt/homebrew/opt/go/libexec/src/testing/testing.go:1629 +0x368
FAIL    awesomeProject3 0.139s
FAIL

[bcmills]

Yes; see #29062.

[goto1134]

I believe, since we agreed on panicing in case -test.paniconexit0 flag is provided, I don't need an exit code as a json field. Please, review the provided PR.

[gopherbot]

Change https://go.dev/cl/517355 mentions this issue: testing: add panic on any os.Exit call, not only zero code

[rsc]

Given the linked CL 517355, should this proposal be retitled?

[goto1134]

Given the linked CL 517355, should this proposal be retitled?

Sure! Thank you for outlining that.

[rsc]

This proposal has been added to the active column of the proposals project
and will now be reviewed at the weekly proposal review meetings.
— rsc for the proposal review group

[rsc]

There are a bunch of tests that do things like implement a -updategolden flag that takes over and may exit non-zero at that point (if it fails). We should figure out how many tests would start breaking if we panic on non-zero exit status. I have definitely run into this myself and had to work around it.

[goto1134]

Can I contribute to this investigation anyhow?

[rsc]

Thinking more about this, any code that can call log.Fatal but might be run during a test would now cause a test panic on top of the log.Fatal. This doesn't seem right to me.

The panic on exit(0) is important because exit(0) stops the test and makes it look like it passed. Any given test has no idea whether there are more test functions to run, so exit(0) making the test look like it passed is definitely wrong.

A non-zero exit (call it exit(1)) will not make a test look like it passed, so the same concerns do not apply.

We retitled this issue because a CL was written focusing on exit(1) but the original complaint was about exit status not appearing in the test2json output. Maybe we should fix that instead. Maybe if test2json does not see the usual PASS/FAIL at the end, it should write its own {"Action": "fail", "Output: test output ended unexpectedly"} or something like that.

[rsc]

Are there any objections to shifting this proposal over to showing the test exit status in the test2json output?

[goto1134]

@rsc , test2json seems like a good place for this functionality — no objections.

[bcmills]

any code that can call log.Fatal but might be run during a test would now cause a test panic on top of the log.Fatal. This doesn't seem right to me.

Hmm. I had a couple of recent encounters with tests that ended up invoking log.Fatal, and they were a huge pain to debug because I couldn't easily even figure out which test was running during the log.Fatal call. A panic with a stack trace honestly would have been really helpful. 😅

[rsc]

Going back to the top comment, both the 'go test' and 'go tool test2json' versions print a final Action:fail, though they differ about the package.

Deleting the timestamps, go test prints:

{"Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"=== RUN   Test/1/1.1\n"}
{"Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"exit status 2\n"}
{"Action":"output","Package":"awesomeProject3","Output":"FAIL\tawesomeProject3\t0.164s\n"}
{"Action":"fail","Package":"awesomeProject3","Elapsed":0.164}

and go tool test2json prints:

{"Action":"output","Test":"Test/1/1.1","Output":"=== RUN   Test/1/1.1\n"}
{"Action":"fail","Test":"Test/1/1.1","Elapsed":0.314}

The "FAIL" print is coming from cmd/go, so it makes sense that test2json would not print it (it's not there to be printed). But we can make test2json synthesize a "exit status 2"-style print.

[rsc]

Have all remaining concerns about this proposal been addressed?

When using go tool test2json cmd..., if cmd exits with a non-zero status, then an additional output line would be synthesized:

{"Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"exit status 2\n"}

This would match the output printed by go test -json when the test exits with a non-zero status.

[rsc]

Based on the discussion above, this proposal seems like a likely accept.
— rsc for the proposal review group

When using go tool test2json cmd..., if cmd exits with a non-zero status, then an additional output line would be synthesized:

{"Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"exit status 2\n"}

This would match the output printed by go test -json when the test exits with a non-zero status.

[rsc]

No change in consensus, so accepted. 🎉
This issue now tracks the work of implementing the proposal.
— rsc for the proposal review group

When using go tool test2json cmd..., if cmd exits with a non-zero status, then an additional output line would be synthesized:

{"Action":"output","Package":"awesomeProject3","Test":"Test/1/1.1","Output":"exit status 2\n"}

This would match the output printed by go test -json when the test exits with a non-zero status.