vm: extract all the crashes from the log

2 files changed, 219 insertions, 51 deletions

diff --git a/vm/vm.go b/vm/vm.go
index 3aa86d6b6..e155fd8e5 100644
--- a/vm/vm.go
+++ b/vm/vm.go
@@ -294,7 +294,7 @@ func WithEarlyFinishCb(cb func()) func(*RunOptions) {
 // and the kernel console output. It detects kernel oopses in output, lost connections, hangs, etc.
 // Returns command+kernel output and a non-symbolized crash report (nil if no error happens).
 func (inst *Instance) Run(ctx context.Context, reporter *report.Reporter, command string, opts ...func(*RunOptions)) (
-	[]byte, *report.Report, error) {
+	[]byte, []*report.Report, error) {
 	runOptions := &RunOptions{
 		beforeContext: 128 << 10,
 		afterContext:  128 << 10,
@@ -316,8 +316,8 @@ func (inst *Instance) Run(ctx context.Context, reporter *report.Reporter, comman
 		reporter:        reporter,
 		lastExecuteTime: time.Now(),
 	}
-	rep := mon.monitorExecution()
-	return mon.output, rep, nil
+	reps := mon.monitorExecution()
+	return mon.output, reps, nil
 }
 
 func (inst *Instance) Info() ([]byte, error) {
@@ -327,11 +327,11 @@ func (inst *Instance) Info() ([]byte, error) {
 	return nil, nil
 }
 
-func (inst *Instance) diagnose(rep *report.Report) ([]byte, bool) {
-	if rep == nil {
-		panic("rep is nil")
+func (inst *Instance) diagnose(reps []*report.Report) ([]byte, bool) {
+	if len(reps) == 0 {
+		panic("reps is empty")
 	}
-	return inst.impl.Diagnose(rep)
+	return inst.impl.Diagnose(reps[0])
 }
 
 func (inst *Instance) Index() int {
@@ -368,7 +368,7 @@ type monitor struct {
 	extractCalled bool
 }
 
-func (mon *monitor) monitorExecution() *report.Report {
+func (mon *monitor) monitorExecution() []*report.Report {
 	ticker := time.NewTicker(mon.tickerPeriod * mon.inst.pool.timeouts.Scale)
 	defer ticker.Stop()
 	defer func() {
@@ -387,10 +387,10 @@ func (mon *monitor) monitorExecution() *report.Report {
 				if mon.exitCondition&ExitNormal == 0 {
 					crash = lostConnectionCrash
 				}
-				return mon.extractError(crash)
+				return mon.extractErrors(crash)
 			case ErrTimeout:
 				if mon.exitCondition&ExitTimeout == 0 {
-					return mon.extractError(timeoutCrash)
+					return mon.extractErrors(timeoutCrash)
 				}
 				return nil
 			default:
@@ -400,7 +400,7 @@ func (mon *monitor) monitorExecution() *report.Report {
 				if mon.exitCondition&ExitError == 0 {
 					crash = lostConnectionCrash
 				}
-				return mon.extractError(crash)
+				return mon.extractErrors(crash)
 			}
 		case out, ok := <-mon.outc:
 			if !ok {
@@ -417,7 +417,7 @@ func (mon *monitor) monitorExecution() *report.Report {
 			// Detect both "no output whatsoever" and "kernel episodically prints
 			// something to console, but fuzzer is not actually executing programs".
 			if time.Since(mon.lastExecuteTime) > mon.inst.pool.timeouts.NoOutput {
-				return mon.extractError(noOutputCrash)
+				return mon.extractErrors(noOutputCrash)
 			}
 		case <-Shutdown:
 			return nil
@@ -425,14 +425,14 @@ func (mon *monitor) monitorExecution() *report.Report {
 	}
 }
 
-func (mon *monitor) appendOutput(out []byte) (*report.Report, bool) {
+func (mon *monitor) appendOutput(out []byte) ([]*report.Report, bool) {
 	lastPos := len(mon.output)
 	mon.output = append(mon.output, out...)
 	if bytes.Contains(mon.output[lastPos:], []byte(executedProgramsStart)) {
 		mon.lastExecuteTime = time.Now()
 	}
 	if mon.reporter.ContainsCrash(mon.output[mon.curPos:]) {
-		return mon.extractError("unknown error"), true
+		return mon.extractErrors("unknown error"), true
 	}
 	if len(mon.output) > 2*mon.beforeContext {
 		copy(mon.output, mon.output[len(mon.output)-mon.beforeContext:])
@@ -455,7 +455,7 @@ func (mon *monitor) appendOutput(out []byte) (*report.Report, bool) {
 	return nil, false
 }
 
-func (mon *monitor) extractError(defaultError string) *report.Report {
+func (mon *monitor) extractErrors(defaultError string) []*report.Report {
 	if mon.extractCalled {
 		panic("extractError called twice")
 	}
@@ -466,7 +466,7 @@ func (mon *monitor) extractError(defaultError string) *report.Report {
 	}
 	diagOutput, diagWait := []byte{}, false
 	if defaultError != "" {
-		diagOutput, diagWait = mon.inst.diagnose(mon.createReport(defaultError))
+		diagOutput, diagWait = mon.inst.diagnose(mon.createReports(defaultError))
 	}
 	// Give it some time to finish writing the error message.
 	// But don't wait for "no output", we already waited enough.
@@ -480,45 +480,52 @@ func (mon *monitor) extractError(defaultError string) *report.Report {
 	}
 	if defaultError == "" && mon.reporter.ContainsCrash(mon.output[mon.curPos:]) {
 		// We did not call Diagnose above because we thought there is no error, so call it now.
-		diagOutput, diagWait = mon.inst.diagnose(mon.createReport(defaultError))
+		diagOutput, diagWait = mon.inst.diagnose(mon.createReports(defaultError))
 		if diagWait {
 			mon.waitForOutput()
 		}
 	}
-	rep := mon.createReport(defaultError)
-	if rep == nil {
+	reps := mon.createReports(defaultError)
+	if len(reps) == 0 {
 		return nil
 	}
 	if len(diagOutput) > 0 {
-		rep.Output = append(rep.Output, vmDiagnosisStart...)
-		rep.Output = append(rep.Output, diagOutput...)
+		reps[0].Output = append(reps[0].Output, vmDiagnosisStart...)
+		reps[0].Output = append(reps[0].Output, diagOutput...)
 	}
-	return rep
+	return reps
 }
 
-func (mon *monitor) createReport(defaultError string) *report.Report {
-	rep := mon.reporter.ParseFrom(mon.output, mon.curPos)
-	if rep == nil {
-		if defaultError == "" {
-			return nil
-		}
-		typ := crash.UnknownType
-		if defaultError == lostConnectionCrash {
-			typ = crash.LostConnection
+func (mon *monitor) createReports(defaultError string) []*report.Report {
+	curPos := mon.curPos
+	var res []*report.Report
+	for {
+		rep := mon.reporter.ParseFrom(mon.output, curPos)
+		if rep == nil {
+			if defaultError == "" || len(res) > 0 {
+				return res
+			}
+			typ := crash.UnknownType
+			if defaultError == lostConnectionCrash {
+				typ = crash.LostConnection
+			}
+			return []*report.Report{{
+				Title:      defaultError,
+				Output:     mon.output,
+				Suppressed: report.IsSuppressed(mon.reporter, mon.output),
+				Type:       typ,
+			}}
 		}
-		return &report.Report{
-			Title:      defaultError,
-			Output:     mon.output,
-			Suppressed: report.IsSuppressed(mon.reporter, mon.output),
-			Type:       typ,
+		curPos = rep.SkipPos
+		start := max(rep.StartPos-mon.beforeContext, 0)
+		end := min(rep.EndPos+mon.afterContext, len(rep.Output))
+		rep.Output = rep.Output[start:end]
+		rep.StartPos -= start
+		rep.EndPos -= start
+		if len(res) == 0 || (len(res) > 0 && !rep.Corrupted && !rep.Suppressed) {
+			res = append(res, rep)
 		}
 	}
-	start := max(rep.StartPos-mon.beforeContext, 0)
-	end := min(rep.EndPos+mon.afterContext, len(rep.Output))
-	rep.Output = rep.Output[start:end]
-	rep.StartPos -= start
-	rep.EndPos -= start
-	return rep
 }
 
 func (mon *monitor) waitForOutput() {
diff --git a/vm/vm_test.go b/vm/vm_test.go
index 5034b1fa3..446898bd6 100644
--- a/vm/vm_test.go
+++ b/vm/vm_test.go
@@ -7,6 +7,7 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"strings"
 	"testing"
 	"time"
 
@@ -15,6 +16,7 @@ import (
 	"github.com/google/syzkaller/pkg/report/crash"
 	"github.com/google/syzkaller/sys/targets"
 	"github.com/google/syzkaller/vm/vmimpl"
+	"github.com/stretchr/testify/assert"
 )
 
 type testPool struct {
@@ -349,8 +351,7 @@ func TestMonitorExecution(t *testing.T) {
 	}
 }
 
-func testMonitorExecution(t *testing.T, test *Test) {
-	dir := t.TempDir()
+func makeLinuxAMD64Futex(t *testing.T) (*Instance, *report.Reporter) {
 	cfg := &mgrconfig.Config{
 		Derived: mgrconfig.Derived{
 			TargetOS:     targets.Linux,
@@ -363,14 +364,14 @@ func testMonitorExecution(t *testing.T, test *Test) {
 			},
 			SysTarget: targets.Get(targets.Linux, targets.AMD64),
 		},
-		Workdir: dir,
+		Workdir: t.TempDir(),
 		Type:    "test",
 	}
 	pool, err := Create(cfg, false)
 	if err != nil {
 		t.Fatal(err)
 	}
-	defer pool.Close()
+	t.Cleanup(func() { pool.Close() })
 	reporter, err := report.NewReporter(cfg)
 	if err != nil {
 		t.Fatal(err)
@@ -379,7 +380,12 @@ func testMonitorExecution(t *testing.T, test *Test) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	defer inst.Close()
+	t.Cleanup(func() { inst.Close() })
+	return inst, reporter
+}
+
+func testMonitorExecution(t *testing.T, test *Test) {
+	inst, reporter := makeLinuxAMD64Futex(t)
 	testInst := inst.impl.(*testInstance)
 	testInst.diagnoseBug = test.DiagnoseBug
 	testInst.diagnoseNoWait = test.DiagnoseNoWait
@@ -399,7 +405,7 @@ func testMonitorExecution(t *testing.T, test *Test) {
 		test.BodyExecuting(testInst.outc, testInst.errc, inject)
 		done <- true
 	}()
-	_, rep, err := inst.Run(context.Background(), reporter, "",
+	_, reps, err := inst.Run(context.Background(), reporter, "",
 		withTestRunOptionsDefaults(),
 		WithExitCondition(test.Exit),
 		WithEarlyFinishCb(func() { finishCalled++ }),
@@ -412,15 +418,16 @@ func testMonitorExecution(t *testing.T, test *Test) {
 	if finishCalled != 1 {
 		t.Fatalf("finish callback is called %v times", finishCalled)
 	}
-	if test.Report != nil && rep == nil {
+	if test.Report != nil && len(reps) == 0 {
 		t.Fatalf("got no report")
 	}
-	if test.Report == nil && rep != nil {
-		t.Fatalf("got unexpected report: %v", rep.Title)
+	if test.Report == nil && len(reps) != 0 {
+		t.Fatalf("got unexpected report: %v", reps[0].Title)
 	}
 	if test.Report == nil {
 		return
 	}
+	rep := reps[0]
 	if test.Report.Title != rep.Title {
 		t.Fatalf("want title %q, got title %q", test.Report.Title, rep.Title)
 	}
@@ -450,3 +457,157 @@ func TestVMType(t *testing.T) {
 		}
 	}
 }
+
+func TestExtractMultipleErrors(t *testing.T) {
+	inst, reporter := makeLinuxAMD64Futex(t)
+	mon := &monitor{
+		RunOptions: &RunOptions{},
+		inst:       inst,
+		reporter:   reporter,
+		output:     []byte(validKASANReport + strings.Repeat(someLine, 10) + validKASANReport),
+	}
+	reps := mon.extractErrors("unknown error")
+	assert.Len(t, reps, 2, "expected to see 2 reports, got %v", len(reps))
+	assert.Equal(t, reps[0].Title, reps[1].Title)
+	assert.False(t, reps[0].Corrupted)
+	assert.False(t, reps[1].Corrupted)
+}
+
+const someLine = "[   96.999999] some message \n"
+const validKASANReport = `
+[   96.262735] BUG: KASAN: double-free or invalid-free in selinux_tun_dev_free_security+0x15/0x20
+[   96.271481] 
+[   96.273098] CPU: 0 PID: 11514 Comm: syz-executor5 Not tainted 4.12.0-rc7+ #2
+[   96.280268] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
+[   96.289602] Call Trace:
+[   96.292180]  dump_stack+0x194/0x257
+[   96.295796]  ? arch_local_irq_restore+0x53/0x53
+[   96.300454]  ? load_image_and_restore+0x10f/0x10f
+[   96.305299]  ? selinux_tun_dev_free_security+0x15/0x20
+[   96.310565]  print_address_description+0x7f/0x260
+[   96.315393]  ? selinux_tun_dev_free_security+0x15/0x20
+[   96.320656]  ? selinux_tun_dev_free_security+0x15/0x20
+[   96.325919]  kasan_report_double_free+0x55/0x80
+[   96.330577]  kasan_slab_free+0xa0/0xc0
+[   96.334450]  kfree+0xd3/0x260
+[   96.337545]  selinux_tun_dev_free_security+0x15/0x20
+[   96.342636]  security_tun_dev_free_security+0x48/0x80
+[   96.347822]  __tun_chr_ioctl+0x2cc1/0x3d60
+[   96.352054]  ? tun_chr_close+0x60/0x60
+[   96.355925]  ? lock_downgrade+0x990/0x990
+[   96.360059]  ? lock_release+0xa40/0xa40
+[   96.364025]  ? __lock_is_held+0xb6/0x140
+[   96.368213]  ? check_same_owner+0x320/0x320
+[   96.372530]  ? tun_chr_compat_ioctl+0x30/0x30
+[   96.377005]  tun_chr_ioctl+0x2a/0x40
+[   96.380701]  ? tun_chr_ioctl+0x2a/0x40
+[   96.385099]  do_vfs_ioctl+0x1b1/0x15c0
+[   96.388981]  ? ioctl_preallocate+0x2d0/0x2d0
+[   96.393378]  ? selinux_capable+0x40/0x40
+[   96.397430]  ? SyS_futex+0x2b0/0x3a0
+[   96.401147]  ? security_file_ioctl+0x89/0xb0
+[   96.405547]  SyS_ioctl+0x8f/0xc0
+[   96.408912]  entry_SYSCALL_64_fastpath+0x1f/0xbe
+[   96.413651] RIP: 0033:0x4512c9
+[   96.416824] RSP: 002b:00007fc65827bc08 EFLAGS: 00000216 ORIG_RAX: 0000000000000010
+[   96.424603] RAX: ffffffffffffffda RBX: 0000000000718000 RCX: 00000000004512c9
+[   96.431863] RDX: 000000002053c000 RSI: 00000000400454ca RDI: 0000000000000005
+[   96.439133] RBP: 0000000000000082 R08: 0000000000000000 R09: 0000000000000000
+[   96.446389] R10: 0000000000000000 R11: 0000000000000216 R12: 00000000004baa97
+[   96.453647] R13: 00000000ffffffff R14: 0000000020124ff3 R15: 0000000000000000
+[   96.460931] 
+[   96.462552] Allocated by task 11514:
+[   96.466258]  save_stack_trace+0x16/0x20
+[   96.470212]  save_stack+0x43/0xd0
+[   96.473649]  kasan_kmalloc+0xaa/0xd0
+[   96.477347]  kmem_cache_alloc_trace+0x101/0x6f0
+[   96.481995]  selinux_tun_dev_alloc_security+0x49/0x170
+[   96.487250]  security_tun_dev_alloc_security+0x6d/0xa0
+[   96.492508]  __tun_chr_ioctl+0x16bc/0x3d60
+[   96.496722]  tun_chr_ioctl+0x2a/0x40
+[   96.500417]  do_vfs_ioctl+0x1b1/0x15c0
+[   96.504282]  SyS_ioctl+0x8f/0xc0
+[   96.507630]  entry_SYSCALL_64_fastpath+0x1f/0xbe
+[   96.512367] 
+[   96.513973] Freed by task 11514:
+[   96.517323]  save_stack_trace+0x16/0x20
+[   96.521276]  save_stack+0x43/0xd0
+[   96.524709]  kasan_slab_free+0x6e/0xc0
+[   96.528577]  kfree+0xd3/0x260
+[   96.531666]  selinux_tun_dev_free_security+0x15/0x20
+[   96.536747]  security_tun_dev_free_security+0x48/0x80
+[   96.541918]  tun_free_netdev+0x13b/0x1b0
+[   96.545959]  register_netdevice+0x8d0/0xee0
+[   96.550260]  __tun_chr_ioctl+0x1bae/0x3d60
+[   96.554475]  tun_chr_ioctl+0x2a/0x40
+[   96.558169]  do_vfs_ioctl+0x1b1/0x15c0
+[   96.562035]  SyS_ioctl+0x8f/0xc0
+[   96.565385]  entry_SYSCALL_64_fastpath+0x1f/0xbe
+[   96.570116] 
+[   96.571724] The buggy address belongs to the object at ffff8801d5961a40
+[   96.571724]  which belongs to the cache kmalloc-32 of size 32
+[   96.584186] The buggy address is located 0 bytes inside of
+[   96.584186]  32-byte region [ffff8801d5961a40, ffff8801d5961a60)
+[   96.595775] The buggy address belongs to the page:
+[   96.600686] page:ffffea00066b8d38 count:1 mapcount:0 mapping:ffff8801d5961000 index:0xffff8801d5961fc1
+[   96.610118] flags: 0x200000000000100(slab)
+[   96.614335] raw: 0200000000000100 ffff8801d5961000 ffff8801d5961fc1 000000010000003f
+[   96.622292] raw: ffffea0006723300 ffffea00066738b8 ffff8801dbc00100
+[   96.628675] page dumped because: kasan: bad access detected
+[   96.634373] 
+[   96.635978] Memory state around the buggy address:
+[   96.640884]  ffff8801d5961900: 00 00 01 fc fc fc fc fc 00 00 00 fc fc fc fc fc
+[   96.648222]  ffff8801d5961980: 00 00 00 00 fc fc fc fc fb fb fb fb fc fc fc fc
+[   96.655567] >ffff8801d5961a00: 00 00 00 fc fc fc fc fc fb fb fb fb fc fc fc fc
+[   96.663255]                                            ^
+[   96.668685]  ffff8801d5961a80: fb fb fb fb fc fc fc fc 00 00 00 fc fc fc fc fc
+[   96.676022]  ffff8801d5961b00: 04 fc fc fc fc fc fc fc fb fb fb fb fc fc fc fc
+[   96.683357] ==================================================================
+[   96.690692] Disabling lock debugging due to kernel taint
+[   96.696117] Kernel panic - not syncing: panic_on_warn set ...
+[   96.696117] 
+[   96.703470] CPU: 0 PID: 11514 Comm: syz-executor5 Tainted: G    B           4.12.0-rc7+ #2
+[   96.711847] Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
+[   96.721354] Call Trace:
+[   96.723926]  dump_stack+0x194/0x257
+[   96.727539]  ? arch_local_irq_restore+0x53/0x53
+[   96.732366]  ? kasan_end_report+0x32/0x50
+[   96.736497]  ? lock_downgrade+0x990/0x990
+[   96.740631]  panic+0x1e4/0x3fb
+[   96.743807]  ? percpu_up_read_preempt_enable.constprop.38+0xae/0xae
+[   96.750194]  ? add_taint+0x40/0x50
+[   96.753723]  ? selinux_tun_dev_free_security+0x15/0x20
+[   96.758976]  ? selinux_tun_dev_free_security+0x15/0x20
+[   96.764233]  kasan_end_report+0x50/0x50
+[   96.768192]  kasan_report_double_free+0x72/0x80
+[   96.772843]  kasan_slab_free+0xa0/0xc0
+[   96.776711]  kfree+0xd3/0x260
+[   96.779802]  selinux_tun_dev_free_security+0x15/0x20
+[   96.784886]  security_tun_dev_free_security+0x48/0x80
+[   96.790061]  __tun_chr_ioctl+0x2cc1/0x3d60
+[   96.794285]  ? tun_chr_close+0x60/0x60
+[   96.798152]  ? lock_downgrade+0x990/0x990
+[   96.802803]  ? lock_release+0xa40/0xa40
+[   96.806763]  ? __lock_is_held+0xb6/0x140
+[   96.810829]  ? check_same_owner+0x320/0x320
+[   96.815137]  ? tun_chr_compat_ioctl+0x30/0x30
+[   96.819611]  tun_chr_ioctl+0x2a/0x40
+[   96.823306]  ? tun_chr_ioctl+0x2a/0x40
+[   96.827181]  do_vfs_ioctl+0x1b1/0x15c0
+[   96.831057]  ? ioctl_preallocate+0x2d0/0x2d0
+[   96.835450]  ? selinux_capable+0x40/0x40
+[   96.839494]  ? SyS_futex+0x2b0/0x3a0
+[   96.843200]  ? security_file_ioctl+0x89/0xb0
+[   96.847590]  SyS_ioctl+0x8f/0xc0
+[   96.850941]  entry_SYSCALL_64_fastpath+0x1f/0xbe
+[   96.855676] RIP: 0033:0x4512c9
+[   96.859020] RSP: 002b:00007fc65827bc08 EFLAGS: 00000216 ORIG_RAX: 0000000000000010
+[   96.866708] RAX: ffffffffffffffda RBX: 0000000000718000 RCX: 00000000004512c9
+[   96.873956] RDX: 000000002053c000 RSI: 00000000400454ca RDI: 0000000000000005
+[   96.881208] RBP: 0000000000000082 R08: 0000000000000000 R09: 0000000000000000
+[   96.888461] R10: 0000000000000000 R11: 0000000000000216 R12: 00000000004baa97
+[   96.895708] R13: 00000000ffffffff R14: 0000000020124ff3 R15: 0000000000000000
+[   96.903943] Dumping ftrace buffer:
+[   96.907460]    (ftrace buffer empty)
+[   96.911148] Kernel Offset: disabled
+`