From 97dd8c98af9e0580ccc1efd51d21118322694842 Mon Sep 17 00:00:00 2001 From: Ayman Bagabas Date: Tue, 1 Aug 2023 11:57:04 -0700 Subject: [PATCH] fix: race condition when creating standard logger (#68) Before, `StandardLog` used to _copy_ the internal buffer causing two or more loggers to share the same buffer triggering a race. Don't copy the internal buffer and reduce the mutex critical section scope. --- logger.go | 9 ++++----- logger_test.go | 35 +++++++++++++++++++++++++++++++++++ stdlog.go | 7 ++----- 3 files changed, 41 insertions(+), 10 deletions(-) diff --git a/logger.go b/logger.go index 0dd4b07..73805bd 100644 --- a/logger.go +++ b/logger.go @@ -58,10 +58,6 @@ func (l *Logger) log(level Level, msg interface{}, keyvals ...interface{}) { return } - l.mu.Lock() - defer l.mu.Unlock() - defer l.b.Reset() - var kvs []interface{} if l.reportTimestamp { kvs = append(kvs, TimestampKey, l.timeFunc()) @@ -98,6 +94,8 @@ func (l *Logger) log(level Level, msg interface{}, keyvals ...interface{}) { kvs = append(kvs, ErrMissingValue) } + l.mu.Lock() + defer l.mu.Unlock() switch l.formatter { case LogfmtFormatter: l.logfmtFormatter(kvs...) @@ -107,7 +105,8 @@ func (l *Logger) log(level Level, msg interface{}, keyvals ...interface{}) { l.textFormatter(kvs...) } - _, _ = l.w.Write(l.b.Bytes()) + // WriteTo will reset the buffer + l.b.WriteTo(l.w) // nolint: errcheck } // Helper marks the calling function as a helper diff --git a/logger_test.go b/logger_test.go index 715fc5d..181278f 100644 --- a/logger_test.go +++ b/logger_test.go @@ -2,8 +2,10 @@ package log import ( "bytes" + "io" "sync" "testing" + "time" "github.com/stretchr/testify/assert" ) @@ -183,3 +185,36 @@ func TestLogWithRaceCondition(t *testing.T) { }) } } + +func TestRace(t *testing.T) { + t.Parallel() + + w := io.Discard + l := New(w) + for i := 0; i < 100; i++ { + t.Run("race", func(t *testing.T) { + t.Parallel() + s := l.StandardLog() + l.Info("foo") + l.GetLevel() + l.Print("foo") + + s.Print("foo") + s.Writer().Write([]byte("bar")) + s.Output(1, "baz") + + l.SetOutput(w) + l.Debug("foo") + l.SetLevel(InfoLevel) + l.GetPrefix() + + o := l.With("foo", "bar") + o.Print("foo") + o.SetTimeFormat(time.Kitchen) + o.Debug("foo") + o.SetOutput(w) + o.Error("foo") + o.SetFormatter(JSONFormatter) + }) + } +} diff --git a/stdlog.go b/stdlog.go index 5911c61..7d352c4 100644 --- a/stdlog.go +++ b/stdlog.go @@ -3,7 +3,6 @@ package log import ( "log" "strings" - "sync" ) type stdLogWriter struct { @@ -54,14 +53,12 @@ type StandardLogOptions struct { // can infer log levels from message prefix. Expected prefixes are DEBUG, INFO, // WARN, ERROR, and ERR. func (l *Logger) StandardLog(opts ...StandardLogOptions) *log.Logger { - nl := *l - nl.mu = &sync.RWMutex{} - nl.helpers = &sync.Map{} + nl := l.With() // The caller stack is // log.Printf() -> l.Output() -> l.out.Write(stdLogger.Write) nl.callerOffset += 3 sl := &stdLogWriter{ - l: &nl, + l: nl, } if len(opts) > 0 { sl.opt = &opts[0]