From 2c98915ac7d304590590fc33a10a8922c466958b Mon Sep 17 00:00:00 2001 From: Roland Shoemaker Date: Sat, 22 May 2021 17:24:17 -0700 Subject: [PATCH] [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 Trust: Katie Hockman Run-TryBot: Roland Shoemaker TryBot-Result: Go Bot Reviewed-by: Katie Hockman --- src/go/build/deps_test.go | 2 +- src/internal/fuzz/coverage.go | 10 ++++++ src/internal/fuzz/fuzz.go | 66 +++++++++++++++++++++++++++++------ src/internal/fuzz/worker.go | 37 ++++++++++++++++---- src/testing/fuzz.go | 8 +++-- 5 files changed, 102 insertions(+), 21 deletions(-) diff --git a/src/go/build/deps_test.go b/src/go/build/deps_test.go index 67989d2e38..2dc2939eec 100644 --- a/src/go/build/deps_test.go +++ b/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 diff --git a/src/internal/fuzz/coverage.go b/src/internal/fuzz/coverage.go index 316aa14783..bd1ff8690d 100644 --- a/src/internal/fuzz/coverage.go +++ b/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 diff --git a/src/internal/fuzz/fuzz.go b/src/internal/fuzz/fuzz.go index 4bcfbeec33..572a0f04d2 100644 --- a/src/internal/fuzz/fuzz.go +++ b/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) - if foundNew && !c.coverageOnlyRun() { + newEdges := c.updateCoverage(result.coverageData) + 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. - duration time.Duration + // totalDuration is the time the worker spent testing inputs. + 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 +} diff --git a/src/internal/fuzz/worker.go b/src/internal/fuzz/worker.go index 2bfd9fce77..34871024c3 100644 --- a/src/internal/fuzz/worker.go +++ b/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 } } diff --git a/src/testing/fuzz.go b/src/testing/fuzz.go index 78a0a600fa..06f755b1ea 100644 --- a/src/testing/fuzz.go +++ b/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 { - Name string - Data []byte - Values []interface{} + Parent string + Name string + Data []byte + Values []interface{} + Generation int } // Cleanup registers a function to be called when the test and all its -- 2.48.1