openssh: improve command errors and debug logging (#377)

Consistently return a more informative error message when an SSH command
fails. The errors now contain the pid, the quoted command, and exit
code.

When debug logging is enabled, also write the full command when the
process starts and when it exits. If the command fails, indent and log
its stdout and stderr buffers. If it succeeds, only log stderr to avoid
logging private VM keys. Instead, the caller will redact, format, and
log a successful JSON response.

Author: gcurtis

internal/cloud/cloud.go

@@ -5,11 +5,9 @@ package cloud
 
 import (
 	"encoding/json"
-	"errors"
 	"fmt"
 	"log"
 	"os"
-	"os/exec"
 	"path/filepath"
 	"strings"
 	"time"
@@ -90,6 +88,11 @@ type vm struct {
 	VMPrivateKey string `json:"vm_private_key"`
 }
 
+func (vm vm) redact() *vm {
+	vm.VMPrivateKey = "***"
+	return &vm
+}
+
 func getVirtualMachine(username string) string {
 	client := openssh.Client{
 		Username: username,
@@ -101,26 +104,24 @@ func getVirtualMachine(username string) string {
 	if envGateway := os.Getenv("DEVBOX_GATEWAY"); envGateway != "" {
 		client.Hostname = envGateway
 	}
-	bytes, err := client.Exec("auth")
+	sshOut, err := client.Exec("auth")
 	if err != nil {
-		log.Println(err)
-		var exitErr *exec.ExitError
-		if errors.As(err, &exitErr) {
-			log.Printf("ssh %s stderr:\n%s", client.Hostname, string(exitErr.Stderr))
-		}
-		os.Exit(1)
-	}
-	debug.Log("ssh %s stdout:\n%s", client.Hostname, string(bytes))
+		log.Fatalln("error requesting VM:", err)
+	}
 	resp := &vm{}
-	err = json.Unmarshal(bytes, resp)
-	if err != nil {
-		log.Fatal(err)
+	if err := json.Unmarshal(sshOut, resp); err != nil {
+		log.Fatalf("error unmarshaling gateway response %q: %v", sshOut, err)
 	}
-	if resp.VMPrivateKey != "" {
-		err := openssh.AddVMKey(resp.VMHost, resp.VMPrivateKey)
-		if err != nil {
-			log.Fatal(err)
-		}
+	if redacted, err := json.MarshalIndent(resp.redact(), "\t", "  "); err == nil {
+		debug.Log("got gateway response:\n\t%s", redacted)
+	}
+	if resp.VMPrivateKey == "" {
+		return resp.VMHost
+	}
+
+	err = openssh.AddVMKey(resp.VMHost, resp.VMPrivateKey)
+	if err != nil {
+		log.Fatalf("error adding new VM key: %v", err)
 	}
 	return resp.VMHost
 }

internal/cloud/openssh/client.go

@@ -4,6 +4,7 @@
 package openssh
 
 import (
+	"bytes"
 	"fmt"
 	"net"
 	"os"
@@ -23,21 +24,29 @@ func (c *Client) Shell() error {
 	cmd := c.cmd("-t")
 	remoteCmd := fmt.Sprintf(`bash -l -c "start_devbox_shell.sh \"%s\""`, c.ProjectDirName)
 	cmd.Args = append(cmd.Args, remoteCmd)
-	debug.Log("running command: %s", cmd)
-
-	// Setup stdin, stdout, stderr
 	cmd.Stdin = os.Stdin
 	cmd.Stdout = os.Stdout
 	cmd.Stderr = os.Stderr
-
-	return cmd.Run()
+	return logCmdRun(cmd)
 }
 
 func (c *Client) Exec(remoteCmd string) ([]byte, error) {
 	sshCmd := c.cmd()
 	sshCmd.Args = append(sshCmd.Args, remoteCmd)
-	debug.Log("cmd/exec: %s", sshCmd)
-	return sshCmd.Output()
+
+	var stdout, stderr bytes.Buffer
+	sshCmd.Stdout = &stdout
+	sshCmd.Stderr = &stderr
+
+	err := logCmdRun(sshCmd)
+	logCmdOutput(sshCmd, "stderr", stderr.Bytes())
+	if err != nil {
+		// Only log output if there was an error, otherwise we might log
+		// a VM's private key.
+		logCmdOutput(sshCmd, "stdout", stdout.Bytes())
+		return nil, err
+	}
+	return stdout.Bytes(), nil
 }
 
 func (c *Client) cmd(sshArgs ...string) *exec.Cmd {
@@ -73,3 +82,41 @@ func destination(username, hostname string) string {
 
 	return result
 }
+
+func logCmdRun(cmd *exec.Cmd) error {
+	// Use cmd.Start so we can log the pid. Don't bother writing errors to
+	// the debug log since those will be printed anyway.
+	if err := cmd.Start(); err != nil {
+		return fmt.Errorf("openssh: start command %q: %w", cmd, err)
+	}
+	debug.Log("openssh: started process %d with command %q", cmd.Process.Pid, cmd)
+
+	if err := cmd.Wait(); err != nil {
+		return fmt.Errorf("openssh: process %d with command %q: %w",
+			cmd.Process.Pid, cmd, err)
+	}
+	debug.Log("openssh: process %d with command %q: exit status 0", cmd.Process.Pid, cmd)
+	return nil
+}
+
+func logCmdOutput(cmd *exec.Cmd, stdstream string, out []byte) {
+	out = bytes.TrimSpace(out)
+	if len(out) == 0 {
+		debug.Log("openssh: process %d with command %q: exit status %d: %s is empty",
+			cmd.Process.Pid, cmd, cmd.ProcessState.ExitCode(), stdstream)
+		return
+	}
+
+	out = bytes.ReplaceAll(out, []byte{'\n'}, []byte{'\n', '\t'})
+	max := 1 << 16 // 64 KiB
+	if overflow := len(out) - max; overflow > 0 {
+		out = bytes.TrimSpace(out[:max])
+		if overflow == 1 {
+			out = append(out, "...truncated 1 byte."...)
+		} else {
+			out = fmt.Appendf(out, "...truncated %d bytes.", overflow)
+		}
+	}
+	debug.Log("openssh: process %d with command %q: exit status %d: %s text:\n\t%s",
+		cmd.Process.Pid, cmd, cmd.ProcessState.ExitCode(), stdstream, out)
+}