]> Cypherpunks repositories - gostls13.git/commitdiff
[dev.fuzz] internal/fuzz: more fuzzing output adjustments
authorKatie Hockman <katie@golang.org>
Tue, 21 Sep 2021 19:51:45 +0000 (15:51 -0400)
committerKatie Hockman <katie@golang.org>
Wed, 22 Sep 2021 14:28:57 +0000 (14:28 +0000)
This change also makes it so that non-recoverable errors (which should
be pretty rare) will no longer be minimized as these failures can be
flakier and harder to minimize successfully.

Updates golang/go#48132

Change-Id: I991d837993ea1fb0304b3ec491cc725ef5265652
Reviewed-on: https://go-review.googlesource.com/c/go/+/351273
Trust: Katie Hockman <katie@golang.org>
Run-TryBot: Katie Hockman <katie@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>
src/cmd/go/testdata/script/test_fuzz_minimize.txt
src/internal/fuzz/fuzz.go
src/internal/fuzz/worker.go

index f0adb9ec3e58b3690eb4be045775175a8f8d1a39..3ef54aed93ab3793f149589cd7952ae59c8d07d0 100644 (file)
@@ -48,10 +48,10 @@ go run check_testdata.go FuzzMinimizerRecoverable 50
 ! go test -run=FuzzMinimizerRecoverable minimizer_test.go
 rm testdata
 
-# Test that minimization is working for non-recoverable errors.
+# Test that minimization doesn't run for non-recoverable errors.
 ! go test -fuzz=FuzzMinimizerNonrecoverable -run=FuzzMinimizerNonrecoverable -fuzztime=10000x minimizer_test.go
 ! stdout '^ok'
-stdout 'minimizing'
+stdout 'minimizing'
 stdout 'fuzzing process terminated unexpectedly: exit status 99'
 stdout FAIL
 
index 2cd7ebb47285870e026ca61f76dd521484673a36..a38036b9d2576def0ad62b10f6ab029ef9c4da2a 100644 (file)
@@ -228,9 +228,6 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                break
                        }
                        c.updateStats(result)
