Move internal/log from apex/log to log/slog (closes #77)

internal/log now logs through log/slog. After Init, records go to a small
slog.Handler that prints the same lines as before; before Init they go to
slog.Default(). The helpers and their call sites are unchanged. With
NO_COLOR set on a terminal, log lines are no longer colored.

pterm is dropped: it only printed progress lines, which fmt now writes
directly, outside slog. apex/log, pterm and their indirect dependencies
leave go.mod; golang.org/x/term becomes direct.

simplelog is not imported: importing it replaces slog's default handler in
every program that imports package mfer. The logger stays process-global,
since injecting it would change package mfer's API.

Progress and log lines now share the logger's lock, so the check progress
test runs check ten times to catch a missing wait.

Model: opus-5-5

internal/log/log.go

@@ -1,19 +1,25 @@
-// Package log provides leveled logging with progress output helpers
-// on top of apex/log and pterm.
+// Package log provides leveled logging on top of log/slog, and helpers that
+// print progress lines which overwrite each other in place on a terminal.
+//
+// Until Init runs, log records go to slog.Default(), so a program that uses
+// package mfer as a library gets them wherever it sends its own slog output.
+// Init switches to the CLI's format on the stderr writer given to SetOutput.
+// Progress lines are not log records: they are written straight to the stdout
+// writer, never through slog.
 package log
 
 import (
+	"context"
 	"fmt"
 	"io"
+	"log/slog"
 	"os"
 	"path/filepath"
 	"runtime"
 	"sync"
 
-	"github.com/apex/log"
-	acli "github.com/apex/log/handlers/cli"
 	"github.com/davecgh/go-spew/spew"
-	"github.com/pterm/pterm"
+	"golang.org/x/term"
 )
 
 // Level represents log severity levels.
@@ -58,28 +64,98 @@ func (l Level) String() string {
 // helpers to the caller of the log package.
 const callerSkip = 2
 
+// Escape sequences for colored log lines.
+const (
+	ansiReset  = "\x1b[0m"
+	ansiBold   = "\x1b[1m"
+	ansiRed    = "\x1b[31m"
+	ansiYellow = "\x1b[33m"
+	ansiBlue   = "\x1b[34m"
+	ansiWhite  = "\x1b[37m"
+)
+
 //nolint:gochecknoglobals // package-level logger state by design
 var (
-	// mu protects the output writers and level
+	// mu protects the variables below
 	mu sync.RWMutex
 	// stdout is the writer for progress output
 	stdout io.Writer = os.Stdout
 	// stderr is the writer for log output
 	stderr io.Writer = os.Stderr
+	// styled is false once DisableStyling has been called
+	styled = true
+	// logger is the CLI logger Init builds; nil until Init runs
+	logger *slog.Logger
 	// currentLevel is our log level (includes Verbose)
 	currentLevel = InfoLevel
 )
 
+// cliHandler is the slog.Handler the CLI logs through. Each record is one
+// line: a symbol for its level right-aligned in four columns, then the
+// message padded to 25 columns. In color, only the symbol is bold and in the
+// level's color; the message is in the terminal's default color. Records are
+// filtered by level before they are made, so the handler takes every record
+// it is given.
+type cliHandler struct {
+	mu    sync.Mutex
+	w     io.Writer
+	color bool
+}
+
+// Enabled reports true for every level.
+func (h *cliHandler) Enabled(context.Context, slog.Level) bool {
+	return true
+}
+
+// Handle writes the record as one line.
+func (h *cliHandler) Handle(_ context.Context, r slog.Record) error {
+	symbol, color := "•", ansiBlue
+
+	switch {
+	case r.Level >= slog.LevelError:
+		symbol, color = "⨯", ansiRed
+	case r.Level >= slog.LevelWarn:
+		color = ansiYellow
+	case r.Level < slog.LevelInfo:
+		color = ansiWhite
+	}
+
+	h.mu.Lock()
+	defer h.mu.Unlock()
+
+	if !h.color {
+		_, err := fmt.Fprintf(h.w, "%4s %-25s\n", symbol, r.Message)
+
+		return err
+	}
+
+	_, err := fmt.Fprintf(h.w, "%s%s%4s%s %-25s%s\n",
+		color, ansiBold, symbol, ansiReset, r.Message, ansiReset)
+
+	return err
+}
+
+// WithAttrs returns the handler unchanged: this package's helpers never
+// attach attributes.
+func (h *cliHandler) WithAttrs([]slog.Attr) slog.Handler {
+	return h
+}
+
+// WithGroup returns the handler unchanged: this package's helpers never open
+// groups.
+func (h *cliHandler) WithGroup(string) slog.Handler {
+	return h
+}
+
 // SetOutput configures the output writers for the log package.
-// stdout is used for progress output, stderr is used for log messages.
+// stdout is used for progress output, stderr is used for log messages
+// from the next Init on.
 func SetOutput(out, err io.Writer) {
 	mu.Lock()
 	defer mu.Unlock()
 
 	stdout = out
 	stderr = err
-
-	pterm.SetDefaultOutput(out)
 }
 
 // GetStdout returns the configured stdout writer.
@@ -98,31 +174,29 @@ func GetStderr() io.Writer {
 	return stderr
 }
 
-// DisableStyling turns off colors and styling for terminal output.
+// DisableStyling turns off colors in log lines from the next Init on.
 func DisableStyling() {
-	pterm.DisableColor()
-	pterm.DisableStyling()
+	mu.Lock()
+	defer mu.Unlock()
 
-	pterm.Debug.Prefix.Text = ""
-	pterm.Info.Prefix.Text = ""
-	pterm.Success.Prefix.Text = ""
-	pterm.Warning.Prefix.Text = ""
-	pterm.Error.Prefix.Text = ""
-	pterm.Fatal.Prefix.Text = ""
+	styled = false
 }
 
-// Init initializes the logger with the CLI handler and default log level.
+// Init sends log records to the CLI handler on the stderr writer given to
+// SetOutput. Log lines are colored when stdout is a terminal whose TERM is
+// not dumb, unless DisableStyling has been called.
 //
-// It reconfigures the process-global apex/log logger under the write lock so
-// the global is never mutated while another goroutine holds the read lock to
-// read it in emit. Without this, parallel callers (e.g. the test suite) race
-// Init's SetLevel/SetHandler against concurrent log calls.
+// It replaces the logger under the write lock, and log calls hold the read
+// lock while they write, so once Init returns nothing writes through the
+// logger it replaced.
 func Init() {
 	mu.Lock()
 	defer mu.Unlock()
 
-	log.SetHandler(acli.New(stderr))
-	log.SetLevel(log.DebugLevel) // Let apex/log pass everything; we filter ourselves
+	color := styled && os.Getenv("TERM") != "dumb" &&
+		term.IsTerminal(int(os.Stdout.Fd()))
+
+	logger = slog.New(&cliHandler{w: stderr, color: color})
 }
 
 // isEnabled returns true if messages at the given level should be logged.
@@ -133,66 +207,87 @@ func isEnabled(l Level) bool {
 	return l >= currentLevel
 }
 
-// emit calls fn while holding the read lock if messages at level l are
-// enabled. Holding the read lock across the apex/log call keeps the global
-// logger from being read while Init reconfigures it under the write lock.
-func emit(l Level, fn func()) {
+// logf logs a formatted message at level l if messages at l are enabled,
+// holding the read lock while the record is written. slog has no verbose or
+// fatal level: verbose messages are logged as info records, and fatal
+// messages as error records.
+func logf(l Level, format string, args ...any) {
 	mu.RLock()
 	defer mu.RUnlock()
 
-	if l >= currentLevel {
-		fn()
+	if l < currentLevel {
+		return
+	}
+
+	lg := logger
+	if lg == nil {
+		lg = slog.Default()
+	}
+
+	msg := fmt.Sprintf(format, args...)
+
+	switch l {
+	case DebugLevel:
+		lg.Debug(msg)
+	case VerboseLevel, InfoLevel:
+		lg.Info(msg)
+	case WarnLevel:
+		lg.Warn(msg)
+	case ErrorLevel, FatalLevel:
+		lg.Error(msg)
 	}
 }
 
-// Fatalf logs a formatted message at fatal level.
+// Fatalf logs a formatted message at fatal level, then exits with status 1.
 func Fatalf(format string, args ...any) {
-	emit(FatalLevel, func() { log.Fatalf(format, args...) })
+	logf(FatalLevel, format, args...)
+	os.Exit(1)
 }
 
-// Fatal logs a message at fatal level.
+// Fatal logs a message at fatal level, then exits with status 1.
 func Fatal(arg string) {
-	emit(FatalLevel, func() { log.Fatal(arg) })
+	logf(FatalLevel, "%s", arg)
+	os.Exit(1)
 }
 
 // Errorf logs a formatted message at error level.
 func Errorf(format string, args ...any) {
-	emit(ErrorLevel, func() { log.Errorf(format, args...) })
+	logf(ErrorLevel, format, args...)
 }
 
 // Error logs a message at error level.
 func Error(arg string) {
-	emit(ErrorLevel, func() { log.Error(arg) })
+	logf(ErrorLevel, "%s", arg)
 }
 
 // Warnf logs a formatted message at warn level.
 func Warnf(format string, args ...any) {
-	emit(WarnLevel, func() { log.Warnf(format, args...) })
+	logf(WarnLevel, format, args...)
 }
 
 // Warn logs a message at warn level.
 func Warn(arg string) {
-	emit(WarnLevel, func() { log.Warn(arg) })
+	logf(WarnLevel, "%s", arg)
 }
 
 // Infof logs a formatted message at info level.
 func Infof(format string, args ...any) {
-	emit(InfoLevel, func() { log.Infof(format, args...) })
+	logf(InfoLevel, format, args...)
 }
 
 // Info logs a message at info level.
 func Info(arg string) {
-	emit(InfoLevel, func() { log.Info(arg) })
+	logf(InfoLevel, "%s", arg)
 }
 
 // Verbosef logs a formatted message at verbose level.
 func Verbosef(format string, args ...any) {
-	emit(VerboseLevel, func() { log.Infof(format, args...) })
+	logf(VerboseLevel, format, args...)
 }
 
 // Verbose logs a message at verbose level.
 func Verbose(arg string) {
-	emit(VerboseLevel, func() { log.Info(arg) })
+	logf(VerboseLevel, "%s", arg)
 }
 
 // Debugf logs a formatted message at debug level with caller location.
@@ -211,20 +306,12 @@ func Debug(arg string) {
 
 // DebugReal logs at debug level with caller info from the specified stack depth.
 func DebugReal(arg string, cs int) {
-	mu.RLock()
-	defer mu.RUnlock()
-
-	if DebugLevel < currentLevel {
-		return
-	}
-
 	_, callerFile, callerLine, ok := runtime.Caller(cs)
 	if !ok {
 		return
 	}
 
-	tag := fmt.Sprintf("%s:%d: ", filepath.Base(callerFile), callerLine)
-	log.Debug(tag + arg)
+	logf(DebugLevel, "%s:%d: %s", filepath.Base(callerFile), callerLine, arg)
 }
 
 // Dump logs a spew dump of the arguments at debug level.
@@ -275,12 +362,19 @@ func GetLevel() Level {
 
 // Progressf prints a progress message that overwrites the current line.
 // Use ProgressDone() when progress is complete to move to the next line.
+// Progress goes to the stdout writer whatever the log level.
 func Progressf(format string, args ...any) {
-	pterm.Printf("\r"+format, args...)
+	mu.Lock()
+	defer mu.Unlock()
+
+	_, _ = fmt.Fprintf(stdout, "\r"+format, args...)
 }
 
 // ProgressDone clears the progress line when progress is complete.
 func ProgressDone() {
-	// Clear the line with spaces and return to beginning
-	pterm.Print("\r\033[K")
+	mu.Lock()
+	defer mu.Unlock()
+
+	// Return to the start of the line and erase it
+	_, _ = fmt.Fprint(stdout, "\r\033[K")
 }

internal/log/log_test.go

@@ -1,12 +1,229 @@
-package log_test
+//nolint:testpackage // white-box tests exercise unexported internals
+package log
 
 import (
+	"bytes"
+	stdlog "log"
+	"log/slog"
+	"os"
 	"testing"
 
-	"sneak.berlin/go/mfer/internal/log"
+	"github.com/stretchr/testify/assert"
 )
 
 func TestBuild(t *testing.T) {
 	t.Parallel()
-	log.Init()
+	Init()
+}
+
+// capture points the package's writers at fresh buffers and sets its level,
+// with colors off, then restores the default writers and level when the test
+// ends. The state it changes is process-wide, so tests that use it do not
+// run in parallel.
+func capture(t *testing.T, l Level) (*bytes.Buffer, *bytes.Buffer) {
+	t.Helper()
+
+	var stdout, stderr bytes.Buffer
+
+	DisableStyling()
+	SetOutput(&stdout, &stderr)
+	SetLevel(l)
+	Init()
+
+	t.Cleanup(func() {
+		SetOutput(os.Stdout, os.Stderr)
+		SetLevel(InfoLevel)
+		Init()
+	})
+
+	return &stdout, &stderr
+}
+
+// TestLevelFiltering logs at every level, through both the plain and the
+// formatting helpers, and checks that exactly the messages at or above the
+// set level are written.
+//
+//nolint:paralleltest // changes the package's process-wide writers and level
+func TestLevelFiltering(t *testing.T) {
+	messages := []struct {
+		level Level
+		text  string
+	}{
+		{DebugLevel, "debug plain"},
+		{DebugLevel, "debug formatted"},
+		{VerboseLevel, "verbose plain"},
+		{VerboseLevel, "verbose formatted"},
+		{InfoLevel, "info plain"},
+		{InfoLevel, "info formatted"},
+		{WarnLevel, "warn plain"},
+		{WarnLevel, "warn formatted"},
+		{ErrorLevel, "error plain"},
+		{ErrorLevel, "error formatted"},
+	}
+
+	levels := []Level{DebugLevel, VerboseLevel, InfoLevel, WarnLevel, ErrorLevel}
+
+	for _, set := range levels {
+		t.Run(set.String(), func(t *testing.T) {
+			stdout, stderr := capture(t, set)
+
+			Debug("debug plain")
+			Debugf("debug %s", "formatted")
+			Verbose("verbose plain")
+			Verbosef("verbose %s", "formatted")
+			Info("info plain")
+			Infof("info %s", "formatted")
+			Warn("warn plain")
+			Warnf("warn %s", "formatted")
+			Error("error plain")
+			Errorf("error %s", "formatted")
+
+			for _, m := range messages {
+				if m.level >= set {
+					assert.Contains(t, stderr.String(), m.text)
+				} else {
+					assert.NotContains(t, stderr.String(), m.text)
+				}
+			}
+
+			assert.Empty(t, stdout.String())
+		})
+	}
+}
+
+// TestLineFormat checks the exact uncolored lines: a symbol per level
+// right-aligned in four columns, then the message padded to 25 columns.
+//
+//nolint:paralleltest // changes the package's process-wide writers and level
+func TestLineFormat(t *testing.T) {
+	_, stderr := capture(t, VerboseLevel)
+
+	Infof("scanning filesystem...")
+	Verbosef("+ %s (%s)", "a.txt", "1 B")
+	Warn("short")
+	Errorf("%s", "a message longer than twenty-five columns")
+
+	want := "   • scanning filesystem...   \n" +
+		"   • + a.txt (1 B)            \n" +
+		"   • short                    \n" +
+		"   ⨯ a message longer than twenty-five columns\n"
+	assert.Equal(t, want, stderr.String())
+}
+
+// TestDebugCallerTag checks that debug lines start with the file and line
+// of the call that logged them.
+//
+//nolint:paralleltest // changes the package's process-wide writers and level
+func TestDebugCallerTag(t *testing.T) {
+	_, stderr := capture(t, DebugLevel)
+
+	Debugf("enumerating path: %s", "/tmp")
+
+	assert.Regexp(t, `^   • log_test\.go:\d+: enumerating path: /tmp\s*\n$`,
+		stderr.String())
+}
+
+// TestColoredLine checks the colored lines: only the symbol is bold and in the
+// level's color; the message is in the terminal's default color.
+func TestColoredLine(t *testing.T) {
+	t.Parallel()
+
+	var buf bytes.Buffer
+
+	lg := slog.New(&cliHandler{w: &buf, color: true})
+	lg.Debug("debug")
+	lg.Info("info")
+	lg.Warn("warn")
+	lg.Error("error")
+
+	want := "\x1b[37m\x1b[1m   •\x1b[0m debug                    \x1b[0m\n" +
+		"\x1b[34m\x1b[1m   •\x1b[0m info                     \x1b[0m\n" +
+		"\x1b[33m\x1b[1m   •\x1b[0m warn                     \x1b[0m\n" +
+		"\x1b[31m\x1b[1m   ⨯\x1b[0m error                    \x1b[0m\n"
+	assert.Equal(t, want, buf.String())
+}
+
+// TestRecordLevels checks the slog level of the record each helper logs,
+// through slog's text handler with the time left out. slog has no verbose
+// level, so verbose messages are info records.
+//
+//nolint:paralleltest // changes the package's process-wide logger and level
+func TestRecordLevels(t *testing.T) {
+	var buf bytes.Buffer
+
+	capture(t, DebugLevel)
+
+	opts := &slog.HandlerOptions{
+		Level: slog.LevelDebug,
+		ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr {
+			if a.Key == slog.TimeKey {
+				return slog.Attr{}
+			}
+
+			return a
+		},
+	}
+
+	mu.Lock()
+	logger = slog.New(slog.NewTextHandler(&buf, opts))
+	mu.Unlock()
+
+	Debugf("debug")
+	Verbosef("verbose")
+	Infof("info")
+	Warnf("warn")
+	Errorf("error")
+
+	assert.Regexp(t, `^level=DEBUG msg="log_test\.go:\d+: debug"\n`+
+		"level=INFO msg=verbose\n"+
+		"level=INFO msg=info\n"+
+		"level=WARN msg=warn\n"+
+		"level=ERROR msg=error\n$", buf.String())
+}
+
+// TestProgress checks that progress lines go to the stdout writer whatever
+// the log level, each starting with a carriage return so it overwrites the
+// last, and that ProgressDone erases the line.
+//
+//nolint:paralleltest // changes the package's process-wide writers and level
+func TestProgress(t *testing.T) {
+	stdout, stderr := capture(t, ErrorLevel)
+
+	Progressf("Scanning: %d files found", 1000)
+	Progressf("Scanning: %d files found", 2000)
+	ProgressDone()
+
+	assert.Equal(t,
+		"\rScanning: 1000 files found\rScanning: 2000 files found\r\x1b[K",
+		stdout.String())
+	assert.Empty(t, stderr.String())
+}
+
+// TestBeforeInit checks that records go to slog.Default() until Init runs,
+// still filtered by the package's level. slog's default handler writes
+// through the standard library's log package.
+//
+//nolint:paralleltest // changes the package's process-wide logger
+func TestBeforeInit(t *testing.T) {
+	var buf bytes.Buffer
+
+	flags := stdlog.Flags()
+
+	stdlog.SetOutput(&buf)
+	stdlog.SetFlags(0)
+
+	mu.Lock()
+	logger = nil
+	mu.Unlock()
+
+	t.Cleanup(func() {
+		stdlog.SetOutput(os.Stderr)
+		stdlog.SetFlags(flags)
+		Init()
+	})
+
+	Infof("loaded manifest with %d files", 3)
+	Verbose("not shown at info level")
+
+	assert.Equal(t, "INFO loaded manifest with 3 files\n", buf.String())
 }