The "complex" test fails on the very first step (`page.goto`)

[ankur22]

Commit tested against: 8b52a028840dbaa5ae61937766d473fcde9fca10 (pre-v0.6.0). Test script: "complex" test.

The "complex" test does not work against the version of xk6-browser mentioned above. It navigates to the site, but seems to fail to get passed the waitUntil: 'networkidle' stage of the page.goto action.

In a randomly chosen tagged version of xk6-browser (v0.4.0) it is able to consistently get through most of the "complex" test, so well passed the page.goto initial step.

[inancgumus]

There is regression somewhere, and git bisect can help even though the complex test script is somewhat flaky. Weirdly, we cannot even pass the page.goto stage with the script. I vote to make this a high priority after dealing with the current high-priority issues.

PS: The script was working after fixing #169. Even though that's an old PR, it possibly can give us clues about where to look next.

[mstoykov]

removing the debug: false fixed it for me

[mstoykov]

removing the debug: false fixed it for me

This is no longer true with the latest version - I first hit what I fixed in #579 and then I get

go.k6.io/k6/js/common.Throw(0x1394a00?, {0x18b3ca0?, 0xc0012c0120?})
        go.k6.io/[email protected]/js/common/util.go:20 +0x55
github.com/grafana/xk6-browser/k6ext.Panic({0x18c2b68, 0xc002384e40}, {0x1600224, 0x27}, {0xc003491df8, 0x2, 0x2})
        github.com/grafana/[email protected]/k6ext/panic.go:51 +0x2d7
github.com/grafana/xk6-browser/common.(*FrameSession).onFrameNavigated(0xc001973c30, 0xc000af66c0, 0x20?)
        github.com/grafana/[email protected]/common/frame_session.go:650 +0x2e9
github.com/grafana/xk6-browser/common.(*FrameSession).initEvents.func1()
        github.com/grafana/[email protected]/common/frame_session.go:257 +0x694
created by github.com/grafana/xk6-browser/common.(*FrameSession).initEvents
        github.com/grafana/[email protected]/common/frame_session.go:228 +0x1ab

Which seems like a case where we should log or return an error, but instead we panic. But no obvious logical error as in #579

[ankur22]

Interesting! I didn't come across this when I was running this locally. Instead I was facing the issue where waitUntil: 'networkidle' wasn't being handled correctly. The reason for that is the event fires (lifecycle event with networkIdle) before the FrameManager registers to the event loop. I'm currently looking to fix it in https://github.com/grafana/xk6-browser/pull/578.

[mstoykov]

With the latest main and also with the commit from before the goto async support I get the following race

==================
WARNING: DATA RACE, 1/1 VUs, 0 complete and 0 interrupted iterations
Write at 0x00c002d32870 by goroutine 80:---------] 1 VUs  00m05.0s/10m0s  0/1 iters, 1 per VU
  runtime.mapdelete_faststr()
      runtime/map_faststr.go:301 +0x0
  github.com/grafana/xk6-browser/common.(*FrameManager).requestFinished()
      github.com/grafana/[email protected]/common/frame_manager.go:485 +0x1e9
  github.com/grafana/xk6-browser/common.(*NetworkManager).onLoadingFinished()
      github.com/grafana/[email protected]/common/network_manager.go:409 +0x664
  github.com/grafana/xk6-browser/common.(*NetworkManager).handleEvents()
      github.com/grafana/[email protected]/common/network_manager.go:352 +0x1ce
  github.com/grafana/xk6-browser/common.(*NetworkManager).initEvents.func1()
      github.com/grafana/[email protected]/common/network_manager.go:333 +0x3e

Previous write at 0x00c002d32870 by goroutine 1780:
  runtime.mapdelete_faststr()
      runtime/map_faststr.go:301 +0x0
  github.com/grafana/xk6-browser/common.(*FrameManager).requestFinished()
      github.com/grafana/[email protected]/common/frame_manager.go:485 +0x1e9
  github.com/grafana/xk6-browser/common.(*NetworkManager).onLoadingFinished()
      github.com/grafana/[email protected]/common/network_manager.go:409 +0x664
  github.com/grafana/xk6-browser/common.(*NetworkManager).handleEvents()
      github.com/grafana/[email protected]/common/network_manager.go:352 +0x1ce
  github.com/grafana/xk6-browser/common.(*NetworkManager).initEvents.func1()
      github.com/grafana/[email protected]/common/network_manager.go:333 +0x3e

