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 3ef54aed93ab3793f149589cd7952ae59c8d07d0..727399f4bbf9d6aa6671152ac53c41f902ea4868 100644 (file)
--- a/src/cmd/go/testdata/script/test_fuzz_minimize.txt
+++ b/src/cmd/go/testdata/script/test_fuzz_minimize.txt
@@ -74,6 +74,12 @@ stdout FAIL
 # 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 @@ package fuzz_test
 import (
        "os"
        "testing"
+       "time"
 )
 
 func FuzzMinimizeZeroDurationSet(f *testing.F) {
@@ -142,6 +149,16 @@ func FuzzMinimizerNonrecoverable(f *testing.F) {
                }
        })
 }
+
+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 2c2a365f4c3908406542146051c786e7ed595862..f6600529114225dd775581cdbe4cf92905a10958 100644 (file)
--- a/src/internal/fuzz/fuzz.go
+++ b/src/internal/fuzz/fuzz.go
@@ -136,13 +136,12 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
 
        // 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 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                if err == nil {
                        err = &crashError{
                                name: filepath.Base(fileName),
-                               err:  errors.New(crashMinimizing.crasherMsg),
+                               err:  errors.New(c.crashMinimizing.crasherMsg),
                        }
                }
        }()
@@ -198,7 +197,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
        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 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        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 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        // 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 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        // 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 @@ type coordinator struct {
        // 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 @@ func (c *coordinator) logStats() {
                } 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 {