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 <[email protected]>
Co-authored-by: hezhipeng.09 <[email protected]>
Co-authored-by: Doug Clark <[email protected]>

Author: 4 people

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
 }
 

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)
+		}
+	}
+}