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

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

Open
dnephin opened this issue Apr 11, 2020 · 8 comments
Open

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

dnephin opened this issue Apr 11, 2020 · 8 comments

Comments

@dnephin
Copy link
Contributor

@dnephin dnephin commented Apr 11, 2020

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.

@andybons
Copy link
Member

@andybons andybons commented Apr 13, 2020

@andybons andybons added this to the Unplanned milestone Apr 13, 2020
@bcmills
Copy link
Member

@bcmills bcmills commented Apr 13, 2020

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

@jayconrod jayconrod commented Apr 13, 2020

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

@dnephin dnephin commented Apr 13, 2020

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

@bcmills bcmills commented Apr 13, 2020

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

@bcmills bcmills commented Apr 13, 2020

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

Aha, that is a bug!

@bcmills
Copy link
Member

@bcmills bcmills commented Apr 13, 2020

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.

dnephin added a commit to dnephin/gotestsum that referenced this issue Apr 20, 2020
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)
dnephin added a commit to dnephin/gotestsum that referenced this issue Apr 20, 2020
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)
dnephin added a commit to dnephin/gotestsum that referenced this issue Apr 20, 2020
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)
dnephin added a commit to hashicorp/consul that referenced this issue May 6, 2020
Replace TestWriter with NewLogBuffer.

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.

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.

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.
dnephin added a commit to hashicorp/consul that referenced this issue May 6, 2020
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
Copy link
Member

@dmitshur dmitshur commented May 13, 2020

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.

dnephin added a commit to hashicorp/consul that referenced this issue May 21, 2020
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.
dnephin added a commit to hashicorp/consul that referenced this issue May 21, 2020
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)
dnephin added a commit to hashicorp/consul that referenced this issue Jun 9, 2020
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)
dnephin added a commit to hashicorp/consul that referenced this issue Jun 9, 2020
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)
dnephin added a commit to hashicorp/consul that referenced this issue Jul 21, 2020
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)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
5 participants
You can’t perform that action at this time.