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

@@ -128,15 +128,10 @@ func (v *Vaultik) Restore(opts *RestoreOptions) error {
 		"paths", opts.Paths,
 	)
 
-	remoteKey, err := v.resolveSnapshotRemoteKey(opts.SnapshotID)
-	if err != nil {
-		return err
-	}
-
 	// Step 1: Download and decrypt the snapshot metadata database
 	log.Info("Downloading snapshot metadata...")
 
-	tempDB, tempDir, err := v.downloadSnapshotDB(opts.SnapshotID, remoteKey, identities)
+	tempDB, tempDir, err := v.downloadSnapshotDB(opts.SnapshotID, identities)
 	if err != nil {
 		return fmt.Errorf("downloading snapshot database: %w", err)
 	}
@@ -759,12 +754,19 @@ func (v *Vaultik) handleRestoreVerification(
 	return nil
 }
 
-// downloadSnapshotDB downloads and decrypts the metadata database of the
-// snapshot at remoteKey, which resolveSnapshotRemoteKey returned for
-// snapshotID.
+// downloadSnapshotDB downloads and decrypts the snapshot metadata
+// database. The identifier is resolved to the snapshot's remote key: a
+// human ID is hashed, and a remote key (or its abbreviation, as printed
+// for a remote-only snapshot) is used as-is, so a host with no local
+// index can restore the snapshots it can only see on the store.
 func (v *Vaultik) downloadSnapshotDB(
-	snapshotID, remoteKey string, identities []age.Identity,
+	snapshotID string, identities []age.Identity,
 ) (*database.DB, string, error) {
+	remoteKey, err := v.resolveSnapshotRemoteKey(snapshotID)
+	if err != nil {
+		return nil, "", err
+	}
+
 	// Download encrypted database from storage
 	dbKey := fmt.Sprintf("metadata/%s/db.zst.age", remoteKey)
 

internal/vaultik/snapshot.go

@@ -969,22 +969,25 @@ func (v *Vaultik) VerifySnapshotWithOptions(
 		Mode:       "shallow",
 	}
 
-	// The key is kept so we can also check for the snapshot's encrypted
-	// database below.
+	v.printVerifyHeader(snapshotID, opts)
+
+	// Resolve the identifier to the snapshot's remote key. A human ID is
+	// hashed; a remote key (or its abbreviation, as printed for a
+	// remote-only snapshot) is used as-is, so a host with no local index
+	// can verify a snapshot it can only see on the store. The key is kept
+	// so we can also check for the snapshot's encrypted database below.
 	remoteKey, err := v.resolveSnapshotRemoteKey(snapshotID)
 	if err != nil {
 		if opts.JSON {
 			result.Status = verifyStatusFailed
-			result.ErrorMessage = err.Error()
+			result.ErrorMessage = fmt.Sprintf("resolving snapshot identifier: %v", err)
 
 			return v.outputVerifyJSON(result)
 		}
 
-		return err
+		return fmt.Errorf("resolving snapshot identifier: %w", err)
 	}
 
-	v.printVerifyHeader(snapshotID, opts)
-
 	manifest, err := v.downloadManifestByKey(remoteKey)
 	if err != nil {
 		if opts.JSON {
@@ -1477,7 +1480,7 @@ func (v *Vaultik) RemoveSnapshot(
 		return result, err
 	}
 
-	inLocalIndex, err := v.findSnapshot(snapshotID, opts.LocalOnly)
+	inLocalIndex, err := v.findSnapshotToRemove(snapshotID, opts)
 	if err != nil {
 		return result, err
 	}
@@ -1540,15 +1543,17 @@ func (v *Vaultik) RemoveSnapshot(
 	return result, nil
 }
 
-// findSnapshot reports whether the local index has a row for
-// snapshotID, and returns errSnapshotNotFound when there is no row and,
-// unless localOnly is set, no metadata on the destination store either.
-// The destination store is consulted only when the local index has no
-// row, so a snapshot in the local index can still be removed from it
-// while the destination store is unreachable, and only after
-// checkDestinationMarker passes, so an unplugged volume's empty mount
-// point is not taken for a store without the snapshot.
-func (v *Vaultik) findSnapshot(snapshotID string, localOnly bool) (bool, error) {
+// findSnapshotToRemove reports whether the local index has a row for
+// snapshotID, and returns errSnapshotNotFound when there is nothing to
+// remove: no row and, unless LocalOnly is set, no metadata on the
+// destination store either. The destination store is consulted only
+// when the local index has no row, so a snapshot in the local index can
+// still be removed from it while the destination store is unreachable,
+// and only after checkDestinationMarker passes, so an unplugged volume's
+// empty mount point is not taken for a store without the snapshot.
+func (v *Vaultik) findSnapshotToRemove(
+	snapshotID string, opts *RemoveOptions,
+) (bool, error) {
 	if v.Repositories != nil {
 		snap, err := v.Repositories.Snapshots.GetByID(v.ctx, snapshotID)
 		if err != nil {
@@ -1560,7 +1565,7 @@ func (v *Vaultik) findSnapshot(snapshotID string, localOnly bool) (bool, error)
 		}
 	}
 
-	if localOnly {
+	if opts.LocalOnly {
 		return false, fmt.Errorf("%w in the local index: %s",
 			errSnapshotNotFound, snapshotID)
 	}

internal/vaultik/snapshot_identifier.go

@@ -28,9 +28,8 @@ var (
 // Two forms are accepted, matching the two things a host can know:
 //
 //   - A human snapshot ID (hostname_name_timestamp), which a host holding
-//     the local index has. It is hashed to its remote key. An ID that
-//     names no snapshot in the local index or on the destination store
-//     is an error (see findSnapshot).
+//     the local index has. It is hashed to its remote key; the store is
+//     not consulted.
 //   - A remote key, or the leading part of one, which is all a host with
 //     no local index can know — it is exactly what `snapshot list` prints
 //     for a remote-only snapshot (see formatRemoteOnlyID). It is resolved
@@ -42,11 +41,6 @@ var (
 // RFC3339 timestamp).
 func (v *Vaultik) resolveSnapshotRemoteKey(identifier string) (string, error) {
 	if !isRemoteKeyOrPrefix(identifier) {
-		_, err := v.findSnapshot(identifier, false)
-		if err != nil {
-			return "", err
-		}
-
 		return snapshot.RemoteSnapshotKey(identifier), nil
 	}
 

internal/vaultik/unknown_snapshot_test.go

@@ -1,62 +0,0 @@
-package vaultik_test
-
-import (
-	"bytes"
-	"context"
-	"testing"
-
-	"github.com/stretchr/testify/assert"
-	"github.com/stretchr/testify/require"
-	"sneak.berlin/go/vaultik/internal/config"
-	"sneak.berlin/go/vaultik/internal/log"
-	"sneak.berlin/go/vaultik/internal/vaultik"
-)
-
-// TestUnknownSnapshotID checks that restore and verify, given an ID that
-// names no snapshot in the local index or on the destination store, say
-// so in the words `snapshot remove` uses and print nothing else.
-func TestUnknownSnapshotID(t *testing.T) {
-	log.Initialize(log.Config{})
-	t.Parallel()
-
-	const unknownID = "host1_home_2026-01-01T00:00:00Z"
-
-	commands := map[string]func(v *vaultik.Vaultik) error{
-		"restore": func(v *vaultik.Vaultik) error {
-			return v.Restore(&vaultik.RestoreOptions{
-				SnapshotID: unknownID,
-				TargetDir:  t.TempDir(),
-			})
-		},
-		"verify": func(v *vaultik.Vaultik) error {
-			return v.VerifySnapshotWithOptions(unknownID, &vaultik.VerifyOptions{})
-		},
-		"verify --deep": func(v *vaultik.Vaultik) error {
-			return v.VerifySnapshotWithOptions(unknownID,
-				&vaultik.VerifyOptions{Deep: true})
-		},
-	}
-
-	for name, run := range commands {
-		t.Run(name, func(t *testing.T) {
-			t.Parallel()
-
-			store := newTestStorer()
-			addManifest(t, store, "snapshot-001", nil)
-
-			// A backup wrote to this destination, so it carries the marker.
-			require.NoError(t, store.Put(context.Background(), markerFile,
-				bytes.NewReader(nil)))
-
-			tv := vaultik.NewForTesting(store)
-			tv.Config = &config.Config{AgeSecretKey: testAgeSecretKey}
-			tv.Repositories = newLocalIndex(t, "snapshot-001")
-
-			err := run(tv.Vaultik)
-
-			require.EqualError(t, err, "snapshot not found in the local "+
-				"index or on the destination store: "+unknownID)
-			assert.Empty(t, tv.Stdout.String())
-		})
-	}
-}

internal/vaultik/verify.go

@@ -120,17 +120,12 @@ func (v *Vaultik) RunDeepVerify(snapshotID string, opts *VerifyOptions) error {
 
 	log.Info("Starting snapshot verification", "snapshot_id", snapshotID, "mode", "deep")
 
-	remoteKey, err := v.resolveSnapshotRemoteKey(snapshotID)
-	if err != nil {
-		return v.deepVerifyFailure(result, opts, err.Error(), err)
-	}
-
 	if !opts.JSON && !v.UI.Quiet() {
 		v.stdoutf("Deep verification of snapshot: %s\n\n", snapshotID)
 	}
 
 	manifest, tempDB, dbBlobs, err := v.loadVerificationData(
-		snapshotID, remoteKey, opts, result, identities)
+		snapshotID, opts, result, identities)
 	if err != nil {
 		return err
 	}
@@ -175,13 +170,21 @@ func (v *Vaultik) RunDeepVerify(snapshotID string, opts *VerifyOptions) error {
 	return nil
 }
 
-// loadVerificationData downloads manifest, database, and blob list for
-// verification of the snapshot at remoteKey, which
-// resolveSnapshotRemoteKey returned for snapshotID.
+// loadVerificationData downloads manifest, database, and blob list for verification
 func (v *Vaultik) loadVerificationData(
-	snapshotID, remoteKey string, opts *VerifyOptions, result *VerifyResult,
+	snapshotID string, opts *VerifyOptions, result *VerifyResult,
 	identities []age.Identity,
 ) (*snapshot.Manifest, *tempDB, []snapshot.BlobInfo, error) {
+	// Resolve the identifier to the snapshot's remote key. A human ID is
+	// hashed; a remote key (or its abbreviation, as printed for a
+	// remote-only snapshot) is used as-is, so a host with no local index
+	// can verify a snapshot it can only see on the store.
+	remoteKey, err := v.resolveSnapshotRemoteKey(snapshotID)
+	if err != nil {
+		return nil, nil, nil, v.deepVerifyFailure(result, opts,
+			fmt.Sprintf("resolving snapshot identifier: %v", err), err)
+	}
+
 	// Download manifest. downloadManifestByKey is the single reader for
 	// remote manifests; see its doc comment.
 	log.Info("Downloading manifest", "remote_key", remoteKey)