Honor NO_COLOR in the terminal log handler (closes #402)

The TTY log handler always wrote ANSI color, unlike internal/ui, which
disables color when NO_COLOR is set. Add a color flag to TTYHandler,
set from NO_COLOR with the same test internal/ui uses, and route every
color code through a paint helper that returns plain text when color is
off. The README's color sentence now covers log lines too.

Model: deepseek-v4-pro (implementation); opus-5-5 (rebase)

README.md

@@ -831,7 +831,8 @@ 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/).
+environment variable is unset (https://no-color.org/). The same rule governs the
+colorized log lines `internal/log` writes to a terminal.
 
 - **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,6 +5,7 @@ import (
 	"fmt"
 	"io"
 	"log/slog"
+	"os"
 	"strconv"
 	"strings"
 	"sync"
@@ -60,6 +61,12 @@ 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
@@ -72,16 +79,19 @@ type TTYHandler struct {
 	groups []string
 }
 
-// NewTTYHandler creates a new TTY handler with colored output.
+// 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.
 func NewTTYHandler(out io.Writer, opts *slog.HandlerOptions) *TTYHandler {
 	if opts == nil {
 		opts = &slog.HandlerOptions{}
 	}
 
 	return &TTYHandler{
-		out:  out,
-		opts: *opts,
-		mu:   &sync.Mutex{},
+		out:   out,
+		opts:  *opts,
+		mu:    &sync.Mutex{},
+		color: os.Getenv("NO_COLOR") == "",
 	}
 }
 
@@ -124,10 +134,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 %s%s%s %s%s%s",
-		colorGray, timestamp, colorReset,
-		levelColor, level, colorReset,
-		colorBold, sanitize(r.Message), colorReset)
+	_, _ = fmt.Fprintf(h.out, "%s %s %s",
+		h.paint(colorGray, timestamp),
+		h.paint(levelColor, level),
+		h.paint(colorBold, sanitize(r.Message)))
 
 	// Attributes carried by the handler come first, then the record's
 	// own. Handler attributes were qualified when they were added; the
@@ -236,6 +246,7 @@ 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),
 	}
@@ -273,9 +284,19 @@ 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%s=%s%s%s",
-		colorCyan, sanitize(a.Key), colorReset,
-		colorBlue, sanitize(value), colorReset)
+	_, _ = 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
 }
 
 // sanitize returns s unchanged when every rune in it is printable, and a

internal/log/tty_handler_test.go

@@ -421,3 +421,44 @@ 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

