diff --git a/v2/utils/logger/logger.go b/v2/utils/logger/logger.go index 3f42cba..6793686 100644 --- a/v2/utils/logger/logger.go +++ b/v2/utils/logger/logger.go @@ -1,10 +1,14 @@ package logger import ( + "context" "fmt" "io" "log/slog" "os" + "sync" + "sync/atomic" + "time" ) type LogLevel int @@ -18,9 +22,17 @@ const ( ) var ( + // mu guards writer and serializes rebuilds. The hot logging path does not + // take it; it reads the published logger via log.Load() instead. + mu sync.Mutex writer io.Writer = os.Stderr levelVar = new(slog.LevelVar) - log *slog.Logger + // writeMu serializes writes to the underlying writer so concurrent log + // calls never produce interleaved lines (logrus locked writes the same way). + writeMu sync.Mutex + // log holds the current *slog.Logger. It is swapped atomically so that + // concurrent log calls never race with SetOutput/SetLogLevel rebuilding it. + log atomic.Pointer[slog.Logger] ) func init() { @@ -28,30 +40,119 @@ func init() { rebuild() } -// rebuild recreates the underlying logger. slog handlers are immutable and -// bound to a writer, so the logger must be rebuilt when the output changes. -// The level is held in a *slog.LevelVar, so level changes do not require it. +// rebuild recreates the underlying logger and atomically publishes it. The +// handler is bound to a writer, so the logger must be rebuilt when the output +// changes; the level is held in a *slog.LevelVar, so level changes do not +// require it. Callers that mutate writer must hold mu; init runs before any +// goroutines, so it may call rebuild without the lock. func rebuild() { - log = slog.New(slog.NewTextHandler(writer, &slog.HandlerOptions{Level: levelVar})) + log.Store(slog.New(&logrusTextHandler{w: writer, level: levelVar})) +} + +// logrusTextHandler is a minimal slog.Handler that reproduces the line format +// of logrus's TextFormatter{FullTimestamp: true}, which this package used +// before migrating to log/slog. It emits exactly: +// +// time="" level= msg="" +// +// The SDK only ever logs a preformatted message with no structured attributes, +// so WithAttrs/WithGroup are intentionally no-ops. +type logrusTextHandler struct { + w io.Writer + level slog.Leveler +} + +func (h *logrusTextHandler) Enabled(_ context.Context, l slog.Level) bool { + return l >= h.level.Level() +} + +// logLineBufSize is the initial capacity for a formatted log line; sized to +// hold a typical timestamp + level + short message without reallocating. +const logLineBufSize = 128 + +// logrus level names. logrus spells the warn level "warning". +const ( + levelDebug = "debug" + levelInfo = "info" + levelWarn = "warning" + levelError = "error" +) + +func (h *logrusTextHandler) Handle(_ context.Context, r slog.Record) error { + buf := make([]byte, 0, logLineBufSize) + buf = append(buf, "time="...) + buf = appendLogrusValue(buf, r.Time.Format(time.RFC3339)) + buf = append(buf, " level="...) + buf = append(buf, logrusLevel(r.Level)...) + buf = append(buf, " msg="...) + buf = appendLogrusValue(buf, r.Message) + buf = append(buf, '\n') + + writeMu.Lock() + defer writeMu.Unlock() + _, err := h.w.Write(buf) + return err +} + +func (h *logrusTextHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h } +func (h *logrusTextHandler) WithGroup(_ string) slog.Handler { return h } + +// logrusLevel maps slog levels to logrus's lowercase level names. Note logrus +// spells the warn level "warning". +func logrusLevel(l slog.Level) string { + switch { + case l < slog.LevelInfo: + return levelDebug + case l < slog.LevelWarn: + return levelInfo + case l < slog.LevelError: + return levelWarn + default: + return levelError + } +} + +// appendLogrusValue appends s, quoting it with %q exactly when logrus's +// TextFormatter would (i.e. when it contains a character outside logrus's +// unquoted set). This is why the timestamp — containing ':' — is quoted. +func appendLogrusValue(b []byte, s string) []byte { + if logrusNeedsQuoting(s) { + return append(b, fmt.Sprintf("%q", s)...) + } + return append(b, s...) +} + +func logrusNeedsQuoting(text string) bool { + for _, ch := range text { + if !((ch >= 'a' && ch <= 'z') || + (ch >= 'A' && ch <= 'Z') || + (ch >= '0' && ch <= '9') || + ch == '-' || ch == '.' || ch == '_' || ch == '/' || ch == '@' || ch == '^' || ch == '+') { + return true + } + } + return false } func Debug(args ...interface{}) { - log.Debug(fmt.Sprint(args...)) + log.Load().Debug(fmt.Sprint(args...)) } func Info(args ...interface{}) { - log.Info(fmt.Sprint(args...)) + log.Load().Info(fmt.Sprint(args...)) } func Warn(args ...interface{}) { - log.Warn(fmt.Sprint(args...)) + log.Load().Warn(fmt.Sprint(args...)) } func Error(args ...interface{}) { - log.Error(fmt.Sprint(args...)) + log.Load().Error(fmt.Sprint(args...)) } func SetOutput(w io.Writer) { + mu.Lock() + defer mu.Unlock() writer = w rebuild() } diff --git a/v2/utils/logger/logger_concurrency_test.go b/v2/utils/logger/logger_concurrency_test.go new file mode 100644 index 0000000..f357733 --- /dev/null +++ b/v2/utils/logger/logger_concurrency_test.go @@ -0,0 +1,47 @@ +package logger + +import ( + "io" + "sync" + "testing" +) + +// TestConcurrentLogAndLevelChange guards against the data race that existed +// when `log` was a plain package var: request goroutines calling Info/Error +// read `log` while another goroutine reassigned it via SetLogLevel/SetOutput +// (OFF forces a rebuild). Run with -race to detect regressions: +// +// go test ./utils/logger/ -race +func TestConcurrentLogAndLevelChange(t *testing.T) { + SetOutput(io.Discard) + defer func() { + // Restore defaults so other specs in the package are unaffected. + SetOutput(io.Discard) + SetLogLevel(ERROR) + }() + + var wg sync.WaitGroup + // Simulate many in-flight SDK calls emitting logs. + for i := 0; i < 50; i++ { + wg.Add(1) + go func() { + defer wg.Done() + Debug("request debug line") + Info("request info line") + Warn("request warn line") + Error("request error line") + }() + } + // Simulate a shared client's UpdateLogLevel being flipped at runtime. + wg.Add(1) + go func() { + defer wg.Done() + for i := 0; i < 50; i++ { + SetLogLevel(DEBUG) + SetLogLevel(OFF) // OFF -> SetOutput -> rebuild() swaps the logger + SetLogLevel(INFO) + SetOutput(io.Discard) + } + }() + wg.Wait() +} diff --git a/v2/utils/logger/verify_behavior_test.go b/v2/utils/logger/verify_behavior_test.go new file mode 100644 index 0000000..a5a5b41 --- /dev/null +++ b/v2/utils/logger/verify_behavior_test.go @@ -0,0 +1,83 @@ +package logger + +import ( + "bytes" + "regexp" + "strings" + "testing" +) + +// TestBehavior_Verify checks level filtering is unchanged AND that the output +// matches logrus's TextFormatter{FullTimestamp:true} line format exactly: +// +// time="" level= msg="" +func TestBehavior_Verify(t *testing.T) { + calls := []struct { + name string + fn func(...interface{}) + }{{"DEBUG", Debug}, {"INFO", Info}, {"WARN", Warn}, {"ERROR", Error}} + cases := []struct { + level LogLevel + name string + visible map[string]bool + }{ + {DEBUG, "DEBUG", map[string]bool{"DEBUG": true, "INFO": true, "WARN": true, "ERROR": true}}, + {INFO, "INFO", map[string]bool{"DEBUG": false, "INFO": true, "WARN": true, "ERROR": true}}, + {WARN, "WARN", map[string]bool{"DEBUG": false, "INFO": false, "WARN": true, "ERROR": true}}, + {ERROR, "ERROR", map[string]bool{"DEBUG": false, "INFO": false, "WARN": false, "ERROR": true}}, + } + for _, c := range cases { + var buf bytes.Buffer + SetOutput(&buf) + SetLogLevel(c.level) + for _, cl := range calls { + cl.fn(cl.name + " message") + } + out := buf.String() + for _, cl := range calls { + if strings.Contains(out, cl.name+" message") != c.visible[cl.name] { + t.Errorf("level %s: %s present=%v want %v", c.name, cl.name, !c.visible[cl.name], c.visible[cl.name]) + } + } + } + + // OFF discards everything. + var buf bytes.Buffer + SetOutput(&buf) + SetLogLevel(OFF) + Error("discarded") + if buf.Len() != 0 { + t.Errorf("OFF: expected no output, got %q", buf.String()) + } + + // Exact logrus-style format, including lowercase levels and "warning". + line := regexp.MustCompile(`^time="[^"]+" level=(\w+) msg="([^"]*)"\n$`) + checks := []struct { + fn func(...interface{}) + level string + inputMsg string + }{ + {Debug, "debug", "hello world"}, + {Info, "info", "hello world"}, + {Warn, "warning", "hello world"}, + {Error, "error", "hello world"}, + } + for _, ch := range checks { + var b bytes.Buffer + SetOutput(&b) + SetLogLevel(DEBUG) + ch.fn(ch.inputMsg) + got := b.String() + m := line.FindStringSubmatch(got) + if m == nil { + t.Errorf("format mismatch: %q", got) + continue + } + if m[1] != ch.level { + t.Errorf("level: got %q want %q (line %q)", m[1], ch.level, got) + } + if m[2] != ch.inputMsg { + t.Errorf("msg: got %q want %q", m[2], ch.inputMsg) + } + } +}