From a774f9905b6a81a22cb69f488d094bf410ae7fec Mon Sep 17 00:00:00 2001 From: Lukasz Raczylo Date: Fri, 14 Aug 2026 11:10:01 +0100 Subject: [PATCH] fix(logging): make level and field-name access concurrency-safe SetFieldName wrote a package-global map with no lock while log read it from many goroutines, and the level, caller, and time-format setters mutated fields without synchronisation. A runtime setter call could crash the process with a concurrent map write. The scalar fields now use atomics on the hot log path and the global field-name map uses a read-write mutex. Behaviour for init-time configuration is unchanged. --- logging/logger.go | 62 +++++++++++++++++++-------- logging/logger_race_test.go | 85 +++++++++++++++++++++++++++++++++++++ logging/logger_test.go | 6 +-- 3 files changed, 133 insertions(+), 20 deletions(-) diff --git a/logging/logger.go b/logging/logger.go index 2500440..f16c79d 100644 --- a/logging/logger.go +++ b/logging/logger.go @@ -12,6 +12,7 @@ import ( "runtime" "strings" "sync" + "sync/atomic" "time" "github.com/goccy/go-json" @@ -40,11 +41,18 @@ const ( ) // Logger represents the logging object with configurations. +// +// timeFormat, minLogLevel and showCaller are read on every log() call, so +// they are stored as atomics rather than behind mu: this keeps the hot log +// path lock-free for the scalar/string config while still being safe to +// mutate concurrently from SetTimeFormat/SetMinLogLevel/SetShowCaller. mu +// continues to protect only the output writer, which requires exclusive +// access while writing bytes. type Logger struct { output io.Writer - timeFormat string - minLogLevel int - showCaller bool + timeFormat atomic.Pointer[string] + minLogLevel atomic.Int32 + showCaller atomic.Bool mu sync.Mutex // Mutex to protect concurrent access to output } @@ -62,12 +70,22 @@ var bufferPool = sync.Pool{ } // fieldNames allows customization of output field names. +// +// It is package-global by design: a single process-wide field-name mapping +// is applied consistently across every Logger instance (this is the +// behavior existing callers rely on, e.g. main.go configures field names on +// one Logger and expects that naming to apply process-wide). fieldNamesMu +// guards it so SetFieldName (writer) and log (reader) can run concurrently +// without a data race. var fieldNames = map[string]string{ "timestamp": "timestamp", "level": "level", "message": "message", } +// fieldNamesMu protects concurrent access to the package-global fieldNames map. +var fieldNamesMu sync.RWMutex + // osExit is a variable to allow mocking os.Exit in tests var osExit = os.Exit @@ -76,12 +94,14 @@ var exitMutex sync.RWMutex // New creates a new Logger with default settings. func New() *Logger { - return &Logger{ - timeFormat: defaultTimeFormat, - minLogLevel: defaultMinLevel, - output: os.Stdout, - showCaller: defaultShowCaller, + l := &Logger{ + output: os.Stdout, } + format := defaultTimeFormat + l.timeFormat.Store(&format) + l.minLogLevel.Store(int32(defaultMinLevel)) + l.showCaller.Store(defaultShowCaller) + return l } // SetOutput sets the output destination for the logger. @@ -105,38 +125,40 @@ func GetLogLevel(level string) int { // SetTimeFormat sets the time format for the logger's timestamp field. func (l *Logger) SetTimeFormat(format string) *Logger { - l.timeFormat = format + l.timeFormat.Store(&format) return l } // SetMinLogLevel sets the minimum log level for the logger. func (l *Logger) SetMinLogLevel(level int) *Logger { - l.minLogLevel = level + l.minLogLevel.Store(int32(level)) return l } // SetFieldName allows customizing the field names in log output. func (l *Logger) SetFieldName(field, name string) *Logger { + fieldNamesMu.Lock() fieldNames[field] = name + fieldNamesMu.Unlock() return l } // SetShowCaller enables or disables including the caller information in log output. func (l *Logger) SetShowCaller(show bool) *Logger { - l.showCaller = show + l.showCaller.Store(show) return l } // shouldLog determines if the message should be logged based on the logger's minimum log level. func (l *Logger) shouldLog(level int) bool { - return level >= l.minLogLevel + return level >= int(l.minLogLevel.Load()) } // IsLevelEnabled reports whether the given level would be emitted by this logger. // Useful to gate expensive log-field construction (map/slice allocations) behind a // cheap level check when the log call would otherwise be dropped. func (l *Logger) IsLevelEnabled(level int) bool { - return level >= l.minLogLevel + return level >= int(l.minLogLevel.Load()) } // log writes the log message with the given level. @@ -145,11 +167,17 @@ func (l *Logger) log(level int, m *LogMessage) { m.Pairs = make(map[string]any) } - m.Pairs[fieldNames["timestamp"]] = time.Now().Format(l.timeFormat) - m.Pairs[fieldNames["level"]] = levelNames[level] - m.Pairs[fieldNames["message"]] = m.Message + fieldNamesMu.RLock() + timestampField := fieldNames["timestamp"] + levelField := fieldNames["level"] + messageField := fieldNames["message"] + fieldNamesMu.RUnlock() - if l.showCaller { + m.Pairs[timestampField] = time.Now().Format(*l.timeFormat.Load()) + m.Pairs[levelField] = levelNames[level] + m.Pairs[messageField] = m.Message + + if l.showCaller.Load() { m.Pairs["caller"] = getCaller() } diff --git a/logging/logger_race_test.go b/logging/logger_race_test.go index 1eb62b5..b53188f 100644 --- a/logging/logger_race_test.go +++ b/logging/logger_race_test.go @@ -2,8 +2,12 @@ package libpack_logger import ( "bytes" + "strings" "sync" "testing" + "time" + + "github.com/goccy/go-json" ) // Test_LogConcurrentAccess verifies that the logger correctly handles concurrent access @@ -52,3 +56,84 @@ func TestLogConcurrentAccess(t *testing.T) { t.Error("Expected log output, but got none") } } + +// TestConcurrentSettersDuringLog verifies that SetFieldName, SetMinLogLevel, +// SetShowCaller, and SetTimeFormat can run concurrently with active log() +// calls without a data race. +// +// Before the fix, SetFieldName wrote the package-global fieldNames map with +// no lock while log() read it from many goroutines, and +// SetMinLogLevel/SetShowCaller/SetTimeFormat mutated Logger fields with no +// lock while shouldLog()/log() read them. This test fails under +// `go test -race` on that code and passes once the setters and readers are +// synchronized. +func TestConcurrentSettersDuringLog(t *testing.T) { + // fieldNames is package-global, so snapshot and restore it: this test + // mutates it concurrently and must not leak state into other tests. + originalFieldNames := make(map[string]string) + for k, v := range fieldNames { + originalFieldNames[k] = v + } + defer func() { + for k, v := range originalFieldNames { + fieldNames[k] = v + } + }() + + output := &bytes.Buffer{} + logger := New().SetOutput(output).SetMinLogLevel(LEVEL_DEBUG) + + const ( + numLoggers = 50 + numSetters = 50 + iterations = 200 + ) + + var wg sync.WaitGroup + wg.Add(numLoggers + numSetters) + + // Goroutines that continuously log, exercising log()'s reads of the + // global fieldNames map and the Logger's minLogLevel/showCaller/ + // timeFormat fields. + for i := 0; i < numLoggers; i++ { + go func(id int) { + defer wg.Done() + msg := &LogMessage{Message: "concurrent setter test"} + for j := 0; j < iterations; j++ { + logger.Info(msg) + logger.Debug(msg) + } + }(i) + } + + // Goroutines that continuously mutate logger-wide configuration while + // logging is in flight from the goroutines above. + for i := 0; i < numSetters; i++ { + go func(id int) { + defer wg.Done() + for j := 0; j < iterations; j++ { + logger.SetFieldName("timestamp", "ts") + logger.SetMinLogLevel(LEVEL_DEBUG) + logger.SetShowCaller(id%2 == 0) + logger.SetTimeFormat(time.RFC3339Nano) + } + }(i) + } + + wg.Wait() + + if output.Len() == 0 { + t.Fatal("Expected log output, but got none") + } + + // Each emitted line must still be well-formed JSON: the concurrent + // setter calls must not corrupt log() output, only race on which + // setting "wins" at each point in time. + lines := strings.Split(strings.TrimSpace(output.String()), "\n") + for i, line := range lines { + var decoded map[string]any + if err := json.Unmarshal([]byte(line), &decoded); err != nil { + t.Fatalf("line %d is not valid JSON: %v\nline: %s", i, err, line) + } + } +} diff --git a/logging/logger_test.go b/logging/logger_test.go index a02e038..b3dfb85 100644 --- a/logging/logger_test.go +++ b/logging/logger_test.go @@ -100,7 +100,7 @@ func (suite *LoggerTestSuite) Test_LogsLevelsPrint() { // Set logger's minimum log level logger.SetMinLogLevel(tt.loggerMinLevel) - fmt.Println("Logger min log level:", levelNames[logger.minLogLevel]) + fmt.Println("Logger min log level:", levelNames[logger.minLogLevel.Load()]) // Call the logging method callLoggerMethod(logger, tt.method, msg) @@ -138,13 +138,13 @@ func containsLogMessage(logOutput, expectedMessage string) bool { func (suite *LoggerTestSuite) Test_SetFormat() { logger := New().SetTimeFormat(time.RFC3339Nano) - assert.Equal(time.RFC3339Nano, logger.timeFormat) + assert.Equal(time.RFC3339Nano, *logger.timeFormat.Load()) } func (suite *LoggerTestSuite) Test_SetMinLogLevel() { logger := New().SetMinLogLevel(LEVEL_DEBUG) - assert.Equal(LEVEL_DEBUG, logger.minLogLevel) + assert.Equal(LEVEL_DEBUG, int(logger.minLogLevel.Load())) } func (suite *LoggerTestSuite) Test_ShouldLog() {