Skip to content

Commit

Permalink
fix: race condition when creating standard logger (#68)
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
aymanbagabas committed Aug 1, 2023
1 parent 280c4e3 commit 97dd8c9
Show file tree
Hide file tree
Showing 3 changed files with 41 additions and 10 deletions.
9 changes: 4 additions & 5 deletions logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -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())
Expand Down Expand Up @@ -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...)
Expand All @@ -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
Expand Down
35 changes: 35 additions & 0 deletions logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,10 @@ package log

import (
"bytes"
"io"
"sync"
"testing"
"time"

"github.com/stretchr/testify/assert"
)
Expand Down Expand Up @@ -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)
})
}
}
7 changes: 2 additions & 5 deletions stdlog.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,6 @@ package log
import (
"log"
"strings"
"sync"
)

type stdLogWriter struct {
Expand Down Expand Up @@ -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]
Expand Down

0 comments on commit 97dd8c9

Please sign in to comment.