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

cmd/go: shutdown crash output is unreadable #46631

Open
klauspost opened this issue Jun 7, 2021 · 5 comments
Open

cmd/go: shutdown crash output is unreadable #46631

klauspost opened this issue Jun 7, 2021 · 5 comments

Comments

@klauspost
Copy link
Contributor

@klauspost klauspost commented Jun 7, 2021

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

λ gotip version
go version devel go1.17-5542c10fbf Fri Jun 4 03:07:33 2021 +0000 windows/amd64

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

go env Output
λ gotip env
set GO111MODULE=
set GOARCH=amd64
set GOBIN=
set GOCACHE=d:\temp\gocache
set GOENV=C:\Users\klaus\AppData\Roaming\go\env
set GOEXE=.exe
set GOFLAGS=
set GOHOSTARCH=amd64
set GOHOSTOS=windows
set GOINSECURE=
set GOMODCACHE=e:\gopath\pkg\mod
set GONOPROXY=
set GONOSUMDB=
set GOOS=windows
set GOPATH=e:\gopath
set GOPRIVATE=
set GOPROXY=https://goproxy.io
set GOROOT=C:\Users\klaus\sdk\gotip
set GOSUMDB=sum.golang.org
set GOTMPDIR=
set GOTOOLDIR=C:\Users\klaus\sdk\gotip\pkg\tool\windows_amd64
set GOVCS=
set GOVERSION=devel go1.17-5542c10fbf Fri Jun 4 03:07:33 2021 +0000
set GCCGO=gccgo
set AR=ar
set CC=gcc
set CXX=g++
set CGO_ENABLED=1
set GOMOD=NUL
set CGO_CFLAGS=-g -O2
set CGO_CPPFLAGS=
set CGO_CXXFLAGS=-g -O2
set CGO_FFLAGS=-g -O2
set CGO_LDFLAGS=-g -O2
set PKG_CONFIG=pkg-config
set GOGCCFLAGS=-m64 -mthreads -fmessage-length=0 -fdebug-prefix-map=d:\temp\wintemp\go-build102784969=/tmp/go-build -gno-record-gcc-switches

What did you do?

Simple fuzz test:

func FuzzCrash(f *testing.F) {
	f.Cleanup(func() {
		panic("error")
	})
	f.Fuzz(func(t *testing.T, data []byte) {
		time.Sleep(time.Second)
	})
}

Run gotip test -fuzz=FuzzCrash -test.run=None -parallel=16. Press ctrl+c which caused a crash.

What did you expect to see?

Readable output.

What did you see instead?

Copy of output: https://gist.github.com/klauspost/a03eaeda5aa172c0a5990f91c6e7b4a9

(Also we obviously didn't call "f.Fail", the CleanUp function probably did).

@katiehockman katiehockman changed the title [dev.fuzz] Shutdown crash output is unreadable. [dev.fuzz] cmd/go: shutdown crash output is unreadable. Jun 7, 2021
@katiehockman katiehockman added this to the Unreleased milestone Jun 7, 2021
@katiehockman
Copy link
Member

@katiehockman katiehockman commented Jun 7, 2021

@katiehockman katiehockman changed the title [dev.fuzz] cmd/go: shutdown crash output is unreadable. [dev.fuzz] cmd/go: shutdown crash output is unreadable Jun 29, 2021
@katiehockman
Copy link
Member

@katiehockman katiehockman commented Jun 29, 2021

I just repro'd this locally and can confirm that something is going wrong here. Will look into it further.

@katiehockman
Copy link
Member

@katiehockman katiehockman commented Jun 29, 2021

It looks like every worker is calling the Cleanup method, and panicking in a way that isn't being caught/logged properly. That very large block of text appears to be a set of stack traces that came from each worker panicking during Cleanup (in your example, you had 16 workers, so that's going to be a lot of output). All of the workers are trying to write to stdout at the same time, to report that there was an issue while running Cleanup, which is why everything is so jumbled.

@jayconrod
Copy link
Contributor

@jayconrod jayconrod commented Jul 6, 2021

I looked into this a bit today. Can confirm, the output is garbled because the worker processes share stdout and stderr. I set it up that way initially to help with debugging, but we should fix it and do it right.

testing uses stdout for test control messages (--- PASS and so on with -v) and logging (via TB.Log). The coordinator process should probably capture stdout, then only forward log lines onto its own stdout.

testing doesn't usually write to stderr (except when parsing its own flags), so anything written there should come from the fuzz target or an unrecovered panic (which is the case here). The coordinator should capture stderr from each worker, then print that or return an error when a worker terminates unexpectedly.

If all the workers panic, the output is going to be overwhelming, even if the coordinator prints each worker's output separately. We may just want to just print output from the first failing worker.

@katiehockman
Copy link
Member

@katiehockman katiehockman commented Jul 14, 2021

This is likely going to be a release blocker for Go 1.18

@katiehockman katiehockman removed this from the Unreleased milestone Sep 14, 2021
@katiehockman katiehockman added this to the Go1.18 milestone Sep 14, 2021
@rsc rsc changed the title [dev.fuzz] cmd/go: shutdown crash output is unreadable cmd/go: shutdown crash output is unreadable Sep 21, 2021
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
4 participants