Log zfs errors line by line, instead of one escaped line

So instead of a long line "invalid option 'x'\nusage:\n list [-Hp] [-r|-d max] [-o property[,...]] [-s property]...\n [-S property]... [-t type[,...]] [filesystem|volume|snapshot] ..." now we log something like this: 2024/10/23 19:49:40 ERROR output: invalid option 'x' subsystem=zfs.cmd job=snap-1d 2024/10/23 19:49:40 ERROR output: usage: subsystem=zfs.cmd job=snap-1d 2024/10/23 19:49:40 ERROR output: list [-Hp] [-r|-d max] [-o property[,...]] [-s property]... subsystem=zfs.cmd job=snap-1d 2024/10/23 19:49:40 ERROR output: [-S property]... [-t type[,...]] [filesystem|volume|snapshot] ... subsystem=zfs.cmd job=snap-1d
dsh2dsh · Oct 23, 2024 · de7001d · de7001d
1 parent 1636f42
commit de7001d
Show file tree

Hide file tree

Showing 3 changed files with 39 additions and 12 deletions.
diff --git a/internal/zfs/zfs.go b/internal/zfs/zfs.go
@@ -169,8 +169,17 @@ type ZFSError struct {
 }
 
 func (self *ZFSError) Error() string {
-	return fmt.Sprintf("zfs exited with error: %s\nstderr:\n%s",
-		self.WaitErr.Error(), self.Stderr)
+	msg := "zfs exited with error: " + self.WaitErr.Error()
+	if len(self.Stderr) == 0 {
+		return msg
+	}
+
+	firstLine, leftBytes, _ := bytes.Cut(self.Stderr, []byte{'\n'})
+	msg += ": " + string(firstLine)
+	if len(leftBytes) != 0 {
+		return msg + fmt.Sprintf(": %d bytes left", len(leftBytes))
+	}
+	return msg
 }
 
 func (self *ZFSError) Unwrap() error {
@@ -228,6 +237,8 @@ func ZFSListIter(ctx context.Context, properties []string,
 		if err != nil {
 			if notExistHint != nil {
 				err = maybeDatasetNotExists(cmd, notExistHint.ToString(), err)
+			} else {
+				cmd.WithStderrOutput(stderrBuf.Bytes()).LogError(err, false)
 			}
 			yield(ZFSListResult{Err: err})
 		}
@@ -275,6 +286,7 @@ func maybeDatasetNotExists(cmd *zfscmd.Cmd, path string, err error) error {
 	}
 
 	if len(zfsError.Stderr) != 0 {
+		cmd.WithStderrOutput(zfsError.Stderr)
 		enotexist := tryDatasetDoesNotExist(path, zfsError.Stderr)
 		if enotexist != nil {
 			cmd.LogError(err, true)

diff --git a/internal/zfs/zfscmd/zfscmd.go b/internal/zfs/zfscmd/zfscmd.go
@@ -36,7 +36,7 @@ type Cmd struct {
 	waitReturnEndSpanCb                      trace.DoneFunc
 
 	usage        usage
-	stdoutStderr []byte
+	stderrOutput []byte
 	logError     bool
 
 	cmdLogger Logger
@@ -58,13 +58,18 @@ func (c *Cmd) WithPipeLen(n int) *Cmd {
 	return c
 }
 
+func (c *Cmd) WithStderrOutput(b []byte) *Cmd {
+	c.stderrOutput = b
+	return c
+}
+
 // err.(*exec.ExitError).Stderr will NOT be set
 func (c *Cmd) CombinedOutput() (o []byte, err error) {
 	c.startPre(false)
 	c.startPost(nil)
 	c.waitPre()
 	o, err = c.cmd.CombinedOutput()
-	c.stdoutStderr = o
+	c.stderrOutput = o
 	c.waitPost(err)
 	return
 }
@@ -222,8 +227,8 @@ func (c *Cmd) waitPost(err error) {
 		var exitError *exec.ExitError
 		if errors.As(err, &exitError) {
 			s = exitError.ProcessState
-			if c.stdoutStderr == nil {
-				c.stdoutStderr = exitError.Stderr
+			if c.stderrOutput == nil {
+				c.stderrOutput = exitError.Stderr
 			}
 		}
 	}

diff --git a/internal/zfs/zfscmd/zfscmd_logging.go b/internal/zfs/zfscmd/zfscmd_logging.go
@@ -1,9 +1,13 @@
 package zfscmd
 
 import (
+	"bufio"
+	"bytes"
 	"errors"
 	"os/exec"
 	"time"
+
+	"github.com/dsh2dsh/zrepl/internal/logger"
 )
 
 // Implementation Note:
@@ -45,13 +49,19 @@ func waitPostLogging(c *Cmd, err error, debug bool) {
 	if errors.As(err, &exitError) {
 		log = log.WithField("status", exitError.ExitCode())
 	}
-	if len(c.stdoutStderr) > 0 {
-		log = log.WithField("stderr", string(c.stdoutStderr))
-	}
 
+	level := logger.Error
 	if debug {
-		log.Debug("command exited with error")
-	} else {
-		log.Error("command exited with error")
+		level = logger.Debug
+	}
+	log.Log(level, "command exited with error")
+
+	if len(c.stderrOutput) == 0 {
+		return
+	}
+
+	s := bufio.NewScanner(bytes.NewReader(c.stderrOutput))
+	for s.Scan() {
+		c.log().Log(level, "output: "+s.Text())
 	}
 }