Navigation timeout with device_emulation.js example

[imiric]

On current main (430e82c), Chromium 105.0.5195.102 and Linux, running xk6 run examples/device_emulation.js fails with:

ERRO[0030] navigating to "https://k6.io/": timed out after 30s
        at reflect.methodValueCall (native)
        at file:///home/ivan/Projects/grafana/xk6-browser/examples/device_emulation.js:17:30(40)
        at native  executor=per-vu-iterations scenario=default source=stacktrace

The relevant stack trace is:

goroutine 86 [select]:
github.com/grafana/xk6-browser/common.(*FrameManager).NavigateFrame(0xc00157c340, 0xc000660000, {0xc000bca7c0, 0xe}, {0x189c068, 0xc0027ddc20})
        github.com/grafana/[email protected]/common/frame_manager.go:671 +0xbd8
github.com/grafana/xk6-browser/common.(*Frame).Goto(0xc000660000, {0xc000bca7c0?, 0x15a5f5f?}, {0x189c068?, 0xc0027ddc20?})
        github.com/grafana/[email protected]/common/frame.go:1060 +0x45
github.com/grafana/xk6-browser/common.(*Page).Goto(0xc0027da420, {0xc000bca7c0, 0xe}, {0x189c068, 0xc0027ddc20})
        github.com/grafana/[email protected]/common/page.go:566 +0x142
reflect.Value.call({0x15823a0?, 0xc0027da420?, 0x7f1071cfb3c8?}, {0x159f313, 0x4}, {0xc0027ddc80, 0x2, 0xc001471040?})
        reflect/value.go:556 +0x845
reflect.Value.Call({0x15823a0?, 0xc0027da420?, 0xc0027ddc20?}, {0xc0027ddc80, 0x2, 0x2})
        reflect/value.go:339 +0xbf
github.com/dop251/goja.(*Runtime).wrapReflectFunc.func1({{0x189c068, 0xc0027dd470}, {0xc0017830a0, 0x2, 0x6}})
        github.com/dop251/[email protected]/runtime.go:1955 +0x1c5
github.com/dop251/goja.(*vm)._nativeCall(0xc001782300, 0xc002da4280, 0x2)
        github.com/dop251/[email protected]/vm.go:3231 +0x1c3
github.com/dop251/goja.call.exec(0x9?, 0xc001782300)
        github.com/dop251/[email protected]/vm.go:3203 +0x788
github.com/dop251/goja.(*vm).run(0xc001782300)
        github.com/dop251/[email protected]/vm.go:495 +0x8b
github.com/dop251/goja.(*baseJsFuncObject)._call(0xc001466180, {0xc002c15320?, 0x1, 0x5bc000583ba0?}, {0x0?, 0x0}, {0x189c950?, 0x2500420?})
        github.com/dop251/[email protected]/func.go:305 +0x3d8
github.com/dop251/goja.(*baseJsFuncObject).call(...)
        github.com/dop251/[email protected]/func.go:315
github.com/dop251/goja.(*baseJsFuncObject).Call(0xc000583bd8?, {{0x189c950, 0x2500420}, {0xc002c15320, 0x1, 0x1}})
        github.com/dop251/[email protected]/func.go:267 +0xa5
github.com/dop251/goja.AssertFunction.func1.1()
        github.com/dop251/[email protected]/runtime.go:2366 +0x74
github.com/dop251/goja.(*vm).try(0xc001782300, 0x400?)
        github.com/dop251/[email protected]/vm.go:634 +0x18a
github.com/dop251/goja.(*Runtime).runWrapped(0xc0026a6e00, 0x8?)
        github.com/dop251/[email protected]/runtime.go:2410 +0x7c
github.com/dop251/goja.AssertFunction.func1({0x189c950?, 0x2500420?}, {0xc002c15320?, 0x1?, 0x1?})
        github.com/dop251/[email protected]/runtime.go:2365 +0x92
go.k6.io/k6/js.(*VU).runFn.func1.1()
        go.k6.io/[email protected]/js/runner.go:766 +0x43
go.k6.io/k6/js/eventloop.(*EventLoop).Start(0xc0014580f0, 0xc002c1dcb0)
        go.k6.io/[email protected]/js/eventloop/eventloop.go:170 +0x177
go.k6.io/k6/js.(*VU).runFn.func1()
        go.k6.io/[email protected]/js/runner.go:765 +0xeb
go.k6.io/k6/js/common.RunWithPanicCatching({0x189da20?, 0xc0001f8fc0?}, 0x8?, 0x90?)
        go.k6.io/[email protected]/js/common/util.go:86 +0x87
go.k6.io/k6/js.(*VU).runFn(0xc001466240, {0x1892828, 0xc000bebf00}, 0x60?, 0xc00072c330, 0xc002c15310, {0xc002c15320, 0x1, 0x1})
        go.k6.io/[email protected]/js/runner.go:764 +0x29e
go.k6.io/k6/js.(*ActiveVU).RunOnce(0xc000bebec0)
        go.k6.io/[email protected]/js/runner.go:712 +0x412
go.k6.io/k6/lib/executor.getIterationRunner.func1({0x18928d0, 0xc002c1dad0}, {0x1887ec0?, 0xc000bebec0?})
        go.k6.io/[email protected]/lib/executor/helpers.go:124 +0x64
go.k6.io/k6/lib/executor.PerVUIterations.Run.func5({0x188e2e0, 0xc001466240})
        go.k6.io/[email protected]/lib/executor/per_vu_iterations.go:223 +0x40a
created by go.k6.io/k6/lib/executor.PerVUIterations.Run
        go.k6.io/[email protected]/lib/executor/per_vu_iterations.go:236 +0xc29

I.e. it's stuck waiting for the LifecycleEvent:

xk6-browser/common/frame_manager.go

Lines 671 to 675 in 430e82c

	select {
	case <-lifecycleEvtCh:
	case <-timeoutCtx.Done():
	handleTimeoutError(timeoutCtx.Err())
	}

It doesn't happen all the time, but a good 90% on my machine, so it's fairly reproducible. @ankur22 was also able to reproduce it on macOS. Note that it doesn't happen in CI, since failed checks still exit the process with code 0, but I actually haven't seen it fail the check either.

We thought we addressed all navigation race conditions in #480, but apparently not, or this is a recent regression. 😞

[imiric]

A couple more observations:

• It doesn't have anything to do with device emulation itself. You can comment that out and not pass any options to browser.newContext(), and it would still time out.
• It seems related to the site itself. E.g. this is the only example that loads https://k6.io/ instead of https://test.k6.io/. For test.k6.io, the test passes consistently.

[imiric]

This was fixed by #578! 🎉 I can no longer reproduce it on main :)