internal/fuzz: log that minimization is occurring

katiehockman · katiehockman · commit ef2ebbebf976 · 2021-10-07T20:37:43.000Z
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 golang#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
@@ -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
@@ -136,21 +136,20 @@ 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
 		}
 		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,15 +235,15 @@ 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
 					}
 					// 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 {
