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/destination_marker.go

@@ -51,7 +51,7 @@ func (v *Vaultik) checkDestinationMarker() error {
 	}
 
 	// Config is nil only in tests, which then record no binding (see
-	// checkStorageBinding).
+	// EnsureStorageBinding).
 	if v.Config != nil {
 		stored, configured, err := v.storageBinding()
 		if err != nil {
@@ -83,19 +83,11 @@ func (v *Vaultik) checkDestinationMarker() error {
 	return nil
 }
 
-// markDestination refuses a local index bound to a different
-// destination, checks the backup destination store for its marker,
-// writes the marker, and then records the binding. A first backup marks
-// its destination and a later one writes the same text again. The
-// binding is recorded last, so a first backup that cannot write to the
-// destination leaves the local index unbound.
+// markDestination checks the backup destination store with
+// checkDestinationMarker and then writes the marker, so a first backup
+// marks its destination and a later one writes the same text again.
 func (v *Vaultik) markDestination() error {
-	err := v.checkStorageBinding()
-	if err != nil {
-		return err
-	}
-
-	err = v.checkDestinationMarker()
+	err := v.checkDestinationMarker()
 	if err != nil {
 		return err
 	}
@@ -107,5 +99,5 @@ func (v *Vaultik) markDestination() error {
 			destinationMarkerKey, err)
 	}
 
-	return v.EnsureStorageBinding()
+	return nil
 }

internal/vaultik/prune.go

@@ -68,7 +68,7 @@ func (v *Vaultik) NukeRemote(force bool) error {
 	// the same way, so the advice below must not follow these errors.
 	// The listing also fails on a destination that answers that it has
 	// no marker while the local index holds snapshots.
-	err := v.checkStorageBinding()
+	err := v.EnsureStorageBinding()
 	if err != nil {
 		return err
 	}
@@ -192,7 +192,7 @@ type PruneBlobsResult struct {
 // PruneDatabase or PruneBlobs individually unless it specifically wants
 // one half.
 func (v *Vaultik) Prune(opts *PruneOptions) error {
-	err := v.checkStorageBinding()
+	err := v.EnsureStorageBinding()
 	if err != nil {
 		return err
 	}

internal/vaultik/snapshot.go

@@ -115,9 +115,14 @@ func (v *Vaultik) CreateSnapshot(opts *SnapshotCreateOptions) error {
 		"index_path", v.Config.IndexPath,
 	)
 
+	err := v.EnsureStorageBinding()
+	if err != nil {
+		return err
+	}
+
 	// Before PruneDatabase: it drops incomplete snapshots, which could
 	// leave the local index without one and so skip the marker check.
-	err := v.markDestination()
+	err = v.markDestination()
 	if err != nil {
 		return err
 	}
@@ -744,7 +749,7 @@ type SnapshotPurgeOptions struct {
 // snapshot name, not the latest globally. This prevents `home` and `system`
 // snapshots from cannibalizing each other.
 func (v *Vaultik) PurgeSnapshotsWithOptions(opts *SnapshotPurgeOptions) error {
-	err := v.checkStorageBinding()
+	err := v.EnsureStorageBinding()
 	if err != nil {
 		return err
 	}
@@ -1280,7 +1285,7 @@ func (v *Vaultik) outputVerifyJSON(result *VerifyResult) error {
 // jq` fail (issue #108). The narration is duplicated as log records,
 // which go to stderr and so cannot corrupt the document.
 func (v *Vaultik) CleanupLocalSnapshots(opts *PruneOptions) error {
-	err := v.checkStorageBinding()
+	err := v.EnsureStorageBinding()
 	if err != nil {
 		return err
 	}
@@ -1470,7 +1475,7 @@ func (v *Vaultik) RemoveSnapshot(
 		SnapshotID: snapshotID,
 	}
 
-	err := v.checkStorageBinding()
+	err := v.EnsureStorageBinding()
 	if err != nil {
 		return result, err
 	}
@@ -1707,7 +1712,7 @@ func (v *Vaultik) removeSnapshotRemote(
 // before it removes anything when the destination store cannot be
 // listed or is not present by checkDestinationMarker.
 func (v *Vaultik) RemoveAllSnapshots(opts *RemoveOptions) (*RemoveResult, error) {
-	err := v.checkStorageBinding()
+	err := v.EnsureStorageBinding()
 	if err != nil {
 		return nil, err
 	}

internal/vaultik/storage_bind.go

@@ -13,30 +13,35 @@ import (
 var errStorageBindingMismatch = errors.New(
 	"local index is bound to a different backup destination")
 
-// checkStorageBinding refuses when the local index database is bound to
-// a different destination than the configured one, with an error that
-// tells the user how to recover (revert the config, or run `vaultik
-// database delete`). Every mutating command calls it before touching
-// either the local index or the destination store, because the two live
-// in lockstep: the local index records which chunks/blobs already exist
-// at the destination, and a mismatched pair produces silent corruption
-// (the scanner sees "known" chunks and skips uploads, then writes
-// snapshots whose manifests reference blobs that aren't on the new
-// destination).
+// EnsureStorageBinding guarantees that the local index database is
+// bound to the currently-configured storage destination. Every mutating
+// command must call this before touching either the local index or the
+// destination store, because the two live in lockstep: the local index
+// records which chunks/blobs already exist at the destination, and
+// mismatched destination + local index produces silent corruption (the
+// scanner sees "known" chunks and skips uploads, then writes snapshots
+// whose manifests reference blobs that aren't on the new destination).
 //
-// It records nothing. Only a backup binds the local index, through
-// EnsureStorageBinding, and it does so before adding anything to it. An
-// unbound local index therefore holds nothing from any destination.
+// Behaviour:
+//   - On first use (empty stored value), record the configured
+//     destination (storage_url, or the s3.* endpoint, bucket and
+//     prefix) and log the binding.
+//   - When the stored value matches the configured destination, do
+//     nothing and return nil.
+//   - When the two differ, refuse with an error that tells the user
+//     how to recover (revert the config, or run `vaultik database
+//     delete` to discard the local index and rebuild against the new
+//     destination on the next backup).
 //
 // Read-only inspection commands (remote info, snapshot list, etc.)
 // deliberately don't call this: they can be run against a bare
 // destination store without any binding state.
-func (v *Vaultik) checkStorageBinding() error {
+func (v *Vaultik) EnsureStorageBinding() error {
 	if v.Repositories == nil || v.Config == nil {
 		// NewForTesting builds a Vaultik with no DB or config;
-		// there's no binding to check. Callers exercising the bind
-		// path use a real DB and populate Config explicitly (see
-		// storage_bind_test.go).
+		// there's nothing to bind and no binding to check. Callers
+		// exercising the bind path use a real DB and populate Config
+		// explicitly (see storage_bind_test.go).
 		return nil
 	}
 
@@ -45,24 +50,6 @@ func (v *Vaultik) checkStorageBinding() error {
 		return err
 	}
 
-	if stored == "" || stored == configured {
-		return nil
-	}
-
-	return fmt.Errorf("%w\n%s",
-		errStorageBindingMismatch, buildBindingMismatchMessage(stored, configured))
-}
-
-// EnsureStorageBinding records the configured destination (storage_url,
-// or the s3.* endpoint, bucket and prefix) as the binding of an unbound
-// local index. It refuses as checkStorageBinding does when the local
-// index is bound to a different destination.
-func (v *Vaultik) EnsureStorageBinding() error {
-	stored, configured, err := v.storageBinding()
-	if err != nil {
-		return err
-	}
-
 	if stored == "" {
 		err = v.Repositories.LocalMeta.Set(
 			v.ctx, database.LocalMetaKeyStorageURL, configured)
@@ -75,12 +62,12 @@ func (v *Vaultik) EnsureStorageBinding() error {
 		return nil
 	}
 
-	if stored != configured {
-		return fmt.Errorf("%w\n%s",
-			errStorageBindingMismatch, buildBindingMismatchMessage(stored, configured))
+	if stored == configured {
+		return nil
 	}
 
-	return nil
+	return fmt.Errorf("%w\n%s",
+		errStorageBindingMismatch, buildBindingMismatchMessage(stored, configured))
 }
 
 // storageBinding returns the destination the local index is bound to

internal/vaultik/storage_bind_test.go

@@ -2,7 +2,6 @@ package vaultik_test
 
 import (
 	"context"
-	"path/filepath"
 	"testing"
 
 	"github.com/stretchr/testify/assert"
@@ -10,126 +9,9 @@ import (
 	"sneak.berlin/go/vaultik/internal/config"
 	"sneak.berlin/go/vaultik/internal/database"
 	"sneak.berlin/go/vaultik/internal/log"
-	"sneak.berlin/go/vaultik/internal/storage"
-	"sneak.berlin/go/vaultik/internal/storage/faultstore"
 	"sneak.berlin/go/vaultik/internal/vaultik"
 )
 
-// storageBindingOf returns the destination the local index is bound to,
-// or "" when it is not bound.
-func storageBindingOf(
-	ctx context.Context, t *testing.T, repos *database.Repositories,
-) string {
-	t.Helper()
-
-	got, err := repos.LocalMeta.Get(ctx, database.LocalMetaKeyStorageURL)
-	require.NoError(t, err)
-
-	return got
-}
-
-// TestFailedFirstBackupLeavesIndexUnbound checks that a first backup
-// the destination refuses, as a mistyped bucket would, leaves the local
-// index unbound, so a backup with the corrected destination succeeds.
-func TestFailedFirstBackupLeavesIndexUnbound(t *testing.T) {
-	log.Initialize(log.Config{})
-	t.Parallel()
-
-	ctx := context.Background()
-	storeDir := t.TempDir()
-	v, repos := newFileDestinationVaultik(ctx, t, storeDir)
-	working := v.Storage
-
-	refusing := faultstore.New(working)
-	refusing.OnPut = func(string) faultstore.PutAction { return faultstore.PutFail }
-	refusing.OnStat = func(string) bool { return true }
-	v.Storage = refusing
-	v.Config.StorageURL = "file://" + filepath.Join(t.TempDir(), "typo")
-
-	require.ErrorIs(t, backUp(v, "first"), faultstore.ErrInjectedUpload)
-	assert.Empty(t, storageBindingOf(ctx, t, repos))
-
-	v.Storage = working
-	v.Config.StorageURL = "file://" + storeDir
-
-	require.NoError(t, backUp(v, "first"))
-	assert.Equal(t, "file://"+storeDir, storageBindingOf(ctx, t, repos))
-}
-
-// TestBackupToOtherDestinationWritesNoMarker checks that a backup
-// refuses a local index bound to a different destination before it
-// writes the marker to the configured one.
-func TestBackupToOtherDestinationWritesNoMarker(t *testing.T) {
-	log.Initialize(log.Config{})
-	t.Parallel()
-
-	ctx := context.Background()
-	firstDir := t.TempDir()
-	v, _ := newFileDestinationVaultik(ctx, t, firstDir)
-	v.Config.StorageURL = "file://" + firstDir
-
-	require.NoError(t, backUp(v, "first"))
-
-	secondDir := t.TempDir()
-	secondStore, err := storage.NewFileStorer(secondDir)
-	require.NoError(t, err)
-
-	v.Storage = secondStore
-	v.Config.StorageURL = "file://" + secondDir
-
-	require.ErrorContains(t, backUp(v, "first"),
-		"local index is bound to a different backup destination")
-	assert.NoFileExists(t, filepath.Join(secondDir, markerFile))
-}
-
-// TestCommandsOtherThanBackupLeaveIndexUnbound checks that commands
-// other than a backup do not bind an unbound local index, whether or not
-// they fail. Each runs on a fresh local index.
-func TestCommandsOtherThanBackupLeaveIndexUnbound(t *testing.T) {
-	log.Initialize(log.Config{})
-	t.Parallel()
-
-	tests := []struct {
-		name string
-		run  func(v *vaultik.Vaultik) error
-	}{
-		{"prune", func(v *vaultik.Vaultik) error {
-			return v.Prune(&vaultik.PruneOptions{Force: true})
-		}},
-		{"snapshot purge", func(v *vaultik.Vaultik) error {
-			return v.PurgeSnapshotsWithOptions(
-				&vaultik.SnapshotPurgeOptions{KeepLatest: true, Force: true})
-		}},
-		{"snapshot remove", func(v *vaultik.Vaultik) error {
-			_, err := v.RemoveSnapshot("host_first_2026-01-02T03:04:05Z",
-				&vaultik.RemoveOptions{Force: true})
-
-			return err
-		}},
-		{"snapshot remove --all", func(v *vaultik.Vaultik) error {
-			_, err := v.RemoveAllSnapshots(&vaultik.RemoveOptions{Force: true})
-
-			return err
-		}},
-		{"remote nuke", func(v *vaultik.Vaultik) error {
-			return v.NukeRemote(true)
-		}},
-	}
-
-	for _, tt := range tests {
-		t.Run(tt.name, func(t *testing.T) {
-			t.Parallel()
-
-			ctx := context.Background()
-			v, repos := newFileDestinationVaultik(ctx, t, t.TempDir())
-
-			_ = tt.run(v)
-
-			assert.Empty(t, storageBindingOf(ctx, t, repos))
-		})
-	}
-}
-
 // buildBindTestVaultik returns a minimal Vaultik wired with a real
 // in-memory DB and a config carrying the given StorageURL. Enough to
 // exercise EnsureStorageBinding without spinning up storage or fx.