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
This commit is contained in:
Ephex2 2022-01-26 17:44:20 -05:00 committed by Bjørn Erik Pedersen
parent 7a080b624e
commit 22055176d2
2 changed files with 58 additions and 2 deletions

View file

@ -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

View file

@ -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