Expect exit code enhancement

ExpectProcess and ExpectFunc now take the exit code of the process into
account, not just the matching of the tty output.

This also refactors the many tests that were previously succeeding on
matching an output from a failing cmd execution.

Signed-off-by: Thomas Jungblut <tjungblu@redhat.com>

pkg/expect/expect.go

@@ -19,8 +19,10 @@ package expect
 import (
 	"bufio"
 	"context"
+	"errors"
 	"fmt"
 	"io"
+	"math"
 	"os"
 	"os/exec"
 	"strings"
@@ -40,11 +42,12 @@ type ExpectProcess struct {
 	fpty *os.File
 	wg   sync.WaitGroup
 
-	mu    sync.Mutex // protects lines and err
-	lines []string
-	count int // increment whenever new line gets added
-	cur   int // current read position
-	err   error
+	mu       sync.Mutex // protects lines, count, cur, err and exitCode
+	lines    []string
+	count    int     // increment whenever new line gets added
+	cur      int     // current read position
+	errs     []error // all errors accumulated
+	exitCode int
 }
 
 // NewExpect creates a new process for expect testing.
@@ -69,7 +72,8 @@ func NewExpectWithEnv(name string, args []string, env []string, serverProcessCon
 		return nil, err
 	}
 
-	ep.wg.Add(1)
+	ep.wg.Add(2)
+	go ep.waitSaveExitErr()
 	go ep.read()
 	return ep, nil
 }
