`page.evaluate()` is flaky

imiric commented 3 years ago

Testing examples/evaluate.js on 1e901b4 and Linux Chromium 93.0.4577.82 fails intermittently.

When running k6 run examples/evaluate.js it either works correctly and outputs:

INFO[0001] {"width":1280,"height":720,"deviceScaleFactor":1}  source=console

Or it fails with a VU panic:

ERRO[0002] panic: runtime error: invalid memory address or nil pointer dereference
goroutine 80 [running]:
runtime/debug.Stack(0xc00309c288, 0xc00309c2a8, 0xc00309c278)
        runtime/debug/stack.go:24 +0x9f
go.k6.io/k6/js.(*VU).runFn.func1(0xc002f71e00, 0xc00309da50)
        go.k6.io/k6@v0.34.1/js/runner.go:737 +0x1e5
panic(0x12ece40, 0x2197970)
        runtime/panic.go:965 +0x1b9
github.com/dop251/goja.AssertFunction.func1.1(0xc00309d948)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/runtime.go:2154 +0x95
panic(0x12ece40, 0x2197970)
        runtime/panic.go:965 +0x1b9
github.com/dop251/goja.(*vm).try.func1(0xc001623900, 0x0, 0xc00309d7f8, 0x0, 0x0, 0x0, 0xc00309d890)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/vm.go:511 +0xc1d
panic(0x12ece40, 0x2197970)
        runtime/panic.go:965 +0x1b9
github.com/grafana/xk6-browser/common.(*ExecutionContext).evaluate(0x0, 0x173fa88, 0xc002feb200, 0x14a0101, 0x1750e78, 0xc003209110, 0x21e6398, 0x0, 0x0, 0x40, ...)
        github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/execution_context.go:150 +0x2dd
github.com/grafana/xk6-browser/common.(*ExecutionContext).Evaluate(...)
        github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/execution_context.go:199
github.com/grafana/xk6-browser/common.(*Frame).Evaluate(0xc00320e000, 0x1750e78, 0xc003209110, 0x21e6398, 0x0, 0x0, 0x4e9d0a, 0xc0032091d0)
        github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/frame.go:589 +0x105
github.com/grafana/xk6-browser/common.(*Page).Evaluate(0xc0030ab440, 0x1750e78, 0xc003209110, 0x21e6398, 0x0, 0x0, 0x0, 0x0)
        github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/page.go:361 +0x68
reflect.Value.call(0x12ba100, 0xc000e58400, 0x13, 0x14a8a43, 0x4, 0xc0032091a0, 0x2, 0x1, 0xc00309d270, 0x40e0f8, ...)
        reflect/value.go:476 +0x8e7
reflect.Value.Call(0x12ba100, 0xc000e58400, 0x13, 0xc00220c708, 0x1, 0x1, 0xc0005f0240, 0x0, 0x0)
        reflect/value.go:337 +0xb9
github.com/dop251/goja.(*Runtime).wrapReflectFunc.func1(0x1750e78, 0xc000569410, 0xc001677190, 0x1, 0x7, 0x1751338, 0xc003204e30)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/runtime.go:1755 +0x3be
github.com/dop251/goja.(*vm)._nativeCall(0xc001623900, 0xc003236140, 0x1)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/vm.go:2649 +0x285
github.com/dop251/goja.call.exec(0x1, 0xc001623900)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/vm.go:2621 +0x907
github.com/dop251/goja.(*vm).run(0xc001623900)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/vm.go:401 +0x94
github.com/dop251/goja.(*baseJsFuncObject)._call(0xc002fba000, 0x1751760, 0x21e5fc0, 0xc002fec630, 0x1, 0x1, 0x0, 0x0, 0x1751760, 0x21e5fc0, ...)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/func.go:172 +0x209
github.com/dop251/goja.(*funcObject).call(...)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/func.go:180
github.com/dop251/goja.(*funcObject).Call(0xc002fba000, 0x1751760, 0x21e5fc0, 0xc002fec630, 0x1, 0x1, 0x659cb0632528eac1, 0x0)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/func.go:140 +0xa8
github.com/dop251/goja.AssertFunction.func1.2()
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/runtime.go:2159 +0x96
github.com/dop251/goja.(*vm).try(0xc001623900, 0xc002ff78b0, 0x0)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/vm.go:517 +0x188
github.com/dop251/goja.AssertFunction.func1(0x1751760, 0x21e5fc0, 0xc002fec630, 0x1, 0x1, 0x0, 0x0, 0x0, 0x0)
        github.com/dop251/goja@v0.0.0-20210912140721-ac5354e9a820/runtime.go:2158 +0x10b
