[dev.fuzz] internal/fuzz: add additional debug logging

When GODEBUG=fuzzdebug=1, log additional debug level information about
what the fuzzer is doing. This provides useful information for
investigating the operation and performance of the fuzzing engine, and
is necessary for profiling new fuzzing strategies.

Change-Id: Ic3e24e7a128781377e62785767a218811c3c2030
Reviewed-on: https://go-review.googlesource.com/c/go/+/324972
Trust: Roland Shoemaker <roland@golang.org>
Trust: Katie Hockman <katie@golang.org>
Run-TryBot: Roland Shoemaker <roland@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Katie Hockman <katie@golang.org>

src/go/build/deps_test.go

@@ -509,7 +509,7 @@ var depsRules = `
 	FMT, flag, runtime/debug, runtime/trace, internal/sysinfo, math/rand
 	< testing;
 
-	FMT, crypto/sha256, encoding/json, go/ast, go/parser, go/token, math/rand, encoding/hex, crypto/sha256
+	FMT, crypto/sha256, encoding/json, go/ast, go/parser, go/token, math/rand, encoding/hex, crypto/sha256, log
 	< internal/fuzz;
 
 	internal/fuzz, internal/testlog, runtime/pprof, regexp

src/internal/fuzz/coverage.go

@@ -45,6 +45,16 @@ func SnapshotCoverage() {
 	copy(coverageSnapshot, cov)
 }
 
+func countEdges(cov []byte) int {
+	n := 0
+	for _, c := range cov {
+		if c > 0 {
+			n++
+		}
+	}
+	return n
+}
+
 var coverageSnapshot []byte
 
 // _counters and _ecounters mark the start and end, respectively, of where

src/internal/fuzz/fuzz.go

@@ -14,11 +14,13 @@ import (
 	"fmt"
 	"io"
 	"io/ioutil"
+	"log"
 	"os"
 	"path/filepath"
 	"reflect"
 	"runtime"
 	"strings"
+	"sync"
 	"time"
 )
 
@@ -237,11 +239,14 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
 							err:  errors.New(result.crasherMsg),
 						}
 					}
+					if printDebugInfo() {
+						log.Printf("DEBUG new crasher, id: %s, parent: %s, gen: %d, size: %d, exec time: %s\n", result.entry.Name, result.entry.Parent, result.entry.Generation, len(result.entry.Data), result.entryDuration)
+					}
 					stop(err)
 				}
 			} else if result.coverageData != nil {
-				foundNew := c.updateCoverage(result.coverageData)
+				newEdges := c.updateCoverage(result.coverageData)
-				if foundNew && !c.coverageOnlyRun() {
+				if newEdges > 0 && !c.coverageOnlyRun() {
 					// Found an interesting value that expanded coverage.
 					// This is not a crasher, but we should add it to the
 					// on-disk corpus, and prioritize it for future fuzzing.
@@ -257,14 +262,27 @@ func CoordinateFuzzing(ctx context.Context, opts CoordinateFuzzingOpts) (err err
 							stop(err)
 						}
 					}
+					if printDebugInfo() {
+						log.Printf("DEBUG new interesting input, id: %s, parent: %s, gen: %d, new edges: %d, total edges: %d, size: %d, exec time: %s\n", result.entry.Name, result.entry.Parent, result.entry.Generation, newEdges, countEdges(c.coverageData), len(result.entry.Data), result.entryDuration)
+					}
 				} else if c.coverageOnlyRun() {
 					c.covOnlyInputs--
+					if printDebugInfo() {
+						log.Printf("DEBUG processed an initial input, id: %s, new edges: %d, size: %d, exec time: %s\n", result.entry.Parent, newEdges, len(result.entry.Data), result.entryDuration)
+					}
 					if c.covOnlyInputs == 0 {
 						// The coordinator has finished getting a baseline for
 						// coverage. Tell all of the workers to inialize their
 						// baseline coverage data (by setting interestingCount
 						// to 0).
 						c.interestingCount = 0
+						if printDebugInfo() {
+							log.Printf("DEBUG finished processing input corpus, entries: %d, initial coverage edges: %d\n", len(c.corpus.entries), countEdges(c.coverageData))
+						}
+					}
+				} else {
+					if printDebugInfo() {
+						log.Printf("DEBUG worker reported interesting input that doesn't expand coverage, id: %s, parent: %s\n", result.entry.Name, result.entry.Parent)
 					}
 				}
 			}
@@ -341,6 +359,8 @@ type corpus struct {
 // TODO: split marshalled and unmarshalled types. In most places, we only need
 // one or the other.
 type CorpusEntry = struct {
+	Parent string
+
 	// Name is the name of the corpus file, if the entry was loaded from the
 	// seed corpus. It can be used with -run. For entries added with f.Add and
 	// entries generated by the mutator, Name is empty.
@@ -351,6 +371,8 @@ type CorpusEntry = struct {
 
 	// Values is the unmarshaled values from a corpus file.
 	Values []interface{}
+
+	Generation int
 }
 
 type fuzzInput struct {
@@ -395,8 +417,11 @@ type fuzzResult struct {
 	// count is the number of values the worker actually tested.
 	count int64
 
-	// duration is the time the worker spent testing inputs.
+	// totalDuration is the time the worker spent testing inputs.
-	duration time.Duration
+	totalDuration time.Duration
+
+	// entryDuration is the time the worker spent execution an interesting result
+	entryDuration time.Duration
 }
 
 // coordinator holds channels that workers can use to communicate with
@@ -468,7 +493,10 @@ func newCoordinator(opts CoordinateFuzzingOpts) (*coordinator, error) {
 		for _, t := range opts.Types {
 			vals = append(vals, zeroValue(t))
 		}
-		corpus.entries = append(corpus.entries, CorpusEntry{Data: marshalCorpusFile(vals...), Values: vals})
+		data := marshalCorpusFile(vals...)
+		h := sha256.Sum256(data)
+		name := fmt.Sprintf("%x", h[:4])
+		corpus.entries = append(corpus.entries, CorpusEntry{Name: name, Data: data, Values: vals})
 	}
 	c := &coordinator{
 		opts:          opts,
@@ -502,7 +530,7 @@ func (c *coordinator) updateStats(result fuzzResult) {
 	// Adjust total stats.
 	c.count += result.count
 	c.countWaiting -= result.countRequested
-	c.duration += result.duration
+	c.duration += result.totalDuration
 }
 
 func (c *coordinator) logStats() {
@@ -560,20 +588,20 @@ func (c *coordinator) coverageOnlyRun() bool {
 
 // updateCoverage updates c.coverageData for all edges that have a higher
 // counter value in newCoverage. It return true if a new edge was hit.
-func (c *coordinator) updateCoverage(newCoverage []byte) bool {
+func (c *coordinator) updateCoverage(newCoverage []byte) int {
 	if len(newCoverage) != len(c.coverageData) {
 		panic(fmt.Sprintf("num edges changed at runtime: %d, expected %d", len(newCoverage), len(c.coverageData)))
 	}
-	newEdge := false
+	newEdges := 0
 	for i := range newCoverage {
 		if newCoverage[i] > c.coverageData[i] {
 			if c.coverageData[i] == 0 {
-				newEdge = true
+				newEdges++
 			}
 			c.coverageData[i] = newCoverage[i]
 		}
 	}
-	return newEdge
+	return newEdges
 }
 
 // readCache creates a combined corpus from seed values and values in the cache
@@ -716,3 +744,21 @@ var zeroVals []interface{} = []interface{}{
 	uint32(0),
 	uint64(0),
 }
+
+var (
+	debugInfo     bool
+	debugInfoOnce sync.Once
+)
+
+func printDebugInfo() bool {
+	debugInfoOnce.Do(func() {
+		debug := strings.Split(os.Getenv("GODEBUG"), ",")
+		for _, f := range debug {
+			if f == "fuzzdebug=1" {
+				debugInfo = true
+				break
+			}
+		}
+	})
+	return debugInfo
+}

src/internal/fuzz/worker.go

@@ -6,6 +6,7 @@ package fuzz
 
 import (
 	"context"
+	"crypto/sha256"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -166,13 +167,28 @@ func (w *worker) coordinate(ctx context.Context) error {
 			result := fuzzResult{
 				countRequested: input.countRequested,
 				count:          resp.Count,
-				duration:       resp.Duration,
+				totalDuration:  resp.TotalDuration,
+				entryDuration:  resp.InterestingDuration,
 			}
 			if resp.Err != "" {
-				result.entry = CorpusEntry{Data: value}
+				h := sha256.Sum256(value)
+				name := fmt.Sprintf("%x", h[:4])
+				result.entry = CorpusEntry{
+					Name:       name,
+					Parent:     input.entry.Name,
+					Data:       value,
+					Generation: input.entry.Generation + 1,
+				}
 				result.crasherMsg = resp.Err
 			} else if resp.CoverageData != nil {
-				result.entry = CorpusEntry{Data: value}
+				h := sha256.Sum256(value)
+				name := fmt.Sprintf("%x", h[:4])
+				result.entry = CorpusEntry{
+					Name:       name,
+					Parent:     input.entry.Name,
+					Data:       value,
+					Generation: input.entry.Generation + 1,
+				}
 				result.coverageData = resp.CoverageData
 			}
 			w.coordinator.resultC <- result
@@ -232,7 +248,7 @@ func (w *worker) minimize(ctx context.Context, input fuzzResult) (min fuzzResult
 	}
 	min.crasherMsg = resp.Err
 	min.count = resp.Count
-	min.duration = resp.Duration
+	min.totalDuration = resp.Duration
 	min.entry.Data = value
 	return min, nil
 }
@@ -496,7 +512,8 @@ type fuzzArgs struct {
 // fuzzResponse contains results from workerServer.fuzz.
 type fuzzResponse struct {
 	// Duration is the time spent fuzzing, not including starting or cleaning up.
-	Duration time.Duration
+	TotalDuration       time.Duration
+	InterestingDuration time.Duration
 
 	// Count is the number of values tested.
 	Count int64
@@ -622,7 +639,7 @@ func (ws *workerServer) fuzz(ctx context.Context, args fuzzArgs) (resp fuzzRespo
 		ws.coverageData = args.CoverageData
 	}
 	start := time.Now()
-	defer func() { resp.Duration = time.Since(start) }()
+	defer func() { resp.TotalDuration = time.Since(start) }()
 
 	fuzzCtx, cancel := context.WithTimeout(ctx, args.Timeout)
 	defer cancel()
@@ -638,7 +655,9 @@ func (ws *workerServer) fuzz(ctx context.Context, args fuzzArgs) (resp fuzzRespo
 	}
 
 	if args.CoverageOnly {
+		fStart := time.Now()
 		ws.fuzzFn(CorpusEntry{Values: vals})
+		resp.InterestingDuration = time.Since(fStart)
 		resp.CoverageData = coverageSnapshot
 		return resp
 	}
@@ -655,7 +674,10 @@ func (ws *workerServer) fuzz(ctx context.Context, args fuzzArgs) (resp fuzzRespo
 			mem.header().count++
 			ws.m.mutate(vals, cap(mem.valueRef()))
 			writeToMem(vals, mem)
-			if err := ws.fuzzFn(CorpusEntry{Values: vals}); err != nil {
+			fStart := time.Now()
+			err := ws.fuzzFn(CorpusEntry{Values: vals})
+			fDur := time.Since(fStart)
+			if err != nil {
 				resp.Err = err.Error()
 				if resp.Err == "" {
 					resp.Err = "fuzz function failed with no output"
@@ -666,6 +688,7 @@ func (ws *workerServer) fuzz(ctx context.Context, args fuzzArgs) (resp fuzzRespo
 				if ws.coverageData[i] == 0 && coverageSnapshot[i] > ws.coverageData[i] {
 					// TODO(jayconrod,katie): minimize this.
 					resp.CoverageData = coverageSnapshot
+					resp.InterestingDuration = fDur
 					return resp
 				}
 			}

src/testing/fuzz.go

@@ -66,9 +66,11 @@ var _ TB = (*F)(nil)
 // We use a type alias because we don't want to export this type, and we can't
 // importing internal/fuzz from testing.
 type corpusEntry = struct {
+	Parent     string
 	Name       string
 	Data       []byte
 	Values     []interface{}
+	Generation int
 }
 
 // Cleanup registers a function to be called when the test and all its