exec: cleanly separate stdout/stderr

Commit 40ba355 intentionally captured
stderr in the output because earlier it was hard to understand why LVM
commands failed. However, we now learned the some error messages can
be safely ignored and not doing so broke LVM mode: when /dev/sda is
unreadable, "vgs" prints a line about it on stderr, but the output on
stdout is fine.

Now we capture both output streams separately, log both, but only
return stdout to the caller.

The TestResult call is unrelated to that fix and will be used for
additional debugging in another PR. It gets added here because it can
use the same test cases and is related.

(cherry picked from commit 3a7c354)

pkg/exec/exec.go

@@ -32,27 +32,59 @@ func Run(cmd *exec.Cmd) (string, error) {
 	klog.V(4).Infof("Executing: %s", cmd)
 
 	r, w := io.Pipe()
+	r2, w2 := io.Pipe()
 	cmd.Stdout = w
-	cmd.Stderr = w
-	buffer := new(bytes.Buffer)
-	r2 := io.TeeReader(r, buffer)
+	cmd.Stderr = w2
+	var stdout, both bytes.Buffer
 	var wg sync.WaitGroup
-	wg.Add(1)
-	go func() {
-		defer wg.Done()
-		scanner := bufio.NewScanner(r2)
-		for scanner.Scan() {
-			klog.V(5).Infof("%s: %s", cmd.Path, scanner.Text())
-		}
-	}()
+	wg.Add(2)
+	// Collect stdout and stderr separately. Storing in the
+	// combined buffer is a bit racy, but we need to know which
+	// output is stdout.
+	go dumpOutput(&wg, r, []io.Writer{&stdout, &both}, cmd.Path+": stdout: ")
+	go dumpOutput(&wg, r2, []io.Writer{&both}, cmd.Path+": stderr: ")
 	err := cmd.Run()
 	w.Close()
+	w2.Close()
 	wg.Wait()
-	klog.V(4).Infof("%s terminated, with %d bytes of output and error %v", cmd.Path, buffer.Len(), err)
+	klog.V(4).Infof("%s terminated, with %d bytes of stdout, %d of combined output and error %v", cmd.Path, stdout.Len(), both.Len(), err)
+
+	switch {
+	case err != nil && both.Len() > 0:
+		err = fmt.Errorf("%q: command failed: %v\nCombined stderr/stdout output: %s", cmd, err, string(both.Bytes()))
+	case err != nil:
+		err = fmt.Errorf("%q: command failed with no output: %v", cmd, err)
+	}
+	return string(stdout.Bytes()), err
+}
+
+func dumpOutput(wg *sync.WaitGroup, in io.Reader, out []io.Writer, prefix string) {
+	defer wg.Done()
+	scanner := bufio.NewScanner(in)
+	for scanner.Scan() {
+		for _, o := range out {
+			o.Write(scanner.Bytes())
+			o.Write([]byte("\n"))
+		}
+		klog.V(5).Infof("%s%s", prefix, scanner.Text())
+	}
+}
 
