From ac6e35b4c213b54a2086b831179b9c324f519695 Mon Sep 17 00:00:00 2001 From: David Bariod Date: Tue, 16 Feb 2021 10:29:37 +0100 Subject: [PATCH] fix for entry data field race condition --- entry.go | 68 +++++++++++++++++++++++++++++--------------------- entry_test.go | 2 +- logger.go | 2 +- logger_test.go | 2 +- logrus_test.go | 39 ++++++++++++++++++++++++++--- 5 files changed, 79 insertions(+), 34 deletions(-) diff --git a/entry.go b/entry.go index 1e32a64..e02e057 100644 --- a/entry.go +++ b/entry.go @@ -78,8 +78,20 @@ func NewEntry(logger *Logger) *Entry { } } +func (entry *Entry) Dup() *Entry { + data := make(Fields, len(entry.Data)) + for k, v := range entry.Data { + data[k] = v + } + return &Entry{Logger: entry.Logger, Data: data, Time: entry.Time, Context: entry.Context, err: entry.err} +} + // Returns the bytes representation of this entry from the formatter. func (entry *Entry) Bytes() ([]byte, error) { + return entry.bytes_nolock() +} + +func (entry *Entry) bytes_nolock() ([]byte, error) { return entry.Logger.Formatter.Format(entry) } @@ -212,51 +224,49 @@ func (entry Entry) HasCaller() (has bool) { // This function is not declared with a pointer value because otherwise // race conditions will occur when using multiple goroutines -func (entry Entry) log(level Level, msg string) { +func (entry *Entry) log(level Level, msg string) { var buffer *bytes.Buffer - // Default to now, but allow users to override if they want. - // - // We don't have to worry about polluting future calls to Entry#log() - // with this assignment because this function is declared with a - // non-pointer receiver. - if entry.Time.IsZero() { - entry.Time = time.Now() + newEntry := entry.Dup() + + if newEntry.Time.IsZero() { + newEntry.Time = time.Now() } - entry.Level = level - entry.Message = msg - entry.Logger.mu.Lock() - if entry.Logger.ReportCaller { - entry.Caller = getCaller() - } - entry.Logger.mu.Unlock() + newEntry.Level = level + newEntry.Message = msg - entry.fireHooks() + newEntry.Logger.mu.Lock() + reportCaller := newEntry.Logger.ReportCaller + newEntry.Logger.mu.Unlock() + + if reportCaller { + newEntry.Caller = getCaller() + } + + newEntry.fireHooks() buffer = getBuffer() defer func() { - entry.Buffer = nil + newEntry.Buffer = nil putBuffer(buffer) }() buffer.Reset() - entry.Buffer = buffer + newEntry.Buffer = buffer - entry.write() + newEntry.write() - entry.Buffer = nil + newEntry.Buffer = nil // To avoid Entry#log() returning a value that only would make sense for // panic() to use in Entry#Panic(), we avoid the allocation by checking // directly here. if level <= PanicLevel { - panic(&entry) + panic(newEntry) } } func (entry *Entry) fireHooks() { - entry.Logger.mu.Lock() - defer entry.Logger.mu.Unlock() err := entry.Logger.Hooks.Fire(entry.Level, entry) if err != nil { fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err) @@ -264,16 +274,18 @@ func (entry *Entry) fireHooks() { } func (entry *Entry) write() { - entry.Logger.mu.Lock() - defer entry.Logger.mu.Unlock() serialized, err := entry.Logger.Formatter.Format(entry) if err != nil { fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err) return } - if _, err = entry.Logger.Out.Write(serialized); err != nil { - fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) - } + func() { + entry.Logger.mu.Lock() + defer entry.Logger.mu.Unlock() + if _, err := entry.Logger.Out.Write(serialized); err != nil { + fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err) + } + }() } func (entry *Entry) Log(level Level, args ...interface{}) { diff --git a/entry_test.go b/entry_test.go index df687ad..035e411 100644 --- a/entry_test.go +++ b/entry_test.go @@ -232,7 +232,7 @@ func TestEntryWithIncorrectField(t *testing.T) { fn := func() {} - e := Entry{} + e := Entry{Logger: New()} eWithFunc := e.WithFields(Fields{"func": fn}) eWithFuncPtr := e.WithFields(Fields{"funcPtr": &fn}) diff --git a/logger.go b/logger.go index dbf627c..3377044 100644 --- a/logger.go +++ b/logger.go @@ -12,7 +12,7 @@ import ( // LogFunction For big messages, it can be more efficient to pass a function // and only call it if the log level is actually enables rather than // generating the log message and then checking if the level is enabled -type LogFunction func()[]interface{} +type LogFunction func() []interface{} type Logger struct { // The logs are `io.Copy`'d to this in a mutex. It's common to set this to a diff --git a/logger_test.go b/logger_test.go index f12a04e..8afb2fe 100644 --- a/logger_test.go +++ b/logger_test.go @@ -25,7 +25,7 @@ func TestFieldValueError(t *testing.T) { t.Error("unexpected error", err) } _, ok := data[FieldKeyLogrusError] - require.True(t, ok) + require.True(t, ok, `cannot found expected "logrus_error" field: %v`, data) } func TestNoFieldValueError(t *testing.T) { diff --git a/logrus_test.go b/logrus_test.go index 9c3c920..4edee28 100644 --- a/logrus_test.go +++ b/logrus_test.go @@ -588,15 +588,48 @@ func TestLoggingRaceWithHooksOnEntry(t *testing.T) { logger.AddHook(hook) entry := logger.WithField("context", "clue") - var wg sync.WaitGroup + var ( + wg sync.WaitGroup + mtx sync.Mutex + start bool + ) + + cond := sync.NewCond(&mtx) + wg.Add(100) - for i := 0; i < 100; i++ { + for i := 0; i < 50; i++ { go func() { - entry.Info("info") + cond.L.Lock() + for !start { + cond.Wait() + } + cond.L.Unlock() + for j := 0; j < 100; j++ { + entry.Info("info") + } wg.Done() }() } + + for i := 0; i < 50; i++ { + go func() { + cond.L.Lock() + for !start { + cond.Wait() + } + cond.L.Unlock() + for j := 0; j < 100; j++ { + entry.WithField("another field", "with some data").Info("info") + } + wg.Done() + }() + } + + cond.L.Lock() + start = true + cond.L.Unlock() + cond.Broadcast() wg.Wait() }