general: Fix issue causing log threads to hang indefinitely when prin…

…t() 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

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

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