go.k6.io/k6/js.(*VU).runFn(0xc002f71e00, 0x173fa88, 0xc002feaf00, 0x128db01, 0xc0021b9638, 0xc002fec630, 0x1, 0x1, 0x0, 0x0, ...)
        go.k6.io/k6@v0.34.1/js/runner.go:742 +0x154
go.k6.io/k6/js.(*ActiveVU).RunOnce(0xc000e4b280, 0x0, 0x0)
        go.k6.io/k6@v0.34.1/js/runner.go:693 +0x414
go.k6.io/k6/lib/executor.getIterationRunner.func1(0x173fa88, 0xc002feac60, 0x1728600, 0xc000e4b280, 0xc002fec580)
        go.k6.io/k6@v0.34.1/lib/executor/helpers.go:88 +0x5e
go.k6.io/k6/lib/executor.PerVUIterations.Run.func3(0x1733180, 0xc002f71e00)
        go.k6.io/k6@v0.34.1/lib/executor/per_vu_iterations.go:236 +0x3dc
created by go.k6.io/k6/lib/executor.PerVUIterations.Run
        go.k6.io/k6@v0.34.1/lib/executor/per_vu_iterations.go:249 +0xb6a

Goja stack:
native
ERRO[0002] a panic occurred in VU code but was caught: runtime error: invalid memory address or nil pointer dereference  executor=per-vu-iterations scenario=default

Or with a null clientWidth TypeError:

ERRO[0001] unable to evaluate expression: exception "Uncaught" (2:44): TypeError: Cannot read properties of null (reading 'clientWidth')
    at __xk6_browser_evaluation_script__:3:45
default at reflect.methodValueCall (native)
        at file:///home/ivan/Projects/grafana/xk6-browser/examples/evaluate.js:8:24(33)  executor=per-vu-iterations scenario=default source=stacktrace

imiric commented 3 years ago

I looked into this today, but didn't have time to fix it properly. I'll describe the issue here in case someone else wants to pick it up, or for my own reference when I'm back after next week.

So here's what's happening:

*ExecutionContext is nil here (called on page.evaluate()): https://github.com/grafana/xk6-browser/blob/1e901b4a803bb932a4efe60380d85ee3dec9209f/common/execution_context.go#L150
This is because Frame.nullContexts() is called when handling the ExecutionContextsCleared event: https://github.com/grafana/xk6-browser/blob/1e901b4a803bb932a4efe60380d85ee3dec9209f/common/frame_session.go#L189-L190
This event is sent whenever the frame is navigated, which happens when page.goto() is called in the script.

So it's a race condition between page.evaluate() and page.goto(), and we should make sure that the ExecutionContext is created in FrameSession.onExecutionContextCreated() before Frame.Evaluate() is called.

A signaling channel might work to indicate that the page/frame is loading, and all methods that depend on ExecutionContext should wait until loading is done.

Although in general I'm not fond of the nulling of contexts when ExecutionContextsCleared is received. Maybe we could use a safer alternative?

robingustafsson commented 3 years ago

Thanks @imiric. I looked into this issue a bit now in the evening as well. Just created a PR: https://github.com/grafana/xk6-browser/pull/21

grafana / xk6-browser

`page.evaluate()` is flaky #19