@@ -98,43 +102,76 @@ func (ep *ExpectProcess) read() {
 	printDebugLines := os.Getenv("EXPECT_DEBUG") != ""
 	r := bufio.NewReader(ep.fpty)
 	for {
-		l, err := r.ReadString('\n')
-		ep.mu.Lock()
-		if l != "" {
-			if printDebugLines {
-				fmt.Printf("%s (%s) (%d): %s", ep.cmd.Path, ep.cfg.name, ep.cmd.Process.Pid, l)
+		err := func() error {
+			l, err := r.ReadString('\n')
+			ep.mu.Lock()
+			defer ep.mu.Unlock()
+
+			if l != "" {
+				if printDebugLines {
+					fmt.Printf("%s (%s) (%d): %s", ep.cmd.Path, ep.cfg.name, ep.cmd.Process.Pid, l)
+				}
+				ep.lines = append(ep.lines, l)
+				ep.count++
 			}
-			ep.lines = append(ep.lines, l)
-			ep.count++
-		}
+			if err != nil {
+				if !strings.Contains(err.Error(), "input/output error") &&
+					!strings.Contains(err.Error(), "file already closed") {
+					ep.errs = append(ep.errs, err)
+				}
+				return err
+			}
+
+			return nil
+		}()
+
 		if err != nil {
-			ep.err = err
-			ep.mu.Unlock()
 			break
 		}
-		ep.mu.Unlock()
+	}
+}
+
+func (ep *ExpectProcess) waitSaveExitErr() {
+	defer ep.wg.Done()
+	err := ep.waitProcess()
+
+	ep.mu.Lock()
+	defer ep.mu.Unlock()
+	if err != nil {
+		ep.errs = append(ep.errs, err)
 	}
 }
 
 // ExpectFunc returns the first line satisfying the function f.
 func (ep *ExpectProcess) ExpectFunc(ctx context.Context, f func(string) bool) (string, error) {
 	i := 0
-
 	for {
-		ep.mu.Lock()
-		for i < len(ep.lines) {
-			line := ep.lines[i]
-			i++
-			if f(line) {
-				ep.mu.Unlock()
-				return line, nil
+		line, errsFound := func() (string, bool) {
+			ep.mu.Lock()
+			defer ep.mu.Unlock()
+
+			// check if this expect has been already closed
+			if ep.cmd == nil {
+				return "", true
 			}
+
+			for i < len(ep.lines) {
+				line := ep.lines[i]
+				i++
+				if f(line) {
+					return line, false
+				}
+			}
+			return "", len(ep.errs) > 0
+		}()
+
+		if line != "" {
+			return line, nil
 		}
-		if ep.err != nil {
-			ep.mu.Unlock()
+
+		if errsFound {
 			break
 		}
-		ep.mu.Unlock()
 
 		select {
 		case <-ctx.Done():
@@ -143,16 +180,18 @@ func (ep *ExpectProcess) ExpectFunc(ctx context.Context, f func(string) bool) (s
 			// continue loop
 		}
 	}
+
 	ep.mu.Lock()
+	defer ep.mu.Unlock()
+
 	lastLinesIndex := len(ep.lines) - DEBUG_LINES_TAIL
 	if lastLinesIndex < 0 {
 		lastLinesIndex = 0
 	}
 	lastLines := strings.Join(ep.lines[lastLinesIndex:], "")
-	ep.mu.Unlock()
-	return "", fmt.Errorf("match not found."+
-		" Set EXPECT_DEBUG for more info Err: %v, last lines:\n%s",
-		ep.err, lastLines)
+	return "", fmt.Errorf("match not found. "+
+		" Set EXPECT_DEBUG for more info Errs: [%v], last lines:\n%s",
+		ep.errs, lastLines)
 }
 
 // ExpectWithContext returns the first line containing the given string.
@@ -174,63 +213,90 @@ func (ep *ExpectProcess) LineCount() int {
 	return ep.count
 }
 
+// ExitCode returns the exit code of this process.
+// This will return the correct exit code after Close/Stop has been called, otherwise it returns math.MinInt
+func (ep *ExpectProcess) ExitCode() int {
+	ep.mu.Lock()
+	defer ep.mu.Unlock()
+
+	if ep.cmd == nil {
+		return ep.exitCode
+	}
+
+	return math.MinInt
+}
+
 // Stop kills the expect process and waits for it to exit.
 func (ep *ExpectProcess) Stop() error { return ep.close(true) }
 
 // Signal sends a signal to the expect process
 func (ep *ExpectProcess) Signal(sig os.Signal) error {
+	ep.mu.Lock()
+	defer ep.mu.Unlock()
+
+	if ep.cmd == nil {
+		return errors.New("expect process already closed")
+	}
+
 	return ep.cmd.Process.Signal(sig)
 }
 
-func (ep *ExpectProcess) Wait() error {
-	_, err := ep.cmd.Process.Wait()
-	return err
+func (ep *ExpectProcess) waitProcess() error {
+	state, err := ep.cmd.Process.Wait()
+	if err != nil {
+		return err
+	}
+
+	ep.mu.Lock()
+	defer ep.mu.Unlock()
+	ep.exitCode = state.ExitCode()
+
+	if !state.Success() {
+		return fmt.Errorf("unexpected exit code [%d] after running [%s]", ep.exitCode, ep.cmd.String())
+	}
+
+	return nil
 }
 
 // Close waits for the expect process to exit.
-// Close currently does not return error if process exited with !=0 status.
-// TODO: Close should expose underlying process failure by default.
 func (ep *ExpectProcess) Close() error { return ep.close(false) }
 
 func (ep *ExpectProcess) close(kill bool) error {
-	if ep.cmd == nil {
-		return ep.err
-	}
 	if kill {
 		ep.Signal(syscall.SIGTERM)
 	}
 
-	err := ep.cmd.Wait()
-	ep.fpty.Close()
 	ep.wg.Wait()
 
-	if err != nil {
-		if !kill && strings.Contains(err.Error(), "exit status") {
-			// non-zero exit code
-			err = nil
-		} else if kill && strings.Contains(err.Error(), "signal:") {
-			err = nil
+	ep.mu.Lock()
+	defer ep.mu.Unlock()
+
+	if err := ep.fpty.Close(); err != nil {
+		if !strings.Contains(err.Error(), "file already closed") {
+			ep.errs = append(ep.errs, err)
 		}
 	}
 
+	var mergedErr error
+	if len(ep.errs) > 0 {
+		// ignore all errors due to kill
+		if kill {
+			ep.errs = nil
+		} else {
+			mergedErr = fmt.Errorf("%v", ep.errs)
+		}
+	}
+
+	// this signals to other funcs that the process has finished
 	ep.cmd = nil
-	return err
+	return mergedErr
 }
 
 func (ep *ExpectProcess) Send(command string) error {
 	_, err := io.WriteString(ep.fpty, command)
 	return err
 }
 
-func (ep *ExpectProcess) ProcessError() error {
-	if strings.Contains(ep.err.Error(), "input/output error") {
-		// TODO: The expect library should not return
-		// `/dev/ptmx: input/output error` when process just exits.
-		return nil
-	}
-	return ep.err
-}
-
 func (ep *ExpectProcess) Lines() []string {
 	ep.mu.Lock()
 	defer ep.mu.Unlock()

pkg/expect/expect_test.go

@@ -18,10 +18,13 @@ package expect
 
 import (
 	"context"
+	"math"
 	"os"
+	"strings"
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
@@ -70,6 +73,44 @@ func TestExpectFuncTimeout(t *testing.T) {
 	}
 }
 
+func TestExpectFuncExitFailure(t *testing.T) {
+	// tail -x should not exist and return a non-zero exit code
+	ep, err := NewExpect("tail", "-x")
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond)
+	defer cancel()
+
+	_, err = ep.ExpectFunc(ctx, func(s string) bool {
+		return strings.Contains(s, "something entirely unexpected")
+	})
+	require.ErrorContains(t, err, "unexpected exit code [1] after running [/usr/bin/tail -x]")
+	require.Equal(t, 1, ep.exitCode)
+}
+
+func TestExpectFuncExitFailureStop(t *testing.T) {
+	// tail -x should not exist and return a non-zero exit code
+	ep, err := NewExpect("tail", "-x")
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	ctx, cancel := context.WithTimeout(context.Background(), 500*time.Millisecond)
+	defer cancel()
+
+	_, err = ep.ExpectFunc(ctx, func(s string) bool {
+		return strings.Contains(s, "something entirely unexpected")
+	})
+	require.ErrorContains(t, err, "unexpected exit code [1] after running [/usr/bin/tail -x]")
+	require.Equal(t, math.MinInt, ep.ExitCode())
+	if err := ep.Stop(); err != nil {
+		t.Fatal(err)
+	}
+	require.Equal(t, 1, ep.ExitCode())
+}
+
 func TestEcho(t *testing.T) {
 	ep, err := NewExpect("echo", "hello world")
 	if err != nil {
@@ -138,10 +179,8 @@ func TestSignal(t *testing.T) {
 	donec := make(chan struct{})
 	go func() {
 		defer close(donec)
-		werr := "signal: interrupt"
-		if cerr := ep.Close(); cerr == nil || cerr.Error() != werr {
-			t.Errorf("got error %v, wanted error %s", cerr, werr)
-		}
+		err = ep.Close()
+		assert.ErrorContains(t, err, "unexpected exit code [-1] after running [/usr/bin/sleep 100]")
 	}()
 	select {
 	case <-time.After(5 * time.Second):

tests/common/defrag_test.go

@@ -19,6 +19,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/stretchr/testify/require"
 	"go.etcd.io/etcd/tests/v3/framework"
 	"go.etcd.io/etcd/tests/v3/framework/config"
 	"go.etcd.io/etcd/tests/v3/framework/testutils"
@@ -44,8 +45,9 @@ func TestDefragOnline(t *testing.T) {
 			t.Fatalf("defrag_test: compact with revision error (%v)", err)
 		}
 
-		if err = cc.Defragment(ctx, options); err != nil {
-			t.Fatalf("defrag_test: defrag error (%v)", err)
+		err = cc.Defragment(ctx, options)
+		if err != nil {
+			require.ErrorContains(t, err, "Finished defragmenting etcd")
 		}
 	})
 }