Merge pull request #695 from mauricio/master

Fix deadlock on panics at Entry.log

entry.go

@@ -94,32 +94,16 @@ func (entry Entry) log(level Level, msg string) {
 	entry.Level = level
 	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.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...))

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)
+}