refactor(logger): extract emit helper to eliminate Printf/Print duplication

internal/logger/logger.go

@@ -104,21 +104,16 @@ func (l *Logger) Enabled() bool {
 	return l.enabled
 }
 
-// Printf prints a formatted message if the logger is enabled.
-// A newline is always added at the end.
-// Time diff since last log is displayed like the debug npm package.
-// Also writes to the file logger in text-only format.
-func (l *Logger) Printf(format string, args ...any) {
-	if !l.enabled {
-		return
-	}
+// emit writes message to stderr (with color + time diff) and to the file logger.
+// The caller must have already checked l.enabled.
+func (l *Logger) emit(messageFn func() string) {
 	l.mu.Lock()
 	now := time.Now()
 	diff := now.Sub(l.lastLog)
 	l.lastLog = now
 	l.mu.Unlock()
 
-	message := fmt.Sprintf(format, args...)
+	message := messageFn()
 
 	// Write to stderr with colors and time diff
 	if l.color != "" {
@@ -131,31 +126,30 @@ func (l *Logger) Printf(format string, args ...any) {
 	LogDebug(l.namespace, "%s", message)
 }
 
-// Print prints a message if the logger is enabled.
+// Printf prints a formatted message if the logger is enabled.
 // A newline is always added at the end.
 // Time diff since last log is displayed like the debug npm package.
 // Also writes to the file logger in text-only format.
-func (l *Logger) Print(args ...any) {
+func (l *Logger) Printf(format string, args ...any) {
 	if !l.enabled {
 		return
 	}
-	l.mu.Lock()
-	now := time.Now()
-	diff := now.Sub(l.lastLog)
-	l.lastLog = now
-	l.mu.Unlock()
-
-	message := fmt.Sprint(args...)
+	l.emit(func() string {
+		return fmt.Sprintf(format, args...)
+	})
+}
 
-	// Write to stderr with colors and time diff
-	if l.color != "" {
-		fmt.Fprintf(os.Stderr, "%s%s%s %s +%s\n", l.color, l.namespace, colorReset, message, strutil.FormatDuration(diff))
-	} else {
-		fmt.Fprintf(os.Stderr, "%s %s +%s\n", l.namespace, message, strutil.FormatDuration(diff))
+// Print prints a message if the logger is enabled.
+// A newline is always added at the end.
+// Time diff since last log is displayed like the debug npm package.
+// Also writes to the file logger in text-only format.
+func (l *Logger) Print(args ...any) {
+	if !l.enabled {
+		return
 	}
-
-	// Also write to file logger in text-only format (no colors, no time diff)
-	LogDebug(l.namespace, "%s", message)
+	l.emit(func() string {
+		return fmt.Sprint(args...)
+	})
 }
 
 // computeEnabled computes whether a namespace matches the DEBUG patterns

internal/logger/logger_test.go

@@ -4,6 +4,7 @@ import (
 	"bytes"
 	"os"
 	"path/filepath"
+	"strings"
 	"testing"
 	"time"
 
@@ -27,6 +28,31 @@ func captureStderr(f func()) string {
 	return buf.String()
 }
 
+type sleepingStringer struct {
+	delay time.Duration
+	value string
+}
+
+func (s sleepingStringer) String() string {
+	time.Sleep(s.delay)
+	return s.value
+}
+
+func extractLoggedDuration(t *testing.T, output string) time.Duration {
+	t.Helper()
+
+	idx := strings.LastIndex(output, "+")
+	require.NotEqual(t, -1, idx, "log output should contain a time diff")
+
+	durationText := strings.TrimSpace(output[idx+1:])
+	durationText = strings.ReplaceAll(durationText, "µs", "us")
+
+	duration, err := time.ParseDuration(durationText)
+	require.NoError(t, err, "log output should end with a parseable duration")
+
+	return duration
+}
+
 func TestNew(t *testing.T) {
 	tests := []struct {
 		name      string
@@ -257,6 +283,46 @@ func TestLogger_TimeDiff(t *testing.T) {
 		"Second log should show time diff with unit")
 }
 
+func TestLogger_TimeDiffExcludesFormattingCost(t *testing.T) {
+	t.Setenv("DEBUG", "*")
+
+	tests := []struct {
+		name string
+		log  func(*Logger, sleepingStringer)
+	}{
+		{
+			name: "Printf",
+			log: func(logger *Logger, arg sleepingStringer) {
+				logger.Printf("%v", arg)
+			},
+		},
+		{
+			name: "Print",
+			log: func(logger *Logger, arg sleepingStringer) {
+				logger.Print(arg)
+			},
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			logger := New("test:format-cost")
+			logger.lastLog = time.Now()
+
+			output := captureStderr(func() {
+				tt.log(logger, sleepingStringer{
+					delay: 50 * time.Millisecond,
+					value: "slow message",
+				})
+			})
+
+			assert.Contains(t, output, "slow message")
+			assert.Less(t, extractLoggedDuration(t, output), 20*time.Millisecond,
+				"time diff should be captured before message formatting runs")
+		})
+	}
+}
+
 func TestColorSelection(t *testing.T) {
 	// Test that selectColor returns consistent colors for the same namespace
 	color1 := selectColor("test:namespace")