From ef2ebbebf976fba17bb97ed285e9c3d10b192d74 Mon Sep 17 00:00:00 2001 From: Katie Hockman Date: Wed, 6 Oct 2021 14:13:23 -0400 Subject: [PATCH] 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 Run-TryBot: Katie Hockman Reviewed-by: Jay Conrod --- .../go/testdata/script/test_fuzz_minimize.txt | 17 ++++++++++++++++ src/internal/fuzz/fuzz.go | 20 +++++++++++-------- 2 files changed, 29 insertions(+), 8 deletions(-) diff --git a/src/cmd/go/testdata/script/test_fuzz_minimize.txt b/src/cmd/go/testdata/script/test_fuzz_minimize.txt index 3ef54aed93..727399f4bb 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 @@ 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 2c2a365f4c..f660052911 100644 --- 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 { -- 2.51.0