// Copyright 2016 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 ( "bytes" "fmt" "os" "sort" "sync" "time" "github.com/google/syzkaller/pkg/csource" instancePkg "github.com/google/syzkaller/pkg/instance" "github.com/google/syzkaller/pkg/log" "github.com/google/syzkaller/pkg/mgrconfig" "github.com/google/syzkaller/pkg/osutil" "github.com/google/syzkaller/pkg/report" "github.com/google/syzkaller/prog" "github.com/google/syzkaller/vm" ) type Result struct { Prog *prog.Prog Duration time.Duration Opts csource.Options CRepro bool // Information about the final (non-symbolized) crash that we reproduced. // Can be different from what we started reproducing. Report *report.Report } type Stats struct { Log []byte ExtractProgTime time.Duration MinimizeProgTime time.Duration SimplifyProgTime time.Duration ExtractCTime time.Duration SimplifyCTime time.Duration } type context struct { cfg *mgrconfig.Config reporter report.Reporter crashTitle string instances chan *instance bootRequests chan int stats *Stats report *report.Report } type instance struct { *vm.Instance index int execprogBin string executorBin string } func Run(crashLog []byte, cfg *mgrconfig.Config, reporter report.Reporter, vmPool *vm.Pool, vmIndexes []int) (*Result, *Stats, error) { if len(vmIndexes) == 0 { return nil, nil, fmt.Errorf("no VMs provided") } target, err := prog.GetTarget(cfg.TargetOS, cfg.TargetArch) if err != nil { return nil, nil, err } entries := target.ParseLog(crashLog) if len(entries) == 0 { return nil, nil, fmt.Errorf("crash log does not contain any programs") } crashStart := len(crashLog) // assuming VM hanged crashTitle := "hang" if rep := reporter.Parse(crashLog); rep != nil { crashStart = rep.StartPos crashTitle = rep.Title } ctx := &context{ cfg: cfg, reporter: reporter, crashTitle: crashTitle, instances: make(chan *instance, len(vmIndexes)), bootRequests: make(chan int, len(vmIndexes)), stats: new(Stats), } ctx.reproLog(0, "%v programs, %v VMs", len(entries), len(vmIndexes)) var wg sync.WaitGroup wg.Add(len(vmIndexes)) for _, vmIndex := range vmIndexes { ctx.bootRequests <- vmIndex go func() { defer wg.Done() for vmIndex := range ctx.bootRequests { var inst *instance maxTry := 3 for try := 0; try < maxTry; try++ { select { case <-vm.Shutdown: try = maxTry continue default: } vmInst, err := vmPool.Create(vmIndex) if err != nil { ctx.reproLog(0, "failed to create VM: %v", err) time.Sleep(10 * time.Second) continue } execprogBin, err := vmInst.Copy(cfg.SyzExecprogBin) if err != nil { ctx.reproLog(0, "failed to copy to VM: %v", err) vmInst.Close() time.Sleep(10 * time.Second) continue } executorBin, err := vmInst.Copy(cfg.SyzExecutorBin) if err != nil { ctx.reproLog(0, "failed to copy to VM: %v", err) vmInst.Close() time.Sleep(10 * time.Second) continue } inst = &instance{ Instance: vmInst, index: vmIndex, execprogBin: execprogBin, executorBin: executorBin, } break } if inst == nil { break } ctx.instances <- inst } }() } go func() { wg.Wait() close(ctx.instances) }() res, err := ctx.repro(entries, crashStart) if err != nil { return nil, nil, err } if res != nil { ctx.reproLog(3, "repro crashed as (corrupted=%v):\n%s", ctx.report.Corrupted, ctx.report.Report) // Try to rerun the repro if the report is corrupted. for attempts := 0; ctx.report.Corrupted && attempts < 3; attempts++ { ctx.reproLog(3, "report is corrupted, running repro again") if res.CRepro { _, err = ctx.testCProg(res.Prog, res.Duration, res.Opts) } else { _, err = ctx.testProg(res.Prog, res.Duration, res.Opts) } if err != nil { return nil, nil, err } } ctx.reproLog(3, "final repro crashed as (corrupted=%v):\n%s", ctx.report.Corrupted, ctx.report.Report) res.Report = ctx.report } close(ctx.bootRequests) for inst := range ctx.instances { inst.Close() } return res, ctx.stats, 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 } } reproStart := time.Now() defer func() { ctx.reproLog(3, "reproducing took %s", time.Since(reproStart)) }() res, err := ctx.extractProg(entries) if err != nil { return nil, err } if res == nil { return nil, nil } defer func() { if res != nil { res.Opts.Repro = false } }() res, err = ctx.minimizeProg(res) if err != nil { return nil, err } // Try extracting C repro without simplifying options first. res, err = ctx.extractC(res) if err != nil { return nil, err } // Simplify options and try extracting C repro. if !res.CRepro { res, err = ctx.simplifyProg(res) if err != nil { return nil, err } } // Simplify C related options. if res.CRepro { res, err = ctx.simplifyC(res) if err != nil { return nil, err } } return res, nil } 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) for i, ent := range entries { procs[ent.Proc] = i } var indices []int for _, idx := range procs { indices = append(indices, idx) } sort.Ints(indices) var lastEntries []*prog.LogEntry for i := len(indices) - 1; i >= 0; i-- { lastEntries = append(lastEntries, entries[indices[i]]) } // 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} 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.extractProgSingle(reverseEntries(lastEntries), timeout) if err != nil { return nil, err } if res != nil { ctx.reproLog(3, "found reproducer with %d syscalls", len(res.Prog.Calls)) return res, nil } // Don't try bisecting if there's only one entry. if len(entries) == 1 { continue } // Execute all programs and bisect the log to find multiple guilty programs. res, err = ctx.extractProgBisect(reverseEntries(entries), timeout) if err != nil { return nil, err } if res != nil { ctx.reproLog(3, "found reproducer with %d syscalls", len(res.Prog.Calls)) return res, nil } } ctx.reproLog(0, "failed to extract reproducer") return nil, nil } 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.DefaultOpts(ctx.cfg) 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, } ctx.reproLog(3, "single: successfully extracted reproducer") return res, nil } } ctx.reproLog(3, "single: failed to extract reproducer") return nil, nil } 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.DefaultOpts(ctx.cfg) duration := func(entries int) time.Duration { return baseDuration + time.Duration((entries/4))*time.Second } // Bisect the log to find multiple guilty programs. entries, err := ctx.bisectProgs(entries, func(progs []*prog.LogEntry) (bool, error) { return ctx.testProgs(progs, duration(len(progs)), opts) }) if err != nil { return nil, err } if len(entries) == 0 { 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. prog := &prog.Prog{ Target: entries[0].P.Target, } for _, entry := range entries { prog.Calls = append(prog.Calls, entry.P.Calls...) } dur := duration(len(entries)) * 3 / 2 // Execute the program without fault injection. crashed, err := ctx.testProg(prog, dur, opts) if err != nil { return nil, err } if crashed { res := &Result{ Prog: prog, Duration: dur, Opts: opts, } ctx.reproLog(3, "bisect: concatenation succeeded") 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: prog, Duration: dur, Opts: opts, } ctx.reproLog(3, "bisect: concatenation succeeded with fault injection") return res, nil } } calls += len(entry.P.Calls) } ctx.reproLog(3, "bisect: concatenation failed") return nil, nil } // 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) }() call := -1 if res.Opts.Fault { call = res.Opts.FaultCall } res.Prog, res.Opts.FaultCall = prog.Minimize(res.Prog, call, true, func(p1 *prog.Prog, callIndex int) bool { crashed, err := ctx.testProg(p1, res.Duration, res.Opts) if err != nil { ctx.reproLog(0, "minimization failed with %v", err) return false } return crashed }) 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) }() for _, simplify := range progSimplifies { opts := res.Opts if !simplify(&opts) { continue } crashed, err := ctx.testProg(res.Prog, res.Duration, opts) if err != nil { return nil, err } if !crashed { continue } res.Opts = opts // Simplification successful, try extracting C repro. res, err = ctx.extractC(res) if err != nil { return nil, err } if res.CRepro { return res, nil } } return res, nil } // Try triggering crash with a C reproducer. 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) }() crashed, err := ctx.testCProg(res.Prog, res.Duration, res.Opts) if err != nil { return nil, err } res.CRepro = crashed return res, nil } // Try to simplify the C reproducer. 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) }() for _, simplify := range cSimplifies { opts := res.Opts if simplify(&opts) { crashed, err := ctx.testCProg(res.Prog, res.Duration, opts) if err != nil { return nil, err } if crashed { res.Opts = opts } } } return res, nil } func (ctx *context) testProg(p *prog.Prog, duration time.Duration, opts csource.Options) (crashed bool, err error) { entry := prog.LogEntry{P: p} if opts.Fault { entry.Fault = true entry.FaultCall = opts.FaultCall entry.FaultNth = opts.FaultNth } return ctx.testProgs([]*prog.LogEntry{&entry}, duration, opts) } 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 := encodeEntries(entries) progFile, err := osutil.WriteTempFile(pstr) if err != nil { return false, err } defer os.Remove(progFile) vmProgFile, err := inst.Copy(progFile) if err != nil { return false, fmt.Errorf("failed to copy to VM: %v", err) } if !opts.Fault { opts.FaultCall = -1 } 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 := instancePkg.ExecprogCmd(inst.execprogBin, inst.executorBin, ctx.cfg.TargetOS, ctx.cfg.TargetArch, opts.Sandbox, opts.Repeat, opts.Threaded, opts.Collide, opts.Procs, -1, -1, vmProgFile) ctx.reproLog(2, "testing program (duration=%v, %+v): %s", duration, opts, program) return ctx.testImpl(inst.Instance, command, duration) } func (ctx *context) testCProg(p *prog.Prog, duration time.Duration, opts csource.Options) (crashed bool, err error) { src, err := csource.Write(p, opts) if err != nil { return false, err } bin, err := csource.Build(p.Target, src) if err != nil { return false, err } defer os.Remove(bin) 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 } return crashed, nil } func (ctx *context) testBin(bin string, duration time.Duration) (crashed bool, err error) { inst := <-ctx.instances if inst == nil { return false, fmt.Errorf("all VMs failed to boot") } defer ctx.returnInstance(inst) bin, err = inst.Copy(bin) if err != nil { return false, fmt.Errorf("failed to copy to VM: %v", err) } return ctx.testImpl(inst.Instance, bin, duration) } func (ctx *context) testImpl(inst *vm.Instance, command string, duration time.Duration) (crashed bool, err error) { outc, errc, err := inst.Run(duration, nil, command) if err != nil { return false, fmt.Errorf("failed to run command in VM: %v", err) } rep := inst.MonitorExecution(outc, errc, ctx.reporter, true) if rep == nil { ctx.reproLog(2, "program did not crash") return false, nil } if rep.Suppressed { ctx.reproLog(2, "suppressed program crash: %v", rep.Title) return false, nil } ctx.report = rep ctx.reproLog(2, "program crashed: %v", rep.Title) return true, nil } func (ctx *context) returnInstance(inst *instance) { ctx.bootRequests <- inst.index inst.Close() } func (ctx *context) reproLog(level int, format string, args ...interface{}) { prefix := fmt.Sprintf("reproducing crash '%v': ", ctx.crashTitle) log.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)) ctx.reproLog(3, "bisect: executing all %d programs", len(progs)) crashed, err := pred(progs) if err != nil { return nil, err } if !crashed { ctx.reproLog(3, "bisect: didn't crash") return nil, nil } guilty := [][]*prog.LogEntry{progs} again: ctx.reproLog(3, "bisect: guilty chunks: %v", chunksToStr(guilty)) for i, chunk := range guilty { if len(chunk) == 1 { continue } guilty1 := guilty[:i] guilty2 := guilty[i+1:] ctx.reproLog(3, "bisect: guilty chunks split: %v, <%v>, %v", chunksToStr(guilty1), len(chunk), chunksToStr(guilty2)) chunk1 := chunk[0 : len(chunk)/2] chunk2 := chunk[len(chunk)/2:] ctx.reproLog(3, "bisect: chunk split: <%v> => <%v>, <%v>", len(chunk), len(chunk1), len(chunk2)) ctx.reproLog(3, "bisect: triggering crash without chunk #1") progs = flatenChunks(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...) ctx.reproLog(3, "bisect: crashed, chunk #1 evicted") goto again } ctx.reproLog(3, "bisect: triggering crash without chunk #2") progs = flatenChunks(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...) ctx.reproLog(3, "bisect: crashed, chunk #2 evicted") goto again } guilty = nil guilty = append(guilty, guilty1...) guilty = append(guilty, chunk1) guilty = append(guilty, chunk2) guilty = append(guilty, guilty2...) ctx.reproLog(3, "bisect: not crashed, both chunks required") 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]) } ctx.reproLog(3, "bisect: success, %d programs left", len(progs)) return progs, nil } func flatenChunks(guilty1, guilty2 [][]*prog.LogEntry, chunk []*prog.LogEntry) []*prog.LogEntry { var 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 } func chunksToStr(chunks [][]*prog.LogEntry) string { log := "[" for i, chunk := range chunks { log += fmt.Sprintf("<%d>", len(chunk)) if i != len(chunks)-1 { log += ", " } } log += "]" return log } 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() } type Simplify func(opts *csource.Options) bool var progSimplifies = []Simplify{ func(opts *csource.Options) bool { if !opts.Fault { return false } opts.Fault = false opts.FaultCall = 0 opts.FaultNth = 0 return true }, func(opts *csource.Options) bool { if !opts.Collide { return false } opts.Collide = false return true }, func(opts *csource.Options) bool { if opts.Collide || !opts.Threaded { return false } opts.Threaded = false return true }, func(opts *csource.Options) bool { if !opts.Repeat { return false } opts.Repeat = false opts.EnableCgroups = false opts.ResetNet = false opts.Procs = 1 return true }, func(opts *csource.Options) bool { if opts.Procs == 1 { return false } opts.Procs = 1 return true }, func(opts *csource.Options) bool { if opts.Sandbox == "none" { return false } opts.Sandbox = "none" return true }, } var cSimplifies = append(progSimplifies, []Simplify{ func(opts *csource.Options) bool { if opts.Sandbox == "" { return false } opts.Sandbox = "" opts.EnableTun = false opts.EnableCgroups = false opts.EnableNetdev = false opts.ResetNet = false return true }, func(opts *csource.Options) bool { if !opts.EnableTun { return false } opts.EnableTun = false return true }, func(opts *csource.Options) bool { if !opts.EnableCgroups { return false } opts.EnableCgroups = false return true }, func(opts *csource.Options) bool { if !opts.EnableNetdev { return false } opts.EnableNetdev = false return true }, func(opts *csource.Options) bool { if !opts.ResetNet { return false } opts.ResetNet = false return true }, func(opts *csource.Options) bool { if !opts.UseTmpDir || opts.Sandbox == "namespace" || opts.EnableCgroups { return false } opts.UseTmpDir = false return true }, func(opts *csource.Options) bool { if !opts.HandleSegv { return false } opts.HandleSegv = false return true }, }...)