diff --git a/internal/cli/app.go b/internal/cli/app.go index 71d1159..35f8e2d 100644 --- a/internal/cli/app.go +++ b/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) }) } diff --git a/internal/cli/entry.go b/internal/cli/entry.go index 8760ba5..d332071 100644 --- a/internal/cli/entry.go +++ b/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...) } diff --git a/internal/cli/entry_failure_once_test.go b/internal/cli/entry_failure_once_test.go new file mode 100644 index 0000000..734f814 --- /dev/null +++ b/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() +} 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) }) } diff --git a/internal/snapshot/scanner.go b/internal/snapshot/scanner.go index 624a006..9bd36b7 100644 --- a/internal/snapshot/scanner.go +++ b/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, - // so an upload it stopped is not logged as a storage failure. + // The record is at info level: the returned error ends the backup + // 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) diff --git a/internal/snapshot/upload_cancel_log_test.go b/internal/snapshot/upload_cancel_log_test.go index 1ae97a7..f17f5ee 100644 --- a/internal/snapshot/upload_cancel_log_test.go +++ b/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 -// initialized, so os.Stderr is pointed at a file first. Not -// parallel-safe: os.Stderr and the logger are process-global. +// meanwhile, at the --verbose level. The logger writes to the os.Stderr +// it finds when it is initialized, so os.Stderr is pointed at a file +// 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) diff --git a/internal/vaultik/restore.go b/internal/vaultik/restore.go index 928ca20..5f41d96 100644 --- a/internal/vaultik/restore.go +++ b/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)