mirror of
https://github.com/lukaszraczylo/graphql-monitoring-proxy.git
synced 2026-10-11 05:27:47 +00:00
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.
This commit is contained in:
+45
-17
@@ -12,6 +12,7 @@ import (
|
|||||||
"runtime"
|
"runtime"
|
||||||
"strings"
|
"strings"
|
||||||
"sync"
|
"sync"
|
||||||
|
"sync/atomic"
|
||||||
"time"
|
"time"
|
||||||
|
|
||||||
"github.com/goccy/go-json"
|
"github.com/goccy/go-json"
|
||||||
@@ -40,11 +41,18 @@ const (
|
|||||||
)
|
)
|
||||||
|
|
||||||
// Logger represents the logging object with configurations.
|
// 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 {
|
type Logger struct {
|
||||||
output io.Writer
|
output io.Writer
|
||||||
timeFormat string
|
timeFormat atomic.Pointer[string]
|
||||||
minLogLevel int
|
minLogLevel atomic.Int32
|
||||||
showCaller bool
|
showCaller atomic.Bool
|
||||||
mu sync.Mutex // Mutex to protect concurrent access to output
|
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.
|
// 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{
|
var fieldNames = map[string]string{
|
||||||
"timestamp": "timestamp",
|
"timestamp": "timestamp",
|
||||||
"level": "level",
|
"level": "level",
|
||||||
"message": "message",
|
"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
|
// osExit is a variable to allow mocking os.Exit in tests
|
||||||
var osExit = os.Exit
|
var osExit = os.Exit
|
||||||
|
|
||||||
@@ -76,12 +94,14 @@ var exitMutex sync.RWMutex
|
|||||||
|
|
||||||
// New creates a new Logger with default settings.
|
// New creates a new Logger with default settings.
|
||||||
func New() *Logger {
|
func New() *Logger {
|
||||||
return &Logger{
|
l := &Logger{
|
||||||
timeFormat: defaultTimeFormat,
|
output: os.Stdout,
|
||||||
minLogLevel: defaultMinLevel,
|
|
||||||
output: os.Stdout,
|
|
||||||
showCaller: defaultShowCaller,
|
|
||||||
}
|
}
|
||||||
|
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.
|
// 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.
|
// SetTimeFormat sets the time format for the logger's timestamp field.
|
||||||
func (l *Logger) SetTimeFormat(format string) *Logger {
|
func (l *Logger) SetTimeFormat(format string) *Logger {
|
||||||
l.timeFormat = format
|
l.timeFormat.Store(&format)
|
||||||
return l
|
return l
|
||||||
}
|
}
|
||||||
|
|
||||||
// SetMinLogLevel sets the minimum log level for the logger.
|
// SetMinLogLevel sets the minimum log level for the logger.
|
||||||
func (l *Logger) SetMinLogLevel(level int) *Logger {
|
func (l *Logger) SetMinLogLevel(level int) *Logger {
|
||||||
l.minLogLevel = level
|
l.minLogLevel.Store(int32(level))
|
||||||
return l
|
return l
|
||||||
}
|
}
|
||||||
|
|
||||||
// SetFieldName allows customizing the field names in log output.
|
// SetFieldName allows customizing the field names in log output.
|
||||||
func (l *Logger) SetFieldName(field, name string) *Logger {
|
func (l *Logger) SetFieldName(field, name string) *Logger {
|
||||||
|
fieldNamesMu.Lock()
|
||||||
fieldNames[field] = name
|
fieldNames[field] = name
|
||||||
|
fieldNamesMu.Unlock()
|
||||||
return l
|
return l
|
||||||
}
|
}
|
||||||
|
|
||||||
// SetShowCaller enables or disables including the caller information in log output.
|
// SetShowCaller enables or disables including the caller information in log output.
|
||||||
func (l *Logger) SetShowCaller(show bool) *Logger {
|
func (l *Logger) SetShowCaller(show bool) *Logger {
|
||||||
l.showCaller = show
|
l.showCaller.Store(show)
|
||||||
return l
|
return l
|
||||||
}
|
}
|
||||||
|
|
||||||
// shouldLog determines if the message should be logged based on the logger's minimum log level.
|
// shouldLog determines if the message should be logged based on the logger's minimum log level.
|
||||||
func (l *Logger) shouldLog(level int) bool {
|
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.
|
// IsLevelEnabled reports whether the given level would be emitted by this logger.
|
||||||
// Useful to gate expensive log-field construction (map/slice allocations) behind a
|
// Useful to gate expensive log-field construction (map/slice allocations) behind a
|
||||||
// cheap level check when the log call would otherwise be dropped.
|
// cheap level check when the log call would otherwise be dropped.
|
||||||
func (l *Logger) IsLevelEnabled(level int) bool {
|
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.
|
// 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 = make(map[string]any)
|
||||||
}
|
}
|
||||||
|
|
||||||
m.Pairs[fieldNames["timestamp"]] = time.Now().Format(l.timeFormat)
|
fieldNamesMu.RLock()
|
||||||
m.Pairs[fieldNames["level"]] = levelNames[level]
|
timestampField := fieldNames["timestamp"]
|
||||||
m.Pairs[fieldNames["message"]] = m.Message
|
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()
|
m.Pairs["caller"] = getCaller()
|
||||||
}
|
}
|
||||||
|
|
||||||
|
|||||||
@@ -2,8 +2,12 @@ package libpack_logger
|
|||||||
|
|
||||||
import (
|
import (
|
||||||
"bytes"
|
"bytes"
|
||||||
|
"strings"
|
||||||
"sync"
|
"sync"
|
||||||
"testing"
|
"testing"
|
||||||
|
"time"
|
||||||
|
|
||||||
|
"github.com/goccy/go-json"
|
||||||
)
|
)
|
||||||
|
|
||||||
// Test_LogConcurrentAccess verifies that the logger correctly handles concurrent access
|
// 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")
|
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)
|
||||||
|
}
|
||||||
|
}
|
||||||
|
}
|
||||||
|
|||||||
@@ -100,7 +100,7 @@ func (suite *LoggerTestSuite) Test_LogsLevelsPrint() {
|
|||||||
|
|
||||||
// Set logger's minimum log level
|
// Set logger's minimum log level
|
||||||
logger.SetMinLogLevel(tt.loggerMinLevel)
|
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
|
// Call the logging method
|
||||||
callLoggerMethod(logger, tt.method, msg)
|
callLoggerMethod(logger, tt.method, msg)
|
||||||
@@ -138,13 +138,13 @@ func containsLogMessage(logOutput, expectedMessage string) bool {
|
|||||||
func (suite *LoggerTestSuite) Test_SetFormat() {
|
func (suite *LoggerTestSuite) Test_SetFormat() {
|
||||||
logger := New().SetTimeFormat(time.RFC3339Nano)
|
logger := New().SetTimeFormat(time.RFC3339Nano)
|
||||||
|
|
||||||
assert.Equal(time.RFC3339Nano, logger.timeFormat)
|
assert.Equal(time.RFC3339Nano, *logger.timeFormat.Load())
|
||||||
}
|
}
|
||||||
|
|
||||||
func (suite *LoggerTestSuite) Test_SetMinLogLevel() {
|
func (suite *LoggerTestSuite) Test_SetMinLogLevel() {
|
||||||
logger := New().SetMinLogLevel(LEVEL_DEBUG)
|
logger := New().SetMinLogLevel(LEVEL_DEBUG)
|
||||||
|
|
||||||
assert.Equal(LEVEL_DEBUG, logger.minLogLevel)
|
assert.Equal(LEVEL_DEBUG, int(logger.minLogLevel.Load()))
|
||||||
}
|
}
|
||||||
|
|
||||||
func (suite *LoggerTestSuite) Test_ShouldLog() {
|
func (suite *LoggerTestSuite) Test_ShouldLog() {
|
||||||
|
|||||||
Reference in New Issue
Block a user