internal/fuzz: log that minimization is occurring
Previously, when fuzzing for a period of time, the
command line output would look something like this:
fuzz: minimizing 34995-byte crash input...
fuzz: elapsed: 3s, execs: 13821 (4604/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 6s, execs: 13821 (2303/sec), new interesting: 0 (total: 1)
fuzz: elapsed: 9s, execs: 13821 (1535/sec), new interesting: 0 (total: 1)
--- FAIL: FuzzFoo (9.05s)
This is the same output it has while fuzzing, so if
minimization runs for a long time (default allows 1
minute), then it looks like minimization is hanging.
It's also confusing that the execs/sec would continually
decrease.
Now, when minimization is running, the command line
output will look something like this:
fuzz: minimizing 34995-byte crash input...
fuzz: elapsed: 3s, minimizing
fuzz: elapsed: 6s, minimizing
fuzz: elapsed: 9s, minimizing
fuzz: elapsed: 9s, minimizing
--- FAIL: FuzzFoo (9.05s)
The final "fuzz: elapsed: 6s, minimizing" could be
printed twice because we always print one final log
to the command line before we exit.
Updates #48820
Change-Id: Ie5b9fde48b8d4e36e13a81ae50a6d69bf4d0dbe3
Reviewed-on: https://go-review.googlesource.com/c/go/+/354371
Trust: Katie Hockman <katie@golang.org>
Run-TryBot: Katie Hockman <katie@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>
diff --git a/src/cmd/go/testdata/script/test_fuzz_minimize.txt b/src/cmd/go/testdata/script/test_fuzz_minimize.txt
index 3ef54aed..727399f 100644
--- a/src/cmd/go/testdata/script/test_fuzz_minimize.txt
+++ b/src/cmd/go/testdata/script/test_fuzz_minimize.txt
@@ -74,6 +74,12 @@
# Test that re-running the unminimized value causes a crash.
! go test -run=FuzzMinimizerRecoverable minimizer_test.go
+! go test -fuzz=FuzzMinimizerTooSlow -run=FuzzMinimizerTooSlow -fuzzminimizetime=3s minimizer_test.go
+stdout 'fuzz: minimizing'
+stdout 'fuzz: elapsed: 3s, minimizing'
+stdout 'testdata[/\\]fuzz[/\\]FuzzMinimizerTooSlow[/\\]'
+stdout FAIL
+
# TODO(jayconrod,katiehockman): add a test which verifies that the right bytes
# are written to testdata in the case of an interrupt during minimization.
@@ -87,6 +93,7 @@
import (
"os"
"testing"
+ "time"
)
func FuzzMinimizeZeroDurationSet(f *testing.F) {
@@ -142,6 +149,16 @@
}
})
}
+
+func FuzzMinimizerTooSlow(f *testing.F) {
+ f.Fuzz(func(t *testing.T, b []byte) {
+ if len(b) > 50 {
+ t.Error("error here")
+ time.Sleep(2 * time.Second)
+ }
+ })
+}
+
-- check_testdata.go --
// +build ignore
diff --git a/src/internal/fuzz/fuzz.go b/src/internal/fuzz/fuzz.go
index 2c2a365..f660052 100644
--- a/src/internal/fuzz/fuzz.go
+++ b/src/internal/fuzz/fuzz.go
@@ -136,13 +136,12 @@
// Ensure that any crash we find is written to the corpus, even if an error
// or interruption occurs while minimizing it.
- var crashMinimizing *fuzzResult
crashWritten := false
defer func() {
- if crashMinimizing == nil || crashWritten {
+ if c.crashMinimizing == nil || crashWritten {
return
}
- fileName, werr := writeToCorpus(crashMinimizing.entry.Data, opts.CorpusDir)
+ fileName, werr := writeToCorpus(c.crashMinimizing.entry.Data, opts.CorpusDir)
if werr != nil {
err = fmt.Errorf("%w\n%v", err, werr)
return
@@ -150,7 +149,7 @@
if err == nil {
err = &crashError{
name: filepath.Base(fileName),
- err: errors.New(crashMinimizing.crasherMsg),
+ err: errors.New(c.crashMinimizing.crasherMsg),
}
}
}()
@@ -198,7 +197,7 @@
for {
var inputC chan fuzzInput
input, ok := c.peekInput()
- if ok && crashMinimizing == nil && !stopping {
+ if ok && c.crashMinimizing == nil && !stopping {
inputC = c.inputC
}
@@ -236,7 +235,7 @@
break
}
if c.canMinimize() && result.canMinimize {
- if crashMinimizing != nil {
+ if c.crashMinimizing != nil {
// This crash is not minimized, and another crash is being minimized.
// Ignore this one and wait for the other one to finish.
break
@@ -244,7 +243,7 @@
// Found a crasher but haven't yet attempted to minimize it.
// Send it back to a worker for minimization. Disable inputC so
// other workers don't continue fuzzing.
- crashMinimizing = &result
+ c.crashMinimizing = &result
fmt.Fprintf(c.opts.Log, "fuzz: minimizing %d-byte crash input...\n", len(result.entry.Data))
c.queueForMinimization(result, nil)
} else if !crashWritten {
@@ -308,7 +307,7 @@
// number of new edges that this result expanded.
// TODO(jayconrod, katiehockman): Don't write a value that's already
// in the corpus.
- if c.canMinimize() && result.canMinimize && crashMinimizing == nil {
+ if c.canMinimize() && result.canMinimize && c.crashMinimizing == nil {
// Send back to workers to find a smaller value that preserves
// at least one new coverage bit.
c.queueForMinimization(result, keepCoverage)
@@ -604,6 +603,9 @@
// same thing.
minimizeQueue queue
+ // crashMinimizing is the crash that is currently being minimized.
+ crashMinimizing *fuzzResult
+
// coverageMask aggregates coverage that was found for all inputs in the
// corpus. Each byte represents a single basic execution block. Each set bit
// within the byte indicates that an input has triggered that block at least
@@ -692,6 +694,8 @@
} else {
fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, testing seed corpus: %d/%d completed\n", c.elapsed(), runSoFar, c.warmupInputCount)
}
+ } else if c.crashMinimizing != nil {
+ fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, minimizing\n", c.elapsed())
} else {
rate := float64(c.count-c.countLastLog) / now.Sub(c.timeLastLog).Seconds()
if coverageEnabled {
