Print a failed command's error once on stderr (closes #433)

A command that failed after startup wrote the error twice on stderr:
as an ERROR log record and as the final ERROR: line. The failure
handlers now log the failure at info level, so the record appears only
under --verbose or --debug, next to the records that led up to it.

Model: opus-5-5

internal/cli/app.go

@@ -339,7 +339,7 @@ func runVaultikApp(
 		},
 		Mode: mode,
 	}, op, func(err error) {
-		log.Error(failMsg, "error", err)
+		log.Info(failMsg, "error", err)
 		ReportErrorf("%s: %v", failMsg, err)
 	})
 }

internal/cli/entry.go

@@ -82,6 +82,10 @@ func emitStartupBanner(args []string, w io.Writer) {
 // 🛑 ERROR: format. Use it from goroutine error paths (where returning
 // an error to cobra isn't an option) and anywhere else a CLI command
 // must surface a failure outside the normal RunE return path.
+//
+// This line is the one report of the failure. A caller that also logs
+// the failure logs it at info level, so the record appears only under
+// --verbose or --debug and the error is not printed twice.
 func ReportErrorf(format string, args ...any) {
 	ui.New(os.Stderr).Errorf(format, args...)
 }

internal/cli/entry_failure_once_test.go

@@ -0,0 +1,105 @@
+package cli //nolint:testpackage // shares the fixtures and capture helpers
+
+import (
+	"encoding/json"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+)
+
+// errorLinePrefix starts the final line that reports a failed command.
+const errorLinePrefix = "ERROR: "
+
+// TestEntryFailureIsPrintedOnce runs commands that fail after startup.
+// stderr must carry the error once, as the final ERROR: line. A log
+// record carrying the same error appears only under --verbose.
+//
+//nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
+func TestEntryFailureIsPrintedOnce(t *testing.T) {
+	for _, testCase := range []struct {
+		name string
+		args []string
+	}{
+		{name: "snapshot create", args: []string{cmdSnapshot, cmdCreate}},
+		{name: "remote info", args: []string{cmdRemote, cmdInfo}},
+		{name: "prune", args: []string{cmdPrune, flagJSON}},
+	} {
+		for _, verbose := range []bool{false, true} {
+			name := testCase.name
+			if verbose {
+				name += " verbose"
+			}
+
+			t.Run(name, func(t *testing.T) {
+				args := append([]string{flagConfig,
+					writeUnusableDestinationConfig(t)}, testCase.args...)
+				if verbose {
+					args = append(args, "--verbose")
+				}
+
+				code, _, stderr := runEntry(t, args...)
+
+				require.Equal(t, 1, code)
+
+				errorLine, records := failureOutput(t, stderr)
+
+				if !verbose {
+					assert.Zero(t, records,
+						"without --verbose no log record repeats the error:\n%s",
+						stderr)
+
+					return
+				}
+
+				assert.NotZero(t, records,
+					"--verbose must keep the log record of %q", errorLine)
+			})
+		}
+	}
+}
+
+// failureOutput requires stderr to hold exactly one ERROR: line and
+// returns it, with the number of log records whose error attribute is
+// the error that line reports. stderr is a pipe here, so every log
+// record is a JSON object on its own line.
+func failureOutput(t *testing.T, stderr string) (string, int) {
+	t.Helper()
+
+	var (
+		errorLines []string
+		records    []map[string]any
+	)
+
+	for line := range strings.Lines(stderr) {
+		var record map[string]any
+		if json.Unmarshal([]byte(line), &record) == nil {
+			records = append(records, record)
+
+			continue
+		}
+
+		if strings.Contains(line, errorLinePrefix) {
+			errorLines = append(errorLines, strings.TrimSpace(line))
+		}
+	}
+
+	require.Len(t, errorLines, 1,
+		"the error must be printed once as an ERROR: line:\n%s", stderr)
+
+	// An error can run over several lines; the ERROR: line holds the
+	// first of them.
+	repeats := 0
+
+	for _, record := range records {
+		failure, ok := record["error"].(string)
+		firstLine, _, _ := strings.Cut(failure, "\n")
+
+		if ok && strings.Contains(errorLines[0], firstLine) {
+			repeats++
+		}
+	}
+
+	return errorLines[0], repeats
+}

internal/cli/info.go

@@ -39,7 +39,7 @@ func NewInfoCommand() *cobra.Command {
 			}, func(v *vaultik.Vaultik) error {
 				return v.ShowInfo()
 			}, func(err error) {
-				log.Error("Failed to show info", "error", err)
+				log.Info("Failed to show info", "error", err)
 				ReportErrorf("Failed to show info: %v", err)
 			})
 		},

internal/cli/prune.go

@@ -60,7 +60,7 @@ referenced.`,
 			}, func(v *vaultik.Vaultik) error {
 				return v.Prune(opts)
 			}, func(err error) {
-				log.Error("Prune operation failed", "error", err)
+				log.Info("Prune operation failed", "error", err)
 				ReportErrorf("Prune failed: %v", err)
 			})
 		},

internal/cli/remote.go

@@ -98,7 +98,7 @@ func newRemoteInfoCommand() *cobra.Command {
 			}, func(v *vaultik.Vaultik) error {
 				return v.RemoteInfo(jsonOutput)
 			}, func(err error) {
-				log.Error("Failed to get remote info", "error", err)
+				log.Info("Failed to get remote info", "error", err)
 				ReportErrorf("Failed to get remote info: %v", err)
 			})
 		},

internal/cli/snapshot.go

@@ -109,7 +109,7 @@ on Linux), then /etc/vaultik/config.yml.`,
 				return v.CreateSnapshot(opts)
 			}, func(err error) {
 				if errors.Is(err, vaultik.ErrPostBackupPruneFailed) {
-					log.Error("Post-backup prune failed", "error", err)
+					log.Info("Post-backup prune failed", "error", err)
 					ReportErrorf("Backup completed, but %v", err)
 
 					return
@@ -118,13 +118,13 @@ on Linux), then /etc/vaultik/config.yml.`,
 				if errors.Is(err, vaultik.ErrFilesUnreadable) ||
 					errors.Is(err, vaultik.ErrSourcePathEmpty) ||
 					errors.Is(err, vaultik.ErrVolumeNotMounted) {
-					log.Error("Backup completed with an error", "error", err)
+					log.Info("Backup completed with an error", "error", err)
 					ReportErrorf("Backup completed, but %v", err)
 
 					return
 				}
 
-				log.Error("Snapshot creation failed", "error", err)
+				log.Info("Snapshot creation failed", "error", err)
 				ReportErrorf("Snapshot creation failed: %v", err)
 			})
 		},
@@ -258,7 +258,7 @@ func newSnapshotVerifyCommand() *cobra.Command {
 					return
 				}
 
-				log.Error("Verification failed", "error", err)
+				log.Info("Verification failed", "error", err)
 				ReportErrorf("Verification failed: %v", err)
 			})
 		},

internal/cli/snapshot_restore.go

@@ -104,7 +104,7 @@ func runRestore(cmd *cobra.Command, args []string, opts *RestoreOptions) error {
 			SkipErrors: rootFlags.SkipErrors,
 		})
 	}, func(err error) {
-		log.Error("Restore operation failed", "error", err)
+		log.Info("Restore operation failed", "error", err)
 		ReportErrorf("Restore failed: %v", err)
 	})
 }