From 977e03308a73cbc954765de9e2efce93f1416294 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Maur=C3=ADcio=20Linhares?= <mlinhares@digitalocean.com>
Date: Mon, 22 Jan 2018 10:35:26 -0500
Subject: [PATCH] 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.
---
 entry.go      | 49 ++++++++++++++++++++++++++++---------------------
 entry_test.go | 38 ++++++++++++++++++++++++++++++++++++++
 2 files changed, 66 insertions(+), 21 deletions(-)

diff --git a/entry.go b/entry.go
index 1fad45e..df6f92d 100644
--- a/entry.go
+++ b/entry.go
@@ -94,32 +94,16 @@ func (entry Entry) log(level Level, msg string) {
 	entry.Level = level
 	entry.Message = msg
 
-	entry.Logger.mu.Lock()
-	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()
-	}
+	entry.fireHooks()
+
 	buffer = bufferPool.Get().(*bytes.Buffer)
 	buffer.Reset()
 	defer bufferPool.Put(buffer)
 	entry.Buffer = buffer
-	serialized, err := entry.Logger.Formatter.Format(&entry)
+
+	entry.write()
+
 	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
 	// 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{}) {
 	if entry.Logger.level() >= DebugLevel {
 		entry.log(DebugLevel, fmt.Sprint(args...))
diff --git a/entry_test.go b/entry_test.go
index 99c3b41..a81e2b3 100644
--- a/entry_test.go
+++ b/entry_test.go
@@ -75,3 +75,41 @@ func TestEntryPanicf(t *testing.T) {
 	entry := NewEntry(logger)
 	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)
+}