@@ -40,9 +40,6 @@ var (
 	// which is secret, so the message is safe to print and log.
 	errInvalidAgeSecretKey = errors.New(
 		"configured age secret key holds no usable age identity")
-	// errWrongPrivateKey is returned when the configured key parses but
-	// is not one of the keys the snapshot was encrypted to.
-	errWrongPrivateKey          = errors.New("cannot decrypt this snapshot")
 	errBlobMissingFromIndex     = errors.New("blob hash missing from blob index")
 	errChunkNotInAnyBlob        = errors.New("chunk not found in any blob")
 	errBlobIDNotInHashIndex     = errors.New("blob id missing from hash index")
@@ -135,10 +132,6 @@ func (v *Vaultik) Restore(opts *RestoreOptions) error {
 	log.Info("Downloading snapshot metadata...")
 
 	tempDB, tempDir, err := v.downloadSnapshotDB(opts.SnapshotID, identities)
-	if errors.Is(err, errWrongPrivateKey) {
-		return err
-	}
-
 	if err != nil {
 		return fmt.Errorf("downloading snapshot database: %w", err)
 	}
@@ -330,28 +323,6 @@ func (v *Vaultik) restoreIdentities() ([]age.Identity, error) {
 	return identities, nil
 }
 
-// newSnapshotDBReader opens the decrypting reader for a snapshot
-// database. When none of the identities can decrypt it, the error says
-// in plain words that the configured private key is the wrong one and
-// names where it was configured.
-func (v *Vaultik) newSnapshotDBReader(
-	r io.Reader, identities []age.Identity,
-) (*blobgen.Reader, error) {
-	blobReader, err := blobgen.NewReader(r, identities...)
-
-	if _, ok := errors.AsType[*age.NoIdentityMatchError](err); ok {
-		return nil, fmt.Errorf(
-			"%w: the private key in %s is not one of the keys the backup was encrypted to",
-			errWrongPrivateKey, v.Config.AgeSecretKeySourceName())
-	}
-
-	if err != nil {
-		return nil, err
-	}
-
-	return blobReader, nil
-}
-
 // restoreAllFiles processes files in blob-locality order: drain every
 // file whose blob set is on disk, download the missing blobs for the
 // pending file with the smallest uncached count, repeat. This keeps
@@ -812,9 +783,9 @@ func (v *Vaultik) downloadSnapshotDB(
 	// the plaintext to a temp file. Neither the encrypted bytes nor the
 	// decrypted database is ever held whole in memory; a snapshot database
 	// can be large.
-	blobReader, err := v.newSnapshotDBReader(reader, identities)
+	blobReader, err := blobgen.NewReader(reader, identities...)
 	if err != nil {
-		return nil, "", err
+		return nil, "", fmt.Errorf("creating decryption reader: %w", err)
 	}
 
 	defer func() { _ = blobReader.Close() }()

internal/vaultik/restore_wrong_key_test.go

@@ -1,76 +0,0 @@
-package vaultik_test
-
-import (
-	"bytes"
-	"context"
-	"io"
-	"testing"
-
-	"filippo.io/age"
-	"github.com/spf13/afero"
-	"github.com/stretchr/testify/require"
-	"sneak.berlin/go/vaultik/internal/blobgen"
-	"sneak.berlin/go/vaultik/internal/config"
-	"sneak.berlin/go/vaultik/internal/snapshot"
-	"sneak.berlin/go/vaultik/internal/ui"
-	"sneak.berlin/go/vaultik/internal/vaultik"
-)
-
-// TestWrongPrivateKeyError checks that restore and deep verify, given a
-// valid private key the backup was not encrypted to, fail with one plain
-// sentence that names where the key was configured.
-func TestWrongPrivateKeyError(t *testing.T) {
-	t.Parallel()
-
-	ctx := context.Background()
-	store := NewMockStorer()
-
-	const snapshotID = "test-host_2026-01-01T00:00:00Z"
-
-	remoteKey := snapshot.RemoteSnapshotKey(snapshotID)
-
-	manifest, err := snapshot.EncodeManifest(
-		&snapshot.Manifest{SnapshotID: remoteKey}, 3)
-	require.NoError(t, err)
-	require.NoError(t, store.Put(ctx,
-		"metadata/"+remoteKey+"/manifest.json.zst", bytes.NewReader(manifest)))
-
-	// The database is encrypted to the test recipient only.
-	var db bytes.Buffer
-
-	writer, err := blobgen.NewWriter(&db, 1, []string{testAgePublicKey})
-	require.NoError(t, err)
-
-	_, err = writer.Write([]byte("snapshot database"))
-	require.NoError(t, err)
-	require.NoError(t, writer.Close())
-	require.NoError(t, store.Put(ctx,
-		"metadata/"+remoteKey+"/db.zst.age", &db))
-
-	otherKey, err := age.GenerateX25519Identity()
-	require.NoError(t, err)
-
-	v := &vaultik.Vaultik{
-		Config:  &config.Config{AgeSecretKey: otherKey.String()},
-		Storage: store,
-		Fs:      afero.NewMemMapFs(),
-		Stdout:  io.Discard,
-		Stderr:  io.Discard,
-		UI:      ui.NewWithColor(io.Discard, false),
-	}
-	v.SetContext(ctx)
-
-	// A Config built directly has no recorded source, so the error names
-	// the config-file field.
-	const want = "cannot decrypt this snapshot: the private key in " +
-		"age_secret_key is not one of the keys the backup was encrypted to"
-
-	err = v.Restore(&vaultik.RestoreOptions{
-		SnapshotID: snapshotID,
-		TargetDir:  t.TempDir(),
-	})
-	require.EqualError(t, err, want)
-
-	err = v.RunDeepVerify(snapshotID, &vaultik.VerifyOptions{Deep: true})
-	require.EqualError(t, err, want)
-}

internal/vaultik/verify.go

@@ -267,10 +267,6 @@ func (v *Vaultik) downloadVerifiedSnapshotDB(
 	defer func() { _ = dbReader.Close() }()
 
 	tdb, err := v.decryptAndLoadDatabase(dbReader, identities)
-	if errors.Is(err, errWrongPrivateKey) {
-		return nil, v.deepVerifyFailure(result, opts, err.Error(), err)
-	}
-
 	if err != nil {
 		return nil, v.deepVerifyFailure(result, opts,
 			fmt.Sprintf("failed to decrypt database: %v", err),
@@ -355,9 +351,9 @@ func (v *Vaultik) decryptAndLoadDatabase(
 	reader io.ReadCloser, identities []age.Identity,
 ) (*tempDB, error) {
 	// Decrypt and decompress through the shared blobgen reader.
-	blobReader, err := v.newSnapshotDBReader(reader, identities)
+	blobReader, err := blobgen.NewReader(reader, identities...)
 	if err != nil {
-		return nil, err
+		return nil, fmt.Errorf("failed to create decryption reader: %w", err)
 	}
 
 	defer func() { _ = blobReader.Close() }()