Fix deadlock on panics at Entry.log

When calling Entry.log a panic inside some of the
locking blocks could cause the whole logger to deadlock.

One of the ways this could happen is for a hook to cause
a panic, when this happens the lock is never unlocked and
the library deadlocks, causing the code that is calling
it to deadlock as well.

This changes how locking happens with unlocks at defer
blocks so even if a panic happens somewhere along the log
call the library will still unlock and continue to function.
This commit is contained in:
Maurício Linhares 2018-01-22 10:35:26 -05:00
parent d682213848
commit 977e03308a
No known key found for this signature in database
GPG Key ID: 9D03B316BB6DFC17
2 changed files with 66 additions and 21 deletions

View File

@ -94,32 +94,16 @@ func (entry Entry) log(level Level, msg string) {
entry.Level = level entry.Level = level
entry.Message = msg entry.Message = msg
entry.Logger.mu.Lock() entry.fireHooks()
err := entry.Logger.Hooks.Fire(level, &entry)
entry.Logger.mu.Unlock()
if err != nil {
entry.Logger.mu.Lock()
fmt.Fprintf(os.Stderr, "Failed to fire hook: %v\n", err)
entry.Logger.mu.Unlock()
}
buffer = bufferPool.Get().(*bytes.Buffer) buffer = bufferPool.Get().(*bytes.Buffer)
buffer.Reset() buffer.Reset()
defer bufferPool.Put(buffer) defer bufferPool.Put(buffer)
entry.Buffer = buffer entry.Buffer = buffer
serialized, err := entry.Logger.Formatter.Format(&entry)
entry.write()
entry.Buffer = nil entry.Buffer = nil
if err != nil {
entry.Logger.mu.Lock()
fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err)
entry.Logger.mu.Unlock()
} else {
entry.Logger.mu.Lock()
_, err = entry.Logger.Out.Write(serialized)
if err != nil {
fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err)
}
entry.Logger.mu.Unlock()
}
// To avoid Entry#log() returning a value that only would make sense for // 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 // panic() to use in Entry#Panic(), we avoid the allocation by checking
@ -129,6 +113,29 @@ func (entry Entry) log(level Level, msg string) {
} }
} }
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)
}
}
func (entry *Entry) write() {
serialized, err := entry.Logger.Formatter.Format(entry)
entry.Logger.mu.Lock()
defer entry.Logger.mu.Unlock()
if err != nil {
fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err)
} else {
_, err = entry.Logger.Out.Write(serialized)
if err != nil {
fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err)
}
}
}
func (entry *Entry) Debug(args ...interface{}) { func (entry *Entry) Debug(args ...interface{}) {
if entry.Logger.level() >= DebugLevel { if entry.Logger.level() >= DebugLevel {
entry.log(DebugLevel, fmt.Sprint(args...)) entry.log(DebugLevel, fmt.Sprint(args...))

View File

@ -75,3 +75,41 @@ func TestEntryPanicf(t *testing.T) {
entry := NewEntry(logger) entry := NewEntry(logger)
entry.WithField("err", errBoom).Panicf("kaboom %v", true) entry.WithField("err", errBoom).Panicf("kaboom %v", true)
} }
const (
badMessage = "this is going to panic"
panicMessage = "this is broken"
)
type panickyHook struct{}
func (p *panickyHook) Levels() []Level {
return []Level{InfoLevel}
}
func (p *panickyHook) Fire(entry *Entry) error {
if entry.Message == badMessage {
panic(panicMessage)
}
return nil
}
func TestEntryHooksPanic(t *testing.T) {
logger := New()
logger.Out = &bytes.Buffer{}
logger.Level = InfoLevel
logger.Hooks.Add(&panickyHook{})
defer func() {
p := recover()
assert.NotNil(t, p)
assert.Equal(t, panicMessage, p)
entry := NewEntry(logger)
entry.Info("another message")
}()
entry := NewEntry(logger)
entry.Info(badMessage)
}