testscript: print background command output on failure (#148)

When a script has failed, the output of the commands running in the
background can be useful to see, so display it then and also in verbose
mode.

Author: rogpeppe

cmd/testscript/main.go

@@ -13,6 +13,7 @@ import (
 	"os/exec"
 	"path/filepath"
 	"strings"
+	"sync/atomic"
 
 	"github.com/rogpeppe/go-internal/goproxytest"
 	"github.com/rogpeppe/go-internal/gotooltest"
@@ -335,6 +336,7 @@ func renderFilename(filename string) string {
 // runT implements testscript.T and is used in the call to testscript.Run
 type runT struct {
 	verbose bool
+	failed  int32
 }
 
 func (r runT) Skip(is ...interface{}) {
@@ -356,9 +358,14 @@ func (r runT) Log(is ...interface{}) {
 }
 
 func (r runT) FailNow() {
+	atomic.StoreInt32(&r.failed, 1)
 	panic(failedRun)
 }
 
+func (r runT) Failed() bool {
+	return atomic.LoadInt32(&r.failed) != 0
+}
+
 func (r runT) Run(n string, f func(t testscript.T)) {
 	// For now we we don't top/tail the run of a subtest. We are currently only
 	// running a single script in a testscript instance, which means that we

testscript/cmd.go

@@ -455,7 +455,10 @@ func (ts *TestScript) cmdWait(neg bool, args []string) {
 	if len(args) > 0 {
 		ts.Fatalf("usage: wait")
 	}
+	ts.waitBackground(true, neg)
+}
 
+func (ts *TestScript) waitBackground(checkStatus bool, neg bool) {
 	var stdouts, stderrs []string
 	for _, bg := range ts.background {
 		<-bg.wait
@@ -475,6 +478,9 @@ func (ts *TestScript) cmdWait(neg bool, args []string) {
 			stderrs = append(stderrs, cmdStderr)
 		}
 
+		if !checkStatus {
+			continue
+		}
 		if bg.cmd.ProcessState.Success() {
 			if bg.neg {
 				ts.Fatalf("unexpected command success")

testscript/testscript.go

@@ -174,6 +174,12 @@ type T interface {
 	Verbose() bool
 }
 
+// TFailed holds optional extra methods implemented on T.
+// It's defined as a separate type for backward compatibility reasons.
+type TFailed interface {
+	Failed() bool
+}
+
 type tshim struct {
 	*testing.T
 }
@@ -387,10 +393,16 @@ func (ts *TestScript) run() {
 		for _, bg := range ts.background {
 			interruptProcess(bg.cmd.Process)
 		}
-		for _, bg := range ts.background {
-			<-bg.wait
+		if ts.t.Verbose() || hasFailed(ts.t) {
+			// In verbose mode or on test failure, we want to see what happened in the background
+			// processes too.
+			ts.waitBackground(false, false)
+		} else {
+			for _, bg := range ts.background {
+				<-bg.wait
+			}
+			ts.background = nil
 		}
-		ts.background = nil
 
 		markTime()
 		// Flush testScript log to testing.T log.
@@ -516,6 +528,13 @@ Script:
 	}
 }
 
+func hasFailed(t T) bool {
+	if t, ok := t.(TFailed); ok {
+		return t.Failed()
+	}
+	return false
+}
+
 func (ts *TestScript) applyScriptUpdates() {
 	if len(ts.scriptUpdates) == 0 {
 		return

testscript/testscript_test.go

@@ -389,6 +389,7 @@ type fakeT struct {
 	log      bytes.Buffer
 	failMsgs []string
 	verbose  bool
+	failed   bool
 }
 
 var errAbort = errors.New("abort test")
@@ -398,6 +399,7 @@ func (t *fakeT) Skip(args ...interface{}) {
 }
 
 func (t *fakeT) Fatal(args ...interface{}) {
+	t.failed = true
 	t.failMsgs = append(t.failMsgs, fmt.Sprint(args...))
 	panic(errAbort)
 }
@@ -419,3 +421,7 @@ func (t *fakeT) Run(name string, f func(T)) {
 func (t *fakeT) Verbose() bool {
 	return t.verbose
 }
+
+func (t *fakeT) Failed() bool {
+	return t.failed
+}