Error when initializing networking: network.EnableParams

[inancgumus]

This CI job failed with the following error:

time="2022-10-05T10:59:35Z" level=error msg="communicating with browser: websocket: close 1006 (abnormal closure): unexpected EOF" category=cdp elapsed="0 ms" goroutine=25
panic: creating a new page: initializing networking *network.EnableParams: websocket: close 1006 (abnormal closure): unexpected EOF

goroutine 28 [running]:
go.k6.io/k6/js/common.Throw(0x13c8720?, {0x187c860?, 0xc0011b1c80?})
	go.k6.io/k6@v0.40.1-0.20220927101031-b5bbf7e96050/js/common/util.go:20 +0x55
github.com/grafana/xk6-browser/k6ext.Panic({0x188b3f8, 0xc0018c7fb0}, {0x1618379, 0x17}, {0xc002605c70?, 0x1, 0x1})
	github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/k6ext/panic.go:51 +0x2c6
github.com/grafana/xk6-browser/common.(*Browser).onAttachedToTarget(0xc0005ea300, 0xc001187f60)
	github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/browser.go:303 +0x6af
github.com/grafana/xk6-browser/common.(*Browser).initEvents.func1()
	github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/browser.go:195 +0x337
created by github.com/grafana/xk6-browser/common.(*Browser).initEvents
	github.com/grafana/xk6-browser@v0.0.0-00010101000000-000000000000/common/browser.go:180 +0x19e

Update: This started happening a lot. See: 1.

Maybe related: grafana/xk6-browser#558, #4242, #4419, grafana/xk6-browser#510 — evaluation needed.

[imiric]

Strange, I haven't seen that one before.

It seems to only happen in that PR, though. Are we sure that it's not caused by the Go or dependency updates? cc: @mstoykov

Have you guys seen it on main? Let's not be quick about creating issues if they only happen in a PR...

EDIT: Sorry, my bad, that first CI failure was on main. I was looking at this one from grafana/xk6-browser#565. It's worthy of an issue.

EDIT2: GitHub is currently having an incident that involves Actions. So I reiterate my sentiment to not be quick about creating issues that only happen in CI. 😅

[inancgumus]

This happened again, here. The Github action status is fine (green).

[imiric]

I don't trust githubstatus.com. It's been green many times before, while the service was obviously failing.

Let's wait a few days and if this is still an issue, consider reopening it.

[inancgumus]

This error happened again here.

[imiric]

This happened again here (macos-latest E2E test, for browser_on.js).

Does anyone think we should reopen this and look into it? I wouldn't be sure where to start, TBH, as this has only happened on CI so far.

Full CI log: 11_Run E2E tests.txt

And again on main: https://github.com/grafana/xk6-browser/actions/runs/3290656809/jobs/5423789093 . TestBrowserContextOptionsDefaultViewport also failed launching the browser.

[imiric]

I'm reopening this since it's become a recurring issue in CI, and I'm not sure it's GitHub related, or with any of our recent changes.

I see a similar error when stress testing the tests package in a VM, as far back as on v0.4.0:

initializing networking *network.EnableParams: context canceled

This doesn't fail the test suite, and it's logged as debug. Since it only happens when running the full suite and the logs are very noisy, it's difficult to tell in which test it actually happens. My guess would be that it's not related to any specific test, but could happen at any moment.

Eventually, the test suite does fail with:

panic: newPageInContext: canceled

goroutine 13775 [running]:
go.k6.io/k6/js/common.Throw(0x1a?, {0x1d3b7a0?, 0xc005020800})
        /root/xk6-browser/vendor/go.k6.io/k6/js/common/util.go:20 +0x79
github.com/grafana/xk6-browser/k6ext.Panic({0x1d49b78, 0xc005b4ba10}, {0x1af9115, 0x14}, {0xc00313dc40?, 0x1, 0x1})
        /root/xk6-browser/k6ext/panic.go:51 +0x418
github.com/grafana/xk6-browser/common.(*BrowserContext).NewPage(0xc005032840)
        /root/xk6-browser/common/browser_context.go:220 +0x1f9
github.com/grafana/xk6-browser/common.(*Browser).NewPage(0x431b30?, {0x0, 0x0})
        /root/xk6-browser/common/browser.go:496 +0x4e
github.com/grafana/xk6-browser/tests.TestWaitForFrameNavigationWithinDocument.func1.1()
        /root/xk6-browser/tests/frame_manager_test.go:40 +0xb1
go.k6.io/k6/js/eventloop.(*EventLoop).Start(0xc0052e4000, 0xc000c00a50)
        /root/xk6-browser/vendor/go.k6.io/k6/js/eventloop/eventloop.go:171 +0x27b
github.com/grafana/xk6-browser/tests.(*testBrowser).await(0xc000c00a00, 0xc004adeec0?)
        /root/xk6-browser/tests/test_browser.go:240 +0x8a
github.com/grafana/xk6-browser/tests.(*testBrowser).awaitWithTimeout.func1()
        /root/xk6-browser/tests/test_browser.go:249 +0x93
created by github.com/grafana/xk6-browser/tests.(*testBrowser).awaitWithTimeout
        /root/xk6-browser/tests/test_browser.go:247 +0x1b6

I think these two events are related, since BrowserContext.NewPage() sends the Target.createTarget command, after which we wait for the internal EventBrowserContextPage, which is emitted in Browser.onAttachedToTarget(), which calls NewPage(), which initializes the FrameSession and ultimately the NetworkManager where we see the iniitalizing network error... 🤯 But the context could be cancelled at any point during all of that, and we need to make sure that it's handled properly.

That's the theory, at least, I still have no idea of how to approach fixing this.

[imiric]

So I wasn't able to find the root cause of this... 😞

In some cases I've seen premature browser closures when this error is logged, which I suspect might be from the test cleanup being done too early. But that wouldn't explain why it also sometimes happens in E2E tests, which I haven't been able to replicate at all (in a VM or natively).

Stress testing the tests package (using this script) is the only way I've been able to reproduce this, but with trace logs enabled it's difficult to see which test the logs belong to. And running the full suite often fails with different errors, which are also unclear and a timesink to dig into.

So I'll move on to other issues for now, and if someone wants to take a look at this, please do.