Report an unreadable blob once, without its bytes (closes #424)

blobgen.NewReader returns ErrNotAgeStream when age cannot open the
data, in place of age's error, which quotes the data's first bytes. A
failed read of the header is still returned as the read error, and a
wrong key as age.NoIdentityMatchError.

Under --skip-errors, restore reports a blob that could not be
downloaded once, with the number of files that need it. Those files
are counted in the final warning, not listed; each is logged at debug
level.

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/blobgen/negative_test.go

@@ -2,8 +2,10 @@ package blobgen_test
 
 import (
 	"bytes"
+	"errors"
 	"fmt"
 	"testing"
+	"testing/iotest"
 
 	"filippo.io/age"
 	"github.com/stretchr/testify/assert"
@@ -120,6 +122,37 @@ func TestNewReaderTrailingAndGarbage(t *testing.T) {
 	})
 }
 
+// TestNewReaderGarbageErrorQuotesNoBytes checks that random bytes in
+// place of a blob fail with ErrNotAgeStream, and that the error carries
+// none of those bytes.
+func TestNewReaderGarbageErrorQuotesNoBytes(t *testing.T) {
+	t.Parallel()
+
+	id, _ := makeIdentity(t)
+	garbage := bytes.Repeat([]byte("garbage-bytes-"), 100)
+
+	_, err := blobgen.NewReader(bytes.NewReader(garbage), id)
+
+	require.ErrorIs(t, err, blobgen.ErrNotAgeStream)
+	assert.NotContains(t, err.Error(), "garbage-bytes-")
+}
+
+// errConnectionReset stands for a storage read that fails.
+var errConnectionReset = errors.New("connection reset")
+
+// TestNewReaderReadFailure checks that a failed read of the age header is
+// returned as that read error, not as ErrNotAgeStream.
+func TestNewReaderReadFailure(t *testing.T) {
+	t.Parallel()
+
+	id, _ := makeIdentity(t)
+
+	_, err := blobgen.NewReader(iotest.ErrReader(errConnectionReset), id)
+
+	require.ErrorIs(t, err, errConnectionReset)
+	assert.NotErrorIs(t, err, blobgen.ErrNotAgeStream)
+}
+
 // TestNewWriterInvalidLevel covers the rejected end of issue case 9: an
 // out-of-range compression level errors and writes nothing to the destination.
 func TestNewWriterInvalidLevel(t *testing.T) {

internal/blobgen/reader.go

@@ -11,6 +11,11 @@ import (
 	"github.com/klauspost/compress/zstd"
 )
 
+// ErrNotAgeStream is returned by NewReader when the data cannot be opened
+// as an age stream, for example because its header is malformed. It
+// replaces age's own error, which can quote the data's first bytes.
+var ErrNotAgeStream = errors.New("not a valid age stream")
+
 // Reader wraps decompression and decryption with SHA256 verification
 type Reader struct {
 	reader       io.Reader
@@ -24,11 +29,25 @@ type Reader struct {
 // NewReader creates a new Reader that decrypts, decompresses, and verifies
 // data. Every supplied identity is offered to age.Decrypt, so a blob
 // encrypted to any one of them can be read.
+//
+// A failure to read r is returned as that error, and a blob encrypted to
+// none of the identities as age.NoIdentityMatchError. Any other failure
+// to open the age stream is ErrNotAgeStream.
 func NewReader(r io.Reader, identities ...age.Identity) (*Reader, error) {
-	// Create decryption reader
-	decReader, err := age.Decrypt(r, identities...)
+	src := &readErrorRecorder{reader: r}
+
+	decReader, err := age.Decrypt(src, identities...)
 	if err != nil {
-		return nil, fmt.Errorf("creating decryption reader: %w", err)
+		var noMatch *age.NoIdentityMatchError
+
+		switch {
+		case src.err != nil:
+			return nil, fmt.Errorf("reading age header: %w", src.err)
+		case errors.As(err, &noMatch):
+			return nil, fmt.Errorf("creating decryption reader: %w", err)
+		default:
+			return nil, ErrNotAgeStream
+		}
 	}
 
 	// Create decompression reader
@@ -52,6 +71,23 @@ func NewReader(r io.Reader, identities ...age.Identity) (*Reader, error) {
 	}, nil
 }
 
+// readErrorRecorder passes reads through to reader and keeps the first
+// error other than io.EOF, so NewReader can tell a failed read from bad
+// data.
+type readErrorRecorder struct {
+	reader io.Reader
+	err    error
+}
+
+func (r *readErrorRecorder) Read(p []byte) (int, error) {
+	n, err := r.reader.Read(p)
+	if err != nil && !errors.Is(err, io.EOF) && r.err == nil {
+		r.err = err
+	}
+
+	return n, err
+}
+
 // Read implements io.Reader
 func (r *Reader) Read(p []byte) (int, error) {
 	n, err := r.teeReader.Read(p)

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/vaultik/restore.go

@@ -106,7 +106,12 @@ type RestoreResult struct {
 	BytesDownloaded int64
 	Duration        time.Duration
 	FilesFailed     int
-	FailedFiles     []string // Paths of files that failed to restore
+	FailedFiles     []string // Paths of files that failed to restore for their own reason
+	// Blobs that could not be downloaded, and the paths of the files
+	// skipped because they need one of them. Those files are counted in
+	// FilesFailed but not listed in the summary.
+	BlobsFailed            int
+	FilesNeedingFailedBlob []string
 	// Verification results (only populated if Verify option is set)
 	FilesVerified     int
 	BytesVerified     int64
@@ -226,6 +231,11 @@ func (v *Vaultik) finishRestore(
 	if result.FilesFailed > 0 {
 		v.UI.Warningf("%d file(s) failed to restore:", result.FilesFailed)
 
+		if result.BlobsFailed > 0 {
+			v.UI.Detailf("%d of them need one of the %d blob(s) that could not be downloaded.",
+				len(result.FilesNeedingFailedBlob), result.BlobsFailed)
+		}
+
 		for _, path := range result.FailedFiles {
 			v.UI.Detailf("%s", v.UI.Path(path))
 		}
@@ -494,8 +504,8 @@ func (v *Vaultik) runRestoreLoop(
 // Returns false when nothing is pending download (the caller stops).
 //
 // A blob that cannot be downloaded is reported through
-// handleRestoreFileError for every pending file that references it, so
-// it aborts the restore unless --skip-errors is set.
+// handleRestoreBlobError, so it aborts the restore unless --skip-errors
+// is set.
 func (s *restoreSession) downloadNextBlobSet(
 	plan *restorePlan, filesByID map[types.FileID]*database.File,
 ) (bool, error) {
@@ -528,12 +538,11 @@ func (s *restoreSession) downloadNextBlobSet(
 				return false, err
 			}
 
-			for _, fileID := range plan.filesReferencingBlob(hash) {
-				fileErr := s.v.handleRestoreFileError(
-					plan, s.opts, s.result, filesByID[fileID], fileID, err)
-				if fileErr != nil {
-					return false, fileErr
-				}
+			blobErr := s.v.handleRestoreBlobError(
+				plan, s.opts, s.result, filesByID,
+				plan.filesReferencingBlob(hash), err)
+			if blobErr != nil {
+				return false, blobErr
 			}
 
 			// next is among the failed files, so the rest of its blob set
@@ -648,6 +657,41 @@ func (v *Vaultik) handleRestoreFileError(
 	return nil
 }
 
+// handleRestoreBlobError records a blob that could not be downloaded.
+// fileIDs are the pending files that need it, never empty. Without
+// --skip-errors the first of them fails the restore. With it, the blob is
+// reported once, and its files are counted as failed and dropped from
+// the plan without being reported one by one.
+func (v *Vaultik) handleRestoreBlobError(
+	plan *restorePlan, opts *RestoreOptions, result *RestoreResult,
+	filesByID map[types.FileID]*database.File, fileIDs []types.FileID,
+	err error,
+) error {
+	if !opts.SkipErrors {
+		return v.handleRestoreFileError(
+			plan, opts, result, filesByID[fileIDs[0]], fileIDs[0], err)
+	}
+
+	log.Error("Failed to restore files", "files", len(fileIDs), "error", err)
+	v.UI.Errorf("Failed to restore %d file(s): %v. Skipping them (--skip-errors).",
+		len(fileIDs), err)
+
+	result.BlobsFailed++
+
+	for _, fileID := range fileIDs {
+		path := filesByID[fileID].Path.String()
+
+		log.Debug("Skipped file that needs a failed blob", "path", path)
+
+		result.FilesFailed++
+		result.FilesNeedingFailedBlob = append(result.FilesNeedingFailedBlob, path)
+
+		plan.finishFile(fileID)
+	}
+
+	return nil
+}
+
 // printRestoreProgress emits a periodic restore-phase status line via
 // the UI writer, mirroring scanner.printProcessingProgress so the two
 // long-running commands have the same on-screen rhythm.
@@ -719,8 +763,8 @@ func (v *Vaultik) handleRestoreVerification(
 ) error {
 	// A file that failed to restore was not written and is already
 	// reported as such, so it is not verified.
-	failedToRestore := make(map[string]bool, len(result.FailedFiles))
-	for _, path := range result.FailedFiles {
+	failedToRestore := make(map[string]bool, result.FilesFailed)
+	for _, path := range slices.Concat(result.FailedFiles, result.FilesNeedingFailedBlob) {
 		failedToRestore[path] = true
 	}
 

internal/vaultik/restore_skip_errors_test.go

@@ -51,27 +51,72 @@ func TestRestoreSkipErrorsSkipsFilesOfMissingBlob(t *testing.T) {
 	t.Parallel()
 
 	ctx := context.Background()
-	assertRestoreSkipsLostFiles(ctx, t, backupThenDeleteOneBlob(ctx, t))
+	backup := backupThenDeleteOneBlob(ctx, t)
+	out := assertRestoreSkipsLostFiles(ctx, t, backup)
+
+	assertLostFilesCountedNotListed(t, backup, out)
+}
+
+// TestRestoreSkipErrorsReportsUnreadableBlobOnce restores with SkipErrors
+// after one blob of a two-blob snapshot was overwritten with other bytes
+// of the same size. The blob must be reported once, by its hash, as not a
+// valid age stream, without quoting its bytes, and its files must be
+// counted, not listed.
+func TestRestoreSkipErrorsReportsUnreadableBlobOnce(t *testing.T) {
+	log.Initialize(log.Config{})
+	t.Parallel()
+
+	ctx := context.Background()
+	backup, lostBlob := backupThenOverwriteOneBlob(ctx, t)
+	out := assertRestoreSkipsLostFiles(ctx, t, backup)
+
+	assert.Equal(t, 1, strings.Count(out, "not a valid age stream"), out)
+	assert.Contains(t, out, lostBlob[:16])
+	assert.NotContains(t, out, overwriteBlobPattern)
+	assertLostFilesCountedNotListed(t, backup, out)
 }
 
 // TestRestoreSkipErrorsSkipsFilesWithChunkInNoBlob restores with
 // SkipErrors a snapshot whose metadata lists chunks that no blob holds, as
-// earlier backup defects left behind.
+// earlier backup defects left behind. Each such file fails for its own
+// reason, so each is listed.
 func TestRestoreSkipErrorsSkipsFilesWithChunkInNoBlob(t *testing.T) {
 	log.Initialize(log.Config{})
 	t.Parallel()
 
 	ctx := context.Background()
-	assertRestoreSkipsLostFiles(ctx, t, backupThenDropOneBlobFromMetadata(ctx, t))
+	backup := backupThenDropOneBlobFromMetadata(ctx, t)
+	out := assertRestoreSkipsLostFiles(ctx, t, backup)
+
+	for path := range backup.lost {
+		assert.Containsf(t, out, path, "%s must be reported", path)
+	}
 }
 
-// assertRestoreSkipsLostFiles restores backup with SkipErrors. Every file
-// stored in the lost blob must be reported as failed and left absent,
-// every other file must be restored intact, and Restore must still return
-// an error.
+// assertLostFilesCountedNotListed checks that the restore output out
+// counts the files of the lost blob and names none of them.
+func assertLostFilesCountedNotListed(
+	t *testing.T, backup *missingBlobBackup, out string,
+) {
+	t.Helper()
+
+	assert.Contains(t, out, fmt.Sprintf(
+		"%d of them need one of the 1 blob(s) that could not be downloaded",
+		len(backup.lost)))
+
+	for path := range backup.lost {
+		assert.NotContainsf(t, out, path,
+			"%s needs the lost blob and must be counted, not listed", path)
+	}
+}
+
+// assertRestoreSkipsLostFiles restores backup with SkipErrors and returns
+// what it printed. Every file stored in the lost blob must be left
+// absent, every other file must be restored intact, and Restore must
+// still return an error.
 func assertRestoreSkipsLostFiles(
 	ctx context.Context, t *testing.T, backup *missingBlobBackup,
-) {
+) string {
 	t.Helper()
 
 	var out bytes.Buffer
@@ -93,8 +138,6 @@ func assertRestoreSkipsLostFiles(
 		restored := filepath.Join(backup.restoreDir, path)
 
 		if backup.lost[path] {
-			assert.Containsf(t, out.String(), path,
-				"%s needs the lost blob and must be reported", path)
 			assert.NoFileExists(t, restored)
 
 			continue
@@ -104,6 +147,8 @@ func assertRestoreSkipsLostFiles(
 		require.NoErrorf(t, err, "%s does not need the lost blob", path)
 		assert.Equalf(t, content, got, "%s restored with wrong content", path)
 	}
+
+	return out.String()
 }
 
 // TestRestoreSkipErrorsVerifyChecksOnlyRestoredFiles restores with
@@ -144,9 +189,9 @@ func TestRestoreSkipErrorsVerifyChecksOnlyRestoredFiles(t *testing.T) {
 // TestRestoreSkipErrorsVerifyReportsFailuresApart restores with
 // SkipErrors and Verify after one blob of a two-blob snapshot was
 // deleted, while one file that does restore is written one byte too long.
-// The restore warning must list only the files of the deleted blob, the
-// verification summary only the long file, each path once, and Restore
-// must return an error.
+// The restore warning must count the files of the deleted blob without
+// listing them, the verification summary must list only the long file,
+// once, and Restore must return an error.
 func TestRestoreSkipErrorsVerifyReportsFailuresApart(t *testing.T) {
 	log.Initialize(log.Config{})
 	t.Parallel()
@@ -186,9 +231,9 @@ func TestRestoreSkipErrorsVerifyReportsFailuresApart(t *testing.T) {
 		"Verification failed: 1 files did not match")
 	require.Truef(t, found, "no verification summary in:\n%s", out.String())
 
+	assertLostFilesCountedNotListed(t, backup, warning)
+
 	for path := range backup.lost {
-		assert.Equalf(t, 1, strings.Count(warning, path),
-			"%s must be listed once as failed to restore", path)
 		assert.NotContainsf(t, summary, path,
 			"%s was not restored and must not fail verification", path)
 	}
@@ -292,6 +337,34 @@ func backupThenDeleteOneBlob(
 	return backup
 }
 
+// overwriteBlobPattern repeats through the bytes that
+// backupThenOverwriteOneBlob writes over a blob.
+const overwriteBlobPattern = "overwritten-blob-bytes-"
+
+// backupThenOverwriteOneBlob backs up missingBlobFileCount single-chunk
+// files, then overwrites the blob holding the first of them with as many
+// bytes of overwriteBlobPattern. It also returns that blob's hash.
+func backupThenOverwriteOneBlob(
+	ctx context.Context, t *testing.T,
+) (*missingBlobBackup, string) {
+	t.Helper()
+
+	backup, db, lostBlob := backupSingleChunkFiles(ctx, t)
+	require.NoError(t, db.Close())
+
+	key := fmt.Sprintf("blobs/%s/%s/%s", lostBlob[:2], lostBlob[2:4], lostBlob)
+
+	info, err := backup.storer.Stat(ctx, key)
+	require.NoError(t, err)
+
+	pattern := bytes.Repeat([]byte(overwriteBlobPattern),
+		int(info.Size)/len(overwriteBlobPattern)+1)
+	require.NoError(t, backup.storer.Put(
+		ctx, key, bytes.NewReader(pattern[:info.Size])))
+
+	return backup, lostBlob
+}
+
 // backupThenDropOneBlobFromMetadata backs up missingBlobFileCount
 // single-chunk files, then removes the blob holding the first of them from
 // the snapshot and exports the snapshot metadata again. The exported