Goroutine 80 (running) created at:
  github.com/grafana/xk6-browser/common.(*NetworkManager).initEvents()
      github.com/grafana/[email protected]/common/network_manager.go:332 +0x34e
  github.com/grafana/xk6-browser/common.NewNetworkManager()
      github.com/grafana/[email protected]/common/network_manager.go:107 +0x57d
  github.com/grafana/xk6-browser/common.NewFrameSession()
      github.com/grafana/[email protected]/common/frame_session.go:120 +0x73a
  github.com/grafana/xk6-browser/common.NewPage()
      github.com/grafana/[email protected]/common/page.go:139 +0xc18
  github.com/grafana/xk6-browser/common.(*Browser).onAttachedToTarget()
      github.com/grafana/[email protected]/common/browser.go:294 +0xadb
  github.com/grafana/xk6-browser/common.(*Browser).initEvents.func1()
      github.com/grafana/[email protected]/common/browser.go:195 +0x424

Goroutine 1780 (running) created at:
  github.com/grafana/xk6-browser/common.(*NetworkManager).initEvents()
      github.com/grafana/[email protected]/common/network_manager.go:332 +0x34e
  github.com/grafana/xk6-browser/common.NewNetworkManager()
      github.com/grafana/[email protected]/common/network_manager.go:107 +0x57d
  github.com/grafana/xk6-browser/common.NewFrameSession()
      github.com/grafana/[email protected]/common/frame_session.go:120 +0x73a
  github.com/grafana/xk6-browser/common.(*FrameSession).attachIFrameToTarget()
      github.com/grafana/[email protected]/common/frame_session.go:843 +0x266
  github.com/grafana/xk6-browser/common.(*FrameSession).onAttachedToTarget()
      github.com/grafana/[email protected]/common/frame_session.go:776 +0x476
  github.com/grafana/xk6-browser/common.(*FrameSession).initEvents.func1()
      github.com/grafana/[email protected]/common/frame_session.go:279 +0x608
==================

Which might be goto related

but the thing that kills the test for me is

panic: handling frameNavigated event to "https://fledge-usa.creativecdn.com/fledge-igmembership?ntk=KEkVm9eNgoZkFBlB_Mqexdx7hBrOVavM6XVKiQwxMH1Oc3uyi6pc6SjOxbUjfWRqlzT2sUrnzGM9FjSwkllzNA": we either navigate top level or have old version of the navigated frame
running (00m05.3s), 1/1 VUs, 0 complete and 0 interrupted iterations
goroutine 2424 [running]:------------------------] 1 VUs  00m05.3s/10m0s  0/1 iters, 1 per VU
go.k6.io/k6/js/common.Throw(0xfd?, {0x233ae00?, 0xc0017eab00})
        go.k6.io/[email protected]/js/common/util.go:20 +0x79
github.com/grafana/xk6-browser/k6ext.Panic({0x2349f48, 0xc002d32120}, {0x1fd43a0, 0x27}, {0xc0032b7d58, 0x2, 0x2})
        github.com/grafana/[email protected]/k6ext/panic.go:51 +0x418
github.com/grafana/xk6-browser/common.(*FrameSession).onFrameNavigated(0xc000cfe6e0, 0xc002245d40, 0x20?)
        github.com/grafana/[email protected]/common/frame_session.go:652 +0x4ba
github.com/grafana/xk6-browser/common.(*FrameSession).initEvents.func1()
        github.com/grafana/[email protected]/common/frame_session.go:257 +0x918
created by github.com/grafana/xk6-browser/common.(*FrameSession).initEvents
        github.com/grafana/[email protected]/common/frame_session.go:228 +0x33f

which seems to be one more case of k6ext.Panic being used not on the event loop which leads to a panic and stopping of xk6-browser instead to an exception :(

edit: If I just make it not panic but log the error, I do get a lot further in the test and IMO either dies because of races with loading and finding elements or because the site under test has changed ... not certain

[inancgumus]

It is not failing on the very first step :yay: