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

A failed command printed its error twice on stderr: as an ERROR log record and as the final ERROR: line the README documents. The command handlers, a restore failure that ends the command and a failed blob upload now log that error at info level or not at all, so without --verbose or --debug only the final line appears.

Model: opus-5-5

internal/cli/app.go

@@ -337,7 +337,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

@@ -85,6 +85,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,205 @@
+package cli //nolint:testpackage // shares the fixtures and capture helpers
+
+import (
+	"context"
+	"encoding/json"
+	"fmt"
+	"io"
+	"os"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"filippo.io/age"
+	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
+	"sneak.berlin/go/vaultik/internal/database"
+	"sneak.berlin/go/vaultik/internal/ui"
+)
+
+const (
+	// errorLinePrefix starts the final line that reports a failed command.
+	errorLinePrefix = "ERROR: "
+
+	flagVerbose = "--verbose"
+	cmdRestore  = "restore"
+
+	// blobsDir is the directory of a destination store that holds the
+	// blobs.
+	blobsDir = "blobs"
+)
+
+// TestEntryFailureIsPrintedOnce runs commands that fail after startup
+// against a destination they cannot use. `info` is not among them: it
+// cannot fail after startup.
+//
+//nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
+func TestEntryFailureIsPrintedOnce(t *testing.T) {
+	for _, command := range [][]string{
+		{cmdSnapshot, cmdCreate},
+		{cmdSnapshot, cmdRemove, someSnapshotID},
+		{cmdSnapshot, cmdVerify, someSnapshotID},
+		{cmdRemote, cmdInfo},
+		{cmdPrune, flagJSON},
+	} {
+		for _, verbose := range []bool{false, true} {
+			name := fmt.Sprintf("%s verbose=%t", strings.Join(command, " "), verbose)
+
+			t.Run(name, func(t *testing.T) {
+				requireErrorPrintedOnce(t, verbose, append([]string{flagConfig,
+					writeUnusableDestinationConfig(t)}, command...)...)
+			})
+		}
+	}
+}
+
+// TestEntryBlobUploadFailureIsPrintedOnce backs up to a destination
+// whose blobs directory is a file, so the blob upload fails.
+//
+//nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
+func TestEntryBlobUploadFailureIsPrintedOnce(t *testing.T) {
+	for _, verbose := range []bool{false, true} {
+		t.Run(fmt.Sprintf("verbose=%t", verbose), func(t *testing.T) {
+			configPath, storeDir := writeBackupConfig(t)
+
+			require.NoError(t, os.WriteFile(
+				filepath.Join(storeDir, blobsDir), nil, 0o600))
+
+			requireErrorPrintedOnce(t, verbose,
+				flagConfig, configPath, cmdSnapshot, cmdCreate)
+		})
+	}
+}
+
+// TestEntryBlobDownloadFailureIsPrintedOnce backs up, deletes the blobs
+// from the destination, and restores, so the blob download fails.
+//
+//nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
+func TestEntryBlobDownloadFailureIsPrintedOnce(t *testing.T) {
+	for _, verbose := range []bool{false, true} {
+		t.Run(fmt.Sprintf("verbose=%t", verbose), func(t *testing.T) {
+			configPath, storeDir := writeBackupConfigWithPrivateKey(t)
+
+			code, _, _ := runEntry(t,
+				flagConfig, configPath, cmdSnapshot, cmdCreate)
+			require.Equal(t, 0, code)
+
+			require.NoError(t, os.RemoveAll(filepath.Join(storeDir, blobsDir)))
+
+			requireErrorPrintedOnce(t, verbose, flagConfig, configPath,
+				cmdSnapshot, cmdRestore, onlySnapshotID(t, configPath), t.TempDir())
+		})
+	}
+}
+
+// requireErrorPrintedOnce runs Entry with args, adding --verbose when
+// verbose is set. The command must fail, and stderr must carry its error
+// once, as the final ERROR: line. A log record carrying the same error
+// appears only under --verbose.
+func requireErrorPrintedOnce(t *testing.T, verbose bool, args ...string) {
+	t.Helper()
+
+	if verbose {
+		args = append(args, flagVerbose)
+	}
+
+	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
+}
+
+// writeBackupConfigWithPrivateKey builds what writeBackupConfig builds,
+// with a generated key pair in place of its recipient. The config also
+// holds the private key, so that restore can decrypt the backup. Returns
+// the config path and the store directory.
+func writeBackupConfigWithPrivateKey(t *testing.T) (string, string) {
+	t.Helper()
+
+	configPath, storeDir := writeBackupConfig(t)
+
+	identity, err := age.GenerateX25519Identity()
+	require.NoError(t, err)
+
+	out := ui.NewWithColor(io.Discard, false)
+
+	require.NoError(t, writeConfigSet(out, configPath,
+		"age_recipients.0", identity.Recipient().String()))
+	require.NoError(t, writeConfigSet(out, configPath,
+		"age_secret_key", identity.String()))
+
+	return configPath, storeDir
+}
+
+// onlySnapshotID returns the ID of the one snapshot in the local index
+// that writeBackupConfig puts beside the config file.
+func onlySnapshotID(t *testing.T, configPath string) string {
+	t.Helper()
+
+	ctx := context.Background()
+
+	db, err := database.New(ctx,
+		filepath.Join(filepath.Dir(configPath), "index.sqlite"))
+	require.NoError(t, err)
+
+	defer func() { require.NoError(t, db.Close()) }()
+
+	backedUp, err := database.NewRepositories(db).Snapshots.GetOnlySnapshot(ctx)
+	require.NoError(t, err)
+
+	return backedUp.ID.String()
+}

