vm: add tests for MonitorExecution

This gives almost 100% coverage for MonitorExecution.
Test all corner cases like lost connection, no output,
diagnose, exiting/non-exiting programs, etc.

Update #875

2 files changed, 329 insertions, 13 deletions

diff --git a/vm/vm.go b/vm/vm.go
index ad323f80d..26bd21745 100644
--- a/vm/vm.go
+++ b/vm/vm.go
@@ -150,7 +150,7 @@ func (inst *Instance) MonitorExecution(outc <-chan []byte, errc <-chan error,
 		canExit:  canExit,
 	}
 	lastExecuteTime := time.Now()
-	ticker := time.NewTicker(10 * time.Second)
+	ticker := time.NewTicker(tickerPeriod)
 	defer ticker.Stop()
 	for {
 		select {
@@ -165,9 +165,13 @@ func (inst *Instance) MonitorExecution(outc <-chan []byte, errc <-chan error,
 			default:
 				// Note: connection lost can race with a kernel oops message.
 				// In such case we want to return the kernel oops.
-				return mon.extractError("lost connection to test machine")
+				return mon.extractError(lostConnectionCrash)
+			}
+		case out, ok := <-outc:
+			if !ok {
+				outc = nil
+				continue
 			}
-		case out := <-outc:
 			lastPos := len(mon.output)
 			mon.output = append(mon.output, out...)
 			if bytes.Contains(mon.output[lastPos:], executingProgram1) ||
@@ -197,14 +201,14 @@ func (inst *Instance) MonitorExecution(outc <-chan []byte, errc <-chan error,
 			// in 140-280s detection delay.
 			// So the current timeout is 5 mins (300s).
 			// We don't want it to be too long too because it will waste time on real hangs.
-			if time.Since(lastExecuteTime) < 5*time.Minute {
+			if time.Since(lastExecuteTime) < noOutputTimeout {
 				break
 			}
 			if inst.Diagnose() {
 				mon.waitForOutput()
 			}
 			rep := &report.Report{
-				Title:      "no output from test machine",
+				Title:      noOutputCrash,
 				Output:     mon.output,
 				Suppressed: report.IsSuppressed(mon.reporter, mon.output),
 			}
@@ -229,7 +233,7 @@ func (mon *monitor) extractError(defaultError string) *report.Report {
 	// Give it some time to finish writing the error message.
 	mon.inst.Diagnose()
 	mon.waitForOutput()
-	if bytes.Contains(mon.output, []byte("SYZ-FUZZER: PREEMPTED")) {
+	if bytes.Contains(mon.output, []byte(fuzzerPreemptedStr)) {
 		return nil
 	}
 	if !mon.reporter.ContainsCrash(mon.output[mon.matchPos:]) {
@@ -237,7 +241,7 @@ func (mon *monitor) extractError(defaultError string) *report.Report {
 			if mon.canExit {
 				return nil
 			}
-			defaultError = "lost connection to test machine"
+			defaultError = lostConnectionCrash
 		}
 		rep := &report.Report{
 			Title:      defaultError,
@@ -265,12 +269,12 @@ func (mon *monitor) extractError(defaultError string) *report.Report {
 }
 
 func (mon *monitor) waitForOutput() {
-	timer := time.NewTimer(10 * time.Second)
+	timer := time.NewTimer(waitForOutputTimeout)
+	defer timer.Stop()
 	for {
 		select {
 		case out, ok := <-mon.outc:
 			if !ok {
-				timer.Stop()
 				return
 			}
 			mon.output = append(mon.output, out...)
@@ -283,12 +287,23 @@ func (mon *monitor) waitForOutput() {
 }
 
 const (
-	beforeContext  = 1024 << 10
-	afterContext   = 128 << 10
 	maxErrorLength = 512
+
+	lostConnectionCrash  = "lost connection to test machine"
+	noOutputCrash        = "no output from test machine"
+	executingProgramStr1 = "executing program"  // syz-fuzzer output
+	executingProgramStr2 = "executed programs:" // syz-execprog output
+	fuzzerPreemptedStr   = "SYZ-FUZZER: PREEMPTED"
 )
 
 var (
-	executingProgram1 = []byte("executing program")  // syz-fuzzer output
-	executingProgram2 = []byte("executed programs:") // syz-execprog output
+	executingProgram1 = []byte(executingProgramStr1)
+	executingProgram2 = []byte(executingProgramStr2)
+
+	beforeContext = 1024 << 10
+	afterContext  = 128 << 10
+
+	tickerPeriod         = 10 * time.Second
+	noOutputTimeout      = 5 * time.Minute
+	waitForOutputTimeout = 10 * time.Second
 )
diff --git a/vm/vm_test.go b/vm/vm_test.go
new file mode 100644
index 000000000..1c66166f7
--- /dev/null
+++ b/vm/vm_test.go
@@ -0,0 +1,301 @@
+// Copyright 2018 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 vm
+
+import (
+	"bytes"
+	"fmt"
+	"io/ioutil"
+	"os"
+	"testing"
+	"time"
+
+	"github.com/google/syzkaller/pkg/mgrconfig"
+	"github.com/google/syzkaller/pkg/report"
+	"github.com/google/syzkaller/vm/vmimpl"
+)
+
+type testPool struct {
+}
+
+func (pool *testPool) Count() int {
+	return 1
+}
+
+func (pool *testPool) Create(workdir string, index int) (vmimpl.Instance, error) {
+	return &testInstance{
+		outc: make(chan []byte, 10),
+		errc: make(chan error, 1),
+	}, nil
+}
+
+type testInstance struct {
+	outc        chan []byte
+	errc        chan error
+	diagnoseBug bool
+}
+
+func (inst *testInstance) Copy(hostSrc string) (string, error) {
+	return "", nil
+}
+
+func (inst *testInstance) Forward(port int) (string, error) {
+	return "", nil
+}
+
+func (inst *testInstance) Run(timeout time.Duration, stop <-chan bool, command string) (
+	outc <-chan []byte, errc <-chan error, err error) {
+	return inst.outc, inst.errc, nil
+}
+
+func (inst *testInstance) Diagnose() bool {
+	if inst.diagnoseBug {
+		inst.outc <- []byte("BUG: DIAGNOSE\n")
+	} else {
+		inst.outc <- []byte("DIAGNOSE\n")
+	}
+	return true
+}
+
+func (inst *testInstance) Close() {
+}
+
+func init() {
+	beforeContext = 200
+	tickerPeriod = 1 * time.Second
+	noOutputTimeout = 5 * time.Second
+	waitForOutputTimeout = 3 * time.Second
+
+	ctor := func(env *vmimpl.Env) (vmimpl.Pool, error) {
+		return &testPool{}, nil
+	}
+	vmimpl.Register("test", ctor, false)
+}
+
+type Test struct {
+	Name        string
+	CanExit     bool // if the program is allowed to exit normally
+	DiagnoseBug bool // Diagnose produces output that is detected as kernel crash
+	Body        func(outc chan []byte, errc chan error)
+	Report      *report.Report
+}
+
+var tests = []*Test{
+	{
+		Name:    "program-exits-normally",
+		CanExit: true,
+		Body: func(outc chan []byte, errc chan error) {
+			time.Sleep(time.Second)
+			errc <- nil
+		},
+	},
+	{
+		Name: "program-exits-when-it-should-not",
+		Body: func(outc chan []byte, errc chan error) {
+			time.Sleep(time.Second)
+			errc <- nil
+		},
+		Report: &report.Report{
+			Title: lostConnectionCrash,
+		},
+	},
+	{
+		Name:        "#875-diagnose-bugs",
+		CanExit:     true,
+		DiagnoseBug: true,
+		Body: func(outc chan []byte, errc chan error) {
+			errc <- nil
+		},
+		Report: &report.Report{
+			Title: "BUG: DIAGNOSE",
+			// TODO: this is wrong.
+			Report: []byte(
+				"BUG: DIAGNOSE\n",
+			),
+		},
+	},
+	{
+		Name: "kernel-crashes",
+		Body: func(outc chan []byte, errc chan error) {
+			outc <- []byte("BUG: bad\n")
+			time.Sleep(time.Second)
+			outc <- []byte("other output\n")
+		},
+		Report: &report.Report{
+			Title: "BUG: bad",
+			Report: []byte(
+				"BUG: bad\n" +
+					"DIAGNOSE\n" +
+					"other output\n",
+			),
+		},
+	},
+	{
+		Name: "fuzzer-is-preempted",
+		Body: func(outc chan []byte, errc chan error) {
+			outc <- []byte("BUG: bad\n")
+			outc <- []byte(fuzzerPreemptedStr + "\n")
+		},
+	},
+	{
+		Name:    "program-exits-but-kernel-crashes-afterwards",
+		CanExit: true,
+		Body: func(outc chan []byte, errc chan error) {
+			errc <- nil
+			time.Sleep(time.Second)
+			outc <- []byte("BUG: bad\n")
+		},
+		Report: &report.Report{
+			Title: "BUG: bad",
+			// TODO: this is wrong.
+			Report: []byte(
+				"DIAGNOSE\n" +
+					"BUG: bad\n",
+			),
+		},
+	},
+	{
+		Name: "timeout",
+		Body: func(outc chan []byte, errc chan error) {
+			errc <- vmimpl.ErrTimeout
+		},
+	},
+	{
+		Name: "program-crashes",
+		Body: func(outc chan []byte, errc chan error) {
+			errc <- fmt.Errorf("error")
+		},
+		Report: &report.Report{
+			Title: lostConnectionCrash,
+		},
+	},
+	{
+		Name: "no-output-1",
+		Body: func(outc chan []byte, errc chan error) {
+		},
+		Report: &report.Report{
+			Title: noOutputCrash,
+		},
+	},
+	{
+		Name: "no-output-2",
+		Body: func(outc chan []byte, errc chan error) {
+			for i := 0; i < 5; i++ {
+				time.Sleep(time.Second)
+				outc <- []byte("something\n")
+			}
+		},
+		Report: &report.Report{
+			Title: noOutputCrash,
+		},
+	},
+	{
+		Name:    "no-no-output-1",
+		CanExit: true,
+		Body: func(outc chan []byte, errc chan error) {
+			for i := 0; i < 5; i++ {
+				time.Sleep(time.Second)
+				outc <- []byte(executingProgramStr1 + "\n")
+			}
+			errc <- nil
+		},
+	},
+	{
+		Name:    "no-no-output-2",
+		CanExit: true,
+		Body: func(outc chan []byte, errc chan error) {
+			for i := 0; i < 5; i++ {
+				time.Sleep(time.Second)
+				outc <- []byte(executingProgramStr2 + "\n")
+			}
+			errc <- nil
+		},
+	},
+	{
+		Name:    "outc-closed",
+		CanExit: true,
+		Body: func(outc chan []byte, errc chan error) {
+			close(outc)
+			time.Sleep(time.Second)
+			errc <- vmimpl.ErrTimeout
+		},
+	},
+	{
+		Name:    "lots-of-output",
+		CanExit: true,
+		Body: func(outc chan []byte, errc chan error) {
+			for i := 0; i < 100; i++ {
+				outc <- []byte("something\n")
+			}
+			time.Sleep(time.Second)
+			errc <- vmimpl.ErrTimeout
+		},
+	},
+}
+
+func TestMonitorExecution(t *testing.T) {
+	for _, test := range tests {
+		test := test
+		t.Run(test.Name, func(t *testing.T) {
+			t.Parallel()
+			testMonitorExecution(t, test)
+		})
+	}
+}
+
+func testMonitorExecution(t *testing.T, test *Test) {
+	dir, err := ioutil.TempDir("", "syz-vm-test")
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer os.RemoveAll(dir)
+	cfg := &mgrconfig.Config{
+		Workdir:      dir,
+		TargetOS:     "linux",
+		TargetArch:   "amd64",
+		TargetVMArch: "amd64",
+		Type:         "test",
+	}
+	pool, err := Create(cfg, false)
+	if err != nil {
+		t.Fatal(err)
+	}
+	reporter, err := report.NewReporter(cfg)
+	if err != nil {
+		t.Fatal(err)
+	}
+	inst, err := pool.Create(0)
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer inst.Close()
+	outc, errc, err := inst.Run(time.Second, nil, "")
+	if err != nil {
+		t.Fatal(err)
+	}
+	testInst := inst.impl.(*testInstance)
+	testInst.diagnoseBug = test.DiagnoseBug
+	done := make(chan bool)
+	go func() {
+		test.Body(testInst.outc, testInst.errc)
+		done <- true
+	}()
+	rep := inst.MonitorExecution(outc, errc, reporter, test.CanExit)
+	<-done
+	if test.Report != nil && rep == nil {
+		t.Fatalf("got no report")
+	}
+	if test.Report == nil && rep != nil {
+		t.Fatalf("got unexpected report: %v", rep.Title)
+	}
+	if test.Report == nil {
+		return
+	}
+	if test.Report.Title != rep.Title {
+		t.Fatalf("want title %q, got title %q", test.Report.Title, rep.Title)
+	}
+	if !bytes.Equal(test.Report.Report, rep.Report) {
+		t.Fatalf("want report:\n%s\n\ngot report:\n%s\n", test.Report.Report, rep.Report)
+	}
+}