[dev.fuzz] internal: fuzzing output adjustments

Print the elapsed time as a nicely formatted duration, and
make small adjustments to the command line output while fuzzing.

Fixes golang/go#48132

Change-Id: Id95f84c0939171a777448c444d9b87d7af26b654
Reviewed-on: https://go-review.googlesource.com/c/go/+/349970
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>

diff --git a/src/cmd/go/testdata/script/test_fuzz_minimize.txt b/src/cmd/go/testdata/script/test_fuzz_minimize.txt
index c180890a9b19759d3a95c7acf129ceb4003e9244..f0adb9ec3e58b3690eb4be045775175a8f8d1a39 100644 (file)
--- a/src/cmd/go/testdata/script/test_fuzz_minimize.txt
+++ b/src/cmd/go/testdata/script/test_fuzz_minimize.txt
@@ -23,14 +23,14 @@ stdout FAIL
 # Test that fuzzminimizetime can be zero seconds, and minimization is disabled
 ! go test -fuzz=FuzzMinimizeZeroDurationSet -run=FuzzMinimizeZeroDurationSet -fuzztime=10000x -fuzzminimizetime=0s minimizer_test.go
 ! stdout '^ok'
-! stdout 'found a crash, minimizing...'
+! stdout 'minimizing'
 stdout 'there was an Error'
 stdout FAIL
 
 # Test that fuzzminimizetime can be zero times, and minimization is disabled
 ! go test -fuzz=FuzzMinimizeZeroLimitSet -run=FuzzMinimizeZeroLimitSet -fuzztime=10000x -fuzzminimizetime=0x minimizer_test.go
 ! stdout '^ok'
-! stdout 'found a crash, minimizing...'
+! stdout 'minimizing'
 stdout 'there was an Error'
 stdout FAIL
 
@@ -51,7 +51,7 @@ rm testdata
 # Test that minimization is working for non-recoverable errors.
 ! go test -fuzz=FuzzMinimizerNonrecoverable -run=FuzzMinimizerNonrecoverable -fuzztime=10000x minimizer_test.go
 ! stdout '^ok'
-stdout 'found a crash, 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 c19ea35f23191c16bb4ed115b2308dbb1cbbb9cf..816da3286f96be7a5d1eca82028daec3559604d6 100644 (file)
--- a/src/internal/fuzz/fuzz.go
+++ b/src/internal/fuzz/fuzz.go
@@ -239,7 +239,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, "found a crash, minimizing...\n")
+                                       fmt.Fprintf(c.opts.Log, "fuzz: found a %d-byte crash input; minimizing...\n", len(result.entry.Data))
                                        c.queueForMinimization(result, nil)
                                } else if !crashWritten {
                                        // Found a crasher that's either minimized or not minimizable.
@@ -256,7 +256,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                fmt.Fprintf(
                                                        c.opts.Log,
                                                        "DEBUG new crasher, elapsed: %s, id: %s, parent: %s, gen: %d, size: %d, exec time: %s\n",
-                                                       time.Since(c.startTime),
+                                                       c.elapsed(),
                                                        fileName,
                                                        result.entry.Parent,
                                                        result.entry.Generation,
@@ -272,7 +272,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                fmt.Fprintf(
                                                        c.opts.Log,
                                                        "DEBUG processed an initial input, elapsed: %s, id: %s, new bits: %d, size: %d, exec time: %s\n",
-                                                       time.Since(c.startTime),
+                                                       c.elapsed(),
                                                        result.entry.Parent,
                                                        countBits(diffCoverage(c.coverageMask, result.coverageData)),
                                                        len(result.entry.Data),
@@ -291,7 +291,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                        fmt.Fprintf(
                                                                c.opts.Log,
                                                                "DEBUG finished processing input corpus, elapsed: %s, entries: %d, initial coverage bits: %d\n",
-                                                               time.Since(c.startTime),
+                                                               c.elapsed(),
                                                                len(c.corpus.entries),
                                                                countBits(c.coverageMask),
                                                        )
@@ -329,7 +329,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                        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",
-                                                               time.Since(c.startTime),
+                                                               c.elapsed(),
                                                                result.entry.Name,
                                                                result.entry.Parent,
                                                                result.entry.Generation,
@@ -345,7 +345,7 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
                                                fmt.Fprintf(
                                                        c.opts.Log,
                                                        "DEBUG worker reported interesting input that doesn't expand coverage, elapsed: %s, id: %s, parent: %s, minimized: %t\n",
-                                                       time.Since(c.startTime),
+                                                       c.elapsed(),
                                                        result.entry.Name,
                                                        result.entry.Parent,
                                                        result.minimizeAttempted,
@@ -644,12 +644,12 @@ func (c *coordinator) updateStats(result fuzzResult) {
 }
 
 func (c *coordinator) logStats() {
-       elapsed := time.Since(c.startTime)
+       elapsed := c.elapsed()
        if c.coverageOnlyRun() {
-               fmt.Fprintf(c.opts.Log, "gathering baseline coverage, elapsed: %.1fs, workers: %d, left: %d\n", elapsed.Seconds(), c.opts.Parallel, c.covOnlyInputs)
+               fmt.Fprintf(c.opts.Log, "gathering baseline coverage, elapsed: %s, workers: %d, left: %d\n", elapsed, c.opts.Parallel, c.covOnlyInputs)
        } else {
-               rate := float64(c.count) / elapsed.Seconds()
-               fmt.Fprintf(c.opts.Log, "fuzzing, elapsed: %.1fs, execs: %d (%.0f/sec), workers: %d, interesting: %d\n", elapsed.Seconds(), c.count, rate, c.opts.Parallel, c.interestingCount)
+               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)
        }
 }
 
@@ -820,6 +820,10 @@ func (c *coordinator) canMinimize() bool {
                (c.opts.Limit == 0 || c.count+c.countWaiting < c.opts.Limit)
 }
 
+func (c *coordinator) elapsed() time.Duration {
+       return time.Since(c.startTime).Round(1 * time.Second)
+}
+
 // readCache creates a combined corpus from seed values and values in the cache
 // (in GOCACHE/fuzz).
 //