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/test2json: test2json doesn't print the final "pass" action if fuzz test is interrupted #53563

Closed
h31 opened this issue Jun 27, 2022 · 8 comments
Labels
FrozenDueToAge help wanted NeedsFix The path to resolution is known, but the work has not been done.
Milestone

Comments

@h31
Copy link

h31 commented Jun 27, 2022

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}
  1. 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
  1. 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

@h31 h31 changed the title cmd/go: test2json doesn't print the final "pass" action if interrupted in case of fuzz test cmd/go: test2json doesn't print the final "pass" action if fuzz test is interrupted Jun 27, 2022
@bcmills bcmills changed the title cmd/go: test2json doesn't print the final "pass" action if fuzz test is interrupted cmd/test2json: test2json doesn't print the final "pass" action if fuzz test is interrupted Jun 28, 2022
@bcmills
Copy link
Contributor

bcmills commented Jun 28, 2022

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

@bcmills bcmills added help wanted NeedsFix The path to resolution is known, but the work has not been done. labels Jun 28, 2022
@bcmills bcmills added this to the Backlog milestone Jun 28, 2022
@h31
Copy link
Author

h31 commented Jun 29, 2022

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

bcmills commented Jun 29, 2022

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

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

@h31
Copy link
Author

h31 commented Jul 6, 2022

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

@gopherbot
Copy link

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

gopherbot pushed a commit that referenced this issue Aug 26, 2022
Updates #53563

Change-Id: I35a3fd56718e198f68cbf73075a78b2fbc66bd7d
Reviewed-on: https://go-review.googlesource.com/c/go/+/419295
TryBot-Result: Gopher Robot <gobot@golang.org>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
Auto-Submit: Bryan Mills <bcmills@google.com>
Run-TryBot: Bryan Mills <bcmills@google.com>
Reviewed-by: Bryan Mills <bcmills@google.com>
Reviewed-by: Ryan Schuster <shuey19831@gmail.com>
Reviewed-by: David Chase <drchase@google.com>
@rsc
Copy link
Contributor

rsc commented Oct 14, 2022

It looks like this has been fixed.

@rsc rsc closed this as completed Oct 14, 2022
@gopherbot
Copy link

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

@bcmills bcmills modified the milestones: Backlog, Go1.20 Dec 7, 2022
gopherbot pushed a commit that referenced this issue Dec 8, 2022
- Start handling signals in 'go test' just before starting the test
  subprocess instead of just after. (It is unlikely that starting the
  process will cause cmd/go to hang in a way that requires signals to
  debug, and it is possible that something the test does — such as
  sending os.Interrupt to its parent processes — will immediately
  send a signal that needs to be handled.)

- In the test-test, don't try to re-parse the parent PIDs after
  sending signals, and sleep for a much shorter time interval.
  (Overrunning the sleep caused the next call to strconv.Atoi — which
  shouldn't even happen! — to fail with a parse error, leading to the
  failure mode observed in
  https://build.golang.org/log/f0982dcfc6a362f9c737eec3e7072dcc7ef29e32.)

Fixes #56083.
Updates #53563.

Change-Id: I346a95bdda5619632659ea854f98a9e17a6aede7
Reviewed-on: https://go-review.googlesource.com/c/go/+/456115
TryBot-Result: Gopher Robot <gobot@golang.org>
Auto-Submit: Bryan Mills <bcmills@google.com>
Reviewed-by: Ian Lance Taylor <iant@google.com>
Run-TryBot: Bryan Mills <bcmills@google.com>
@golang golang locked and limited conversation to collaborators Dec 7, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
FrozenDueToAge help wanted NeedsFix The path to resolution is known, but the work has not been done.
Projects
None yet
Development

No branches or pull requests

5 participants