go/test2json: panic in goroutine results in missing Action=Fail TestEvent #38382

dnephin · 2020-04-11T22:39:45Z

Related to #37555

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

$ go version
go version go1.14.2 linux/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
GOOS=linux
GOARCH=amd64

What did you do?

package mypkg

import (
	"testing"
	"time"
)

func Test_PanicInGoroutine(t *testing.T) {
	go func() { panic("panicing in a goroutine") }()
	time.Sleep(10 * time.Millisecond)
}

$ go test 
panic: panicing in a goroutine

goroutine 7 [running]:
gotest.tools/gotestsum/tmp2.Test_PanicInGoroutine.func1()
	/home/daniel/pers/code/gotestsum/tmp2/main_test.go:9 +0x39
created by gotest.tools/gotestsum/tmp2.Test_PanicInGoroutine
	/home/daniel/pers/code/gotestsum/tmp2/main_test.go:9 +0x35
FAIL	gotest.tools/gotestsum/tmp2	0.003s
FAIL

$ go test -json
{"Time":"2020-04-11T18:36:29.705478289-04:00","Action":"run","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine"}
{"Time":"2020-04-11T18:36:29.705575001-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"=== RUN   Test_PanicInGoroutine\n"}
{"Time":"2020-04-11T18:36:29.707652936-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"panic: panicing in a goroutine\n"}
{"Time":"2020-04-11T18:36:29.707663408-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"\n"}
{"Time":"2020-04-11T18:36:29.707666872-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"goroutine 7 [running]:\n"}
{"Time":"2020-04-11T18:36:29.707669584-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"gotest.tools/gotestsum/tmp2.Test_PanicInGoroutine.func1()\n"}
{"Time":"2020-04-11T18:36:29.707675539-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"\t/home/daniel/pers/code/gotestsum/tmp2/main_test.go:9 +0x39\n"}
{"Time":"2020-04-11T18:36:29.707688443-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"created by gotest.tools/gotestsum/tmp2.Test_PanicInGoroutine\n"}
{"Time":"2020-04-11T18:36:29.707695646-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Output":"\t/home/daniel/pers/code/gotestsum/tmp2/main_test.go:9 +0x35\n"}
{"Time":"2020-04-11T18:36:29.707843506-04:00","Action":"output","Package":"gotest.tools/gotestsum/tmp2","Output":"FAIL\tgotest.tools/gotestsum/tmp2\t0.003s\n"}
{"Time":"2020-04-11T18:36:29.707855313-04:00","Action":"fail","Package":"gotest.tools/gotestsum/tmp2","Elapsed":0.003}

What did you expect to see?

In go1.13 and earlier I received the following TestEvent:

{"Time":"2020-04-11T22:37:41.54673436Z","Action":"fail","Package":"gotest.tools/gotestsum/tmp2","Test":"Test_PanicInGoroutine","Elapsed":0.004}

What did you see instead?

That event was missing. There is an Action=fail for the package, but none for the test.

The text was updated successfully, but these errors were encountered:

andybons · 2020-04-13T05:30:00Z

@bcmills @jayconrod @matloob

bcmills · 2020-04-13T15:09:56Z

The new output seems correct to me. The goroutine that panics may not be related in any way to the test that was running during the panic, so the failure should not be attributed to that specific test.

(Consider, for example: https://play.golang.org/p/C9JJsDkzOhM.)

jayconrod · 2020-04-13T15:14:27Z

+1. Not sure whether this was changed intentionally, but the new behavior seems more correct. A panic in a goroutine other than the one running a test can't always be attributed to a specific test. It could have been started by a parallel test, a previous test, TestMain, or something else.

dnephin · 2020-04-13T16:14:41Z

Shouldn't any test which has an Action=run have a corresponding Action=pass or fail ? That seemed to be the case in previous versions of Go. This test has failed, but there is no Action=fail for the test.

The goroutine that panics may not be related in any way to the test that was running during the panic, so the failure should not be attributed to that specific test.

The panic is already associated with the test. The output TestEvent has the test name on it.

bcmills · 2020-04-13T17:32:40Z

Shouldn't any test which has an Action=run have a corresponding Action=pass or fail ?

No. If the process exits before the test function completes, and nothing in the test so far has invoked (*T).Fail then the test has neither passed nor failed, so it would be inaccurate to report any result for it. (#29062 is related.)

bcmills · 2020-04-13T17:33:13Z

The panic is already associated with the test. The output TestEvent has the test name on it.

Aha, that is a bug!

bcmills · 2020-04-13T17:35:32Z

But maybe that bug is more helpful than it is harmful: the goroutine isn't necessarily associated with the currently-running test, but background-goroutine panics probably do relate to the running test more often than not.

If a test panics it may never send a final ActionFail event. By tracking the running tests we can add any incomplete tests to Failed when the execution ends. This behaviour changed in go1.14. See golang/go#38382 (comment)

Replaces #7559 See golang/go#38458 and golang/go#38382 (comment) Running tests in parallel, with background goroutines, results in test output not being associated with the correct test. `go test` does not make any guarantees about output from goroutines being attributed to the correct test case. The previous solution did not address this problem because test output could still be hidden when it was associated with a test that did not fail. You would have to look at all of the log output to find the relevant lines. It also made debugging test failures more difficult because each log line was very long and contained the test name twice. This commit attempts a new approach. Instead of printing all the logs, only print when a test fails. This should work well when there are a small number of failures, but may not work well when there are many test failures at the same time. In those cases the failures are unlikely a result of a specific test, and the log output is likely less useful. All of the logs are printed from the test goroutine, so they should be associated with the correct test. Also removes some test helpers that were not used, or only had a single caller. Packages which expose many functions with similar names can be difficult to use correctly.

dmitshur · 2020-05-13T21:06:19Z

Based on the conversation above, I believe it's safe to remove WaitingForInfo label by now. If that isn't true, please feel free to add it again and specify what information is needed.

Replaces #7559 Running tests in parallel, with background goroutines, results in test output not being associated with the correct test. `go test` does not make any guarantees about output from goroutines being attributed to the correct test case. The previous solution did not address this problem because test output could still be hidden when it was associated with a test that did not fail. You would have to look at all of the log output to find the relevant lines. It also made debugging test failures more difficult because each log line was very long and contained the test name twice. This commit attempts a new approach. Instead of printing all the logs, only print when a test fails. This should work well when there are a small number of failures, but may not work well when there are many test failures at the same time. In those cases the failures are unlikely a result of a specific test, and the log output is likely less useful. All of the logs are printed from the test goroutine, so they should be associated with the correct test. Also removes some test helpers that were not used, or only had a single caller. Packages which expose many functions with similar names can be difficult to use correctly. Related: golang/go#38458 (may be fixed in go1.15) golang/go#38382 (comment)

Replaces #7559 Running tests in parallel, with background goroutines, results in test output not being associated with the correct test. `go test` does not make any guarantees about output from goroutines being attributed to the correct test case. Attaching log output from background goroutines also cause data races. If the goroutine outlives the test, it will race with the test being marked done. Previously this was noticed as a panic when logging, but with the race detector enabled it is shown as a data race. The previous solution did not address the problem of correct test attribution because test output could still be hidden when it was associated with a test that did not fail. You would have to look at all of the log output to find the relevant lines. It also made debugging test failures more difficult because each log line was very long. This commit attempts a new approach. Instead of printing all the logs, only print when a test fails. This should work well when there are a small number of failures, but may not work well when there are many test failures at the same time. In those cases the failures are unlikely a result of a specific test, and the log output is likely less useful. All of the logs are printed from the test goroutine, so they should be associated with the correct test. Also removes some test helpers that were not used, or only had a single caller. Packages which expose many functions with similar names can be difficult to use correctly. Related: golang/go#38458 (may be fixed in go1.15) golang/go#38382 (comment)

rsc · 2022-10-14T15:48:24Z

I believe this output is correct, per the discussion above. The test function did not explicitly fail. The test died instead. That's a different kind of outcome, and it has a different kind of output.

dnephin · 2022-10-15T17:12:56Z

But a panic generally does result in an explicit fail event. Consider these two examples using go1.19.2:

func Test_PanicInGoroutine(t *testing.T) {
	go func() { panic("panicing in a goroutine") }()
	time.Sleep(10 * time.Millisecond)
}

Output: (no fail event for the test)

{"Time":"2022-10-15T13:02:00.320120402-04:00","Action":"run","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine"}
{"Time":"2022-10-15T13:02:00.320163078-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"=== RUN   Test_PanicInGoroutine\n"}
{"Time":"2022-10-15T13:02:00.322259556-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"panic: panicing in a goroutine\n"}
{"Time":"2022-10-15T13:02:00.322267286-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"\n"}
{"Time":"2022-10-15T13:02:00.322269464-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"goroutine 7 [running]:\n"}
{"Time":"2022-10-15T13:02:00.322271383-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"gotest.tools/v3/tmp.Test_PanicInGoroutine.func1()\n"}
{"Time":"2022-10-15T13:02:00.322273757-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"\t/home/daniel/pers/code/gotest.tools/tmp/main_test.go:9 +0x27\n"}
{"Time":"2022-10-15T13:02:00.322275633-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"created by gotest.tools/v3/tmp.Test_PanicInGoroutine\n"}
{"Time":"2022-10-15T13:02:00.322277138-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInGoroutine","Output":"\t/home/daniel/pers/code/gotest.tools/tmp/main_test.go:9 +0x25\n"}
{"Time":"2022-10-15T13:02:00.322411598-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Output":"FAIL\tgotest.tools/v3/tmp\t0.003s\n"}
{"Time":"2022-10-15T13:02:00.322419607-04:00","Action":"fail","Package":"gotest.tools/v3/tmp","Elapsed":0.003}

compare this to

func Test_PanicInTest(t *testing.T) {
	panic("panicing in a test")
}

Output: (includes a test fail event)

{"Time":"2022-10-15T13:02:50.132424104-04:00","Action":"run","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest"}
{"Time":"2022-10-15T13:02:50.132473025-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"=== RUN   Test_PanicInTest\n"}
{"Time":"2022-10-15T13:02:50.132484758-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"--- FAIL: Test_PanicInTest (0.00s)\n"}
{"Time":"2022-10-15T13:02:50.134605362-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"panic: panicing in a test [recovered]\n"}
{"Time":"2022-10-15T13:02:50.134613159-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\tpanic: panicing in a test\n"}
{"Time":"2022-10-15T13:02:50.134615738-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\n"}
{"Time":"2022-10-15T13:02:50.134617376-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"goroutine 6 [running]:\n"}
{"Time":"2022-10-15T13:02:50.134619005-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"testing.tRunner.func1.2({0x503180, 0x5517b8})\n"}
{"Time":"2022-10-15T13:02:50.134623868-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\t/opt/go1.19/src/testing/testing.go:1396 +0x24e\n"}
{"Time":"2022-10-15T13:02:50.134625589-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"testing.tRunner.func1()\n"}
{"Time":"2022-10-15T13:02:50.134626971-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\t/opt/go1.19/src/testing/testing.go:1399 +0x39f\n"}
{"Time":"2022-10-15T13:02:50.134628421-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"panic({0x503180, 0x5517b8})\n"}
{"Time":"2022-10-15T13:02:50.134629781-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\t/opt/go1.19/src/runtime/panic.go:884 +0x212\n"}
{"Time":"2022-10-15T13:02:50.134631198-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"gotest.tools/v3/tmp.Test_PanicInTest(0x0?)\n"}
{"Time":"2022-10-15T13:02:50.134632618-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\t/home/daniel/pers/code/gotest.tools/tmp/main_test.go:8 +0x27\n"}
{"Time":"2022-10-15T13:02:50.134634435-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"testing.tRunner(0xc000007860, 0x52f338)\n"}
{"Time":"2022-10-15T13:02:50.134635847-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\t/opt/go1.19/src/testing/testing.go:1446 +0x10b\n"}
{"Time":"2022-10-15T13:02:50.134637274-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"created by testing.(*T).Run\n"}
{"Time":"2022-10-15T13:02:50.134713803-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Output":"\t/opt/go1.19/src/testing/testing.go:1493 +0x35f\n"}
{"Time":"2022-10-15T13:02:50.134873903-04:00","Action":"fail","Package":"gotest.tools/v3/tmp","Test":"Test_PanicInTest","Elapsed":0}
{"Time":"2022-10-15T13:02:50.134885688-04:00","Action":"output","Package":"gotest.tools/v3/tmp","Output":"FAIL\tgotest.tools/v3/tmp\t0.003s\n"}
{"Time":"2022-10-15T13:02:50.134890572-04:00","Action":"fail","Package":"gotest.tools/v3/tmp","Elapsed":0.003}

In both cases the test did not explicitly fail, but in one case we get the correct events, and the other we do not.

How are tools that use the test2json output supposed to deal with this? Are they expected to have to parse the full output to figure out that the test panicked? Isn't the purpose of the Action field in events to communicate the result of a test? A lack of any pass or fail for a test case seems ambiguous.

@rsc could I ask you to reconsider this?

This was referenced Apr 11, 2020

cmd/go: tests that panic or exit are marked as passing when -json flag is used #37555

Closed

go1.14: test2json does not always send a 'test failed' event when test panics gotestyourself/gotestsum#99

Closed

andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 13, 2020

andybons added this to the Unplanned milestone Apr 13, 2020

bcmills added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 13, 2020

dnephin mentioned this issue Apr 20, 2020

Print incomplete tests as failures in the summary gotestyourself/gotestsum#104

Merged

dmitshur removed the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label May 13, 2020

dnephin mentioned this issue May 21, 2020

testutil: NewLogBuffer - buffer logs until a test fails hashicorp/consul#7948

Merged

This was referenced Aug 9, 2020

Passing tests reported as failures in summary gotestyourself/gotestsum#141

Closed

cmd/test2json: tests that panic are marked as passing #40132

Closed

bcmills mentioned this issue Apr 12, 2021

cmd/go: go test hides the exit status of the test binary #45508

Open

rsc closed this as completed Oct 14, 2022

ddelnano mentioned this issue Dec 7, 2022

Upstream gotestsum changes used by acc test suite vatesfr/terraform-provider-xenorchestra#218

Closed

golang locked and limited conversation to collaborators Oct 15, 2023

gopherbot added the FrozenDueToAge label Oct 15, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

go/test2json: panic in goroutine results in missing Action=Fail TestEvent #38382

go/test2json: panic in goroutine results in missing Action=Fail TestEvent #38382

dnephin commented Apr 11, 2020

andybons commented Apr 13, 2020

bcmills commented Apr 13, 2020

jayconrod commented Apr 13, 2020

dnephin commented Apr 13, 2020 •

edited

bcmills commented Apr 13, 2020

bcmills commented Apr 13, 2020

bcmills commented Apr 13, 2020

dmitshur commented May 13, 2020

rsc commented Oct 14, 2022

dnephin commented Oct 15, 2022

go/test2json: panic in goroutine results in missing Action=Fail TestEvent #38382

go/test2json: panic in goroutine results in missing Action=Fail TestEvent #38382

Comments

dnephin commented Apr 11, 2020

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

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

andybons commented Apr 13, 2020

bcmills commented Apr 13, 2020

jayconrod commented Apr 13, 2020

dnephin commented Apr 13, 2020 • edited

bcmills commented Apr 13, 2020

bcmills commented Apr 13, 2020

bcmills commented Apr 13, 2020

dmitshur commented May 13, 2020

rsc commented Oct 14, 2022

dnephin commented Oct 15, 2022

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

What operating system and processor architecture are you using (`go env`)?

dnephin commented Apr 13, 2020 •

edited