SK-2871: make slog logger thread-safe and match logrus output format

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,40 +22,137 @@ 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() {
 	levelVar.Set(slog.LevelError)
 	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="<RFC3339>" level=<lowercase> msg="<message>"
+//
+// 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()
 }

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()
+}

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="<RFC3339>" level=<lowercase> msg="<message>"
+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)
+		}
+	}
+}