fix: rework output handling in restic pkg to improve error capturing and consistency

internal/ioutil/ioutil.go

@@ -19,7 +19,7 @@ func (l *LimitWriter) Write(p []byte) (rnw int, err error) {
 	rnw = len(p)
 	if l.N <= 0 {
 		l.D += len(p)
-		return 0, nil
+		return
 	}
 	if len(p) > l.N {
 		l.D += len(p) - l.N

pkg/restic/error.go

@@ -1,7 +1,7 @@
 package restic
 
 import (
-	"context"
+	"bytes"
 	"fmt"
 	"os/exec"
 )
@@ -28,7 +28,7 @@ func (e *CmdError) Is(target error) bool {
 }
 
 // newCmdError creates a new error indicating that running a command failed.
-func newCmdError(ctx context.Context, cmd *exec.Cmd, err error) *CmdError {
+func newCmdError(cmd *exec.Cmd, err error) *CmdError {
 	shortCmd := cmd.String()
 	if len(shortCmd) > 100 {
 		shortCmd = shortCmd[:100] + "..."
@@ -59,18 +59,38 @@ func (e *ErrorWithOutput) Is(target error) bool {
 	return ok
 }
 
-// newErrorWithOutput creates a new error with the given output.
-func newErrorWithOutput(err error, output string) error {
-	if output == "" {
+type errorMessageCollector struct {
+	Output       *bytes.Buffer
+	DroppedBytes int
+}
+
+func (e *errorMessageCollector) Write(p []byte) (int, error) {
+	if e.Output == nil {
+		e.Output = &bytes.Buffer{}
+	}
+	if e.Output.Len() >= outputBufferLimit {
+		e.DroppedBytes += len(p)
+		return len(p), nil
+	}
+	return e.Output.Write(p)
+}
+
+func (e *errorMessageCollector) AddOutputToError(err error) error {
+	if e.Output == nil {
 		return err
 	}
-
-	if len(output) > outputBufferLimit {
-		output = output[:outputBufferLimit] + fmt.Sprintf("\n... %d bytes truncated ...\n", len(output)-outputBufferLimit)
+	if e.DroppedBytes > 0 {
+		return &ErrorWithOutput{
+			Err:    err,
+			Output: fmt.Sprintf("%s\n... %d bytes truncated ...", e.Output.String(), e.DroppedBytes),
+		}
 	}
-
 	return &ErrorWithOutput{
 		Err:    err,
-		Output: output,
+		Output: e.Output.String(),
 	}
 }
+
+func (e *errorMessageCollector) AddCmdOutputToError(cmd *exec.Cmd, err error) error {
+	return newCmdError(cmd, e.AddOutputToError(err))
+}

pkg/restic/outputs.go

@@ -2,7 +2,6 @@ package restic
 
 import (
 	"bufio"
-	"bytes"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -210,7 +209,7 @@ func processProgressOutput[T ProgressEntryValidator](
 	scanner := bufio.NewScanner(output)
 	scanner.Split(bufio.ScanLines)
 
-	nonJSONOutput := bytes.NewBuffer(nil)
+	nonJSONOutput := &errorMessageCollector{}
 	var captureNonJSON io.Writer = nonJSONOutput
 	if logger != nil {
 		captureNonJSON = io.MultiWriter(nonJSONOutput, logger)
@@ -230,7 +229,7 @@ func processProgressOutput[T ProgressEntryValidator](
 		}
 
 		if err := event.IsFatalError(); err != nil {
-			return summary, newErrorWithOutput(fmt.Errorf("restic died with error: %v", err), nonJSONOutput.String())
+			return summary, nonJSONOutput.AddOutputToError(err)
 		}
 
 		if err := event.Validate(); err != nil {
@@ -250,11 +249,10 @@ func processProgressOutput[T ProgressEntryValidator](
 	}
 
 	if err := scanner.Err(); err != nil {
-		return summary, newErrorWithOutput(err, nonJSONOutput.String())
+		return summary, nonJSONOutput.AddOutputToError(err)
 	}
-
 	if !gotSummary {
-		return summary, newErrorWithOutput(errors.New("no summary event found"), nonJSONOutput.String())
+		return summary, nonJSONOutput.AddOutputToError(errors.New("no summary event found"))
 	}
 
 	return summary, nil

pkg/restic/outputs_test.go

@@ -2,6 +2,8 @@ package restic
 
 import (
 	"bytes"
+	"reflect"
+	"strings"
 	"testing"
 )
 
@@ -26,11 +28,53 @@ func TestReadBackupProgressEntries(t *testing.T) {
 	}
 }
 
+func TestReadVerboseBackupProgressEntries(t *testing.T) {
+	t.Parallel()
+
+	testInput := `{"message_type":"status","seconds_elapsed":8,"percent_done":0,"total_files":10,"files_done":1,"total_bytes":27557,"current_files":["/cur/file.txt"]}
+{"message_type":"verbose_status","action":"modified","item":"/foo/bar.txt","duration":0.024449704,"data_size":0,"data_size_in_repo":0,"metadata_size":0,"metadata_size_in_repo":0,"total_files":0}
+{"message_type":"exit_error","code":1,"message":"my sentinel error message"}`
+
+	events := []BackupProgressEntry{}
+	_, err := processProgressOutput[*BackupProgressEntry](bytes.NewBuffer([]byte(testInput)), nil, func(event *BackupProgressEntry) {
+		events = append(events, *event)
+	})
+	if err == nil || !strings.Contains(err.Error(), "my sentinel error message") {
+		t.Fatalf("wanted error containing 'my sentinel error message', got: %v", err)
+	}
+	// Assert that we get exactly the expected set of events.
+	wantEvents := []BackupProgressEntry{
+		{
+			MessageType:  "status",
+			PercentDone:  0,
+			TotalFiles:   10,
+			FilesDone:    1,
+			TotalBytes:   27557,
+			CurrentFiles: []string{"/cur/file.txt"},
+		},
+		{
+			MessageType: "verbose_status",
+			Action:      "modified",
+			Item:        "/foo/bar.txt",
+		},
+	}
+
+	if len(events) != len(wantEvents) {
+		t.Fatalf("wanted %d events, got: %d", len(wantEvents), len(events))
+	}
+
+	for i, event := range events {
+		if !reflect.DeepEqual(event, wantEvents[i]) {
+			t.Errorf("event %d: wanted %v, got %v", i, wantEvents[i], event)
+		}
+	}
+}
+
 func TestReadLs(t *testing.T) {
 	testInput := `{"time":"2023-11-10T19:14:17.053824063-08:00","tree":"3e2918b261948e69602ee9504b8f475bcc7cdc4dcec0b3f34ecdb014287d07b2","paths":["/backrest"],"hostname":"pop-os","username":"dontpanic","uid":1000,"gid":1000,"id":"db155169d788e6e432e320aedbdff5a54cc439653093bb56944a67682528aa52","short_id":"db155169","struct_type":"snapshot"}
-	{"name":".git","type":"dir","path":"/.git","uid":1000,"gid":1000,"mode":2147484157,"mtime":"2023-11-10T18:32:38.156599473-08:00","atime":"2023-11-10T18:32:38.156599473-08:00","ctime":"2023-11-10T18:32:38.156599473-08:00","struct_type":"node"}
-	{"name":".gitignore","type":"file","path":"/.gitignore","uid":1000,"gid":1000,"size":22,"mode":436,"mtime":"2023-11-10T00:41:26.611346634-08:00","atime":"2023-11-10T00:41:26.611346634-08:00","ctime":"2023-11-10T00:41:26.611346634-08:00","struct_type":"node"}
-	{"name":"README.md","type":"file","path":"/README.md","uid":1000,"gid":1000,"size":762,"mode":436,"mtime":"2023-11-10T00:59:06.842538768-08:00","atime":"2023-11-10T00:59:06.842538768-08:00","ctime":"2023-11-10T00:59:06.842538768-08:00","struct_type":"node"}`
+{"name":".git","type":"dir","path":"/.git","uid":1000,"gid":1000,"mode":2147484157,"mtime":"2023-11-10T18:32:38.156599473-08:00","atime":"2023-11-10T18:32:38.156599473-08:00","ctime":"2023-11-10T18:32:38.156599473-08:00","struct_type":"node"}
+{"name":".gitignore","type":"file","path":"/.gitignore","uid":1000,"gid":1000,"size":22,"mode":436,"mtime":"2023-11-10T00:41:26.611346634-08:00","atime":"2023-11-10T00:41:26.611346634-08:00","ctime":"2023-11-10T00:41:26.611346634-08:00","struct_type":"node"}
+{"name":"README.md","type":"file","path":"/README.md","uid":1000,"gid":1000,"size":762,"mode":436,"mtime":"2023-11-10T00:59:06.842538768-08:00","atime":"2023-11-10T00:59:06.842538768-08:00","ctime":"2023-11-10T00:59:06.842538768-08:00","struct_type":"node"}`
 
 	b := bytes.NewBuffer([]byte(testInput))
 

pkg/restic/restic.go

@@ -66,64 +66,106 @@ func (r *Repo) commandWithContext(ctx context.Context, args []string, opts ...Ge
 	cmd := exec.CommandContext(ctx, fullCmd[0], fullCmd[1:]...)
 	cmd.Env = append(cmd.Env, opt.extraEnv...)
 
-	logger := LoggerFromContext(ctx)
-	if logger != nil {
-		sw := &ioutil.SynchronizedWriter{W: logger}
-		cmd.Stderr = sw
-		cmd.Stdout = sw
-		fmt.Fprintf(logger, "command: %q\n", fullCmd)
-	}
-
 	return cmd
 }
 
-func (r *Repo) pipeCmdOutputToWriter(cmd *exec.Cmd, handlers ...io.Writer) {
-	stdoutHandlers := slices.Clone(handlers)
-	stderrHandlers := slices.Clone(handlers)
-
-	if cmd.Stdout != nil {
-		handlers = append(stdoutHandlers, cmd.Stdout)
-	}
-	if cmd.Stderr != nil {
-		handlers = append(stderrHandlers, cmd.Stderr)
-	}
-
-	mw := io.MultiWriter(handlers...)
-	mw = &ioutil.SynchronizedWriter{W: mw}
-	cmd.Stdout = mw
-	cmd.Stderr = mw
+type outputOpts struct {
+	stdErrWriters []io.Writer
+	stdOutWriters []io.Writer
 }
 
-// executeWithOutput runs a command and captures the output in a buffer
-func (r *Repo) executeWithOutput(ctx context.Context, args []string, opts ...GenericOption) ([]byte, error) {
-	cmd := r.commandWithContext(ctx, args, opts...)
-	output := bytes.NewBuffer(nil)
-	r.pipeCmdOutputToWriter(cmd, output)
+func withStdErrTo(writer io.Writer) func(cmd *exec.Cmd, opts *outputOpts) {
+	return func(cmd *exec.Cmd, opts *outputOpts) {
+		opts.stdErrWriters = append(opts.stdErrWriters, writer)
+	}
+}
 
-	err := cmd.Run()
-	if err != nil {
-		return output.Bytes(), newCmdError(ctx, cmd, newErrorWithOutput(err, output.String()))
+func withStdOutTo(writer io.Writer) func(cmd *exec.Cmd, opts *outputOpts) {
+	return func(cmd *exec.Cmd, opts *outputOpts) {
+		opts.stdOutWriters = append(opts.stdOutWriters, writer)
+	}
+}
+
+func withAllTo(writer io.Writer) func(cmd *exec.Cmd, opts *outputOpts) {
+	return func(cmd *exec.Cmd, opts *outputOpts) {
+		sw := &ioutil.SynchronizedWriter{W: writer}
+		opts.stdErrWriters = append(opts.stdErrWriters, sw)
+		opts.stdOutWriters = append(opts.stdOutWriters, sw)
+	}
+}
+
+func withLogWriterFromContext(ctx context.Context) func(cmd *exec.Cmd, opts *outputOpts) {
+	return func(cmd *exec.Cmd, opts *outputOpts) {
+		logger := LoggerFromContext(ctx)
+		if logger != nil {
+			fmt.Fprintf(logger, "command: %q\n", cmd)
+			opts.stdErrWriters = append(opts.stdErrWriters, logger)
+			opts.stdOutWriters = append(opts.stdOutWriters, logger)
+		}
+	}
+}
+
+func (r *Repo) handleOutput(cmd *exec.Cmd, opts ...func(cmd *exec.Cmd, opts *outputOpts)) {
+	outputOpts := &outputOpts{}
+
+	for _, opt := range opts {
+		opt(cmd, outputOpts)
 	}
 
-	return output.Bytes(), nil
+	var stdOutWriter io.Writer
+	if len(outputOpts.stdOutWriters) > 1 {
+		stdOutWriter = io.MultiWriter(outputOpts.stdOutWriters...)
+	} else if len(outputOpts.stdOutWriters) == 1 {
+		stdOutWriter = outputOpts.stdOutWriters[0]
+	}
+
+	var stdErrWriter io.Writer
+	if len(outputOpts.stdErrWriters) > 1 {
+		stdErrWriter = io.MultiWriter(outputOpts.stdErrWriters...)
+	} else if len(outputOpts.stdErrWriters) == 1 {
+		stdErrWriter = outputOpts.stdErrWriters[0]
+	}
+
+	if stdOutWriter != nil {
+		if cmd.Stdout != nil {
+			cmd.Stdout = io.MultiWriter(cmd.Stdout, stdOutWriter)
+		} else {
+			cmd.Stdout = stdOutWriter
+		}
+	}
+	if stdErrWriter != nil {
+		if cmd.Stderr != nil {
+			cmd.Stderr = io.MultiWriter(cmd.Stderr, stdErrWriter)
+		} else {
+			cmd.Stderr = stdErrWriter
+		}
+	}
 }
 
 // executeWithJSONOutput runs a command and parses its JSON output
 func (r *Repo) executeWithJSONOutput(ctx context.Context, args []string, result interface{}, opts ...GenericOption) error {
-	output, err := r.executeWithOutput(ctx, args, opts...)
-	if err != nil {
-		return err
+	// Create a pipe
+	errorCollector := errorMessageCollector{}
+	stdoutOutput := bytes.NewBuffer(nil)
+
+	// Run the command
+	cmd := r.commandWithContext(ctx, args, opts...)
+	r.handleOutput(cmd, withAllTo(&errorCollector), withStdOutTo(stdoutOutput), withLogWriterFromContext(ctx))
+	if err := cmd.Run(); err != nil {
+		return errorCollector.AddCmdOutputToError(cmd, err)
 	}
 
+	stdOutBytes := stdoutOutput.Bytes()
+
 	// Try to parse the entire output first
-	origErr := json.Unmarshal(output, result)
+	origErr := json.Unmarshal(stdOutBytes, result)
 	if origErr == nil {
 		return nil
 	}
 
 	// Find the index afterwhich everything is whitespace
-	allWhitespaceAfterIdx := len(output)
-	for i, b := range output {
+	allWhitespaceAfterIdx := len(stdoutOutput.Bytes())
+	for i, b := range stdoutOutput.Bytes() {
 		if unicode.IsSpace(rune(b)) {
 			allWhitespaceAfterIdx = i
 		}
@@ -132,16 +174,15 @@ func (r *Repo) executeWithJSONOutput(ctx context.Context, args []string, result
 	// If that fails, try by skipping bytes until a newline is found
 	start := 0
 	for start < allWhitespaceAfterIdx {
-		if err := json.Unmarshal(output[start:], result); err == nil {
-			zap.S().Warnf("Command %v output may have contained a skipped warning from restic that was not valid JSON: %s", args, string(output[start:]))
+		if err := json.Unmarshal(stdOutBytes[start:], result); err == nil {
+			zap.S().Warnf("Command %v output may have contained a skipped warning from restic that was not valid JSON: %s", args, string(stdOutBytes[start:]))
 			return nil
 		}
-		start = start + bytes.IndexRune(output[start:], '\n')
+		start = start + bytes.IndexRune(stdOutBytes[start:], '\n')
 		start++ // skip the newline itself
 	}
 
-	return newCmdError(ctx, r.commandWithContext(ctx, args),
-		newErrorWithOutput(fmt.Errorf("command output is not valid JSON: %w", origErr), string(output)))
+	return errorCollector.AddCmdOutputToError(cmd, fmt.Errorf("command output is not valid JSON: %w", origErr))
 }
 
 // Exists checks if the repository exists.
@@ -149,16 +190,17 @@ func (r *Repo) executeWithJSONOutput(ctx context.Context, args []string, result
 func (r *Repo) Exists(ctx context.Context, opts ...GenericOption) error {
 	r.checkExists.Do(func() {
 		output := bytes.NewBuffer(nil)
+		errorCollector := errorMessageCollector{}
 		cmd := r.commandWithContext(ctx, []string{"cat", "config"}, opts...)
-		r.pipeCmdOutputToWriter(cmd, output)
+		r.handleOutput(cmd, withAllTo(&errorCollector), withStdOutTo(output), withLogWriterFromContext(ctx))
 		if err := cmd.Run(); err != nil {
 			var exitErr *exec.ExitError
 			if errors.As(err, &exitErr) && exitErr.ExitCode() == 10 {
 				err = ErrRepoNotFound
 			}
-			r.exists = newCmdError(ctx, cmd, newErrorWithOutput(err, output.String()))
+			r.exists = errorCollector.AddCmdOutputToError(cmd, err)
 		} else if err := json.Unmarshal(output.Bytes(), &r.repoConfig); err != nil {
-			r.exists = newCmdError(ctx, cmd, newErrorWithOutput(fmt.Errorf("command output is not valid JSON: %w", err), output.String()))
+			r.exists = errorCollector.AddCmdOutputToError(cmd, fmt.Errorf("command output is not valid JSON: %w", err))
 		} else {
 			r.exists = nil
 		}
@@ -175,17 +217,18 @@ func (r *Repo) init(ctx context.Context, opts ...GenericOption) error {
 	r.shouldInitialize.Do(func() {
 		cmd := r.commandWithContext(ctx, []string{"init", "--json"}, opts...)
 		output := bytes.NewBuffer(nil)
-		r.pipeCmdOutputToWriter(cmd, output)
+		errorCollector := errorMessageCollector{}
+		r.handleOutput(cmd, withAllTo(&errorCollector), withStdOutTo(output), withLogWriterFromContext(ctx))
 
 		if err := cmd.Run(); err != nil {
 			if strings.Contains(output.String(), "config file already exists") || strings.Contains(output.String(), "already initialized") {
 				r.initialized = errAlreadyInitialized
 			} else {
-				r.initialized = newCmdError(ctx, cmd, newCmdError(ctx, cmd, newErrorWithOutput(err, output.String())))
+				r.initialized = errorCollector.AddCmdOutputToError(cmd, err)
 			}
 		} else {
 			if err := json.Unmarshal(output.Bytes(), &r.repoConfig); err != nil {
-				r.initialized = newCmdError(ctx, cmd, newErrorWithOutput(fmt.Errorf("command output is not valid JSON: %w", err), output.String()))
+				r.initialized = errorCollector.AddCmdOutputToError(cmd, fmt.Errorf("command output is not valid JSON: %w", err))
 			}
 			r.exists = r.initialized
 		}
@@ -205,40 +248,34 @@ func (r *Repo) Config(ctx context.Context, opts ...GenericOption) (RepoConfig, e
 	return r.repoConfig, nil
 }
 
-type cmdRunnerWithProgress[T ProgressEntryValidator] struct {
-	repo       *Repo
-	callback   func(T)
-	failureErr error
-}
-
-// handleExitError processes a command exit error and converts it to an appropriate error type
-func (cr *cmdRunnerWithProgress[T]) handleExitError(err error) error {
+func handleResticExitError(err error, failureErr error) error {
 	var exitErr *exec.ExitError
 	if errors.As(err, &exitErr) {
 		if exitErr.ExitCode() == 3 {
 			return ErrPartialBackup
-		} else {
-			return fmt.Errorf("exit code %d: %w", exitErr.ExitCode(), cr.failureErr)
 		}
+		return fmt.Errorf("exit code %d: %w", exitErr.ExitCode(), failureErr)
 	}
 	return err
 }
 
-func (cr *cmdRunnerWithProgress[T]) Run(ctx context.Context, args []string, opts ...GenericOption) (T, error) {
+func runCommandWithProgress[T ProgressEntryValidator](ctx context.Context, r *Repo, args []string, callback func(T), failureErr error, opts ...GenericOption) (T, error) {
 	logger := LoggerFromContext(ctx)
 	cmdCtx, cancel := context.WithCancel(ctx)
 	defer cancel()
 	cmdCtx = ContextWithLogger(cmdCtx, nil) // ensure no logger is used
-	cmd := cr.repo.commandWithContext(cmdCtx, args, opts...)
+	cmd := r.commandWithContext(cmdCtx, args, opts...)
 
 	// Ensure the command is logged since we're overriding the logger
 	if logger != nil {
 		fmt.Fprintf(logger, "command: %q\n", cmd)
+	} else {
+		logger = io.Discard
 	}
 
-	buf := buffer.New(32 * 1024) // 32KB IO buffer for the realtime event parsing
+	buf := buffer.New(8 * 1024) // 8KB IO buffer for the realtime event parsing
 	reader, writer := nio.Pipe(buf)
-	cr.repo.pipeCmdOutputToWriter(cmd, writer)
+	r.handleOutput(cmd, withAllTo(writer))
 
 	var readErr error
 	var summary T
@@ -247,7 +284,7 @@ func (cr *cmdRunnerWithProgress[T]) Run(ctx context.Context, args []string, opts
 	wg.Add(1)
 	go func() {
 		defer wg.Done()
-		result, err := processProgressOutput[T](reader, logger, cr.callback)
+		result, err := processProgressOutput[T](reader, logger, callback)
 		summary = result
 		if err != nil {
 			readErr = fmt.Errorf("output processing: %w", err)
@@ -260,9 +297,9 @@ func (cr *cmdRunnerWithProgress[T]) Run(ctx context.Context, args []string, opts
 
 	if cmdErr != nil || readErr != nil {
 		if cmdErr != nil {
-			cmdErr = cr.handleExitError(cmdErr)
+			cmdErr = handleResticExitError(cmdErr, failureErr)
 		}
-		return summary, newCmdError(ctx, cmd, errors.Join(cmdErr, readErr))
+		return summary, newCmdError(cmd, errors.Join(cmdErr, readErr))
 	}
 
 	return summary, nil
@@ -279,27 +316,18 @@ func (r *Repo) Backup(ctx context.Context, paths []string, progressCallback func
 	args = append(args, paths...)
 	opts = append(slices.Clone(opts), WithEnv("RESTIC_PROGRESS_FPS=2"))
 
-	cr := cmdRunnerWithProgress[*BackupProgressEntry]{
-		repo:       r,
-		callback:   progressCallback,
-		failureErr: ErrBackupFailed,
-	}
-	return cr.Run(ctx, args, opts...)
+	return runCommandWithProgress(ctx, r, args, progressCallback, ErrBackupFailed, opts...)
 }
 
 func (r *Repo) Restore(ctx context.Context, snapshot string, callback func(*RestoreProgressEntry), opts ...GenericOption) (*RestoreProgressEntry, error) {
 	opts = append(slices.Clone(opts), WithEnv("RESTIC_PROGRESS_FPS=2"))
 	args := []string{"restore", "--json", snapshot}
 
-	cr := cmdRunnerWithProgress[*RestoreProgressEntry]{
-		repo:       r,
-		callback:   callback,
-		failureErr: ErrRestoreFailed,
-	}
-	return cr.Run(ctx, args, opts...)
+	return runCommandWithProgress(ctx, r, args, callback, ErrRestoreFailed, opts...)
 }
 
 func (r *Repo) Snapshots(ctx context.Context, opts ...GenericOption) ([]*Snapshot, error) {
+
 	var snapshots []*Snapshot
 	if err := r.executeWithJSONOutput(ctx, []string{"snapshots", "--json"}, &snapshots, opts...); err != nil {
 		return nil, err
@@ -335,8 +363,13 @@ func (r *Repo) Forget(ctx context.Context, policy *RetentionPolicy, opts ...Gene
 
 func (r *Repo) ForgetSnapshot(ctx context.Context, snapshotId string, opts ...GenericOption) error {
 	args := []string{"forget", "--json", snapshotId}
-	_, err := r.executeWithOutput(ctx, args, opts...)
-	return err
+	cmd := r.commandWithContext(ctx, args, opts...)
+	errorCollector := errorMessageCollector{}
+	r.handleOutput(cmd, withAllTo(&errorCollector), withLogWriterFromContext(ctx))
+	if err := cmd.Run(); err != nil {
+		return errorCollector.AddCmdOutputToError(cmd, err)
+	}
+	return nil
 }
 
 func (r *Repo) Prune(ctx context.Context, pruneOutput io.Writer, opts ...GenericOption) error {
@@ -344,24 +377,18 @@ func (r *Repo) Prune(ctx context.Context, pruneOutput io.Writer, opts ...Generic
 }
 
 func (r *Repo) Check(ctx context.Context, checkOutput io.Writer, opts ...GenericOption) error {
-	cmd := r.commandWithContext(ctx, []string{"check"}, opts...)
-	if checkOutput != nil {
-		r.pipeCmdOutputToWriter(cmd, checkOutput)
-	}
-	if err := cmd.Run(); err != nil {
-		return newCmdError(ctx, cmd, err)
-	}
-	return nil
+	return r.runSimpleCommand(ctx, []string{"check"}, checkOutput, opts...)
 }
 
 // runSimpleCommand executes a command with optional output capture
 func (r *Repo) runSimpleCommand(ctx context.Context, args []string, outputWriter io.Writer, opts ...GenericOption) error {
 	cmd := r.commandWithContext(ctx, args, opts...)
+	errorCollector := errorMessageCollector{}
 	if outputWriter != nil {
-		r.pipeCmdOutputToWriter(cmd, outputWriter)
+		r.handleOutput(cmd, withStdOutTo(outputWriter), withAllTo(&errorCollector), withLogWriterFromContext(ctx))
 	}
 	if err := cmd.Run(); err != nil {
-		return newCmdError(ctx, cmd, err)
+		return errorCollector.AddCmdOutputToError(cmd, err)
 	}
 	return nil
 }
@@ -373,22 +400,28 @@ func (r *Repo) ListDirectory(ctx context.Context, snapshot string, path string,
 	}
 
 	cmd := r.commandWithContext(ctx, []string{"ls", "--json", snapshot, path}, opts...)
+	errorCollector := errorMessageCollector{}
 	output := bytes.NewBuffer(nil)
-	r.pipeCmdOutputToWriter(cmd, output)
+	r.handleOutput(cmd, withStdOutTo(output), withAllTo(&errorCollector), withLogWriterFromContext(ctx))
 	if err := cmd.Run(); err != nil {
-		return nil, nil, newCmdError(ctx, cmd, newErrorWithOutput(err, output.String()))
+		return nil, nil, errorCollector.AddCmdOutputToError(cmd, fmt.Errorf("error running command: %w", err))
 	}
 
 	snap, entries, err := readLs(output)
 	if err != nil {
-		return nil, nil, newCmdError(ctx, cmd, fmt.Errorf("error parsing JSON: %w", err))
+		return nil, nil, errorCollector.AddCmdOutputToError(cmd, fmt.Errorf("error parsing JSON: %w", err))
 	}
 	return snap, entries, nil
 }
 
 func (r *Repo) Unlock(ctx context.Context, opts ...GenericOption) error {
-	_, err := r.executeWithOutput(ctx, []string{"unlock"}, opts...)
-	return err
+	errorCollector := errorMessageCollector{}
+	cmd := r.commandWithContext(ctx, []string{"unlock"}, opts...)
+	r.handleOutput(cmd, withAllTo(&errorCollector), withLogWriterFromContext(ctx))
+	if err := cmd.Run(); err != nil {
+		return errorCollector.AddCmdOutputToError(cmd, err)
+	}
+	return nil
 }
 
 func (r *Repo) Stats(ctx context.Context, opts ...GenericOption) (*RepoStats, error) {
@@ -406,12 +439,18 @@ func (r *Repo) AddTags(ctx context.Context, snapshotIDs []string, tags []string,
 	args = append(args, "--add", strings.Join(tags, ","))
 	args = append(args, snapshotIDs...)
 
-	_, err := r.executeWithOutput(ctx, args, opts...)
-	return err
+	errorCollector := errorMessageCollector{}
+	cmd := r.commandWithContext(ctx, args, opts...)
+	r.handleOutput(cmd, withAllTo(&errorCollector), withLogWriterFromContext(ctx))
+	if err := cmd.Run(); err != nil {
+		return errorCollector.AddCmdOutputToError(cmd, err)
+	}
+	return nil
 }
 
 func (r *Repo) GenericCommand(ctx context.Context, args []string, opts ...GenericOption) error {
 	cmd := r.commandWithContext(ctx, args, opts...)
+	r.handleOutput(cmd, withLogWriterFromContext(ctx))
 	if err := cmd.Run(); err != nil {
 		return err
 	}

pkg/restic/restic_test.go

@@ -638,62 +638,76 @@ func TestResticExitError(t *testing.T) {
 	}
 }
 
-func TestJSONCommandResilantToBeginningWarnings(t *testing.T) {
+func TestJSONCommand(t *testing.T) {
 	t.Parallel()
 	if runtime.GOOS == "windows" {
 		t.Skip("this test is designed to run on Linux, as it uses bash")
 	}
 
-	r := NewRepo("bash", "")
-	var result struct {
-		Foo string `json:"foo"`
-	}
-	if err := r.executeWithJSONOutput(context.Background(), []string{"-c", "echo 'warning: this is a warning' >&2; echo '{\"foo\": \"bar\"}';"}, &result); err != nil {
-		t.Fatalf("expected command to succeed, got error: %v", err)
+	tests := []struct {
+		name           string
+		command        string
+		expectedResult string
+		expectError    bool
+		errorContains  string
+	}{
+		{
+			name:           "resilient to beginning prints",
+			command:        "echo 'warning: this is a warning' >&1; echo '{\"foo\": \"bar\"}';",
+			expectedResult: "bar",
+			expectError:    false,
+		},
+		{
+			name:           "resilient to beginning warnings",
+			command:        "echo 'warning: this is a warning' >&2; echo '{\"foo\": \"bar\"}';",
+			expectedResult: "bar",
+			expectError:    false,
+		},
+		{
+			name:          "fails with prints after JSON",
+			command:       "echo '{\"foo\": \"bar\"}'; echo 'warning: this is a warning' >&1;",
+			expectError:   true,
+			errorContains: "command output is not valid JSON",
+		},
+		{
+			name:           "succeeds with warnings after JSON",
+			command:        "echo '{\"foo\": \"bar\"}'; echo 'warning: this is a warning' >&2;",
+			expectError:    false,
+			expectedResult: "bar",
+		},
+		{
+			name:          "fails if no valid JSON",
+			command:       "echo 'not really any valid\njson here\n'",
+			expectError:   true,
+			errorContains: "command output is not valid JSON",
+		},
 	}
 
-	if result.Foo != "bar" {
-		t.Errorf("expected foo to be 'bar', got: %s", result.Foo)
-	}
-}
+	for _, tc := range tests {
+		t.Run(tc.name, func(t *testing.T) {
+			t.Parallel()
+			r := NewRepo("bash", "")
+			var result struct {
+				Foo string `json:"foo"`
+			}
+			err := r.executeWithJSONOutput(context.Background(), []string{"-c", tc.command}, &result)
 
-func TestJSONCommandFailsWithWarningsAtEnd(t *testing.T) {
-	t.Parallel()
-	if runtime.GOOS == "windows" {
-		t.Skip("this test is designed to run on Linux, as it uses bash")
-	}
-
-	r := NewRepo("bash", "")
-	var result struct {
-		Foo string `json:"foo"`
-	}
-	err := r.executeWithJSONOutput(context.Background(), []string{"-c", "echo '{\"foo\": \"bar\"}'; echo 'warning: this is a warning' >&2;"}, &result)
-	if err == nil {
-		t.Fatal("expected command to fail with warnings after JSON output, but it succeeded")
-	}
-
-	if !strings.Contains(err.Error(), "command output is not valid JSON") {
-		t.Errorf("expected error to contain 'command output is not valid JSON', got: %v", err)
-	}
-}
-
-func TestJSONCommandFailsIfNoValidJSON(t *testing.T) {
-	t.Parallel()
-	if runtime.GOOS == "windows" {
-		t.Skip("this test is designed to run on Linux, as it uses bash")
-	}
-
-	r := NewRepo("bash", "")
-	var result struct {
-		Foo string `json:"foo"`
-	}
-	err := r.executeWithJSONOutput(context.Background(), []string{"-c", "echo 'not really any valid\njson here\n'"}, &result)
-	if err == nil {
-		t.Fatal("expected command to fail with empty JSON output, but it succeeded")
-	}
-
-	if !strings.Contains(err.Error(), "command output is not valid JSON") {
-		t.Errorf("expected error to contain 'command output is not valid JSON', got: %v", err)
+			if tc.expectError {
+				if err == nil {
+					t.Fatal("expected command to fail, but it succeeded")
+				}
+				if !strings.Contains(err.Error(), tc.errorContains) {
+					t.Errorf("expected error to contain '%s', got: %v", tc.errorContains, err)
+				}
+			} else {
+				if err != nil {
+					t.Fatalf("expected command to succeed, got error: %v", err)
+				}
+				if result.Foo != tc.expectedResult {
+					t.Errorf("expected foo to be '%s', got: '%s'", tc.expectedResult, result.Foo)
+				}
+			}
+		})
 	}
 }