`MatchTimeout` setting is not respected

[rexagod]

👋🏼 Hello, thank you for your work here!

I think there's something up with regexp2.MatchTimeout. I should mention that I've read the section on Catastrophic Backtracking and Timeouts but that doesn't seem to explain why the following takes increasingly longer time to run as I increase the string length, rather than timing out after an interval (with reasonable buffer).

For the following snippet, where N:

func TestCatastrophicBacktrackTimeout(t *testing.T) {
	r, err := regexp.Compile("(.+)*\\?", 0)
	if err != nil {
		t.Fatal(err)
	}
	var exp = "Lorem ipsum dolor sit amet, consectetur adipiscing elit?"
	for range N {
		exp += exp
	}

	timeout := time.Second
	t.Run(fmt.Sprint(timeout), func(t *testing.T) {
		r.MatchTimeout = timeout
		start := time.Now()
		m, err := r.FindStringMatch(exp)
		elapsed := time.Since(start)
		t.Log("m == nil", m == nil)
		t.Log("err == nil", err == nil)
		t.Log("elapsed", elapsed)
	})
}

is 10 (elapsed is less than timeout):

┌[rexagod@fedora] [/dev/pts/0] [2594 ⚡] 
└[~/repositories/work/kube-state-metrics]> go test -v -timeout 5s -run ^TestCatastrophicBacktrackTimeout$ k8s.io/kube-state-metrics/v2/pkg/allowdenylist
zsh: correct 'test' to 'tests' [nyae]? n
=== RUN   TestCatastrophicBacktrackTimeout
=== RUN   TestCatastrophicBacktrackTimeout/1s
    allowdenylist_test.go:311: m == nil false
    allowdenylist_test.go:312: err == nil true
    allowdenylist_test.go:313: elapsed 555.744µs
--- PASS: TestCatastrophicBacktrackTimeout (0.00s)
    --- PASS: TestCatastrophicBacktrackTimeout/1s (0.00s)
PASS
ok      k8s.io/kube-state-metrics/v2/pkg/allowdenylist  0.007s

is 22 (elapsed is more than timeout):

┌[rexagod@fedora] [/dev/pts/0] [2594 ⚡] [1]
└[~/repositories/work/kube-state-metrics]> go test -v -timeout 5s -run ^TestCatastrophicBacktrackTimeout$ k8s.io/kube-state-metrics/v2/pkg/allowdenylist
zsh: correct 'test' to 'tests' [nyae]? n
=== RUN   TestCatastrophicBacktrackTimeout
=== RUN   TestCatastrophicBacktrackTimeout/1s
    allowdenylist_test.go:311: m == nil false
    allowdenylist_test.go:312: err == nil true
    allowdenylist_test.go:313: elapsed 2.92970801s
--- PASS: TestCatastrophicBacktrackTimeout (3.75s)
    --- PASS: TestCatastrophicBacktrackTimeout/1s (2.93s)
PASS
ok      k8s.io/kube-state-metrics/v2/pkg/allowdenylist  3.911s

is 25 (elapsed is more than test timeout):

┌[rexagod@fedora] [/dev/pts/0] [2594 ⚡] 
└[~/repositories/work/kube-state-metrics]> go test -v -timeout 5s -run ^TestCatastrophicBacktrackTimeout$ k8s.io/kube-state-metrics/v2/pkg/allowdenylist
zsh: correct 'test' to 'tests' [nyae]? n
=== RUN   TestCatastrophicBacktrackTimeout
panic: test timed out after 5s
        running tests:
                TestCatastrophicBacktrackTimeout (5s)

goroutine 34 [running]:
testing.(*M).startAlarm.func1()
        /home/rexagod/.g/go/src/testing/testing.go:2373 +0x385
created by time.goFunc
        /home/rexagod/.g/go/src/time/sleep.go:215 +0x2d

goroutine 1 [chan receive]:
testing.(*T).Run(0xc0000aeea0, {0x799596?, 0x0?}, 0x7c1348)
        /home/rexagod/.g/go/src/testing/testing.go:1751 +0x3ab