internal/cli/entry_snapshot_create_prune_test.go

@@ -61,8 +61,8 @@ func TestEntrySnapshotCreateRejectsKeepNewerThanBeforeBackup(t *testing.T) {
 
 // TestEntrySnapshotCreateReportsPostBackupPruneFailure makes the
 // post-backup prune fail after a good backup, by planting a manifest
-// that cannot be decoded, and checks that the failure is reported as the
+// that cannot be decoded, and checks that the failure is reported once,
-// prune's and not as a failed snapshot creation.
+// as the prune's and not as a failed snapshot creation.
 //
 //nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
 func TestEntrySnapshotCreateReportsPostBackupPruneFailure(t *testing.T) {
@@ -83,6 +83,9 @@ func TestEntrySnapshotCreateReportsPostBackupPruneFailure(t *testing.T) {
 	assert.Contains(t, stderr, "Backup completed, but post-backup prune failed")
 	assert.NotContains(t, stderr, "Snapshot creation failed")
 
+	_, repeats := failureOutput(t, stderr)
+	assert.Zero(t, repeats, "no log record may repeat the error:\n%s", stderr)
+
 	snapshots, err := os.ReadDir(filepath.Join(storeDir, "metadata"))
 	require.NoError(t, err)
 	assert.Len(t, snapshots, 2,
@@ -93,7 +96,8 @@ func TestEntrySnapshotCreateReportsPostBackupPruneFailure(t *testing.T) {
 // empties the source directory, as a volume that is not mounted leaves
 // its mount point, and runs `snapshot create --prune`. The command exits
 // non-zero and reports the backup as completed, not as a failed snapshot
-// creation. See https://git.eeqj.de/sneak/vaultik/issues/388.
+// creation. The error is printed once. See
+// https://git.eeqj.de/sneak/vaultik/issues/388.
 //
 //nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
 func TestEntrySnapshotCreatePruneExitsNonZeroWhenSourceIsEmpty(t *testing.T) {
@@ -114,6 +118,9 @@ func TestEntrySnapshotCreatePruneExitsNonZeroWhenSourceIsEmpty(t *testing.T) {
 		"Backup completed, but 1 source path(s) were empty")
 	assert.NotContains(t, stderr, "Snapshot creation failed")
 
+	_, repeats := failureOutput(t, stderr)
+	assert.Zero(t, repeats, "no log record may repeat the error:\n%s", stderr)
+
 	snapshots, err := os.ReadDir(filepath.Join(storeDir, "metadata"))
 	require.NoError(t, err)
 	assert.Len(t, snapshots, 2, "the older snapshot is kept")
@@ -124,7 +131,8 @@ func TestEntrySnapshotCreatePruneExitsNonZeroWhenSourceIsEmpty(t *testing.T) {
 // directory as a mount point, and runs `snapshot create --prune`, which
 // does not find it as one. The command exits non-zero, reports the
 // backup as completed, not as a failed snapshot creation, and keeps the
-// older snapshot. See https://git.eeqj.de/sneak/vaultik/issues/395.
+// older snapshot. The error is printed once. See
+// https://git.eeqj.de/sneak/vaultik/issues/395.
 //
 //nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals
 func TestEntrySnapshotCreatePruneExitsNonZeroWhenMountPointIsMissing(
@@ -159,6 +167,9 @@ func TestEntrySnapshotCreatePruneExitsNonZeroWhenMountPointIsMissing(
 		"an earlier snapshot recorded were not found")
 	assert.NotContains(t, stderr, "Snapshot creation failed")
 
+	_, repeats := failureOutput(t, stderr)
+	assert.Zero(t, repeats, "no log record may repeat the error:\n%s", stderr)
+
 	snapshots, err := os.ReadDir(filepath.Join(storeDir, "metadata"))
 	require.NoError(t, err)
 	assert.Len(t, snapshots, 2, "the older snapshot is kept")

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)
 	})
 }

internal/snapshot/scanner.go

@@ -1875,10 +1875,12 @@ func (s *Scanner) uploadBlobIfNeeded(
 	err = s.storage.PutWithProgress(ctx, blobPath, blobWithReader.Reader,
 		finishedBlob.Compressed, progressCallback)
 	if err != nil {
-		// Only an interrupt cancels ctx, and the user is told about it,
+		// The record is at info level: the returned error ends the backup
-		// so an upload it stopped is not logged as a storage failure.
+		// and is printed as its ERROR: line. Only an interrupt cancels
+		// ctx, and the user is told about it, so an upload it stopped is
+		// not logged as a storage failure.
 		if ctx.Err() == nil {
-			log.Error("Failed to upload blob", "hash", finishedBlob.Hash, "error", err)
+			log.Info("Failed to upload blob", "hash", finishedBlob.Hash, "error", err)
 		}
 
 		return 0, false, fmt.Errorf("uploading blob to storage: %w", err)

internal/snapshot/upload_cancel_log_test.go

@@ -37,9 +37,9 @@ func uploadTestBlob(ctx context.Context, store storage.Storer) error {
 }
 
 // captureLog runs fn and returns what the logger wrote to stderr
-// meanwhile. The logger writes to the os.Stderr it finds when it is
+// meanwhile, at the --verbose level. The logger writes to the os.Stderr
-// initialized, so os.Stderr is pointed at a file first. Not
+// it finds when it is initialized, so os.Stderr is pointed at a file
-// parallel-safe: os.Stderr and the logger are process-global.
+// first. Not parallel-safe: os.Stderr and the logger are process-global.
 func captureLog(t *testing.T, fn func()) string {
 	t.Helper()
 
@@ -53,7 +53,7 @@ func captureLog(t *testing.T, fn func()) string {
 	previous := os.Stderr
 	os.Stderr = stderrFile
 
-	log.Initialize(log.Config{})
+	log.Initialize(log.Config{Verbose: true})
 
 	fn()
 
@@ -107,10 +107,10 @@ func TestInterruptedUploadIsNotLoggedAsError(t *testing.T) {
 	}
 }
 
-// An upload that fails for any other reason is still logged as an error.
+// An upload that fails for any other reason is still logged.
 //
 //nolint:paralleltest // captureLog replaces os.Stderr
-func TestFailedUploadIsLoggedAsError(t *testing.T) {
+func TestFailedUploadIsLogged(t *testing.T) {
 	inner, err := storage.NewFileStorer(t.TempDir())
 	if err != nil {
 		t.Fatal(err)

internal/vaultik/restore.go

@@ -667,19 +667,19 @@ func (v *Vaultik) restoreProgressTick(
 
 // handleRestoreFileError records a per-file restore failure: fatal unless
 // --skip-errors is set, in which case the file is counted as failed and
-// dropped from the plan.
+// dropped from the plan. A fatal failure is not logged here: the returned
+// error is printed as the command's ERROR: line.
 func (v *Vaultik) handleRestoreFileError(
 	plan *restorePlan, opts *RestoreOptions, result *RestoreResult,
 	file *database.File, fileID types.FileID, err error,
 ) error {
-	log.Error("Failed to restore file", "path", file.Path, "error", err)
-
 	if !opts.SkipErrors {
 		return fmt.Errorf(
 			"restoring %s: %w (pass --skip-errors to continue past "+
 				"restore failures)", file.Path, err)
 	}
 
+	log.Error("Failed to restore file", "path", file.Path, "error", err)
 	v.UI.Errorf("Failed to restore %s: %v. Skipping (--skip-errors).",
 		v.UI.Path(file.Path.String()), err)