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

README.md

@@ -831,8 +831,7 @@ Work planned after 1.0. Loosely ordered by priority.
 
 Every command's user-facing output is governed by `internal/ui`, in one of two
 ways. Color is enabled when the stream written to is a TTY and the `NO_COLOR`
-environment variable is unset (https://no-color.org/). The same rule governs the
-colorized log lines `internal/log` writes to a terminal.
+environment variable is unset (https://no-color.org/).
 
 - **Status, progress, warnings, and errors** go through the `internal/ui`
   message methods below: marker-prefixed, colored on a TTY, and — except

internal/log/tty_handler.go

@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"io"
 	"log/slog"
-	"os"
 	"strconv"
 	"strings"
 	"sync"
@@ -61,12 +60,6 @@ type TTYHandler struct {
 	mu   *sync.Mutex
 	out  io.Writer
 
-	// color reports whether records are written with ANSI color. It is
-	// false when NO_COLOR is set, matching internal/ui's shouldColor
-	// test; the caller already chose this handler for a terminal, so
-	// TTY-ness is not re-checked here.
-	color bool
-
 	// attrs are the attributes accumulated through WithAttrs, emitted
 	// ahead of each record's own attributes. Their keys already carry
 	// the group path that was open when they were added, so no
@@ -79,19 +72,16 @@ type TTYHandler struct {
 	groups []string
 }
 
-// NewTTYHandler creates a new TTY handler. Color is enabled unless the
-// NO_COLOR environment variable is set to a non-empty value, the same
-// test internal/ui applies to status lines.
+// NewTTYHandler creates a new TTY handler with colored output.
 func NewTTYHandler(out io.Writer, opts *slog.HandlerOptions) *TTYHandler {
 	if opts == nil {
 		opts = &slog.HandlerOptions{}
 	}
 
 	return &TTYHandler{
-		out:   out,
-		opts:  *opts,
-		mu:    &sync.Mutex{},
-		color: os.Getenv("NO_COLOR") == "",
+		out:  out,
+		opts: *opts,
+		mu:   &sync.Mutex{},
 	}
 }
 
@@ -134,10 +124,10 @@ func (h *TTYHandler) Handle(_ context.Context, r slog.Record) error {
 	// are written around it: it can carry text from an untrusted source
 	// (a storage error, for one), and a raw control character would
 	// otherwise reach the terminal.
-	_, _ = fmt.Fprintf(h.out, "%s %s %s",
-		h.paint(colorGray, timestamp),
-		h.paint(levelColor, level),
-		h.paint(colorBold, sanitize(r.Message)))
+	_, _ = fmt.Fprintf(h.out, "%s%s%s %s%s%s %s%s%s",
+		colorGray, timestamp, colorReset,
+		levelColor, level, colorReset,
+		colorBold, sanitize(r.Message), colorReset)
 
 	// Attributes carried by the handler come first, then the record's
 	// own. Handler attributes were qualified when they were added; the
@@ -246,7 +236,6 @@ func (h *TTYHandler) clone() *TTYHandler {
 		opts:   h.opts,
 		mu:     h.mu,
 		out:    h.out,
-		color:  h.color,
 		attrs:  make([]slog.Attr, len(h.attrs), len(h.attrs)+1),
 		groups: make([]string, len(h.groups), len(h.groups)+1),
 	}
@@ -284,19 +273,9 @@ func (h *TTYHandler) writeAttr(a slog.Attr) {
 	// the snapshot database — so a control character in one of them must
 	// be rendered as an escape sequence rather than reaching the terminal,
 	// where it could move the cursor or inject its own colours.
-	_, _ = fmt.Fprintf(h.out, " %s=%s",
-		h.paint(colorCyan, sanitize(a.Key)),
-		h.paint(colorBlue, sanitize(value)))
-}
-
-// paint wraps s in the given ANSI color when color is enabled, and
-// returns s unchanged otherwise.
-func (h *TTYHandler) paint(color, s string) string {
-	if !h.color {
-		return s
-	}
-
-	return color + s + colorReset
+	_, _ = fmt.Fprintf(h.out, " %s%s%s=%s%s%s",
+		colorCyan, sanitize(a.Key), colorReset,
+		colorBlue, sanitize(value), colorReset)
 }
 
 // sanitize returns s unchanged when every rune in it is printable, and a

internal/log/tty_handler_test.go

@@ -421,44 +421,3 @@ func TestTTYHandlerEmptyGroupAndAttrsAreNoOps(t *testing.T) {
 	assert.Contains(t, plain, "kept=yes")
 	assert.NotContains(t, plain, " =")
 }
-
-// TestTTYHandlerRespectsNoColor checks that only a non-empty NO_COLOR
-// turns color off, matching internal/ui's shouldColor test. The handler
-// is only ever chosen for a terminal, so this is the one remaining
-// condition that can still leave color in log output.
-func TestTTYHandlerRespectsNoColor(t *testing.T) {
-	cases := []struct {
-		name    string
-		noColor string
-		colored bool
-	}{
-		{
-			name:    "NO_COLOR turns color off",
-			noColor: "1",
-		},
-		{
-			name:    "empty NO_COLOR keeps color on",
-			noColor: "",
-			colored: true,
-		},
-	}
-
-	for _, testCase := range cases {
-		t.Run(testCase.name, func(t *testing.T) {
-			t.Setenv("NO_COLOR", testCase.noColor)
-
-			var buf bytes.Buffer
-
-			logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
-			logger.Info("hello", "key", "value")
-
-			if testCase.colored {
-				assert.Contains(t, buf.String(), "\x1b[",
-					"an empty NO_COLOR must leave ANSI color in log output")
-			} else {
-				assert.NotContains(t, buf.String(), "\x1b[",
-					"NO_COLOR must suppress every ANSI escape in log output")
-			}
-		})
-	}
-}

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

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