Merge pull request #244 from xairy/up-better-repro

Bisect the log to find multiple guilty programs

2 files changed, 470 insertions, 99 deletions

diff --git a/pkg/repro/repro.go b/pkg/repro/repro.go
index 67fac81d7..d3f4bc6cb 100644
--- a/pkg/repro/repro.go
+++ b/pkg/repro/repro.go
@@ -4,6 +4,7 @@
 package repro
 
 import (
+	"bytes"
 	"fmt"
 	"os"
 	"path/filepath"
@@ -20,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 {
@@ -32,6 +43,7 @@ type context struct {
 	crashDesc    string
 	instances    chan *instance
 	bootRequests chan int
+	stats        Stats
 }
 
 type instance struct {
@@ -41,14 +53,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")
@@ -62,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,
@@ -70,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 {
@@ -88,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
@@ -128,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 {
@@ -136,8 +143,62 @@ func Run(crashLog []byte, cfg *mgrconfig.Config, vmPool *vm.Pool, vmIndexes []in
 	return res, err
 }
 
-func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error) {
-	Logf(2, "reproducing crash '%v': suspecting %v programs", ctx.crashDesc, len(entries))
+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 res, err
+	}
+	if res == nil {
+		return nil, nil
+	}
+
+	res, err = ctx.minimizeProg(res)
+	if err != nil {
+		return res, err
+	}
+
+	res, err = ctx.simplifyProg(res)
+	if err != nil {
+		return res, err
+	}
+
+	res, err = ctx.extractC(res)
+	if err != nil {
+		return res, err
+	}
+	if !res.CRepro {
+		res.Opts.Repro = false
+		return res, nil
+	}
+
+	res, err = ctx.simplifyC(res)
+	if err != nil {
+		return res, err
+	}
+
+	res.Opts.Repro = false
+	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)
@@ -154,6 +215,41 @@ func (ctx *context) reproExtractProg(entries []*prog.LogEntry) (*Result, error)
 		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 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.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
+		}
+	}
+
+	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.Options{
 		Threaded:   true,
 		Collide:    true,
@@ -168,52 +264,130 @@ 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,
 			}
-			crashed, err := ctx.testProg(ent.P, dur, 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.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
+	}
+
+	// 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 entries == nil {
+		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...)
+	}
+
+	// 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,
+		}
+		ctx.reproLog(3, "bisect: concatenation succeded")
+		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
+				ctx.reproLog(3, "bisect: concatenation succeeded with fault injection")
+				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
+	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
@@ -221,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(1, "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)
@@ -282,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)
@@ -294,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 {
@@ -368,54 +560,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 +598,20 @@ 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)
-	Logf(2, "reproducing crash '%v': testing program (duration=%v, %+v): %s",
-		ctx.crashDesc, duration, opts, p)
+	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)
+	ctx.reproLog(2, "testing program (duration=%v, %+v): %s", duration, opts, program)
 	return ctx.testImpl(inst.Instance, command, duration)
 }
 
@@ -454,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
@@ -485,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
 }
 
@@ -496,3 +670,137 @@ 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.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{}
+		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
+	}
+
+	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", logGuilty(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", logGuilty(guilty1), len(chunk), logGuilty(guilty2))
+
+		chunk1 := chunk[0 : len(chunk)/2]
+		chunk2 := chunk[len(chunk)/2 : len(chunk)]
+		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 := 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...)
+			ctx.reproLog(3, "bisect: crashed, chunk #1 evicted")
+			goto again
+		}
+
+		ctx.reproLog(3, "bisect: triggering crash without chunk #2")
+		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...)
+			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 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()
+}
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)
+			}
+		}
+	}
+}