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/snapshot/scanner.go

@@ -1861,11 +1861,7 @@ func (s *Scanner) uploadBlobIfNeeded(
 	err = s.storage.PutWithProgress(ctx, blobPath, blobWithReader.Reader,
 		finishedBlob.Compressed, progressCallback)
 	if err != nil {
-		// 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)
-		}
+		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

@@ -1,147 +0,0 @@
-//nolint:testpackage // exercises the unexported uploadBlobIfNeeded
-package snapshot
-
-import (
-	"bytes"
-	"context"
-	"fmt"
-	"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"
-
-// cancelOnPutStorer stands in for a backend whose upload the user
-// interrupts: it cancels the operation's context mid-upload and fails
-// the way the S3 backend does when its context is cancelled.
-type cancelOnPutStorer struct {
-	storage.Storer
-
-	cancel context.CancelFunc
-}
-
-func (c *cancelOnPutStorer) PutWithProgress(
-	ctx context.Context, _ string, _ io.Reader,
-	_ int64, _ storage.ProgressCallback,
-) error {
-	c.cancel()
-
-	return fmt.Errorf("upload multipart failed: %w", ctx.Err())
-}
-
-// 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)
-
-	store := &cancelOnPutStorer{Storer: inner, cancel: cancel}
-
-	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)
-	}
-}