From dc5b1d31c8c648b2fad1b2e85f6cca2dc1249455 Mon Sep 17 00:00:00 2001 From: Katie Hockman Date: Tue, 21 Sep 2021 15:51:45 -0400 Subject: [PATCH] [dev.fuzz] internal/fuzz: more fuzzing output adjustments 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 Run-TryBot: Katie Hockman TryBot-Result: Go Bot Reviewed-by: Jay Conrod --- .../go/testdata/script/test_fuzz_minimize.txt | 4 +- src/internal/fuzz/fuzz.go | 104 ++++++++++-------- src/internal/fuzz/worker.go | 40 ++++--- 3 files changed, 83 insertions(+), 65 deletions(-) diff --git a/src/cmd/go/testdata/script/test_fuzz_minimize.txt b/src/cmd/go/testdata/script/test_fuzz_minimize.txt index f0adb9ec3e..3ef54aed93 100644 --- a/src/cmd/go/testdata/script/test_fuzz_minimize.txt +++ b/src/cmd/go/testdata/script/test_fuzz_minimize.txt @@ -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 diff --git a/src/internal/fuzz/fuzz.go b/src/internal/fuzz/fuzz.go index 2cd7ebb472..a38036b9d2 100644 --- a/src/internal/fuzz/fuzz.go +++ b/src/internal/fuzz/fuzz.go @@ -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 { diff --git a/src/internal/fuzz/worker.go b/src/internal/fuzz/worker.go index da82a95fa1..36a7c629e5 100644 --- a/src/internal/fuzz/worker.go +++ b/src/internal/fuzz/worker.go @@ -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 } -- 2.50.0