-                       if c.opts.Limit > 0 && c.count >= c.opts.Limit {
-                               stop(nil)
-                       }
 
                        if result.crasherMsg != "" {
                                if c.warmupRun() && result.entry.IsSeed {
@@ -238,7 +235,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        stop(errors.New(result.crasherMsg))
                                        break
                                }
-                               if c.canMinimize() && !result.minimizeAttempted {
+                               if c.canMinimize() && result.canMinimize {
                                        if crashMinimizing != nil {
                                                // This crash is not minimized, and another crash is being minimized.
                                                // Ignore this one and wait for the other one to finish.
@@ -248,7 +245,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                        // Send it back to a worker for minimization. Disable inputC so
                                        // other workers don't continue fuzzing.
                                        crashMinimizing = &result
-                                       fmt.Fprintf(c.opts.Log, "fuzz: found a %d-byte crash input; minimizing...\n", len(result.entry.Data))
+                                       fmt.Fprintf(c.opts.Log, "fuzz: minimizing %d-byte crash input...\n", len(result.entry.Data))
                                        c.queueForMinimization(result, nil)
                                } else if !crashWritten {
                                        // Found a crasher that's either minimized or not minimizable.
@@ -261,7 +258,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                        err:  errors.New(result.crasherMsg),
                                                }
                                        }
-                                       if printDebugInfo() {
+                                       if shouldPrintDebugInfo() {
                                                fmt.Fprintf(
                                                        c.opts.Log,
                                                        "DEBUG new crasher, elapsed: %s, id: %s, parent: %s, gen: %d, size: %d, exec time: %s\n",
@@ -277,7 +274,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                }
                        } else if result.coverageData != nil {
                                if c.warmupRun() {
-                                       if printDebugInfo() {
+                                       if shouldPrintDebugInfo() {
                                                fmt.Fprintf(
                                                        c.opts.Log,
                                                        "DEBUG processed an initial input, elapsed: %s, id: %s, new bits: %d, size: %d, exec time: %s\n",
@@ -289,15 +286,18 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                )
                                        }
                                        c.updateCoverage(result.coverageData)
-                                       c.warmupInputCount--
-                                       if printDebugInfo() && c.warmupInputCount == 0 {
-                                               fmt.Fprintf(
-                                                       c.opts.Log,
-                                                       "DEBUG finished processing input corpus, elapsed: %s, entries: %d, initial coverage bits: %d\n",
-                                                       c.elapsed(),
-                                                       len(c.corpus.entries),
-                                                       countBits(c.coverageMask),
-                                               )
+                                       c.warmupInputLeft--
+                                       if c.warmupInputLeft == 0 {
+                                               fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, gathering baseline coverage: %d/%d completed, now fuzzing with %d workers\n", c.elapsed(), c.warmupInputCount, c.warmupInputCount, c.opts.Parallel)
+                                               if shouldPrintDebugInfo() {
+                                                       fmt.Fprintf(
+                                                               c.opts.Log,
+                                                               "DEBUG finished processing input corpus, elapsed: %s, entries: %d, initial coverage bits: %d\n",
+                                                               c.elapsed(),
+                                                               len(c.corpus.entries),
+                                                               countBits(c.coverageMask),
+                                                       )
+                                               }
                                        }
                                } else if keepCoverage := diffCoverage(c.coverageMask, result.coverageData); keepCoverage != nil {
                                        // Found a value that expanded coverage.
@@ -308,7 +308,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 !result.minimizeAttempted && crashMinimizing == nil && c.canMinimize() {
+                                       if c.canMinimize() && result.canMinimize && crashMinimizing == nil {
                                                // Send back to workers to find a smaller value that preserves
                                                // at least one new coverage bit.
                                                c.queueForMinimization(result, keepCoverage)
@@ -327,7 +327,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                c.corpus.entries = append(c.corpus.entries, result.entry)
                                                c.inputQueue.enqueue(result.entry)
                                                c.interestingCount++
-                                               if printDebugInfo() {
+                                               if shouldPrintDebugInfo() {
                                                        fmt.Fprintf(
                                                                c.opts.Log,
                                                                "DEBUG new interesting input, elapsed: %s, id: %s, parent: %s, gen: %d, new bits: %d, total bits: %d, size: %d, exec time: %s\n",
@@ -343,31 +343,40 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                }
                                        }
                                } else {
-                                       if printDebugInfo() {
+                                       if shouldPrintDebugInfo() {
                                                fmt.Fprintf(
                                                        c.opts.Log,
-                                                       "DEBUG worker reported interesting input that doesn't expand coverage, elapsed: %s, id: %s, parent: %s, minimized: %t\n",
+                                                       "DEBUG worker reported interesting input that doesn't expand coverage, elapsed: %s, id: %s, parent: %s, canMinimize: %t\n",
                                                        c.elapsed(),
                                                        result.entry.Name,
                                                        result.entry.Parent,
-                                                       result.minimizeAttempted,
+                                                       result.canMinimize,
                                                )
                                        }
                                }
                        } else if c.warmupRun() {
                                // No error or coverage data was reported for this input during
                                // warmup, so continue processing results.
-                               c.warmupInputCount--
-                               if printDebugInfo() && c.warmupInputCount == 0 {
-                                       fmt.Fprintf(
-                                               c.opts.Log,
-                                               "DEBUG finished testing-only phase, elapsed: %s, entries: %d\n",
-                                               time.Since(c.startTime),
-                                               len(c.corpus.entries),
-                                       )
+                               c.warmupInputLeft--
+                               if c.warmupInputLeft == 0 {
+                                       fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, testing seed corpus: %d/%d completed, now fuzzing with %d workers\n", c.elapsed(), c.warmupInputCount, c.warmupInputCount, c.opts.Parallel)
+                                       if shouldPrintDebugInfo() {
+                                               fmt.Fprintf(
+                                                       c.opts.Log,
+                                                       "DEBUG finished testing-only phase, elapsed: %s, entries: %d\n",
+                                                       time.Since(c.startTime),
+                                                       len(c.corpus.entries),
+                                               )
+                                       }
                                }
                        }
 
+                       // Once the result has been processed, stop the worker if we
+                       // have reached the fuzzing limit.
+                       if c.opts.Limit > 0 && c.count >= c.opts.Limit {
+                               stop(nil)
+                       }
+
                case inputC <- input:
                        // Sent the next input to a worker.
                        c.sentInput(input)
@@ -477,9 +486,9 @@ type fuzzResult struct {
        // crasherMsg is an error message from a crash. It's "" if no crash was found.
        crasherMsg string
 
-       // minimizeAttempted is true if the worker attempted to minimize this input.
-       // The worker may or may not have succeeded.
-       minimizeAttempted bool
+       // canMinimize is true if the worker should attempt to minimize this result.
+       // It may be false because an attempt has already been made.
+       canMinimize bool
 
        // coverageData is set if the worker found new coverage.
        coverageData []byte
@@ -551,12 +560,17 @@ type coordinator struct {
        // been found this execution.
        interestingCount int64
 
-       // warmupInputCount is the number of entries in the corpus which still need
-       // to be received from workers to run once during warmup, but not fuzz. This
-       // could be for coverage data, or only for the purposes of verifying that
-       // the seed corpus doesn't have any crashers. See warmupRun.
+       // warmupInputCount is the count of all entries in the corpus which will
+       // need to be received from workers to run once during warmup, but not fuzz.
+       // This could be for coverage data, or only for the purposes of verifying
+       // that the seed corpus doesn't have any crashers. See warmupRun.
        warmupInputCount int
 
+       // warmupInputLeft is the number of entries in the corpus which still need
+       // to be received from workers to run once during warmup, but not fuzz.
+       // See warmupInputLeft.
+       warmupInputLeft int
+
        // duration is the time spent fuzzing inside workers, not counting time
        // starting up or tearing down.
        duration time.Duration
@@ -570,8 +584,7 @@ type coordinator struct {
        corpus corpus
 
        // minimizationAllowed is true if one or more of the types of fuzz
-       // function's parameters can be minimized, and either the limit or duration
-       // for minimization is non-zero.
+       // function's parameters can be minimized.
        minimizationAllowed bool
 
        // inputQueue is a queue of inputs that workers should try fuzzing. This is
@@ -639,6 +652,7 @@ func newCoordinator(opts CoordinateFuzzingOpts) (*coordinator, error) {
                // Set c.coverageMask to a clean []byte full of zeros.
                c.coverageMask = make([]byte, covSize)
        }
+       c.warmupInputLeft = c.warmupInputCount
 
        if len(c.corpus.entries) == 0 {
                fmt.Fprintf(c.opts.Log, "warning: starting with empty corpus\n")
@@ -662,16 +676,16 @@ func (c *coordinator) updateStats(result fuzzResult) {
 }
 
 func (c *coordinator) logStats() {
-       elapsed := c.elapsed()
        if c.warmupRun() {
+               runSoFar := c.warmupInputCount - c.warmupInputLeft
                if coverageEnabled {
-                       fmt.Fprintf(c.opts.Log, "gathering baseline coverage, elapsed: %s, workers: %d, left: %d\n", elapsed, c.opts.Parallel, c.warmupInputCount)
+                       fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, gathering baseline coverage: %d/%d completed\n", c.elapsed(), runSoFar, c.warmupInputCount)
                } else {
-                       fmt.Fprintf(c.opts.Log, "testing seed corpus, elapsed: %s, workers: %d, left: %d\n", elapsed, c.opts.Parallel, c.warmupInputCount)
+                       fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, testing seed corpus: %d/%d completed\n", c.elapsed(), runSoFar, c.warmupInputCount)
                }
        } else {
                rate := float64(c.count) / time.Since(c.startTime).Seconds() // be more precise here
-               fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, execs: %d (%.0f/sec), workers: %d, interesting: %d\n", elapsed, c.count, rate, c.opts.Parallel, c.interestingCount)
+               fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, execs: %d (%.0f/sec), interesting: %d\n", c.elapsed(), c.count, rate, c.interestingCount)
        }
 }
 
@@ -692,7 +706,7 @@ func (c *coordinator) peekInput() (fuzzInput, bool) {
                return fuzzInput{}, false
        }
        if c.inputQueue.len == 0 {
-               if c.warmupInputCount > 0 {
+               if c.warmupRun() {
                        // Wait for coverage/testing-only run to finish before sending more
                        // inputs.
                        return fuzzInput{}, false
@@ -819,7 +833,7 @@ func (c *coordinator) sentMinimizeInput(input fuzzMinimizeInput) {
 // phase ends when all workers have finished, and the coordinator has a combined
 // coverage map.
 func (c *coordinator) warmupRun() bool {
-       return c.warmupInputCount > 0
+       return c.warmupInputLeft > 0
 }
 
 // updateCoverage sets bits in c.coverageMask that are set in newCoverage.
@@ -1006,7 +1020,7 @@ var (
        debugInfoOnce sync.Once
 )
 
-func printDebugInfo() bool {
+func shouldPrintDebugInfo() bool {
        debugInfoOnce.Do(func() {
                debug := strings.Split(os.Getenv("GODEBUG"), ",")
                for _, f := range debug {
index da82a95fa1857e227f5a834d9f6da2f6fa66c090..36a7c629e5497ac0dabd12d19cd4569b78e6eac1 100644 (file)
@@ -140,8 +140,8 @@ func (w *worker) coordinate(ctx context.Context) error {
                                // for example, F.Fail was called first.
                                return fmt.Errorf("fuzzing process exited unexpectedly due to an internal failure: %w", err)
                        }
-                       // Worker exited non-zero or was terminated by a non-interrupt signal
-                       // (for example, SIGSEGV) while fuzzing.
+                       // Worker exited non-zero or was terminated by a non-interrupt
+                       // signal (for example, SIGSEGV) while fuzzing.
                        return fmt.Errorf("fuzzing process terminated unexpectedly: %w", err)
                        // TODO(jayconrod,katiehockman): if -keepfuzzing, restart worker.
 
@@ -154,6 +154,7 @@ func (w *worker) coordinate(ctx context.Context) error {
                                CoverageData: input.coverageData,
                        }
                        entry, resp, err := w.client.fuzz(ctx, input.entry, args)
+                       canMinimize := true
                        if err != nil {
                                // Error communicating with worker.
                                w.stop()
@@ -184,7 +185,9 @@ func (w *worker) coordinate(ctx context.Context) error {
                                }
                                // Unexpected termination. Set error message and fall through.
                                // We'll restart the worker on the next iteration.
+                               // Don't attempt to minimize this since it crashed the worker.
                                resp.Err = fmt.Sprintf("fuzzing process terminated unexpectedly: %v", w.waitErr)
+                               canMinimize = false
                        }
                        result := fuzzResult{
                                limit:         input.limit,
@@ -194,6 +197,7 @@ func (w *worker) coordinate(ctx context.Context) error {
                                entry:         entry,
                                crasherMsg:    resp.Err,
                                coverageData:  resp.CoverageData,
+                               canMinimize:   canMinimize,
                        }
                        w.coordinator.resultC <- result
 
@@ -206,10 +210,10 @@ func (w *worker) coordinate(ctx context.Context) error {
                                // TODO: double-check this is handled correctly when
                                // implementing -keepfuzzing.
                                result = fuzzResult{
-                                       entry:             input.entry,
-                                       crasherMsg:        input.crasherMsg,
-                                       minimizeAttempted: true,
-                                       limit:             input.limit,
+                                       entry:       input.entry,
+                                       crasherMsg:  input.crasherMsg,
+                                       canMinimize: false,
+                                       limit:       input.limit,
                                }
                                if result.crasherMsg == "" {
                                        result.crasherMsg = err.Error()
@@ -247,11 +251,11 @@ func (w *worker) minimize(ctx context.Context, input fuzzMinimizeInput) (min fuz
                        // may not have been in a good state, but the error won't be meaningful
                        // to the user. Just return the original crasher without logging anything.
                        return fuzzResult{
-                               entry:             input.entry,
-                               crasherMsg:        input.crasherMsg,
-                               coverageData:      input.keepCoverage,
-                               minimizeAttempted: true,
-                               limit:             input.limit,
+                               entry:        input.entry,
+                               crasherMsg:   input.crasherMsg,
+                               coverageData: input.keepCoverage,
+                               canMinimize:  false,
+                               limit:        input.limit,
                        }, nil
                }
                return fuzzResult{}, fmt.Errorf("fuzzing process terminated unexpectedly while minimizing: %w", w.waitErr)
@@ -262,13 +266,13 @@ func (w *worker) minimize(ctx context.Context, input fuzzMinimizeInput) (min fuz
        }
 
        return fuzzResult{
-               entry:             entry,
-               crasherMsg:        resp.Err,
-               coverageData:      resp.CoverageData,
-               minimizeAttempted: true,
-               limit:             input.limit,
-               count:             resp.Count,
-               totalDuration:     resp.Duration,
+               entry:         entry,
+               crasherMsg:    resp.Err,
+               coverageData:  resp.CoverageData,
+               canMinimize:   false,
+               limit:         input.limit,
+               count:         resp.Count,
+               totalDuration: resp.Duration,
        }, nil
 }