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

internal/vaultik/missing_destination_test.go

@@ -7,6 +7,7 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
+	"sync"
 	"testing"
 
 	"github.com/spf13/afero"
@@ -24,19 +25,28 @@ import (
 // that is not plugged in, cannot be listed. It is not an empty store, so
 // no command may conclude from it that the local snapshots are gone.
 
-// newFileDestinationVaultik returns a Vaultik that backs up the
-// snapshot named "first" to a file:// destination at storeDir.
+// newFileDestinationVaultik writes the fault source tree and returns a
+// Vaultik that backs it up to a file:// destination at storeDir.
 func newFileDestinationVaultik(
 	ctx context.Context, t *testing.T, storeDir string,
 ) (*vaultik.Vaultik, *database.Repositories) {
 	t.Helper()
 
-	osFs := afero.NewOsFs()
 	tempDir := t.TempDir()
 	dataDir := filepath.Join(tempDir, "src")
-	dbPath := filepath.Join(tempDir, "index.sqlite")
+	writeFaultSourceTree(t, afero.NewOsFs(), dataDir)
 
-	writeFaultSourceTree(t, osFs, dataDir)
+	return openFileDestinationVaultik(ctx, t, storeDir, dataDir,
+		filepath.Join(tempDir, "index.sqlite"))
+}
+
+// openFileDestinationVaultik returns a Vaultik that backs up dataDir to a
+// file:// destination at storeDir, with its local index at dbPath. The
+// index is closed when the test ends.
+func openFileDestinationVaultik(
+	ctx context.Context, t *testing.T, storeDir, dataDir, dbPath string,
+) (*vaultik.Vaultik, *database.Repositories) {
+	t.Helper()
 
 	store, err := storage.NewFileStorer(storeDir)
 	require.NoError(t, err)
@@ -48,22 +58,84 @@ func newFileDestinationVaultik(
 	repos := database.NewRepositories(db)
 	cfg := changedFileConfig(dataDir, dbPath)
 
-	return newBackupVaultik(ctx, cfg, store, repos, db, osFs), repos
+	return newBackupVaultik(ctx, cfg, store, repos, db, afero.NewOsFs()), repos
+}
+
+// firstBackup is one backup of the snapshot named "first" to a file://
+// destination. dir holds its source tree in src, its store in store and
+// its closed local index in index/index.sqlite. The first test that
+// needs it makes it, and TestMain removes it. Every test that copies it
+// backs up the same source tree, so no test may change that tree.
+//
+//nolint:gochecknoglobals // made once and shared by the tests that copy it
+var firstBackup struct {
+	once  sync.Once
+	dir   string
+	ready bool
+}
+
+// TestMain removes firstBackup once every test has run.
+func TestMain(m *testing.M) {
+	code := m.Run()
+
+	_ = os.RemoveAll(firstBackup.dir)
+
+	os.Exit(code)
+}
+
+// makeFirstBackup writes the fault source tree and backs it up as the
+// snapshot named "first", all in a new directory that it records in
+// firstBackup.
+func makeFirstBackup(ctx context.Context, t *testing.T) {
+	t.Helper()
+
+	dir, err := os.MkdirTemp("", "vaultik-first-backup-")
+	require.NoError(t, err)
+
+	firstBackup.dir = dir
+	storeDir := filepath.Join(dir, "store")
+	dataDir := filepath.Join(dir, "src")
+	indexDir := filepath.Join(dir, "index")
+
+	require.NoError(t, os.Mkdir(storeDir, 0o750))
+	require.NoError(t, os.Mkdir(indexDir, 0o750))
+	writeFaultSourceTree(t, afero.NewOsFs(), dataDir)
+
+	v, _ := openFileDestinationVaultik(ctx, t, storeDir, dataDir,
+		filepath.Join(indexDir, "index.sqlite"))
+	require.NoError(t, backUp(v, "first"))
+	require.NoError(t, v.DB.Close())
+
+	firstBackup.ready = true
 }
 
 // backUpToFileDestination creates the directory storeDir, as a user must
-// before the first backup, and backs up the snapshot named "first" to a
-// file:// destination there. Everything the returned Vaultik prints
-// after the backup goes to the returned buffer.
+// before the first backup, and returns a Vaultik whose file://
+// destination there holds a backup of the snapshot named "first". The
+// store and the local index are copies of firstBackup's, which is faster
+// than backing up in every test. The returned Vaultik backs up a source
+// tree shared with every other caller, so no test may change that tree.
+// Everything the returned Vaultik prints after the backup goes to the
+// returned buffer.
 func backUpToFileDestination(
 	ctx context.Context, t *testing.T, storeDir string,
 ) (*vaultik.Vaultik, *database.Repositories, *bytes.Buffer) {
 	t.Helper()
 
-	require.NoError(t, os.MkdirAll(storeDir, 0o750))
+	firstBackup.once.Do(func() { makeFirstBackup(ctx, t) })
+	require.True(t, firstBackup.ready, "another test failed to make firstBackup")
 
-	v, repos := newFileDestinationVaultik(ctx, t, storeDir)
-	require.NoError(t, backUp(v, "first"))
+	require.NoError(t, os.MkdirAll(storeDir, 0o750))
+	require.NoError(t, os.CopyFS(storeDir,
+		os.DirFS(filepath.Join(firstBackup.dir, "store"))))
+
+	indexDir := t.TempDir()
+	require.NoError(t, os.CopyFS(indexDir,
+		os.DirFS(filepath.Join(firstBackup.dir, "index"))))
+
+	v, repos := openFileDestinationVaultik(ctx, t, storeDir,
+		filepath.Join(firstBackup.dir, "src"),
+		filepath.Join(indexDir, "index.sqlite"))
 
 	out := &bytes.Buffer{}
 	v.Stdout = out

internal/vaultik/restore_locality_test.go

@@ -46,11 +46,11 @@ import (
 //     slice out a few KB — currently the dominant cost in restore.
 //
 // The test deliberately constructs an adversarial scenario: three
-// blobs A/B/C of ~6 MB each, nine files distributed across them, and
-// path-ordered names that interleave the blobs (a1, b1, c1, a2, b2,
-// c2, …) so naive path-order processing would touch every blob before
-// finishing any of them.
-// localitySource is one 1 MiB fixture file used by the locality test.
+// blobs A/B/C of five 64 KiB chunks each, nine files distributed across
+// them, and path-ordered names that interleave the blobs (a1, b1, c1,
+// a2, b2, c2, …) so naive path-order processing would touch every blob
+// before finishing any of them.
+// localitySource is one 64 KiB fixture file used by the locality test.
 type localitySource struct {
 	path string
 	data []byte
@@ -65,10 +65,10 @@ type localityCopy struct {
 
 // localitySourceBytes is the size of each source file of the locality
 // fixture.
-const localitySourceBytes = 1024 * 1024
+const localitySourceBytes = 64 * 1024
 
 // buildLocalityFixture writes the adversarial source layout described
-// in TestRestoreLocalityAndReadAt: 15 sources of 1 MiB each (which the
+// in TestRestoreLocalityAndReadAt: 15 sources of 64 KiB each (which the
 // backup packs into 3 blobs of 5 chunks) plus 9 interleaved-name copies
 // (3 per blob group).
 func buildLocalityFixture(

internal/vaultik/restore_sweeper_integration_test.go

@@ -27,10 +27,10 @@ import (
 // TestRestoreSweeperEvictsBlobs exercises the reference-counted blob
 // disk cache eviction during restore.
 //
-// The scenario: 30 unique 1 MB random files plus 10 duplicates of those
-// (40 files total, 30 MB of unique content) get backed up with a 10 MB
-// blob_size_limit. After backup the snapshot's encrypted blobs are
-// restored through Vaultik.Restore, and per-key Get counts on the
+// The scenario: 30 unique 128 KiB random files plus 10 duplicates of
+// those (40 files total, 3.75 MiB of unique content) get backed up with
+// a 1 MiB blob_size_limit. After backup the snapshot's encrypted blobs
+// are restored through Vaultik.Restore, and per-key Get counts on the
 // storage layer are recorded. Each blob in the snapshot MUST be
 // downloaded exactly once — re-downloads would mean the sweeper either
 // evicted a blob that was still needed (LRU regression) or that the
@@ -41,7 +41,7 @@ import (
 // original AND every duplicate referencing its chunks have been
 // restored.
 // buildSweeperFixture writes the source layout for the sweeper test: 30
-// unique 1 MB random files plus 10 duplicates of a random subset. The
+// unique 128 KiB random files plus 10 duplicates of a random subset. The
 // PRNG seed is fixed so failures are reproducible; the entropy is what
 // matters here — the FastCDC chunker needs realistic-looking data to
 // pick chunk boundaries naturally. Returns the expected content by
@@ -51,7 +51,7 @@ func buildSweeperFixture(
 ) map[string][]byte {
 	t.Helper()
 
-	const fileSize = 1 * 1024 * 1024
+	const fileSize = 128 * 1024
 
 	rng := rand.New(rand.NewSource(42)) //nolint:gosec // G404: fixture data only
 
@@ -159,7 +159,7 @@ func runSweeperBackup(
 	require.NoError(t, err)
 	require.Equal(t, uniqueFiles+duplicateFiles, scanResult.FilesScanned)
 	require.Greater(t, scanResult.BlobsCreated, 1,
-		"30 MB of unique data at 10 MB blob size should yield multiple blobs")
+		"3.75 MiB of unique data at 1 MiB blob size should yield multiple blobs")
 
 	require.NoError(t, sm.CompleteSnapshot(ctx, snapshotID))
 	require.NoError(t, sm.ExportSnapshotMetadata(ctx, dbPath, snapshotID))
@@ -199,8 +199,8 @@ func TestRestoreSweeperEvictsBlobs(t *testing.T) {
 
 	expected := buildSweeperFixture(t, fs, dataDir, uniqueFiles, duplicateFiles)
 
-	chunkSize := int64(64 * 1024)
-	maxBlobSize := int64(10 * 1024 * 1024)
+	chunkSize := int64(16 * 1024)
+	maxBlobSize := int64(1024 * 1024)
 
 	storer, err := storage.NewFileStorer(storeDir)
 	require.NoError(t, err)

internal/vaultik/snapshot_list_test.go

@@ -187,6 +187,17 @@ func (e *listEnv) addRemoteRawTimestamp(
 	t.Helper()
 
 	remoteKey := snapshot.RemoteSnapshotKey(snapshotID)
+	e.putRemoteManifest(t, remoteKey,
+		encodeRemoteManifest(t, remoteKey, timestamp))
+
+	return remoteKey
+}
+
+// encodeRemoteManifest returns the encoded manifest of a one-blob
+// snapshot whose remote key is remoteKey.
+func encodeRemoteManifest(t *testing.T, remoteKey, timestamp string) []byte {
+	t.Helper()
+
 	manifest := &snapshot.Manifest{
 		// Note: the hashed key, never the human ID. That is precisely
 		// why a remote-only snapshot cannot be named.
@@ -202,11 +213,17 @@ func (e *listEnv) addRemoteRawTimestamp(
 	data, err := snapshot.EncodeManifest(manifest, 3)
 	require.NoError(t, err)
 
-	err = e.store.Put(context.Background(),
+	return data
+}
+
+// putRemoteManifest stores an encoded manifest on the destination store
+// under remoteKey.
+func (e *listEnv) putRemoteManifest(t *testing.T, remoteKey string, data []byte) {
+	t.Helper()
+
+	err := e.store.Put(context.Background(),
 		"metadata/"+remoteKey+"/manifest.json.zst", bytes.NewReader(data))
 	require.NoError(t, err)
-
-	return remoteKey
 }
 
 // Fixtures shared across the listing tests.
@@ -791,9 +808,17 @@ func TestListSnapshots_JSONReportsTruncation(t *testing.T) {
 
 	timestamp := time.Date(2026, 3, 2, 11, 22, 33, 0, time.UTC)
 
-	// One past the cap, so exactly one snapshot is omitted.
+	// One past the cap, so exactly one snapshot is omitted. The listing
+	// names a snapshot by the key its manifest is stored under, never by
+	// the manifest's own ID. So all of them share one encoded manifest:
+	// encoding 1001 took seconds.
+	data := encodeRemoteManifest(t,
+		snapshot.RemoteSnapshotKey("otherhost_bulk"),
+		timestamp.Format(time.RFC3339))
+
 	for i := range maxRemoteOnlyRowsForTest + 1 {
-		env.addRemote(t, fmt.Sprintf("otherhost_bulk_%04d", i), timestamp)
+		env.putRemoteManifest(t, snapshot.RemoteSnapshotKey(
+			fmt.Sprintf("otherhost_bulk_%04d", i)), data)
 	}
 
 	stderr := captureProcessStderr(t, func() {