From bbde16d0994ae4d2812b31a9fd3798e56ea1d723 Mon Sep 17 00:00:00 2001 From: Brinenas <51021984+Brinenas@users.noreply.github.com> Date: Wed, 1 Jan 2025 03:52:57 +0800 Subject: [PATCH] fix Incorrect timeout error when using FindStringMatch() (#86) * fix Timeout Error issue: when the fastclock stop running, then next matches will get a wrong fast.current and daeline, thus trigger an incorrect timeout error. Co-authored-by: ccoVeille <3875889+ccoVeille@users.noreply.github.com> Co-authored-by: hezhipeng.09 Co-authored-by: Doug Clark --- fastclock.go | 12 ++++++++++ fastclock_test.go | 56 +++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 68 insertions(+) diff --git a/fastclock.go b/fastclock.go index caf2c9d..d256e63 100644 --- a/fastclock.go +++ b/fastclock.go @@ -50,8 +50,20 @@ func makeDeadline(d time.Duration) fasttime { // Start or extend clock if necessary. if end > fast.clockEnd.read() { + // If time.Since(last use) > timeout, there's a chance that + // fast.current will no longer be updated, which can lead to + // incorrect 'end' calculations that can trigger a false timeout + fast.mu.Lock() + if !fast.running && !fast.start.IsZero() { + // update fast.current + fast.current.write(durationToTicks(time.Since(fast.start))) + // recalculate our end value + end = fast.current.read() + durationToTicks(d+clockPeriod) + } + fast.mu.Unlock() extendClock(end) } + return end } diff --git a/fastclock_test.go b/fastclock_test.go index ccc149a..70201c4 100644 --- a/fastclock_test.go +++ b/fastclock_test.go @@ -2,6 +2,7 @@ package regexp2 import ( "fmt" + "log" "testing" "time" ) @@ -56,3 +57,58 @@ func TestStopTimeoutClock(t *testing.T) { t.Errorf("Expected isRunning to be %v, got %v", want, got) } } +func TestIncorrectDeadline(t *testing.T) { + if fast.start.IsZero() { + fast.start = time.Now() + } + // make fast stopped + for fast.running { + time.Sleep(clockPeriod) + } + t.Logf("current fast: %+v", fast) + timeout := 5 * clockPeriod + // make the error time much bigger + time.Sleep(10 * clockPeriod) + nowTick := durationToTicks(time.Since(fast.start)) + // before fix, fast.current will be the time fast stopped, and end is incorrect too + // after fix, fast.current will be current time. + d := makeDeadline(timeout) + gotTick := fast.current.read() + t.Logf("nowTick: %+v, gotTick: %+v", nowTick, gotTick) + if nowTick > gotTick { + t.Errorf("Expectd current should greater than %v, got %v", gotTick, nowTick) + } + expectedDeadTick := nowTick + durationToTicks(timeout) + if d < expectedDeadTick { + t.Errorf("Expectd deadTick %v, got %v", expectedDeadTick, d) + } +} + +func TestIncorrectTimeoutError(t *testing.T) { + log.SetFlags(log.Lmicroseconds) + re := MustCompile(`\[(\d+)\]\s+\[([\s\S]+)\]\s+([\s\S]+).*`, RE2) + // there's a lot of slop in the timeout process (on purpose to keep resources low) + // need a timeout of at least 5x the clockPeriod to have consistent test behavior + re.MatchTimeout = 5 * clockPeriod + + _, err := re.FindStringMatch("[10000] [Dec 15, 2012 1:42:43 AM] com.dev.log.LoggingExample main") + if err != nil { + t.Fatalf("expected no error, got %v", err) + } + + // now wait - this makes sure the background timer goroutine is stopped + time.Sleep(time.Second + re.MatchTimeout*2) + + if val := fast.clockEnd.read() - fast.current.read(); val > 0 { + t.Fatalf("unexpected bg timer running: %v", val) + } + + // each of these should be plenty fast to not timeout + for i := 0; i < 1000; i++ { + _, err := re.FindStringMatch("[10000] [Dec 15, 2012 1:42:43 AM] com.dev.log.LoggingExample main") + if err != nil { + log.Printf("timeout") + t.Fatalf("Expecting no error, got: '%v' on iteration %v", err, i) + } + } +}