From f120acd2c783edd34aee1b89d89cba04371451bc Mon Sep 17 00:00:00 2001 From: sneak Date: Wed, 11 Nov 2026 01:54:36 +0000 Subject: [PATCH] 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 | 2 +- internal/cli/entry.go | 4 + internal/cli/entry_failure_once_test.go | 102 ++++++++++++++++++++++++ internal/cli/info.go | 2 +- internal/cli/prune.go | 2 +- internal/cli/remote.go | 2 +- internal/cli/snapshot.go | 8 +- internal/cli/snapshot_restore.go | 2 +- 8 files changed, 115 insertions(+), 9 deletions(-) create mode 100644 internal/cli/entry_failure_once_test.go diff --git a/internal/cli/app.go b/internal/cli/app.go index bd54f1d..66c09c9 100644 --- a/internal/cli/app.go +++ b/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) }) } diff --git a/internal/cli/entry.go b/internal/cli/entry.go index e9d3a6c..a2dafef 100644 --- a/internal/cli/entry.go +++ b/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...) } diff --git a/internal/cli/entry_failure_once_test.go b/internal/cli/entry_failure_once_test.go new file mode 100644 index 0000000..13b754e --- /dev/null +++ b/internal/cli/entry_failure_once_test.go @@ -0,0 +1,102 @@ +package cli //nolint:testpackage // shares the fixtures and capture helpers + +import ( + "encoding/json" + "slices" + "strings" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +const ( + // errorLinePrefix starts the final line that reports a failed command. + errorLinePrefix = "ERROR: " + + flagVerbose = "--verbose" +) + +// 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 _, command := range [][]string{ + {cmdSnapshot, cmdCreate}, + {cmdRemote, cmdInfo}, + {cmdPrune, flagJSON}, + } { + for _, verbose := range []bool{false, true} { + args := slices.Clone(command) + if verbose { + args = append(args, flagVerbose) + } + + t.Run(strings.Join(args, " "), func(t *testing.T) { + code, _, stderr := runEntry(t, append([]string{flagConfig, + writeUnusableDestinationConfig(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 +} diff --git a/internal/cli/info.go b/internal/cli/info.go index 27d40de..5430656 100644 --- a/internal/cli/info.go +++ b/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) }) }, diff --git a/internal/cli/prune.go b/internal/cli/prune.go index 6b6843a..6063e7a 100644 --- a/internal/cli/prune.go +++ b/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) }) }, diff --git a/internal/cli/remote.go b/internal/cli/remote.go index 4bf403f..f46bb26 100644 --- a/internal/cli/remote.go +++ b/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) }) }, diff --git a/internal/cli/snapshot.go b/internal/cli/snapshot.go index 8996d35..27056fc 100644 --- a/internal/cli/snapshot.go +++ b/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) }) }, diff --git a/internal/cli/snapshot_restore.go b/internal/cli/snapshot_restore.go index 8609b90..6e75ffc 100644 --- a/internal/cli/snapshot_restore.go +++ b/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) }) }