testing.runTests.func1(0xc0000aeea0)
        /home/rexagod/.g/go/src/testing/testing.go:2168 +0x37
testing.tRunner(0xc0000aeea0, 0xc0000cfc70)
        /home/rexagod/.g/go/src/testing/testing.go:1690 +0xf4
testing.runTests(0xc000012408, {0xa54180, 0x6, 0x6}, {0x470a70?, 0x4706da?, 0xa5d600?})
        /home/rexagod/.g/go/src/testing/testing.go:2166 +0x43d
testing.(*M).Run(0xc00018b4a0)
        /home/rexagod/.g/go/src/testing/testing.go:2034 +0x64a
main.main()
        _testmain.go:55 +0x9b

goroutine 8 [running]:
        goroutine running on other thread; stack unavailable
created by testing.(*T).Run in goroutine 1
        /home/rexagod/.g/go/src/testing/testing.go:1743 +0x390
FAIL    k8s.io/kube-state-metrics/v2/pkg/allowdenylist  5.408s
FAIL

I'm trying to replace Go's builtin library in kubernetes/kube-state-metrics#2616 to allow for lookarounds, so a degree of confidence that exponential operations get cut off is needed, thanks!

[dlclark]

This isn't an example of catastrophic backtracking -- sending in a 35MB string on my laptop takes ~33.958µs to match and is only marginally impacted by the length of the string. I suspect the walk clock time isn't coming from the Regex engine steps (which is the only place the timeout is checked), but rather something like the conversion of a long string into a slice of runes on your computer. You can confirm that here: https://regex101.com/r/n7GIhH/2 and seeing that the number of steps (1 match, 12 steps) doesn't increase as long as the question mark is at the end of the test string. However, if you move the question mark back 1 character from the end now it's 24 steps, 2 chars back is 48 steps, 3 is 96 steps, etc. Now that's catastrophic backtracking!

So to test catastrophic backtracking and timeouts you'll need to switch your match string to exclude the question mark.

var exp = "Lorem ipsum dolor sit amet, consectetur adipiscing elit"
exp = strings.Repeat(exp, 2^10)

This should hit a timeout after about 1 second and return an error (timeout is the only error that can be returned from a FindStringMatch).

[rexagod]

I suspect the walk clock time isn't coming from the Regex engine steps (which is the only place the timeout is checked), but rather something like the conversion of a long string into a slice of runes on your computer.

Is that intentional? The interpretation of the input string, handled by this library, is somehow being influenced by the length of the string, which tends to take up more time as it grows, irrespective of the defined match timeout.

[rexagod]

To answer myself, apparently it is. This behavior is also apparent in the built-in regexp library.

runtime.stringtoslicerune
/home/rexagod/.g/go/src/runtime/string.go

  Total:       510ms      510ms (flat, cum) 31.29%
    187            .          .            
    188            .          .           func stringtoslicerune(buf *[tmpStringBufSize]rune, s string) []rune { 
    189            .          .           	// two passes. 
    190            .          .           	// unlike slicerunetostring, no race because strings are immutable. 
    191            .          .           	n := 0 
    192         60ms       60ms           	for range s { 
    193            .          .           		n++ 
    194            .          .           	} 
    195            .          .            
    196            .          .           	var a []rune 
    197            .          .           	if buf != nil && n <= len(buf) { 
    198            .          .           		*buf = [tmpStringBufSize]rune{} 
    199            .          .           		a = buf[:n] 
    200            .          .           	} else { 
    201            .          .           		a = rawruneslice(n) 
    202            .          .           	} 
    203            .          .            
    204            .          .           	n = 0 
    205         70ms       70ms           	for _, r := range s { 
    206        380ms      380ms           		a[n] = r 
    207            .          .           		n++ 
    208            .          .           	} 
    209            .          .           	return a 
    210            .          .           } 
    211            .          .