vm: call finish callback always

Always call the finish callback to make control flow consistent
if VM crash/does not crash. Then users can rely on the callback
being always called.

Fix a bug highlighted by the extended test:
currently we call extractError/callback twice when the fuzzer is preempted.
If the fuzzer is preempted, extractError returns nil,
which makes appendOutput return nil as well,
which makes the main loop continue as if no crash/preemption happened.
It will exit, but only after 5 min "no output" timeout.
Most likley the output will still contain the preemption message,
so no "no output" will be reported, but the additional 5 min wait
is unnecessary.

2 files changed, 22 insertions, 6 deletions

diff --git a/vm/vm.go b/vm/vm.go
index 4887ef65e..4f31fd821 100644
--- a/vm/vm.go
+++ b/vm/vm.go
@@ -290,11 +290,17 @@ type monitor struct {
 	beforeContext   int
 	matchPos        int
 	lastExecuteTime time.Time
+	extractCalled   bool
 }
 
 func (mon *monitor) monitorExecution() *report.Report {
 	ticker := time.NewTicker(tickerPeriod * mon.inst.pool.timeouts.Scale)
 	defer ticker.Stop()
+	defer func() {
+		if mon.finished != nil {
+			mon.finished()
+		}
+	}()
 	for {
 		select {
 		case err := <-mon.errc:
@@ -327,11 +333,11 @@ func (mon *monitor) monitorExecution() *report.Report {
 				continue
 			}
 			mon.inst.pool.statOutputReceived.Add(len(out))
-			if rep := mon.appendOutput(out); rep != nil {
+			if rep, done := mon.appendOutput(out); done {
 				return rep
 			}
 		case out := <-mon.injected:
-			if rep := mon.appendOutput(out); rep != nil {
+			if rep, done := mon.appendOutput(out); done {
 				return rep
 			}
 		case <-ticker.C:
@@ -346,7 +352,7 @@ func (mon *monitor) monitorExecution() *report.Report {
 	}
 }
 
-func (mon *monitor) appendOutput(out []byte) *report.Report {
+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:], executingProgram1) ||
@@ -354,7 +360,7 @@ func (mon *monitor) appendOutput(out []byte) *report.Report {
 		mon.lastExecuteTime = time.Now()
 	}
 	if mon.reporter.ContainsCrash(mon.output[mon.matchPos:]) {
-		return mon.extractError("unknown error")
+		return mon.extractError("unknown error"), true
 	}
 	if len(mon.output) > 2*mon.beforeContext {
 		copy(mon.output, mon.output[len(mon.output)-mon.beforeContext:])
@@ -376,13 +382,18 @@ func (mon *monitor) appendOutput(out []byte) *report.Report {
 	if mon.matchPos < 0 {
 		mon.matchPos = 0
 	}
-	return nil
+	return nil, false
 }
 
 func (mon *monitor) extractError(defaultError string) *report.Report {
+	if mon.extractCalled {
+		panic("extractError called twice")
+	}
+	mon.extractCalled = true
 	if mon.finished != nil {
 		// If the caller wanted an early notification, provide it.
 		mon.finished()
+		mon.finished = nil
 	}
 	diagOutput, diagWait := []byte{}, false
 	if defaultError != "" {
diff --git a/vm/vm_test.go b/vm/vm_test.go
index 184f6137f..d523b2e4c 100644
--- a/vm/vm_test.go
+++ b/vm/vm_test.go
@@ -401,7 +401,9 @@ func testMonitorExecution(t *testing.T, test *Test) {
 		test.Body(testInst.outc, testInst.errc)
 		done <- true
 	}()
-	opts := []any{test.Exit}
+	finishCalled := 0
+	finishCb := EarlyFinishCb(func() { finishCalled++ })
+	opts := []any{test.Exit, finishCb}
 	if test.InjectOutput != "" {
 		c := make(chan []byte, 1)
 		c <- []byte(test.InjectOutput)
@@ -412,6 +414,9 @@ func testMonitorExecution(t *testing.T, test *Test) {
 		t.Fatal(err)
 	}
 	<-done
+	if finishCalled != 1 {
+		t.Fatalf("finish callback is called %v times", finishCalled)
+	}
 	if test.Report != nil && rep == nil {
 		t.Fatalf("got no report")
 	}