fix: Improve debuggability of ptytest failures (#3367)

Since we were not failing tests with `require` the error output was
somewhat hidden in the stream of log messages. This change standardizes
`ptytest` logging and failing to improve visibility.

pty/ptytest/ptytest.go

@@ -4,6 +4,7 @@ import (
 	"bufio"
 	"bytes"
 	"context"
+	"fmt"
 	"io"
 	"os/exec"
 	"runtime"
@@ -21,6 +22,8 @@ import (
 )
 
 func New(t *testing.T) *PTY {
+	t.Helper()
+
 	ptty, err := pty.New()
 	require.NoError(t, err)
 
@@ -28,6 +31,8 @@ func New(t *testing.T) *PTY {
 }
 
 func Start(t *testing.T, cmd *exec.Cmd) (*PTY, pty.Process) {
+	t.Helper()
+
 	ptty, ps, err := pty.Start(cmd)
 	require.NoError(t, err)
 	return create(t, ptty, cmd.Args[0]), ps
@@ -42,14 +47,6 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY {
 		_ = logr.Close()
 		<-logDone // Guard against logging after test.
 	})
-	go func() {
-		defer close(logDone)
-		s := bufio.NewScanner(logr)
-		for s.Scan() {
-			// Quote output to avoid terminal escape codes, e.g. bell.
-			t.Logf("%s: stdout: %q", name, s.Text())
-		}
-	}()
 
 	// Write to log and output buffer.
 	copyDone := make(chan struct{})
@@ -66,19 +63,32 @@ func create(t *testing.T, ptty pty.PTY, name string) *PTY {
 		<-copyDone
 	})
 
-	return &PTY{
+	tpty := &PTY{
-		t:   t,
+		t:    t,
-		PTY: ptty,
+		PTY:  ptty,
-		out: out,
+		out:  out,
+		name: name,
 
 		runeReader: bufio.NewReaderSize(out, utf8.UTFMax),
 	}
+
+	go func() {
+		defer close(logDone)
+		s := bufio.NewScanner(logr)
+		for s.Scan() {
+			// Quote output to avoid terminal escape codes, e.g. bell.
+			tpty.logf("stdout: %q", s.Text())
+		}
+	}()
+
+	return tpty
 }
 
 type PTY struct {
-	t *testing.T
 	pty.PTY
-	out *stdbuf
+	t    *testing.T
+	out  *stdbuf
+	name string
 
 	runeReader *bufio.Reader
 }
@@ -113,17 +123,17 @@ func (p *PTY) ExpectMatch(str string) string {
 	select {
 	case err := <-match:
 		if err != nil {
-			p.t.Fatalf("%s: read error: %v (wanted %q; got %q)", time.Now(), err, str, buffer.String())
+			p.fatalf("read error", "%v (wanted %q; got %q)", err, str, buffer.String())
 			return ""
 		}
-		p.t.Logf("%s: matched %q = %q", time.Now(), str, buffer.String())
+		p.logf("matched %q = %q", str, buffer.String())
 		return buffer.String()
 	case <-timeout.Done():
 		// Ensure goroutine is cleaned up before test exit.
 		_ = p.out.closeErr(p.Close())
 		<-match
 
-		p.t.Fatalf("%s: match exceeded deadline: wanted %q; got %q", time.Now(), str, buffer.String())
+		p.fatalf("match exceeded deadline", "wanted %q; got %q", str, buffer.String())
 		return ""
 	}
 }
@@ -131,8 +141,9 @@ func (p *PTY) ExpectMatch(str string) string {
 func (p *PTY) Write(r rune) {
 	p.t.Helper()
 
+	p.logf("stdin: %q", r)
 	_, err := p.Input().Write([]byte{byte(r)})
-	require.NoError(p.t, err)
+	require.NoError(p.t, err, "write failed")
 }
 
 func (p *PTY) WriteLine(str string) {
@@ -142,8 +153,27 @@ func (p *PTY) WriteLine(str string) {
 	if runtime.GOOS == "windows" {
 		newline = append(newline, '\n')
 	}
+	p.logf("stdin: %q", str+string(newline))
 	_, err := p.Input().Write(append([]byte(str), newline...))
-	require.NoError(p.t, err)
+	require.NoError(p.t, err, "write line failed")
+}
+
+func (p *PTY) logf(format string, args ...interface{}) {
+	p.t.Helper()
+
+	// Match regular logger timestamp format, we seem to be logging in
+	// UTC in other places as well, so match here.
+	p.t.Logf("%s: %s: %s", time.Now().UTC().Format("2006-01-02 15:04:05.000"), p.name, fmt.Sprintf(format, args...))
+}
+
+func (p *PTY) fatalf(reason string, format string, args ...interface{}) {
+	p.t.Helper()
+
+	// Ensure the message is part of the normal log stream before
+	// failing the test.
+	p.logf("%s: %s", reason, fmt.Sprintf(format, args...))
+
+	require.FailNowf(p.t, reason, format, args...)
 }
 
 // stdbuf is like a buffered stdout, it buffers writes until read.