cmd/test2json: test2json doesn't print the final "pass" action if fuzz test is interrupted

[h31]

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

$ go version
go version go1.19beta1 darwin/amd64
(also reproduces on 1.18.3)

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
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/artyom/Library/Caches/go-build"
GOENV="/Users/artyom/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/artyom/GoTestProjects/gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/artyom/GoTestProjects/gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/artyom/go/go1.19beta1"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/artyom/go/go1.19beta1/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.19beta1"
GCCGO="gccgo"
GOAMD64="v1"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/artyom/GoTestProjects/FuzzingExample/go.mod"
GOWORK=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch x86_64 -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/pr/5k6c2yx97cjb9t5fh0httxv80000gn/T/go-build3359030399=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

Having a simple fuzz test that checks nothing:

func FuzzReverse(f *testing.F) {
	f.Fuzz(func(t *testing.T, orig string) {
	})
}

1. Running using go test -json works as expected, "pass" action is at the end of the output:
   $ go test -json ./... -fuzz '^\QFuzzReverse\E$' -run '^$'

Output

{"Time":"2022-06-27T11:52:38.319666+02:00","Action":"output","Package":"FuzzingExample","Output":"=== FUZZ  FuzzReverse\n"}
{"Time":"2022-06-27T11:52:38.322383+02:00","Action":"output","Package":"FuzzingExample","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 0/7 completed\n"}
{"Time":"2022-06-27T11:52:38.352022+02:00","Action":"output","Package":"FuzzingExample","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 7/7 completed, now fuzzing with 16 workers\n"}
{"Time":"2022-06-27T11:52:41.322438+02:00","Action":"output","Package":"FuzzingExample","Output":"fuzz: elapsed: 3s, execs: 435869 (145286/sec), new interesting: 0 (total: 7)\n"}
{"Time":"2022-06-27T11:52:44.323377+02:00","Action":"output","Package":"FuzzingExample","Output":"fuzz: elapsed: 6s, execs: 869883 (144628/sec), new interesting: 0 (total: 7)\n"}
^C{"Time":"2022-06-27T11:52:45.174137+02:00","Action":"output","Package":"FuzzingExample","Output":"fuzz: elapsed: 7s, execs: 974379 (122828/sec), new interesting: 0 (total: 7)\n"}
{"Time":"2022-06-27T11:52:45.174221+02:00","Action":"output","Package":"FuzzingExample","Test":"FuzzReverse","Output":"--- PASS: FuzzReverse (6.85s)\n"}
{"Time":"2022-06-27T11:52:45.174236+02:00","Action":"pass","Package":"FuzzingExample","Test":"FuzzReverse","Elapsed":6.85}
{"Time":"2022-06-27T11:52:45.174252+02:00","Action":"output","Package":"FuzzingExample","Output":"PASS\n"}
{"Time":"2022-06-27T11:52:45.185718+02:00","Action":"output","Package":"FuzzingExample","Output":"ok  \tFuzzingExample\t6.987s\n"}
{"Time":"2022-06-27T11:52:45.185759+02:00","Action":"pass","Package":"FuzzingExample","Elapsed":6.987}

2. Running using a built binary without JSON output works as expected (PASS line is at the end of the output):
   $ go test -c -o /path/to/binary -gcflags -d=libfuzzer FuzzingExample
$ /path/to/binary -test.v -test.paniconexit0 -test.fuzz '^\QFuzzReverse\E$' -test.fuzzcachedir ... -test.run '^$'

Output

=== FUZZ  FuzzReverse
fuzz: elapsed: 0s, gathering baseline coverage: 0/1 completed
fuzz: elapsed: 0s, gathering baseline coverage: 1/1 completed, now fuzzing with 16 workers
fuzz: elapsed: 3s, execs: 1711613 (570540/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 6s, execs: 3623372 (637232/sec), new interesting: 0 (total: 1)
^Cfuzz: elapsed: 7s, execs: 3876385 (498863/sec), new interesting: 0 (total: 1)
--- PASS: FuzzReverse (6.51s)
PASS

3. Running using a built binary with JSON output does not work as expected (no "pass" action is at the end of the output):
   $ go tool test2json -t /path/to/binary -test.v -test.paniconexit0 -test.fuzz '^\QFuzzReverse\E$' -test.fuzzcachedir ... -test.run '^$'

Output

{"Time":"2022-06-27T12:03:48.207279+02:00","Action":"output","Output":"=== FUZZ  FuzzReverse\n"}
{"Time":"2022-06-27T12:03:48.209107+02:00","Action":"output","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 0/1 completed\n"}
{"Time":"2022-06-27T12:03:48.217796+02:00","Action":"output","Output":"fuzz: elapsed: 0s, gathering baseline coverage: 1/1 completed, now fuzzing with 16 workers\n"}
{"Time":"2022-06-27T12:03:51.209555+02:00","Action":"output","Output":"fuzz: elapsed: 3s, execs: 1805658 (601817/sec), new interesting: 0 (total: 1)\n"}
^Cgo tool test2json: signal: interrupt

What did you expect to see?

"pass" action at the end of the output

What did you see instead?

An interruption message

[bcmills]

How are you interrupting the test?

Probably the interrupt signal from your console is being sent to the test2json process instead of (or in addition to) the actual test process, causing test2json itself to terminate before it processes the test output.

go test does not exhibit this behavior because cmd/go explicitly ignores os.Interrupt:
https://cs.opensource.google/go/go/+/master:src/cmd/go/internal/base/signal_unix.go;l=14;drc=3af5280c003038e5fea1a84e7e57e85e96e131a3

[h31]

@bcmills Hello!
I'm using Ctrl-C shortcut to interrupt the launched command. Are there any ways to interrupt the actual test process without fetching the process hierarchy and searching for the necessary child process? Probably test2json should behave the same as go test in terms of signal handling.

[bcmills]

Probably test2json should behave the same as go test in terms of signal handling.

I agree. Want to send a fix for Go 1.20? I'd be happy to review.
(https://go.dev/doc/contribute)

[sidntrivedi012]

Hey @h31 👋 , in case you are short of bandwidth to work on this, I can take this up 🙌 . Thanks!

[h31]

Hello @sidntrivedi012! Thank you, sounds great, I would appreciate your help

[gopherbot]

Change https://go.dev/cl/419295 mentions this issue: cmd/test2json: add signal handler

[rsc]

It looks like this has been fixed.

[gopherbot]

Change https://go.dev/cl/456115 mentions this issue: cmd/go: deflake TestScript/test2json_interrupt