]> Cypherpunks repositories - gostls13.git/commitdiff
[dev.fuzz] internal/fuzz: add additional debug logging
authorRoland Shoemaker <roland@golang.org>
Sun, 23 May 2021 00:24:17 +0000 (17:24 -0700)
committerRoland Shoemaker <roland@golang.org>
Mon, 7 Jun 2021 18:15:26 +0000 (18:15 +0000)
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
src/internal/fuzz/coverage.go
src/internal/fuzz/fuzz.go
src/internal/fuzz/worker.go
src/testing/fuzz.go

index 67989d2e38d2028aee5a4b8435880a0ddaef84ce..2dc2939eec98634498a0bc31f6451cc3fa01bb19 100644 (file)
@@ -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
index 316aa147839c81dfd0a91ffd2982fb915d5b1637..bd1ff8690db684df8ad26030ece28bbf79f2e2d0 100644 (file)
@@ -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
index 4bcfbeec331c82f892387627f07cafc5f31722ee..572a0f04d25c8e4651fbf2e3bd790ccf6458e8f0 100644 (file)
@@ -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
+}
index 2bfd9fce771111cf4490bb814a92dabdcc3f7a0c..34871024c3ba70c8aba53d58abc85978d6ecff15 100644 (file)
@@ -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
                                }
                        }
index 78a0a600fa140aa0241f1ccfd0320a0784e0b0f3..06f755b1ea06e6633543f673621655fa2258639f 100644 (file)
@@ -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