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: hard to tell what tests were running when the timeout was hit #23601

Open
mvdan opened this Issue Jan 29, 2018 · 2 comments

Comments

Projects
None yet
2 participants
@mvdan
Member

mvdan commented Jan 29, 2018

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

go version devel +e72e69a3f6 Thu Jan 25 00:12:18 2018 +0000 linux/amd64

Does this issue reproduce with the latest release?

Yes.

What did you do?

Hit a test timeout in a trybot build: https://storage.googleapis.com/go-build-log/b9cbc869/freebsd-amd64-11_1_dbe018c1.log

Then wondered what tests were running when the timeout was hit.

What did you expect to see?

Something fairly obvious, like:

panic: test timed out after 3m0s

tests running when timeout was reached:
TestWebInterface

Or perhaps a --- FAIL TestWebInterface line, even.

What did you see instead?

Besides the panic line, something hidden in the goroutine trace showing the actual test name:

goroutine 360 [semacquire, 2 minutes]:
sync.runtime_Semacquire(0xc4201965f4)
	/tmp/workdir/go/src/runtime/sema.go:56 +0x39
sync.(*WaitGroup).Wait(0xc4201965e8)
	/tmp/workdir/go/src/sync/waitgroup.go:129 +0x72
net/http/httptest.(*Server).Close(0xc4201965b0)
	/tmp/workdir/go/src/net/http/httptest/server.go:221 +0x208
cmd/vendor/github.com/google/pprof/internal/driver.TestWebInterface(0xc4203f22d0)
	/tmp/workdir/go/src/cmd/vendor/github.com/google/pprof/internal/driver/webui_test.go:128 +0xded
testing.tRunner(0xc4203f22d0, 0x985408)
	/tmp/workdir/go/src/testing/testing.go:777 +0xd0
created by testing.(*T).Run
	/tmp/workdir/go/src/testing/testing.go:824 +0x2e0

I realise that knowing what tests were running when the timeout was hit isn't always useful, nor does it mean that those tests were blocked forever or taking longer than expected. For example, if the timeout is 1m and one of many tests takes 59s, it could be that the slow test finishes and another test hits the timeout.

Having said that, from a user's point of view, the current output can be more difficult to understand than it needs to be. For example, in the usual case where a single test is blocking forever and no other tests are running, it's not at all straightforward to tell what test that is.

Using the flag -v might help, but that doesn't help in the case where one has a test failure log without it that is non-trivial to reproduce or re-run.

@ianlancetaylor

This comment has been minimized.

Contributor

ianlancetaylor commented Jan 29, 2018

Dup of #19397? At any rate it seems that any plausible fix for #19397 would fix this also.

@mvdan

This comment has been minimized.

Member

mvdan commented Jan 29, 2018

Seems very much related, thanks. I even gave my thumbs up to that one a while ago, but couldn't find it now.

I'm not sure if it should be closed as a duplicate. Potentially, that issue could be closed as "nothing to do since we can't take over the signals".

@ianlancetaylor ianlancetaylor added this to the Unplanned milestone Mar 28, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment