From cdcbe8adfde745a31ddf0ebc6d973fa8c5d67bfb Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Wed, 11 Nov 2026 05:30:02 +0100 Subject: [PATCH] Do not log an upload stopped by Ctrl-C as an error (closes #434) Pressing Ctrl-C or sending SIGTERM during a backup logged the interrupted blob upload as an ERROR before the interrupted message. The upload step now skips that record when the backup's context has been cancelled, whatever error the storage returned. An upload that fails for any other reason is still logged. Model: opus-5-5 --- internal/snapshot/scanner.go | 6 +- internal/snapshot/upload_cancel_log_test.go | 135 ++++++++++++++++++++ 2 files changed, 140 insertions(+), 1 deletion(-) create mode 100644 internal/snapshot/upload_cancel_log_test.go diff --git a/internal/snapshot/scanner.go b/internal/snapshot/scanner.go index de8db7e..d87fb9a 100644 --- a/internal/snapshot/scanner.go +++ b/internal/snapshot/scanner.go @@ -1861,7 +1861,11 @@ func (s *Scanner) uploadBlobIfNeeded( err = s.storage.PutWithProgress(ctx, blobPath, blobWithReader.Reader, finishedBlob.Compressed, progressCallback) if err != nil { - log.Error("Failed to upload blob", "hash", finishedBlob.Hash, "error", err) + // 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) + } 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 new file mode 100644 index 0000000..1ae97a7 --- /dev/null +++ b/internal/snapshot/upload_cancel_log_test.go @@ -0,0 +1,135 @@ +//nolint:testpackage // exercises the unexported uploadBlobIfNeeded +package snapshot + +import ( + "bytes" + "context" + "io" + "os" + "path/filepath" + "strings" + "testing" + "time" + + "sneak.berlin/go/vaultik/internal/blob" + "sneak.berlin/go/vaultik/internal/log" + "sneak.berlin/go/vaultik/internal/storage" + "sneak.berlin/go/vaultik/internal/storage/faultstore" + "sneak.berlin/go/vaultik/internal/ui" +) + +const uploadFailedLogMessage = "Failed to upload blob" + +// uploadTestBlob uploads a small blob through store. +func uploadTestBlob(ctx context.Context, store storage.Storer) error { + data := []byte("blob data") + s := &Scanner{storage: store, ui: ui.NewWithColor(io.Discard, false)} + + _, _, err := s.uploadBlobIfNeeded(ctx, "blobs/test", &blob.WithReader{ + FinishedBlob: &blob.FinishedBlob{ + Hash: "test", + Compressed: int64(len(data)), + }, + Reader: bytes.NewReader(data), + }, time.Now(), &ScanResult{}) + + return err +} + +// 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. +func captureLog(t *testing.T, fn func()) string { + t.Helper() + + stderrPath := filepath.Join(t.TempDir(), "stderr") + + stderrFile, err := os.Create(stderrPath) //nolint:gosec // G304: test temp path + if err != nil { + t.Fatalf("creating stderr file: %v", err) + } + + previous := os.Stderr + os.Stderr = stderrFile + + log.Initialize(log.Config{}) + + fn() + + os.Stderr = previous + + log.Initialize(log.Config{}) + + _ = stderrFile.Close() + + captured, err := os.ReadFile(stderrPath) //nolint:gosec // G304: test temp path + if err != nil { + t.Fatalf("reading stderr file: %v", err) + } + + return string(captured) +} + +// An upload stopped by Ctrl-C or SIGTERM is not logged as an error; the +// interrupted message is all the user sees. See +// https://git.eeqj.de/sneak/vaultik/issues/434. +// +//nolint:paralleltest // captureLog replaces os.Stderr +func TestInterruptedUploadIsNotLoggedAsError(t *testing.T) { + inner, err := storage.NewFileStorer(t.TempDir()) + if err != nil { + t.Fatal(err) + } + + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + + // The user interrupts mid-upload. The injected error does not wrap + // context.Canceled, so only ctx shows why the upload failed. + store := faultstore.New(inner) + store.OnPut = func(string) faultstore.PutAction { + cancel() + + return faultstore.PutFail + } + + var uploadErr error + + stderr := captureLog(t, func() { uploadErr = uploadTestBlob(ctx, store) }) + + if uploadErr == nil { + t.Fatal("expected the upload to fail") + } + + if strings.Contains(stderr, uploadFailedLogMessage) { + t.Errorf("interrupted upload logged as a failure: %q", stderr) + } +} + +// An upload that fails for any other reason is still logged as an error. +// +//nolint:paralleltest // captureLog replaces os.Stderr +func TestFailedUploadIsLoggedAsError(t *testing.T) { + inner, err := storage.NewFileStorer(t.TempDir()) + if err != nil { + t.Fatal(err) + } + + store := faultstore.New(inner) + store.OnPut = func(string) faultstore.PutAction { return faultstore.PutFail } + + var uploadErr error + + stderr := captureLog(t, func() { + uploadErr = uploadTestBlob(context.Background(), store) + }) + + if uploadErr == nil { + t.Fatal("expected the upload to fail") + } + + if !strings.Contains(stderr, uploadFailedLogMessage) { + t.Errorf("failed upload not logged: %q", stderr) + } +}