From 3349d055d7b275f6a8d33780c47f8ca5023a8377 Mon Sep 17 00:00:00 2001 From: Andrey Konovalov Date: Wed, 21 Jun 2017 19:47:18 +0200 Subject: repro: bisect the log to find multiple guilty programs --- pkg/repro/repro.go | 401 ++++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 321 insertions(+), 80 deletions(-) (limited to 'pkg') diff --git a/pkg/repro/repro.go b/pkg/repro/repro.go index 67fac81d7..0c126cb18 100644 --- a/pkg/repro/repro.go +++ b/pkg/repro/repro.go @@ -4,6 +4,7 @@ package repro import ( + "bytes" "fmt" "os" "path/filepath" @@ -41,14 +42,6 @@ type instance struct { executorBin string } -func reverseEntries(entries []*prog.LogEntry) []*prog.LogEntry { - last := len(entries) - 1 - for i := 0; i < len(entries)/2; i++ { - entries[i], entries[last-i] = entries[last-i], entries[i] - } - return entries -} - func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []int) (*Result, error) { if len(vmIndexes) == 0 { return nil, fmt.Errorf("no VMs provided") @@ -136,6 +129,46 @@ func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []in return res, err } +func (ctx *context) repro(entries []*prog.LogEntry, crashStart int) (*Result, error) { + // Cut programs that were executed after crash. + for i, ent := range entries { + if ent.Start > crashStart { + entries = entries[:i] + break + } + } + + res, err := ctx.reproExtractProg(entries) + if err != nil { + return res, err + } + if res == nil { + return nil, nil + } + + res, err = ctx.reproMinimizeProg(res) + if err != nil { + return res, err + } + + res, err = ctx.reproExtractC(res) + if err != nil { + return res, err + } + if !res.CRepro { + res.Opts.Repro = false + return res, nil + } + + res, err = ctx.reproMinimizeC(res) + if err != nil { + return res, err + } + + res.Opts.Repro = false + return res, nil +} + func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) { Logf(2, "reproducing crash '%v': suspecting %v programs", ctx.crashDesc, len(entries)) @@ -154,6 +187,49 @@ func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) lastEntries = append(lastEntries, entries[indices[i]]) } + // Execute each program separately for 10 seconds, that should detect simple crashes (i.e. no races and no hangs). + // Programs are executed in reverse order, usually the last program is the guilty one. + res, err := ctx.reproExtractProgSingle(reverseEntries(lastEntries), 10*time.Second) + if err != nil { + return res, err + } + if res != nil { + return res, nil + } + + // Execute all programs and bisect the log to find guilty programs. + res, err = ctx.reproExtractProgBisect(reverseEntries(entries), 10*time.Second) + if err != nil { + return res, err + } + if res != nil { + return res, nil + } + + // Execute each program separately for 5 minutes to catch races and hangs. Note that the max duration must be larger + // than hang/no output detection duration in vm.MonitorExecution, which is currently set to 3 mins. + res, err = ctx.reproExtractProgSingle(reverseEntries(lastEntries), 5*time.Minute) + if err != nil { + return res, err + } + if res != nil { + return res, nil + } + + // Execute all programs and bisect the log with 5 minute timeout. + res, err = ctx.reproExtractProgBisect(reverseEntries(entries), 5*time.Minute) + if err != nil { + return res, err + } + if res != nil { + return res, nil + } + + Logf(0, "reproducing crash '%v': no program crashed", ctx.crashDesc) + return nil, nil +} + +func (ctx *context) reproExtractProgSingle(entries []*prog.LogEntry, duration time.Duration) (*Result, error) { opts := csource.Options{ Threaded: true, Collide: true, @@ -168,46 +244,207 @@ func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) Repro: true, } - // Execute the suspected programs. - // We first try to execute each program for 10 seconds, that should detect simple crashes - // (i.e. no races and no hangs). Then we execute each program for 5 minutes - // to catch races and hangs. Note that the max duration must be larger than - // hang/no output detection duration in vm.MonitorExecution, which is currently set to 3 mins. - // Programs are executed in reverse order, usually the last program is the guilty one. - durations := []time.Duration{10 * time.Second, 5 * time.Minute} - suspected := [][]*prog.LogEntry{reverseEntries(entries), reverseEntries(lastEntries)} - var res *Result - for i, dur := range durations { - for _, ent := range suspected[i] { - opts.Fault = ent.Fault - opts.FaultCall = ent.FaultCall - opts.FaultNth = ent.FaultNth - if opts.FaultCall < 0 || opts.FaultCall >= len(ent.P.Calls) { - opts.FaultCall = len(ent.P.Calls) - 1 + for _, ent := range entries { + opts.Fault = ent.Fault + opts.FaultCall = ent.FaultCall + opts.FaultNth = ent.FaultNth + if opts.FaultCall < 0 || opts.FaultCall >= len(ent.P.Calls) { + opts.FaultCall = len(ent.P.Calls) - 1 + } + crashed, err := ctx.testProg(ent.P, duration, opts) + if err != nil { + return nil, err + } + if crashed { + res := &Result{ + Prog: ent.P, + Duration: duration * 3 / 2, + Opts: opts, + } + return res, nil + } + } + + return nil, nil +} + +func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuration time.Duration) (*Result, error) { + Logf(3, "reproducing crash '%v': bisect: bisecting %d programs", ctx.crashDesc, len(entries)) + + opts := csource.Options{ + Threaded: true, + Collide: true, + Repeat: true, + Procs: ctx.cfg.Procs, + Sandbox: ctx.cfg.Sandbox, + EnableTun: true, + UseTmpDir: true, + HandleSegv: true, + WaitRepeat: true, + Debug: true, + Repro: true, + } + + duration := func(entries int) time.Duration { + return baseDuration + time.Duration((entries/4))*time.Second + } + + // Check that executing the whole log results in a crash. + Logf(3, "reproducing crash '%v': bisect: executing all %d programs", ctx.crashDesc, len(entries)) + crashed, err := ctx.testProgs(entries, duration(len(entries)), opts) + if err != nil { + return nil, err + } + if !crashed { + Logf(3, "reproducing crash '%v': bisect: didn't crash", ctx.crashDesc) + return nil, nil + } + + compose := func(guilty1, guilty2 [][]*prog.LogEntry, chunk []*prog.LogEntry) []*prog.LogEntry { + progs := []*prog.LogEntry{} + for _, c := range guilty1 { + progs = append(progs, c...) + } + progs = append(progs, chunk...) + for _, c := range guilty2 { + progs = append(progs, c...) + } + return progs + } + + logGuilty := func(guilty [][]*prog.LogEntry) string { + log := "[" + for i, chunk := range guilty { + log += fmt.Sprintf("<%d>", len(chunk)) + if i != len(guilty)-1 { + log += ", " } - crashed, err := ctx.testProg(ent.P, dur, opts) + } + log += "]" + return log + } + + // Bisect the programs to find the ones that cause the crash. + guilty := [][]*prog.LogEntry{entries} +again: + Logf(3, "reproducing crash '%v': bisect: guilty chunks: %v", ctx.crashDesc, logGuilty(guilty)) + for i, chunk := range guilty { + if len(chunk) == 1 { + continue + } + + guilty1 := guilty[:i] + guilty2 := guilty[i+1:] + Logf(3, "reproducing crash '%v': bisect: guilty chunks split: %v, <%v>, %v", ctx.crashDesc, logGuilty(guilty1), len(chunk), logGuilty(guilty2)) + + chunk1 := chunk[0 : len(chunk)/2] + chunk2 := chunk[len(chunk)/2 : len(chunk)] + Logf(3, "reproducing crash '%v': bisect: chunk split: <%v> => <%v>, <%v>", ctx.crashDesc, len(chunk), len(chunk1), len(chunk2)) + + Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #1", ctx.crashDesc) + progs := compose(guilty1, guilty2, chunk2) + crashed, err := ctx.testProgs(progs, duration(len(progs)), opts) + if err != nil { + return nil, err + } + + if crashed { + guilty = nil + guilty = append(guilty, guilty1...) + guilty = append(guilty, chunk2) + guilty = append(guilty, guilty2...) + Logf(3, "reproducing crash '%v': bisect: crashed, chunk #1 evicted", ctx.crashDesc) + goto again + } + + Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #2", ctx.crashDesc) + progs = compose(guilty1, guilty2, chunk1) + crashed, err = ctx.testProgs(progs, duration(len(progs)), opts) + if err != nil { + return nil, err + } + + if crashed { + guilty = nil + guilty = append(guilty, guilty1...) + guilty = append(guilty, chunk1) + guilty = append(guilty, guilty2...) + Logf(3, "reproducing crash '%v': bisect: crashed, chunk #2 evicted", ctx.crashDesc) + goto again + } + + guilty = nil + guilty = append(guilty, guilty1...) + guilty = append(guilty, chunk1) + guilty = append(guilty, chunk2) + guilty = append(guilty, guilty2...) + + Logf(3, "reproducing crash '%v': bisect: not crashed, both chunks required", ctx.crashDesc) + + goto again + } + + // Concatenate all programs into one. + entries = []*prog.LogEntry{} + var prog prog.Prog + for _, chunk := range guilty { + if len(chunk) != 1 { + return nil, fmt.Errorf("bad bisect result: %v", guilty) + } + entries = append(entries, chunk[0]) + prog.Calls = append(prog.Calls, chunk[0].P.Calls...) + } + + // TODO: Minimize each program before concatenation. + // TODO: Return multiple programs if concatenation fails. + + Logf(3, "reproducing crash '%v': bisect: %d programs left:\n\n%s\n", ctx.crashDesc, len(entries), encodeEntries(entries)) + Logf(3, "reproducing crash '%v': bisect: concatenating", ctx.crashDesc) + + // Execute the program without fault injection. + dur := duration(len(entries)) * 3 / 2 + crashed, err = ctx.testProg(&prog, dur, opts) + if err != nil { + return nil, err + } + if crashed { + res := &Result{ + Prog: &prog, + Duration: dur, + Opts: opts, + } + Logf(3, "reproducing crash '%v': bisect: concatenation succeded", ctx.crashDesc) + return res, nil + } + + // Try with fault injection. + calls := 0 + for _, entry := range entries { + if entry.Fault { + opts.FaultCall = calls + entry.FaultCall + opts.FaultNth = entry.FaultNth + if entry.FaultCall < 0 || entry.FaultCall >= len(entry.P.Calls) { + opts.FaultCall = calls + len(entry.P.Calls) - 1 + } + crashed, err := ctx.testProg(&prog, dur, opts) if err != nil { return nil, err } if crashed { - res = &Result{ - Prog: ent.P, - Duration: dur * 3 / 2, + res := &Result{ + Prog: &prog, + Duration: dur, Opts: opts, } - break + Logf(3, "reproducing crash '%v': bisect: concatenation succeded with fault injection", ctx.crashDesc) + return res, nil } } - if res != nil { - break - } - } - if res == nil { - Logf(0, "reproducing crash '%v': no program crashed", ctx.crashDesc) - return nil, nil + calls += len(entry.P.Calls) } - return res, nil + Logf(3, "reproducing crash '%v': bisect: concatenation failed", ctx.crashDesc) + return nil, nil } func (ctx *context) reproMinimizeProg(res *Result) (*Result, error) { @@ -221,7 +458,7 @@ func (ctx *context) reproMinimizeProg(res *Result) (*Result, error) { res.Prog, res.Opts.FaultCall = prog.Minimize(res.Prog, call, func(p1 *prog.Prog, callIndex int) bool { crashed, err := ctx.testProg(p1, res.Duration, res.Opts) if err != nil { - Logf(1, "reproducing crash '%v': minimization failed with %v", ctx.crashDesc, err) + Logf(0, "reproducing crash '%v': minimization failed with %v", ctx.crashDesc, err) return false } return crashed @@ -368,54 +605,27 @@ func (ctx *context) reproMinimizeC(res *Result) (*Result, error) { return res, nil } -func (ctx *context) repro(entries []*prog.LogEntry, crashStart int) (*Result, error) { - // Cut programs that were executed after crash. - for i, ent := range entries { - if ent.Start > crashStart { - entries = entries[:i] - break - } - } - - res, err := ctx.reproExtractProg(entries) - if err != nil { - return res, err - } - if res == nil { - return nil, nil - } - - res, err = ctx.reproMinimizeProg(res) - if err != nil { - return res, err - } - - res, err = ctx.reproExtractC(res) - if err != nil { - return res, err - } - if !res.CRepro { - res.Opts.Repro = false - return res, nil - } - - res, err = ctx.reproMinimizeC(res) - if err != nil { - return res, err +func (ctx *context) testProg(p *prog.Prog, duration time.Duration, opts csource.Options) (crashed bool, err error) { + entry := prog.LogEntry{P: p} + if opts.FaultCall != -1 { + entry.Fault = true + entry.FaultCall = opts.FaultCall + entry.FaultNth = opts.FaultNth } - - res.Opts.Repro = false - return res, nil + return ctx.testProgs([]*prog.LogEntry{&entry}, duration, opts) } -func (ctx *context) testProg(p *prog.Prog, duration time.Duration, opts csource.Options) (crashed bool, err error) { +func (ctx *context) testProgs(entries []*prog.LogEntry, duration time.Duration, opts csource.Options) (crashed bool, err error) { inst := <-ctx.instances if inst == nil { return false, fmt.Errorf("all VMs failed to boot") } defer ctx.returnInstance(inst) + if len(entries) == 0 { + return false, fmt.Errorf("no programs to execute") + } - pstr := p.Serialize() + pstr := encodeEntries(entries) progFile, err := fileutil.WriteTempFile(pstr) if err != nil { return false, err @@ -433,10 +643,21 @@ func (ctx *context) testProg(p *prog.Prog, duration time.Duration, opts csource. if !opts.Fault { opts.FaultCall = -1 } - command := fmt.Sprintf("%v -executor %v -cover=0 -procs=%v -repeat=%v -sandbox %v -threaded=%v -collide=%v -fault_call=%v -fault_nth=%v %v", - inst.execprogBin, inst.executorBin, opts.Procs, repeat, opts.Sandbox, opts.Threaded, opts.Collide, opts.FaultCall, opts.FaultNth, vmProgFile) + program := entries[0].P.String() + if len(entries) > 1 { + program = "[" + for i, entry := range entries { + program += fmt.Sprintf("%v", len(entry.P.Calls)) + if i != len(entries)-1 { + program += ", " + } + } + program += "]" + } + command := fmt.Sprintf("%v -executor %v -cover=0 -procs=%v -repeat=%v -sandbox %v -threaded=%v -collide=%v %v", + inst.execprogBin, inst.executorBin, opts.Procs, repeat, opts.Sandbox, opts.Threaded, opts.Collide, vmProgFile) Logf(2, "reproducing crash '%v': testing program (duration=%v, %+v): %s", - ctx.crashDesc, duration, opts, p) + ctx.crashDesc, duration, opts, program) return ctx.testImpl(inst.Instance, command, duration) } @@ -496,3 +717,23 @@ func (ctx *context) returnInstance(inst *instance) { ctx.bootRequests <- inst.index inst.Close() } + +func reverseEntries(entries []*prog.LogEntry) []*prog.LogEntry { + last := len(entries) - 1 + for i := 0; i < len(entries)/2; i++ { + entries[i], entries[last-i] = entries[last-i], entries[i] + } + return entries +} + +func encodeEntries(entries []*prog.LogEntry) []byte { + buf := new(bytes.Buffer) + for _, ent := range entries { + opts := "" + if ent.Fault { + opts = fmt.Sprintf(" (fault-call:%v fault-nth:%v)", ent.FaultCall, ent.FaultNth) + } + fmt.Fprintf(buf, "executing program %v%v:\n%v", ent.Proc, opts, string(ent.P.Serialize())) + } + return buf.Bytes() +} -- cgit mrf-deployment From 65542325fba5dccb740427a6b74a57d06620f740 Mon Sep 17 00:00:00 2001 From: Andrey Konovalov Date: Fri, 23 Jun 2017 15:54:57 +0200 Subject: repro: add bisection test --- pkg/repro/repro.go | 217 ++++++++++++++++++++++++++---------------------- pkg/repro/repro_test.go | 63 ++++++++++++++ 2 files changed, 180 insertions(+), 100 deletions(-) create mode 100644 pkg/repro/repro_test.go (limited to 'pkg') diff --git a/pkg/repro/repro.go b/pkg/repro/repro.go index 0c126cb18..91f6dab82 100644 --- a/pkg/repro/repro.go +++ b/pkg/repro/repro.go @@ -269,8 +269,6 @@ func (ctx *context) reproExtractProgSingle(entries []*prog.LogEntry, duration ti } func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuration time.Duration) (*Result, error) { - Logf(3, "reproducing crash '%v': bisect: bisecting %d programs", ctx.crashDesc, len(entries)) - opts := csource.Options{ Threaded: true, Collide: true, @@ -289,121 +287,32 @@ func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuratio return baseDuration + time.Duration((entries/4))*time.Second } - // Check that executing the whole log results in a crash. - Logf(3, "reproducing crash '%v': bisect: executing all %d programs", ctx.crashDesc, len(entries)) - crashed, err := ctx.testProgs(entries, duration(len(entries)), opts) + // Bisect the log to find multiple guilty programs. + entries, err := bisectProgs(entries, ctx.crashDesc, func(progs []*prog.LogEntry) (bool, error) { + return ctx.testProgs(progs, duration(len(progs)), opts) + }) if err != nil { return nil, err } - if !crashed { - Logf(3, "reproducing crash '%v': bisect: didn't crash", ctx.crashDesc) + if entries == nil { return nil, nil } - compose := func(guilty1, guilty2 [][]*prog.LogEntry, chunk []*prog.LogEntry) []*prog.LogEntry { - progs := []*prog.LogEntry{} - for _, c := range guilty1 { - progs = append(progs, c...) - } - progs = append(progs, chunk...) - for _, c := range guilty2 { - progs = append(progs, c...) - } - return progs - } - - logGuilty := func(guilty [][]*prog.LogEntry) string { - log := "[" - for i, chunk := range guilty { - log += fmt.Sprintf("<%d>", len(chunk)) - if i != len(guilty)-1 { - log += ", " - } - } - log += "]" - return log - } - - // Bisect the programs to find the ones that cause the crash. - guilty := [][]*prog.LogEntry{entries} -again: - Logf(3, "reproducing crash '%v': bisect: guilty chunks: %v", ctx.crashDesc, logGuilty(guilty)) - for i, chunk := range guilty { - if len(chunk) == 1 { - continue - } - - guilty1 := guilty[:i] - guilty2 := guilty[i+1:] - Logf(3, "reproducing crash '%v': bisect: guilty chunks split: %v, <%v>, %v", ctx.crashDesc, logGuilty(guilty1), len(chunk), logGuilty(guilty2)) - - chunk1 := chunk[0 : len(chunk)/2] - chunk2 := chunk[len(chunk)/2 : len(chunk)] - Logf(3, "reproducing crash '%v': bisect: chunk split: <%v> => <%v>, <%v>", ctx.crashDesc, len(chunk), len(chunk1), len(chunk2)) - - Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #1", ctx.crashDesc) - progs := compose(guilty1, guilty2, chunk2) - crashed, err := ctx.testProgs(progs, duration(len(progs)), opts) - if err != nil { - return nil, err - } - - if crashed { - guilty = nil - guilty = append(guilty, guilty1...) - guilty = append(guilty, chunk2) - guilty = append(guilty, guilty2...) - Logf(3, "reproducing crash '%v': bisect: crashed, chunk #1 evicted", ctx.crashDesc) - goto again - } - - Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #2", ctx.crashDesc) - progs = compose(guilty1, guilty2, chunk1) - crashed, err = ctx.testProgs(progs, duration(len(progs)), opts) - if err != nil { - return nil, err - } - - if crashed { - guilty = nil - guilty = append(guilty, guilty1...) - guilty = append(guilty, chunk1) - guilty = append(guilty, guilty2...) - Logf(3, "reproducing crash '%v': bisect: crashed, chunk #2 evicted", ctx.crashDesc) - goto again - } - - guilty = nil - guilty = append(guilty, guilty1...) - guilty = append(guilty, chunk1) - guilty = append(guilty, chunk2) - guilty = append(guilty, guilty2...) - - Logf(3, "reproducing crash '%v': bisect: not crashed, both chunks required", ctx.crashDesc) - - goto again - } - // Concatenate all programs into one. - entries = []*prog.LogEntry{} var prog prog.Prog - for _, chunk := range guilty { - if len(chunk) != 1 { - return nil, fmt.Errorf("bad bisect result: %v", guilty) - } - entries = append(entries, chunk[0]) - prog.Calls = append(prog.Calls, chunk[0].P.Calls...) + for _, entry := range entries { + prog.Calls = append(prog.Calls, entry.P.Calls...) } // TODO: Minimize each program before concatenation. // TODO: Return multiple programs if concatenation fails. - Logf(3, "reproducing crash '%v': bisect: %d programs left:\n\n%s\n", ctx.crashDesc, len(entries), encodeEntries(entries)) + Logf(3, "reproducing crash '%v': bisect: \n\n%s\n", ctx.crashDesc, encodeEntries(entries)) Logf(3, "reproducing crash '%v': bisect: concatenating", ctx.crashDesc) // Execute the program without fault injection. dur := duration(len(entries)) * 3 / 2 - crashed, err = ctx.testProg(&prog, dur, opts) + crashed, err := ctx.testProg(&prog, dur, opts) if err != nil { return nil, err } @@ -718,6 +627,114 @@ func (ctx *context) returnInstance(inst *instance) { inst.Close() } +func bisectProgs(progs []*prog.LogEntry, crashDesc string, pred func([]*prog.LogEntry) (bool, error)) ([]*prog.LogEntry, error) { + Logf(3, "reproducing crash '%v': bisect: bisecting %d programs", crashDesc, len(progs)) + + compose := func(guilty1, guilty2 [][]*prog.LogEntry, chunk []*prog.LogEntry) []*prog.LogEntry { + progs := []*prog.LogEntry{} + for _, c := range guilty1 { + progs = append(progs, c...) + } + progs = append(progs, chunk...) + for _, c := range guilty2 { + progs = append(progs, c...) + } + return progs + } + + logGuilty := func(guilty [][]*prog.LogEntry) string { + log := "[" + for i, chunk := range guilty { + log += fmt.Sprintf("<%d>", len(chunk)) + if i != len(guilty)-1 { + log += ", " + } + } + log += "]" + return log + } + + Logf(3, "reproducing crash '%v': bisect: executing all %d programs", crashDesc, len(progs)) + crashed, err := pred(progs) + if err != nil { + return nil, err + } + if !crashed { + Logf(3, "reproducing crash '%v': bisect: didn't crash", crashDesc) + return nil, nil + } + + guilty := [][]*prog.LogEntry{progs} +again: + Logf(3, "reproducing crash '%v': bisect: guilty chunks: %v", crashDesc, logGuilty(guilty)) + for i, chunk := range guilty { + if len(chunk) == 1 { + continue + } + + guilty1 := guilty[:i] + guilty2 := guilty[i+1:] + Logf(3, "reproducing crash '%v': bisect: guilty chunks split: %v, <%v>, %v", crashDesc, logGuilty(guilty1), len(chunk), logGuilty(guilty2)) + + chunk1 := chunk[0 : len(chunk)/2] + chunk2 := chunk[len(chunk)/2 : len(chunk)] + Logf(3, "reproducing crash '%v': bisect: chunk split: <%v> => <%v>, <%v>", crashDesc, len(chunk), len(chunk1), len(chunk2)) + + Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #1", crashDesc) + progs := compose(guilty1, guilty2, chunk2) + crashed, err := pred(progs) + if err != nil { + return nil, err + } + + if crashed { + guilty = nil + guilty = append(guilty, guilty1...) + guilty = append(guilty, chunk2) + guilty = append(guilty, guilty2...) + Logf(3, "reproducing crash '%v': bisect: crashed, chunk #1 evicted", crashDesc) + goto again + } + + Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #2", crashDesc) + progs = compose(guilty1, guilty2, chunk1) + crashed, err = pred(progs) + if err != nil { + return nil, err + } + + if crashed { + guilty = nil + guilty = append(guilty, guilty1...) + guilty = append(guilty, chunk1) + guilty = append(guilty, guilty2...) + Logf(3, "reproducing crash '%v': bisect: crashed, chunk #2 evicted", crashDesc) + goto again + } + + guilty = nil + guilty = append(guilty, guilty1...) + guilty = append(guilty, chunk1) + guilty = append(guilty, chunk2) + guilty = append(guilty, guilty2...) + + Logf(3, "reproducing crash '%v': bisect: not crashed, both chunks required", crashDesc) + + goto again + } + + progs = nil + for _, chunk := range guilty { + if len(chunk) != 1 { + return nil, fmt.Errorf("bad bisect result: %v", guilty) + } + progs = append(progs, chunk[0]) + } + + Logf(3, "reproducing crash '%v': bisect: success, %d programs left", crashDesc, len(progs)) + return progs, nil +} + func reverseEntries(entries []*prog.LogEntry) []*prog.LogEntry { last := len(entries) - 1 for i := 0; i < len(entries)/2; i++ { diff --git a/pkg/repro/repro_test.go b/pkg/repro/repro_test.go new file mode 100644 index 000000000..ed7843be7 --- /dev/null +++ b/pkg/repro/repro_test.go @@ -0,0 +1,63 @@ +// Copyright 2017 syzkaller project authors. All rights reserved. +// Use of this source code is governed by Apache 2 LICENSE that can be found in the LICENSE file. + +package repro + +import ( + "math/rand" + "testing" + "time" + + "github.com/google/syzkaller/prog" +) + +func initTest(t *testing.T) (*rand.Rand, int) { + iters := 1000 + if testing.Short() { + iters = 100 + } + seed := int64(time.Now().UnixNano()) + rs := rand.NewSource(seed) + t.Logf("seed=%v", seed) + return rand.New(rs), iters +} + +func TestBisect(t *testing.T) { + rd, iters := initTest(t) + for n := 0; n < iters; n++ { + var progs []*prog.LogEntry + numTotal := rd.Intn(300) + numGuilty := 0 + for i := 0; i < numTotal; i++ { + var prog prog.LogEntry + if rd.Intn(30) == 0 { + prog.Proc = 42 + numGuilty += 1 + } + progs = append(progs, &prog) + } + if numGuilty == 0 { + var prog prog.LogEntry + prog.Proc = 42 + progs = append(progs, &prog) + numGuilty += 1 + } + progs, _ = bisectProgs(progs, "test", func(p []*prog.LogEntry) (bool, error) { + guilty := 0 + for _, prog := range p { + if prog.Proc == 42 { + guilty += 1 + } + } + return guilty == numGuilty, nil + }) + if len(progs) != numGuilty { + t.Fatalf("bisect test failed: wrong number of guilty progs: got: %v, want: %v", len(progs), numGuilty) + } + for _, prog := range progs { + if prog.Proc != 42 { + t.Fatalf("bisect test failed: wrong program is guilty: progs: %v", progs) + } + } + } +} -- cgit mrf-deployment From 41d7a8a64b82c7b7212f7865b691f68d62683b6b Mon Sep 17 00:00:00 2001 From: Andrey Konovalov Date: Fri, 23 Jun 2017 19:09:50 +0200 Subject: repro: add 1 minute duration --- pkg/repro/repro.go | 56 +++++++++++++++++++++--------------------------------- 1 file changed, 22 insertions(+), 34 deletions(-) (limited to 'pkg') diff --git a/pkg/repro/repro.go b/pkg/repro/repro.go index 91f6dab82..b335a2ccc 100644 --- a/pkg/repro/repro.go +++ b/pkg/repro/repro.go @@ -187,42 +187,30 @@ func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) lastEntries = append(lastEntries, entries[indices[i]]) } - // Execute each program separately for 10 seconds, that should detect simple crashes (i.e. no races and no hangs). - // Programs are executed in reverse order, usually the last program is the guilty one. - res, err := ctx.reproExtractProgSingle(reverseEntries(lastEntries), 10*time.Second) - if err != nil { - return res, err - } - if res != nil { - return res, nil - } - - // Execute all programs and bisect the log to find guilty programs. - res, err = ctx.reproExtractProgBisect(reverseEntries(entries), 10*time.Second) - if err != nil { - return res, err - } - if res != nil { - return res, nil - } - - // Execute each program separately for 5 minutes to catch races and hangs. Note that the max duration must be larger + // The shortest duration is 10 seconds to detect simple crashes (i.e. no races and no hangs). + // The longest duration is 5 minutes to catch races and hangs. Note that this value must be larger // than hang/no output detection duration in vm.MonitorExecution, which is currently set to 3 mins. - res, err = ctx.reproExtractProgSingle(reverseEntries(lastEntries), 5*time.Minute) - if err != nil { - return res, err - } - if res != nil { - return res, nil - } + timeouts := []time.Duration{10*time.Second, 1*time.Minute, 5*time.Minute} - // Execute all programs and bisect the log with 5 minute timeout. - res, err = ctx.reproExtractProgBisect(reverseEntries(entries), 5*time.Minute) - if err != nil { - return res, err - } - if res != nil { - return res, nil + for _, timeout := range timeouts { + // Execute each program separately to detect simple crashes caused by a single program. + // Programs are executed in reverse order, usually the last program is the guilty one. + res, err := ctx.reproExtractProgSingle(reverseEntries(lastEntries), timeout) + if err != nil { + return res, err + } + if res != nil { + return res, nil + } + + // Execute all programs and bisect the log to find multiple guilty programs. + res, err = ctx.reproExtractProgBisect(reverseEntries(entries), timeout) + if err != nil { + return res, err + } + if res != nil { + return res, nil + } } Logf(0, "reproducing crash '%v': no program crashed", ctx.crashDesc) -- cgit mrf-deployment From e379542e8bdc86bf0889615c6457c26a2f9446cf Mon Sep 17 00:00:00 2001 From: Andrey Konovalov Date: Mon, 26 Jun 2017 13:57:55 +0200 Subject: repro, manager: show repro logs and stats on manager dashboard --- pkg/repro/repro.go | 170 +++++++++++++++++++++++++++++++++---------------- syz-manager/html.go | 8 +++ syz-manager/manager.go | 4 ++ 3 files changed, 128 insertions(+), 54 deletions(-) (limited to 'pkg') diff --git a/pkg/repro/repro.go b/pkg/repro/repro.go index b335a2ccc..d3f4bc6cb 100644 --- a/pkg/repro/repro.go +++ b/pkg/repro/repro.go @@ -21,11 +21,21 @@ import ( "github.com/google/syzkaller/vm" ) +type Stats struct { + Log []byte + ExtractProgTime time.Duration + MinimizeProgTime time.Duration + SimplifyProgTime time.Duration + ExtractCTime time.Duration + SimplifyCTime time.Duration +} + type Result struct { Prog *prog.Prog Duration time.Duration Opts csource.Options CRepro bool + Stats Stats } type context struct { @@ -33,6 +43,7 @@ type context struct { crashDesc string instances chan *instance bootRequests chan int + stats Stats } type instance struct { @@ -55,7 +66,6 @@ func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []in crashStart = len(crashLog) // assuming VM hanged crashDesc = "hang" } - Logf(0, "reproducing crash '%v': %v programs, %v VMs", crashDesc, len(entries), len(vmIndexes)) ctx := &context{ cfg: cfg, @@ -63,6 +73,7 @@ func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []in instances: make(chan *instance, len(vmIndexes)), bootRequests: make(chan int, len(vmIndexes)), } + ctx.reproLog(0, "%v programs, %v VMs", len(entries), len(vmIndexes)) var wg sync.WaitGroup wg.Add(len(vmIndexes)) for _, vmIndex := range vmIndexes { @@ -81,21 +92,21 @@ func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []in } vmInst, err := vmPool.Create(vmIndex) if err != nil { - Logf(0, "reproducing crash '%v': failed to create VM: %v", crashDesc, err) + ctx.reproLog(0, "failed to create VM: %v", err) time.Sleep(10 * time.Second) continue } execprogBin, err := vmInst.Copy(filepath.Join(cfg.Syzkaller, "bin/syz-execprog")) if err != nil { - Logf(0, "reproducing crash '%v': failed to copy to VM: %v", crashDesc, err) + ctx.reproLog(0, "failed to copy to VM: %v", err) vmInst.Close() time.Sleep(10 * time.Second) continue } executorBin, err := vmInst.Copy(filepath.Join(cfg.Syzkaller, "bin/syz-executor")) if err != nil { - Logf(0, "reproducing crash '%v': failed to copy to VM: %v", crashDesc, err) + ctx.reproLog(0, "failed to copy to VM: %v", err) vmInst.Close() time.Sleep(10 * time.Second) continue @@ -121,6 +132,9 @@ func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []in }() res, err := ctx.repro(entries, crashStart) + if res != nil { + res.Stats = ctx.stats + } close(ctx.bootRequests) for inst := range ctx.instances { @@ -138,7 +152,12 @@ func (ctx *context) repro(entries []*prog.LogEntry, crashStart int) (*Result, er } } - res, err := ctx.reproExtractProg(entries) + reproStart := time.Now() + defer func() { + ctx.reproLog(3, "reproducing took %s", time.Since(reproStart)) + }() + + res, err := ctx.extractProg(entries) if err != nil { return res, err } @@ -146,12 +165,17 @@ func (ctx *context) repro(entries []*prog.LogEntry, crashStart int) (*Result, er return nil, nil } - res, err = ctx.reproMinimizeProg(res) + res, err = ctx.minimizeProg(res) if err != nil { return res, err } - res, err = ctx.reproExtractC(res) + res, err = ctx.simplifyProg(res) + if err != nil { + return res, err + } + + res, err = ctx.extractC(res) if err != nil { return res, err } @@ -160,7 +184,7 @@ func (ctx *context) repro(entries []*prog.LogEntry, crashStart int) (*Result, er return res, nil } - res, err = ctx.reproMinimizeC(res) + res, err = ctx.simplifyC(res) if err != nil { return res, err } @@ -169,8 +193,12 @@ func (ctx *context) repro(entries []*prog.LogEntry, crashStart int) (*Result, er return res, nil } -func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) { - Logf(2, "reproducing crash '%v': suspecting %v programs", ctx.crashDesc, len(entries)) +func (ctx *context) extractProg(entries []*prog.LogEntry) (*Result, error) { + ctx.reproLog(2, "extracting reproducer from %v programs", len(entries)) + start := time.Now() + defer func() { + ctx.stats.ExtractProgTime = time.Since(start) + }() // Extract last program on every proc. procs := make(map[int]int) @@ -190,34 +218,38 @@ func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) // The shortest duration is 10 seconds to detect simple crashes (i.e. no races and no hangs). // The longest duration is 5 minutes to catch races and hangs. Note that this value must be larger // than hang/no output detection duration in vm.MonitorExecution, which is currently set to 3 mins. - timeouts := []time.Duration{10*time.Second, 1*time.Minute, 5*time.Minute} + timeouts := []time.Duration{10 * time.Second, 1 * time.Minute, 5 * time.Minute} for _, timeout := range timeouts { // Execute each program separately to detect simple crashes caused by a single program. // Programs are executed in reverse order, usually the last program is the guilty one. - res, err := ctx.reproExtractProgSingle(reverseEntries(lastEntries), timeout) + res, err := ctx.extractProgSingle(reverseEntries(lastEntries), timeout) if err != nil { return res, err } if res != nil { + ctx.reproLog(3, "found reproducer with %d syscalls", len(res.Prog.Calls)) return res, nil } // Execute all programs and bisect the log to find multiple guilty programs. - res, err = ctx.reproExtractProgBisect(reverseEntries(entries), timeout) + res, err = ctx.extractProgBisect(reverseEntries(entries), timeout) if err != nil { return res, err } if res != nil { + ctx.reproLog(3, "found reproducer with %d syscalls", len(res.Prog.Calls)) return res, nil } } - Logf(0, "reproducing crash '%v': no program crashed", ctx.crashDesc) + ctx.reproLog(0, "failed to extract reproducer") return nil, nil } -func (ctx *context) reproExtractProgSingle(entries []*prog.LogEntry, duration time.Duration) (*Result, error) { +func (ctx *context) extractProgSingle(entries []*prog.LogEntry, duration time.Duration) (*Result, error) { + ctx.reproLog(3, "single: executing %d programs separately with timeout %s", len(entries), duration) + opts := csource.Options{ Threaded: true, Collide: true, @@ -249,14 +281,18 @@ func (ctx *context) reproExtractProgSingle(entries []*prog.LogEntry, duration ti Duration: duration * 3 / 2, Opts: opts, } + ctx.reproLog(3, "single: successfully extracted reproducer") return res, nil } } + ctx.reproLog(3, "single: failed to extract reproducer") return nil, nil } -func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuration time.Duration) (*Result, error) { +func (ctx *context) extractProgBisect(entries []*prog.LogEntry, baseDuration time.Duration) (*Result, error) { + ctx.reproLog(3, "bisect: bisecting %d programs with base timeout %s", len(entries), baseDuration) + opts := csource.Options{ Threaded: true, Collide: true, @@ -276,7 +312,7 @@ func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuratio } // Bisect the log to find multiple guilty programs. - entries, err := bisectProgs(entries, ctx.crashDesc, func(progs []*prog.LogEntry) (bool, error) { + entries, err := ctx.bisectProgs(entries, func(progs []*prog.LogEntry) (bool, error) { return ctx.testProgs(progs, duration(len(progs)), opts) }) if err != nil { @@ -286,18 +322,18 @@ func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuratio return nil, nil } + // TODO: Minimize each program before concatenation. + // TODO: Return multiple programs if concatenation fails. + + ctx.reproLog(3, "bisect: %d programs left: \n\n%s\n", len(entries), encodeEntries(entries)) + ctx.reproLog(3, "bisect: trying to concatenate") + // Concatenate all programs into one. var prog prog.Prog for _, entry := range entries { prog.Calls = append(prog.Calls, entry.P.Calls...) } - // TODO: Minimize each program before concatenation. - // TODO: Return multiple programs if concatenation fails. - - Logf(3, "reproducing crash '%v': bisect: \n\n%s\n", ctx.crashDesc, encodeEntries(entries)) - Logf(3, "reproducing crash '%v': bisect: concatenating", ctx.crashDesc) - // Execute the program without fault injection. dur := duration(len(entries)) * 3 / 2 crashed, err := ctx.testProg(&prog, dur, opts) @@ -310,7 +346,7 @@ func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuratio Duration: dur, Opts: opts, } - Logf(3, "reproducing crash '%v': bisect: concatenation succeded", ctx.crashDesc) + ctx.reproLog(3, "bisect: concatenation succeded") return res, nil } @@ -333,21 +369,25 @@ func (ctx *context) reproExtractProgBisect(entries []*prog.LogEntry, baseDuratio Duration: dur, Opts: opts, } - Logf(3, "reproducing crash '%v': bisect: concatenation succeded with fault injection", ctx.crashDesc) + ctx.reproLog(3, "bisect: concatenation succeeded with fault injection") return res, nil } } calls += len(entry.P.Calls) } - Logf(3, "reproducing crash '%v': bisect: concatenation failed", ctx.crashDesc) + ctx.reproLog(3, "bisect: concatenation failed") return nil, nil } -func (ctx *context) reproMinimizeProg(res *Result) (*Result, error) { - Logf(2, "reproducing crash '%v': minimizing guilty program", ctx.crashDesc) +// Minimize calls and arguments. +func (ctx *context) minimizeProg(res *Result) (*Result, error) { + ctx.reproLog(2, "minimizing guilty program") + start := time.Now() + defer func() { + ctx.stats.MinimizeProgTime = time.Since(start) + }() - // Minimize calls and arguments. call := -1 if res.Opts.Fault { call = res.Opts.FaultCall @@ -355,13 +395,23 @@ func (ctx *context) reproMinimizeProg(res *Result) (*Result, error) { res.Prog, res.Opts.FaultCall = prog.Minimize(res.Prog, call, func(p1 *prog.Prog, callIndex int) bool { crashed, err := ctx.testProg(p1, res.Duration, res.Opts) if err != nil { - Logf(0, "reproducing crash '%v': minimization failed with %v", ctx.crashDesc, err) + ctx.reproLog(0, "minimization failed with %v", err) return false } return crashed }, true) - // Minimize repro options (threaded, collide, sandbox, etc). + return res, nil +} + +// Simplify repro options (threaded, collide, sandbox, etc). +func (ctx *context) simplifyProg(res *Result) (*Result, error) { + ctx.reproLog(2, "simplifying guilty program") + start := time.Now() + defer func() { + ctx.stats.SimplifyProgTime = time.Since(start) + }() + opts := res.Opts opts.Collide = false crashed, err := ctx.testProg(res.Prog, res.Duration, opts) @@ -416,8 +466,12 @@ func (ctx *context) reproMinimizeProg(res *Result) (*Result, error) { return res, nil } -func (ctx *context) reproExtractC(res *Result) (*Result, error) { - Logf(2, "reproducing crash '%v': extracting C reproducer", ctx.crashDesc) +func (ctx *context) extractC(res *Result) (*Result, error) { + ctx.reproLog(2, "extracting C reproducer") + start := time.Now() + defer func() { + ctx.stats.ExtractCTime = time.Since(start) + }() // Try triggering crash with a C reproducer. crashed, err := ctx.testCProg(res.Prog, res.Duration, res.Opts) @@ -428,8 +482,12 @@ func (ctx *context) reproExtractC(res *Result) (*Result, error) { return res, nil } -func (ctx *context) reproMinimizeC(res *Result) (*Result, error) { - Logf(2, "reproducing crash '%v': minimizing C reproducer", ctx.crashDesc) +func (ctx *context) simplifyC(res *Result) (*Result, error) { + ctx.reproLog(2, "simplifying C reproducer") + start := time.Now() + defer func() { + ctx.stats.SimplifyCTime = time.Since(start) + }() // Try to simplify the C reproducer. if res.Opts.EnableTun { @@ -553,8 +611,7 @@ func (ctx *context) testProgs(entries []*prog.LogEntry, duration time.Duration, } command := fmt.Sprintf("%v -executor %v -cover=0 -procs=%v -repeat=%v -sandbox %v -threaded=%v -collide=%v %v", inst.execprogBin, inst.executorBin, opts.Procs, repeat, opts.Sandbox, opts.Threaded, opts.Collide, vmProgFile) - Logf(2, "reproducing crash '%v': testing program (duration=%v, %+v): %s", - ctx.crashDesc, duration, opts, program) + ctx.reproLog(2, "testing program (duration=%v, %+v): %s", duration, opts, program) return ctx.testImpl(inst.Instance, command, duration) } @@ -572,8 +629,7 @@ func (ctx *context) testCProg(p *prog.Prog, duration time.Duration, opts csource return false, err } defer os.Remove(bin) - Logf(2, "reproducing crash '%v': testing compiled C program (duration=%v, %+v): %s", - ctx.crashDesc, duration, opts, p) + ctx.reproLog(2, "testing compiled C program (duration=%v, %+v): %s", duration, opts, p) crashed, err = ctx.testBin(bin, duration) if err != nil { return false, err @@ -603,10 +659,10 @@ func (ctx *context) testImpl(inst *vm.Instance, command string, duration time.Du desc, text, output, crashed, timedout := vm.MonitorExecution(outc, errc, false, ctx.cfg.ParsedIgnores) _, _, _ = text, output, timedout if !crashed { - Logf(2, "reproducing crash '%v': program did not crash", ctx.crashDesc) + ctx.reproLog(2, "program did not crash") return false, nil } - Logf(2, "reproducing crash '%v': program crashed: %v", ctx.crashDesc, desc) + ctx.reproLog(2, "program crashed: %v", desc) return true, nil } @@ -615,8 +671,14 @@ func (ctx *context) returnInstance(inst *instance) { inst.Close() } -func bisectProgs(progs []*prog.LogEntry, crashDesc string, pred func([]*prog.LogEntry) (bool, error)) ([]*prog.LogEntry, error) { - Logf(3, "reproducing crash '%v': bisect: bisecting %d programs", crashDesc, len(progs)) +func (ctx *context) reproLog(level int, format string, args ...interface{}) { + prefix := fmt.Sprintf("reproducing crash '%v': ", ctx.crashDesc) + Logf(level, prefix+format, args...) + ctx.stats.Log = append(ctx.stats.Log, []byte(fmt.Sprintf(format, args...)+"\n")...) +} + +func (ctx *context) bisectProgs(progs []*prog.LogEntry, pred func([]*prog.LogEntry) (bool, error)) ([]*prog.LogEntry, error) { + ctx.reproLog(3, "bisect: bisecting %d programs", len(progs)) compose := func(guilty1, guilty2 [][]*prog.LogEntry, chunk []*prog.LogEntry) []*prog.LogEntry { progs := []*prog.LogEntry{} @@ -642,19 +704,19 @@ func bisectProgs(progs []*prog.LogEntry, crashDesc string, pred func([]*prog.Log return log } - Logf(3, "reproducing crash '%v': bisect: executing all %d programs", crashDesc, len(progs)) + ctx.reproLog(3, "bisect: executing all %d programs", len(progs)) crashed, err := pred(progs) if err != nil { return nil, err } if !crashed { - Logf(3, "reproducing crash '%v': bisect: didn't crash", crashDesc) + ctx.reproLog(3, "bisect: didn't crash") return nil, nil } guilty := [][]*prog.LogEntry{progs} again: - Logf(3, "reproducing crash '%v': bisect: guilty chunks: %v", crashDesc, logGuilty(guilty)) + ctx.reproLog(3, "bisect: guilty chunks: %v", logGuilty(guilty)) for i, chunk := range guilty { if len(chunk) == 1 { continue @@ -662,13 +724,13 @@ again: guilty1 := guilty[:i] guilty2 := guilty[i+1:] - Logf(3, "reproducing crash '%v': bisect: guilty chunks split: %v, <%v>, %v", crashDesc, logGuilty(guilty1), len(chunk), logGuilty(guilty2)) + ctx.reproLog(3, "bisect: guilty chunks split: %v, <%v>, %v", logGuilty(guilty1), len(chunk), logGuilty(guilty2)) chunk1 := chunk[0 : len(chunk)/2] chunk2 := chunk[len(chunk)/2 : len(chunk)] - Logf(3, "reproducing crash '%v': bisect: chunk split: <%v> => <%v>, <%v>", crashDesc, len(chunk), len(chunk1), len(chunk2)) + ctx.reproLog(3, "bisect: chunk split: <%v> => <%v>, <%v>", len(chunk), len(chunk1), len(chunk2)) - Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #1", crashDesc) + ctx.reproLog(3, "bisect: triggering crash without chunk #1") progs := compose(guilty1, guilty2, chunk2) crashed, err := pred(progs) if err != nil { @@ -680,11 +742,11 @@ again: guilty = append(guilty, guilty1...) guilty = append(guilty, chunk2) guilty = append(guilty, guilty2...) - Logf(3, "reproducing crash '%v': bisect: crashed, chunk #1 evicted", crashDesc) + ctx.reproLog(3, "bisect: crashed, chunk #1 evicted") goto again } - Logf(3, "reproducing crash '%v': bisect: triggering crash without chunk #2", crashDesc) + ctx.reproLog(3, "bisect: triggering crash without chunk #2") progs = compose(guilty1, guilty2, chunk1) crashed, err = pred(progs) if err != nil { @@ -696,7 +758,7 @@ again: guilty = append(guilty, guilty1...) guilty = append(guilty, chunk1) guilty = append(guilty, guilty2...) - Logf(3, "reproducing crash '%v': bisect: crashed, chunk #2 evicted", crashDesc) + ctx.reproLog(3, "bisect: crashed, chunk #2 evicted") goto again } @@ -706,7 +768,7 @@ again: guilty = append(guilty, chunk2) guilty = append(guilty, guilty2...) - Logf(3, "reproducing crash '%v': bisect: not crashed, both chunks required", crashDesc) + ctx.reproLog(3, "bisect: not crashed, both chunks required") goto again } @@ -719,7 +781,7 @@ again: progs = append(progs, chunk[0]) } - Logf(3, "reproducing crash '%v': bisect: success, %d programs left", crashDesc, len(progs)) + ctx.reproLog(3, "bisect: success, %d programs left", len(progs)) return progs, nil } diff --git a/syz-manager/html.go b/syz-manager/html.go index fad275615..26cccda45 100644 --- a/syz-manager/html.go +++ b/syz-manager/html.go @@ -253,6 +253,8 @@ func (mgr *Manager) httpReport(w http.ResponseWriter, r *http.Request) { prog, _ := ioutil.ReadFile(filepath.Join(mgr.crashdir, crashID, "repro.prog")) cprog, _ := ioutil.ReadFile(filepath.Join(mgr.crashdir, crashID, "repro.cprog")) rep, _ := ioutil.ReadFile(filepath.Join(mgr.crashdir, crashID, "repro.report")) + log, _ := ioutil.ReadFile(filepath.Join(mgr.crashdir, crashID, "repro.log")) + stats, _ := ioutil.ReadFile(filepath.Join(mgr.crashdir, crashID, "repro.stats")) fmt.Fprintf(w, "Syzkaller hit '%s' bug on commit %s.\n\n", trimNewLines(desc), trimNewLines(tag)) if len(rep) != 0 { @@ -270,6 +272,12 @@ func (mgr *Manager) httpReport(w http.ResponseWriter, r *http.Request) { fmt.Fprintf(w, "C reproducer:\n%s\n\n", cprog) } } + if len(stats) > 0 { + fmt.Fprintf(w, "Reproducing stats:\n%s\n\n", stats) + } + if len(log) > 0 { + fmt.Fprintf(w, "Reproducing log:\n%s\n\n", log) + } } func collectCrashes(workdir string) ([]*UICrashType, error) { diff --git a/syz-manager/manager.go b/syz-manager/manager.go index eaf275c22..0b4ae3dc2 100644 --- a/syz-manager/manager.go +++ b/syz-manager/manager.go @@ -620,6 +620,10 @@ func (mgr *Manager) saveRepro(crash *Crash, res *repro.Result) { if len(crash.text) > 0 { ioutil.WriteFile(filepath.Join(dir, "repro.report"), []byte(crash.text), 0660) } + ioutil.WriteFile(filepath.Join(dir, "repro.log"), res.Stats.Log, 0660) + stats := fmt.Sprintf("Extracting prog: %s\nMinimizing prog: %s\nSimplifying prog options: %s\nExtracting C: %s\nSimplifying C: %s\n", + res.Stats.ExtractProgTime, res.Stats.MinimizeProgTime, res.Stats.SimplifyProgTime, res.Stats.ExtractCTime, res.Stats.SimplifyCTime) + ioutil.WriteFile(filepath.Join(dir, "repro.stats"), []byte(stats), 0660) var cprogText []byte if res.CRepro { cprog, err := csource.Write(res.Prog, res.Opts) -- cgit mrf-deployment