-	output := string(buffer.Bytes())
-	if err != nil {
-		err = fmt.Errorf("command %q failed: %v\nOutput: %s", cmd, err, output)
+// CmdResult always returns an informative description of what command ran and what the
+// outcome (stdout+stderr, exit code if any) was. Logging is left entirely to the caller.
+func CmdResult(cmd string, args ...string) string {
+	c := exec.Command(cmd, args...)
+	output, err := c.CombinedOutput()
+	result := fmt.Sprintf("%q:", c)
+	switch {
+	case err != nil && len(output) == 0:
+		result += fmt.Sprintf(" command failed with no output: %v", err)
+	case err != nil:
+		result += fmt.Sprintf(" command failed: %v\nOutput:\n%s", err, string(output))
+	case len(output) > 0:
+		result += fmt.Sprintf("\n%s", output)
+	default:
+		result += " no output"
 	}
-	return output, err
+	return result
 }

pkg/exec/exec_test.go

@@ -7,68 +7,121 @@ SPDX-License-Identifier: Apache-2.0
 package exec
 
 import (
-	"strings"
 	"testing"
 
+	"github.com/stretchr/testify/assert"
+
 	"k8s.io/klog/v2"
 )
 
 func init() {
 	klog.InitFlags(nil)
 }
 
-func Test_Failure(t *testing.T) {
-	output, err := RunCommand("no-such-binary", "foo")
-	if err == nil {
-		t.Errorf("did not get expected error")
-	}
-	if output != "" {
-		t.Errorf("unexpected output: %q", output)
-	}
-}
+var testcases = map[string]struct {
+	cmd []string
 
-func Test_BadArgs(t *testing.T) {
-	badFile := "/no/such/file"
-	output, err := RunCommand("ls", badFile)
-	if err == nil {
-		t.Errorf("did not get expected error")
-	}
-	if strings.Index(output, badFile) == -1 {
-		t.Errorf("file name not in output: %q", output)
-	}
+	expectedError  string
+	expectedOutput string
+	expectedResult string
+}{
+	"no-such-binary": {
+		cmd:            []string{"no-such-binary", "foo"},
+		expectedError:  `"no-such-binary foo": command failed with no output: exec: "no-such-binary": executable file not found in $PATH`,
+		expectedResult: `"no-such-binary foo": command failed with no output: exec: "no-such-binary": executable file not found in $PATH`,
+	},
+	"bad-args": {
+		cmd: []string{"ls", "/no/such/file"},
+		expectedError: `"/bin/ls /no/such/file": command failed: exit status 2
+Combined stderr/stdout output: ls: cannot access '/no/such/file': No such file or directory
+`,
+		expectedResult: `"/bin/ls /no/such/file": command failed: exit status 2
+Output:
+ls: cannot access '/no/such/file': No such file or directory
+`,
+	},
+	"stdout": {
+		cmd: []string{"echo", "hello", "world"},
+		expectedOutput: `hello world
+`,
+		expectedResult: `"/bin/echo hello world":
+hello world
+`,
+	},
+	"stderr": {
+		cmd: []string{"sh", "-c", "echo >&2 hello world"},
+		expectedResult: `"/bin/sh -c echo >&2 hello world":
+hello world
+`,
+	},
+	"both": {
+		cmd: []string{"sh", "-c", "echo >&2 hello; echo world"},
+		expectedOutput: `world
+`,
+		expectedResult: `"/bin/sh -c echo >&2 hello; echo world":
+hello
+world
+`,
+	},
+	"stdout-with-error": {
+		cmd: []string{"sh", "-c", "echo hello world; exit 1"},
+		expectedOutput: `hello world
+`,
+		expectedError: `"/bin/sh -c echo hello world; exit 1": command failed: exit status 1
+Combined stderr/stdout output: hello world
+`,
+		expectedResult: `"/bin/sh -c echo hello world; exit 1": command failed: exit status 1
+Output:
+hello world
+`,
+	},
+	"stderr-with-error": {
+		cmd: []string{"sh", "-c", "echo >&2 hello world; exit 1"},
+		expectedError: `"/bin/sh -c echo >&2 hello world; exit 1": command failed: exit status 1
+Combined stderr/stdout output: hello world
+`,
+		expectedResult: `"/bin/sh -c echo >&2 hello world; exit 1": command failed: exit status 1
+Output:
+hello world
+`,
+	},
+	// This test case cannot be run reliably because ordering of stdout/stderr lines is random.
+	//
+	// 	"both-with-error": {
+	// 		cmd: []string{"sh", "-c", "echo >&2 hello; echo world; exit 1"},
+	// 		expectedOutput: `world
+	// `,
+	// 		expectedError: `"/bin/sh -c echo >&2 hello; echo world; exit 1": command failed: exit status 1
+	// Combined stderr/stdout output: world
+	// hello
+	// `,
+	// 		expectedResult: `"/bin/sh -c echo >&2 hello; echo world; exit 1": command failed: exit status 1
+	// Output:
+	// hello
+	// world
+	// `,
+	// },
 }
 
-func Test_Echo(t *testing.T) {
-	output, err := RunCommand("echo", "hello", "world")
-	if err != nil {
-		t.Errorf("unexpected error: %v", err)
-	}
-	if strings.Index(output, "hello world") == -1 {
-		t.Errorf("'hello world' not in output: %q", output)
+func TestRun(t *testing.T) {
+	for name, tc := range testcases {
+		t.Run(name, func(t *testing.T) {
+			output, err := RunCommand(tc.cmd[0], tc.cmd[1:]...)
+			assert.Equal(t, tc.expectedOutput, output, "output")
+			errStr := ""
+			if err != nil {
+				errStr = err.Error()
+			}
+			assert.Equal(t, tc.expectedError, errStr, "error")
+		})
 	}
 }
 
-func Test_Lines(t *testing.T) {
-	output, err := RunCommand("echo", "hello\nworld\n")
-	if err != nil {
-		t.Errorf("unexpected error: %v", err)
-	}
-	if strings.Index(output, "hello\nworld") == -1 {
-		t.Errorf("'hello\nworld' not in output: %q", output)
-	}
-}
-
-func Test_Error(t *testing.T) {
-	output, err := RunCommand("sh", "-c", "echo hello world && false")
-	if err == nil {
-		t.Fatal("unexpected success")
-	}
-	t.Logf("got expected error: %v", err)
-	if strings.Index(output, "hello world") == -1 {
-		t.Errorf("'hello world' not in output: %q", output)
-	}
-	msg := err.Error()
-	if strings.Index(msg, "Output: hello world") == -1 {
-		t.Errorf("'Output: hello world' not in error: %v", err)
+func TestResult(t *testing.T) {
+	for name, tc := range testcases {
+		t.Run(name, func(t *testing.T) {
+			result := CmdResult(tc.cmd[0], tc.cmd[1:]...)
+			assert.Equal(t, tc.expectedResult, result)
+		})
 	}
 }