general: Fix issue causing log threads to hang indefinitely when print() panics

The function printIfNotPrinted() defined for DistinctLogger unlocked the mutex within
the logger only after the print() function ran. If print panics, the mutex would stay
locked and future attempts to read or write from the logger mutex would cause the goroutine
to hang indefinitely.

Deferred the unlocking of the mutex to prevent this. Also, put l.m[key] before the print()
call since this will prevent another bug where the same warning potentially gets logged
multiple times if the print() call panics.

Fixes #9380

diff --git a/helpers/general.go b/helpers/general.go
index 236a763fa91f94dc4f5a96a85732d64ed5c5520b..472ebc4a45b9719ae0ea00969512be1a0b0b432f 100644 (file)
--- a/helpers/general.go
+++ b/helpers/general.go
@@ -360,9 +360,10 @@ func (l *DistinctLogger) printIfNotPrinted(level, logStatement string, print fun
                return
        }
        l.Lock()
+       defer l.Unlock()
+       l.m[key] = true // Placing this after print() can cause duplicate warning entries to be logged when --panicOnWarning is true.
        print()
-       l.m[key] = true
-       l.Unlock()
+
 }
 
 // NewDistinctErrorLogger creates a new DistinctLogger that logs ERRORs

diff --git a/helpers/general_test.go b/helpers/general_test.go
index 7fe00c51a632c7c9d727b0b2675a7d3e9cea9341..be9834d3f61f9531f294b7b94cb424d3a15cb2ba 100644 (file)
--- a/helpers/general_test.go
+++ b/helpers/general_test.go
@@ -18,6 +18,7 @@ import (
        "reflect"
        "strings"
        "testing"
+       "time"
 
        "github.com/gohugoio/hugo/config"
 
@@ -58,6 +59,60 @@ func TestResolveMarkup(t *testing.T) {
        }
 }
 
+func TestDistinctLoggerDoesNotLockOnWarningPanic(t *testing.T) {
+       // Testing to make sure logger mutex doesn't lock if warnings cause panics.
+       // func Warnf() of DistinctLogger is defined in general.go
+       l := NewDistinctLogger(loggers.NewWarningLogger())
+
+       // Set PanicOnWarning to true to reproduce issue 9380
+       // Ensure global variable loggers.PanicOnWarning is reset to old value after test
+       if loggers.PanicOnWarning == false {
+               loggers.PanicOnWarning = true
+               defer func() {
+                       loggers.PanicOnWarning = false
+               }()
+       }
+
+       // Establish timeout in case a lock occurs:
+       timeIsUp := make(chan bool)
+       timeOutSeconds := 1
+       go func() {
+               time.Sleep(time.Second * time.Duration(timeOutSeconds))
+               timeIsUp <- true
+       }()
+
+       // Attempt to run multiple logging threads in parallel
+       counterC := make(chan int)
+       goroutines := 5
+
+       for i := 0; i < goroutines; i++ {
+               go func() {
+                       defer func() {
+                               // Intentional panic successfully recovered - notify counter channel
+                               recover()
+                               counterC <- 1
+                       }()
+
+                       l.Warnf("Placeholder template message: %v", "In this test, logging a warning causes a panic.")
+               }()
+       }
+
+       // All goroutines should complete before timeout
+       var counter int
+       for {
+               select {
+               case <-counterC:
+                       counter++
+                       if counter == goroutines {
+                               return
+                       }
+               case <-timeIsUp:
+                       t.Errorf("Unable to log warnings with --panicOnWarning within alloted time of: %v seconds. Investigate possible mutex locking on panic in distinct warning logger.", timeOutSeconds)
+                       return
+               }
+       }
+}
+
 func TestFirstUpper(t *testing.T) {
        for i, this := range []struct {
                in     string