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

ankur22 · 2022-09-21T09:21:22Z

Commit tested against: 8b52a02 (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.

The text was updated successfully, but these errors were encountered:

inancgumus · 2022-09-21T10:01:09Z

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 · 2022-09-21T10:18:05Z

removing the debug: false fixed it for me

Updates #542

mstoykov · 2022-10-11T07:15:53Z

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

Updates #542

ankur22 · 2022-10-11T08:47:25Z

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 #578.

mstoykov · 2022-10-13T15:56:30Z

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 · 2023-02-28T11:40:01Z

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

ankur22 added the bug Something isn't working label Sep 21, 2022

mstoykov added a commit that referenced this issue Oct 11, 2022

Fix what seems like an obvious logical error

08f4aad

Updates #542

mstoykov mentioned this issue Oct 11, 2022

Fix onLoadingFinished reqFromParent nil check #579

Merged

mstoykov added a commit that referenced this issue Oct 11, 2022

Fix what seems like an obvious logical error

1114144

Updates #542

mstoykov mentioned this issue Oct 13, 2022

Fix races around touching state.Group outside of the event loop #589

Merged

inancgumus added this to the v0.7.0 milestone Nov 9, 2022

inancgumus removed this from the v0.7.0 milestone Feb 7, 2023

inancgumus closed this as completed Feb 28, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

ankur22 commented Sep 21, 2022

inancgumus commented Sep 21, 2022 •

edited

Loading

mstoykov commented Sep 21, 2022

mstoykov commented Oct 11, 2022

ankur22 commented Oct 11, 2022 •

edited

Loading

mstoykov commented Oct 13, 2022 •

edited

Loading

inancgumus commented Feb 28, 2023

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

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

Comments

ankur22 commented Sep 21, 2022

inancgumus commented Sep 21, 2022 • edited Loading

mstoykov commented Sep 21, 2022

mstoykov commented Oct 11, 2022

ankur22 commented Oct 11, 2022 • edited Loading

mstoykov commented Oct 13, 2022 • edited Loading

inancgumus commented Feb 28, 2023

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

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

inancgumus commented Sep 21, 2022 •

edited

Loading

ankur22 commented Oct 11, 2022 •

edited

Loading

mstoykov commented Oct 13, 2022 •

edited

Loading