Skip to content
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

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

Open
goto1134 opened this issue Aug 8, 2023 · 22 comments · May be fixed by #61864
Open

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

goto1134 opened this issue Aug 8, 2023 · 22 comments · May be fixed by #61864

Comments

@goto1134
Copy link

goto1134 commented Aug 8, 2023

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.
@gopherbot gopherbot added this to the Proposal milestone Aug 8, 2023
@bcmills
Copy link
Contributor

bcmills commented Aug 8, 2023

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.

@bcmills
Copy link
Contributor

bcmills commented Aug 8, 2023

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
Copy link
Author

goto1134 commented Aug 8, 2023

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
Copy link
Contributor

bcmills commented Aug 8, 2023

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
Copy link
Author

goto1134 commented Aug 8, 2023

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
Copy link
Author

goto1134 commented Aug 8, 2023

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

@goto1134 goto1134 changed the title proposal: cmd/internal/test2json: show non-zero exit code messages or even panic on them proposal: cmd/test2json: show non-zero exit code messages or even panic on them Aug 8, 2023
@bcmills
Copy link
Contributor

bcmills commented Aug 8, 2023

Yes; see #29062.

@goto1134
Copy link
Author

goto1134 commented Aug 8, 2023

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.

goto1134 added a commit to goto1134/go that referenced this issue Aug 8, 2023
@gopherbot
Copy link

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

goto1134 added a commit to goto1134/go that referenced this issue Aug 8, 2023
@rsc
Copy link
Contributor

rsc commented Aug 9, 2023

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

@goto1134 goto1134 changed the title proposal: cmd/test2json: show non-zero exit code messages or even panic on them proposal: testic: panic on non-zero exit codes Aug 9, 2023
@goto1134 goto1134 changed the title proposal: testic: panic on non-zero exit codes proposal: testing: panic on non-zero exit codes Aug 9, 2023
@goto1134
Copy link
Author

goto1134 commented Aug 9, 2023

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

Sure! Thank you for outlining that.

@rsc
Copy link
Contributor

rsc commented Aug 9, 2023

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
Copy link
Contributor

rsc commented Sep 6, 2023

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
Copy link
Author

goto1134 commented Sep 6, 2023

Can I contribute to this investigation anyhow?

@rsc
Copy link
Contributor

rsc commented Sep 20, 2023

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
Copy link
Contributor

rsc commented Oct 11, 2023

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

@goto1134
Copy link
Author

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

@bcmills
Copy link
Contributor

bcmills commented Oct 11, 2023

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 rsc changed the title proposal: testing: panic on non-zero exit codes proposal: testing: report non-zero exit status in test2json output Oct 24, 2023
@rsc rsc changed the title proposal: testing: report non-zero exit status in test2json output proposal: testing: report non-zero exit status in -json output Oct 24, 2023
@rsc
Copy link
Contributor

rsc commented Oct 26, 2023

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
Copy link
Contributor

rsc commented Nov 2, 2023

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
Copy link
Contributor

rsc commented Nov 10, 2023

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
Copy link
Contributor

rsc commented Nov 16, 2023

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.

@rsc rsc changed the title proposal: testing: report non-zero exit status in -json output testing: report non-zero exit status in -json output Nov 16, 2023
@rsc rsc modified the milestones: Proposal, Backlog Nov 16, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Status: Accepted
Development

Successfully merging a pull request may close this issue.

4 participants