From b4d50c04441be32bfdcf5fe4db31cbfa639536b2 Mon Sep 17 00:00:00 2001 From: clawbot Date: Wed, 11 Nov 2026 01:54:29 +0000 Subject: [PATCH] Do not log an interrupted blob upload as an error (closes #434) Ctrl-C or SIGTERM cancels the operation's context, which makes the blob upload in progress fail. The upload step logged that failure at level ERROR before the interrupted message, so a cancellation the user asked for read as a storage failure. It now logs the failure only while the context is still live; only an interrupt cancels it. Any other upload failure is still logged. Model: opus-5-5 --- internal/snapshot/scanner.go | 6 +- internal/snapshot/upload_cancel_log_test.go | 147 ++++++++++++++++++++ 2 files changed, 152 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..1f9a856 --- /dev/null +++ b/internal/snapshot/upload_cancel_log_test.go @@ -0,0 +1,147 @@ +//nolint:testpackage // exercises the unexported uploadBlobIfNeeded +package snapshot + +import ( + "bytes" + "context" + "fmt" + "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" + +// cancelOnPutStorer stands in for a backend whose upload the user +// interrupts: it cancels the operation's context mid-upload and fails +// the way the S3 backend does when its context is cancelled. +type cancelOnPutStorer struct { + storage.Storer + + cancel context.CancelFunc +} + +func (c *cancelOnPutStorer) PutWithProgress( + ctx context.Context, _ string, _ io.Reader, + _ int64, _ storage.ProgressCallback, +) error { + c.cancel() + + return fmt.Errorf("upload multipart failed: %w", ctx.Err()) +} + +// 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) + + store := &cancelOnPutStorer{Storer: inner, cancel: cancel} + + 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) + } +}