diff --git a/types/logger/logger.go b/types/logger/logger.go index bba5ac3eb..2f8973abe 100644 --- a/types/logger/logger.go +++ b/types/logger/logger.go @@ -106,7 +106,6 @@ func RateLimitedFnWithClock(logf Logf, f time.Duration, burst int, maxCache int, } mu.Lock() - defer mu.Unlock() rl, ok := msgLim[format] if ok { msgCache.MoveToFront(rl.ele) @@ -138,8 +137,8 @@ func RateLimitedFnWithClock(logf Logf, f time.Duration, burst int, maxCache int, rl.nBlocked = 0 } if rl.nBlocked == 0 && rl.bucket.Get() { - logf(format, args...) - if rl.bucket.remaining == 0 { + hitLimit := rl.bucket.remaining == 0 + if hitLimit { // Enter "blocked" mode immediately after // reaching the burst limit. We want to // always accompany the format() message @@ -148,12 +147,16 @@ func RateLimitedFnWithClock(logf Logf, f time.Duration, burst int, maxCache int, // message anyway. But this way they can // be on two separate lines and we don't // corrupt the original message. - logf("[RATELIMIT] format(%q)", format) rl.nBlocked = 1 } - return + mu.Unlock() // release before calling logf + logf(format, args...) + if hitLimit { + logf("[RATELIMIT] format(%q)", format) + } } else { rl.nBlocked++ + mu.Unlock() } } } diff --git a/types/logger/logger_test.go b/types/logger/logger_test.go index 990e09617..fc9502105 100644 --- a/types/logger/logger_test.go +++ b/types/logger/logger_test.go @@ -170,3 +170,16 @@ func TestSynchronization(t *testing.T) { }) } } + +// test that RateLimitedFn is safe for reentrancy without deadlocking +func TestRateLimitedFnReentrancy(t *testing.T) { + rlogf := RateLimitedFn(t.Logf, time.Nanosecond, 10, 10) + rlogf("Hello.") + rlogf("Hello, %v", ArgWriter(func(bw *bufio.Writer) { + bw.WriteString("world") + })) + rlogf("Hello, %v", ArgWriter(func(bw *bufio.Writer) { + bw.WriteString("bye") + rlogf("boom") // this used to deadlock + })) +}