diff --git a/internal/logger/logger.go b/internal/logger/logger.go index d376b5c72..6af9b5617 100644 --- a/internal/logger/logger.go +++ b/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 diff --git a/internal/logger/logger_test.go b/internal/logger/logger_test.go index 826ea6341..3a72576d7 100644 --- a/internal/logger/logger_test.go +++ b/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")