From c406de492badb7b4edf018d1b27159761d4a4d2a Mon Sep 17 00:00:00 2001 From: bb7133 Date: Sun, 18 Oct 2026 22:58:48 -0700 Subject: [PATCH] log: make write timeout per waiter instead of shared lockWithTimeoutWrapper counted timeout ticks from one ticker shared by all waiters. Each tick is delivered to only one waiter, so with N callers queued behind a stuck write every caller waited about timeout * N seconds before panicking or discarding. Give every call its own timer so the wait is bounded by timeout regardless of how many goroutines are waiting. Co-Authored-By: Claude Opus 5.5 --- log.go | 29 ++++++++++++++++++----------- log_test.go | 30 ++++++++++++++++++++++++++++++ 2 files changed, 48 insertions(+), 11 deletions(-) diff --git a/log.go b/log.go index d4e597e..60a7887 100644 --- a/log.go +++ b/log.go @@ -136,7 +136,6 @@ func LockWithTimeoutAction(ws zapcore.WriteSyncer, timeout int, action string) z r := &lockWithTimeoutWrapper{ ws: ws, lock: make(chan struct{}, 1), - t: time.NewTicker(time.Second), timeout: timeout, timeoutAction: normalizeTimeoutAction(action), } @@ -146,7 +145,6 @@ func LockWithTimeoutAction(ws zapcore.WriteSyncer, timeout int, action string) z type lockWithTimeoutWrapper struct { ws zapcore.WriteSyncer lock chan struct{} - t *time.Ticker timeout int timeoutAction string timedOut atomic.Bool @@ -173,16 +171,25 @@ func (s *lockWithTimeoutWrapper) getLockOrBlock() bool { } } - for i := 0; i < s.timeout; { - select { - case s.lock <- struct{}{}: - s.timedOut.Store(false) - return true - case <-s.t.C: - i++ - } + select { + case s.lock <- struct{}{}: + s.timedOut.Store(false) + return true + default: + } + + // Each caller waits on its own timer. A ticker shared by all waiters would + // deliver each tick to only one of them, stretching the wait to roughly + // timeout * waiters. + timer := time.NewTimer(time.Duration(s.timeout) * time.Second) + defer timer.Stop() + select { + case s.lock <- struct{}{}: + s.timedOut.Store(false) + return true + case <-timer.C: + return false } - return false } func (s *lockWithTimeoutWrapper) unlock() { diff --git a/log_test.go b/log_test.go index 995d941..00d19e9 100644 --- a/log_test.go +++ b/log_test.go @@ -18,6 +18,7 @@ import ( "bufio" "bytes" "net/url" + "sync" "testing" "time" @@ -178,6 +179,35 @@ func TestTimeoutActionDiscard(t *testing.T) { require.Contains(t, blocking.String(), "written") } +func TestTimeoutNotScaledByWaiters(t *testing.T) { + const waiters = 8 + for _, action := range []string{LogTimeoutActionDiscard, LogTimeoutActionPanic} { + t.Run(action, func(t *testing.T) { + blocking := newBlockingOnceWriteSyncer() + ws := LockWithTimeoutAction(blocking, 1, action) + go func() { _, _ = ws.Write([]byte("first")) }() + <-blocking.started + + // All waiters queue up behind the stuck write at the same time. Each + // of them must give up after its own timeout, not after + // timeout * waiters. + start := time.Now() + var wg sync.WaitGroup + for range waiters { + wg.Add(1) + go func() { + defer wg.Done() + defer func() { _ = recover() }() + _, _ = ws.Write([]byte("blocked")) + }() + } + wg.Wait() + require.Less(t, time.Since(start), 3*time.Second) + close(blocking.release) + }) + } +} + type hang struct{} func (_ hang) Write(_ []byte) (int, error) {