Fix/125 cannot create frame session (context canceled)

[inancgumus]

Update (2021-12-23)

I added a few more bug fixes after receiving another script that fails with this error (from a user in our community). Now we no longer try to attach a frame or worker if the browser is already closed. These commits solved the user's issues: 77949eb and a3aea00.

Update (2021-12-20)

This PR only focuses on fixing and gracefully handling "cannot create frame session" problem in #125 with this afe4550 commit. Later on, within other commits, it fixes related data race issues, makes some refactorings, and cleans things up.

The problem was about the propagation of #49 into this one. We throw an error when we cannot find a context with a given id while a new FrameSession is trying to boot up. So the extension is already in a terminating state but FrameSession doesn't know about it. This PR prevents FrameSession to rethrow if the context was canceled and instead log.

However, it's not focusing on fixing #49 as it's a whole world of a different problem, and we don't have a good fix for it yet (see: 6382e42 and d4e3900).

First Update

In this PR:

• I changed the handling of execution contexts.
• Fixed most of the data races.
• Refactored some parts of the code.
• Fixed cannot create frame session (context canceled) problem.
• Skipped creating frame sessions for frames with empty URLs (such as about:blank)

With these, this PR seemed to fix the problems to some extent:

• Tom's script was failing on the 2nd group before, clickBusinessCards—16% of the whole script
• Now it works until the customerReviewed group—%67 of the whole script

I discovered some reasons why it still fails.

I noticed we receive deprecated events like:

• Page.frameScheduledNavigation
• Page.frameClearedScheduledNavigation

So, I believe the last steps don't work because of these and we can create new issues for handling them. So I let them return as errors:

ERRO[0094] unknown command or event "Page.frameScheduledNavigation"
ERRO[0094] unknown command or event "Page.frameClearedScheduledNavigation"

---

Related: #19

[inancgumus]

@robingustafsson, do you have any idea why the session gets closed first:

Closed session ID: EBD975C5F3C41A8557C46D7AB3EFD06A

INFO[0005] sid=1241375EAFBAD72F5ED96C4053A617FE method="Network.getResponseBody"  category="\x1b[35mSession:Execute\x1b[0m" elapsed="0 ms" goroutine=44
INFO[0005] sid=1241375EAFBAD72F5ED96C4053A617FE method="Network.getResponseBody"  category="\x1b[35mSession:Execute:s.conn.send\x1b[0m" elapsed="0 ms" goroutine=44
INFO[0005] sid=1241375EAFBAD72F5ED96C4053A617FE cannot unmarshal: unknown command or event ""  category="\x1b[35mSession:readLoop:<-s.readCh\x1b[0m" elapsed="0 ms" goroutine=38

ERRO[0005] sid:EBD975C5F3C41A8557C46D7AB3EFD06A wsURL:"ws://127.0.0.1:60570/devtools/browser/7ba29ff7-6edb-48c7-a03e-95b3ce0e5941", closeSession  category="\x1b[35mConnection:recvLoop:EventDetachedFromTarget\x1b[0m" elapsed="0 ms" goroutine=68
ERRO[0005] sid=EBD975C5F3C41A8557C46D7AB3EFD06A wsURL=ws://127.0.0.1:60570/devtools/browser/7ba29ff7-6edb-48c7-a03e-95b3ce0e5941  category="\x1b[35mConnection:closeSession\x1b[0m" elapsed="0 ms" goroutine=68
INFO[0005] sid=EBD975C5F3C41A8557C46D7AB3EFD06A          category="\x1b[35mSession:close\x1b[0m" elapsed="0 ms" goroutine=68

And then, Page.addScriptToEvaluateOnNewDocument tries to inject the script to the closed session:

ERRO[0015] wsURL:"ws://127.0.0.1:60570/devtools/browser/7ba29ff7-6edb-48c7-a03e-95b3ce0e5941" sid:1241375EAFBAD72F5ED96C4053A617FE, msg err:Cannot find context with specified id (-32000)  category="\x1b[35mConnection:send\x1b[0m" elapsed="0 ms" goroutine=30
ERRO[0015] unable to evaluate expression: Cannot find context with specified id (-32000)
	at reflect.methodValueCall (native)
	at file:///Users/inanc/grafana/tom-12nov.js:78:26(15)
	at go.k6.io/k6/js/common.Bind.func1 (native)
	at clickBusinessCards (file:///Users/inanc/grafana/tom-12nov.js:74:17(17))
	at file:///Users/inanc/grafana/tom-12nov.js:44:21(8)  executor=per-vu-iterations scenario=default source=stacktrace
ERRO[0015] sid=EBD975C5F3C41A8557C46D7AB3EFD06A method="Page.addScriptToEvaluateOnNewDocument", returns  category="\x1b[35mSession:Execute:<-evCancelCtx.Done()\x1b[0m" elapsed="1 ms" goroutine=970
ERRO[0015] returning, ctx.Err: "context canceled"        category="\x1b[35mconnection:sendLoop\x1b[0m" elapsed="0 ms" goroutine=69
ERRO[0015] wsURL:"ws://127.0.0.1:60570/devtools/browser/7ba29ff7-6edb-48c7-a03e-95b3ce0e5941" sid:EBD975C5F3C41A8557C46D7AB3EFD06A err:context canceled  category="\x1b[35mConnection:send:<-c.ctx.Done()\x1b[0m" elapsed="0 ms" goroutine=47
INFO[0015] sid:EBD975C5F3C41A8557C46D7AB3EFD06A tid:AC46CC93BEE8796F78585F9692325947 err:unable to add script to evaluate for isolated world: context canceled  category="\x1b[35mNewFrameSession:initIsolatedWorld\x1b[0m" elapsed="0 ms" goroutine=47

Resulting in:
panic: cannot create frame session: unable to add script to evaluate for isolated world: context canceled

[robingustafsson]

Can't say for sure from just the those log lines you've posted.

The close call says that we received a EventDetachedFromTarget, what target did we detach from?

Regarding the resulting error, the only way to arrive at that error message unable to add script to evaluate for isolated world is when creating a new FrameSession for an iframe (well, besides the main frame session).

So could this be in relation to the destruction of an iframe at the same time as a new iframe is created perhaps and we handle that poorly right now? 🤔

[inancgumus]

Can't say for sure from just those log lines you've posted.

The close call says that we received a EventDetachedFromTarget, what target did we detach from?

@robingustafsson I’ll try to find out the target tomorrow and let you know. Thanks for pointing it out!

Regarding the resulting error, the only way to arrive at that error message unable to add script to evaluate for isolated world is when creating a new FrameSession for an iframe (well, besides the main frame session).

So could this be in relation to the destruction of an iframe at the same time as a new iframe is created perhaps and we handle that poorly right now? 🤔

Thanks! I read about the article you linked in the code about isolated contexts, and yeah, I was suspicious of an iframe handling issue too. I’ll first try to create a test (if not exists) if I can.

[inancgumus]

The close call says that we received a EventDetachedFromTarget, what target did we detach from?

@robingustafsson
Can you point me in the code where I should investigate next?

Weird thing:

• There is no IFrame on our site. So a new page loads a fresh new one.

What I did:

• I've enabled the targetID in session logs.
• The same targetID and sessionID are getting closed.
  • TargetID (tid): A3090F4ECB94747A6660763EA5A92D8B
  • SessionID (sid): C2EEAA73BF1B1ECE0FC2A188FA7A8E94
• Then we try to inject a script to a closed (detached) target.

INFO[0008] <- {"method":"Network.loadingFailed","params":{"requestId":"4352BADD39733710C3721B3C17C0F012","timestamp":107412.566322,"type":"Document","errorText":"net::ERR_ABORTED","canceled":true},"sessionId":"28234C8BA995F6FE6E9CDF4C01592852"}  category="cdp:recv" elapsed="2 ms" goroutine=65
INFO[0008] <- {"method":"Target.detachedFromTarget","params":{"sessionId":"C2EEAA73BF1B1ECE0FC2A188FA7A8E94","targetId":"A3090F4ECB94747A6660763EA5A92D8B"},"sessionId":"28234C8BA995F6FE6E9CDF4C01592852"}  category="cdp:recv" elapsed="0 ms" goroutine=65
INFO[0008] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid:A3090F4ECB94747A6660763EA5A92D8B wsURL:"ws://127.0.0.1:50119/devtools/browser/7a9081be-5e4e-4346-bf52-96e1a04c2cbe", closeSession  category="Connection:recvLoop:EventDetachedFromTarget" elapsed="0 ms" goroutine=65
INFO[0008] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid:A3090F4ECB94747A6660763EA5A92D8B wsURL:ws://127.0.0.1:50119/devtools/browser/7a9081be-5e4e-4346-bf52-96e1a04c2cbe  category="Connection:closeSession" elapsed="0 ms" goroutine=65
INFO[0008] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid:A3090F4ECB94747A6660763EA5A92D8B  category="Session:close" elapsed="0 ms" goroutine=65
INFO[0008] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid:A3090F4ECB94747A6660763EA5A92D8B  category="Session:readLoop:<-s.done" elapsed="1 ms" goroutine=1030
INFO[0008] <- {"method":"Page.frameStoppedLoading","params":{"frameId":"A3090F4ECB94747A6660763EA5A92D8B"},"sessionId":"28234C8BA995F6FE6E9CDF4C01592852"}  category="cdp:recv" elapsed="3 ms" goroutine=65
INFO[0008] <- {"method":"Page.frameDetached","params":{"frameId":"A3090F4ECB94747A6660763EA5A92D8B","reason":"remove"},"sessionId":"28234C8BA995F6FE6E9CDF4C01592852"}  category="cdp:recv" elapsed="11 ms" goroutine=65

...

INFO[0042] sid:28234C8BA995F6FE6E9CDF4C01592852 stid:2AC2D468203DA753654C16F69409EE55 ptid:2AC2D468203DA753654C16F69409EE55 selector:"//a[text()='Browse designs']"  category="Page:WaitForSelector" elapsed="563 ms" goroutine=49
INFO[0042] sid:28234C8BA995F6FE6E9CDF4C01592852 tid:2AC2D468203DA753654C16F69409EE55 method:"Runtime.callFunctionOn"  category="Session:Execute" elapsed="0 ms" goroutine=49
INFO[0042] sid:28234C8BA995F6FE6E9CDF4C01592852 tid:2AC2D468203DA753654C16F69409EE55 method:"Runtime.callFunctionOn"  category="Session:Execute:s.conn.send" elapsed="0 ms" goroutine=49
INFO[0042] -> {"id":82,"sessionId":"28234C8BA995F6FE6E9CDF4C01592852","method":"Runtime.callFunctionOn","params":{"functionDeclaration":"\n\t\t(injected, selector, scope, strict, state, timeout, ...args) =\u003e {\n\t\t\treturn injected.waitForSelector(selector, scope, strict, state, 'raf', timeout, ...args);\n\t\t}\n\t\n//# sourceURL=__xk6_browser_evaluation_script__\n","arguments":[{"objectId":"2562850493479125420.3.2"},{"value":{"selector":"//a[text()='Browse designs']","parts":[{"name":"xpath","body":"//a[text()='Browse designs']"}],"capture":null}},{"objectId":"2562850493479125420.3.1"},{"value":false},{"value":"visible"},{"value":30000}],"userGesture":true,"awaitPromise":true,"executionContextId":3}}  category="cdp:send" elapsed="0 ms" goroutine=66
INFO[0042] <- {"id":82,"error":{"code":-32000,"message":"Cannot find context with specified id"},"sessionId":"28234C8BA995F6FE6E9CDF4C01592852"}  category="cdp:recv" elapsed="1 ms" goroutine=65
INFO[0042] sid:28234C8BA995F6FE6E9CDF4C01592852 tid:2AC2D468203DA753654C16F69409EE55 cannot unmarshal: unknown command or event ""  category="Session:readLoop:<-s.readCh" elapsed="0 ms" goroutine=55
INFO[0042] sid:28234C8BA995F6FE6E9CDF4C01592852 tid:2AC2D468203DA753654C16F69409EE55 wsURL:"ws://127.0.0.1:50119/devtools/browser/7a9081be-5e4e-4346-bf52-96e1a04c2cbe", msg err:Cannot find context with specified id (-32000)  category="Connection:send" elapsed="0 ms" goroutine=49
ERRO[0042] unable to evaluate expression: Cannot find context with specified id (-32000)
	at reflect.methodValueCall (native)
	at file:///Users/inanc/grafana/tom-12nov.js:78:26(15)
	at go.k6.io/k6/js/common.Bind.func1 (native)
	at clickBusinessCards (file:///Users/inanc/grafana/tom-12nov.js:74:17(17))
	at file:///Users/inanc/grafana/tom-12nov.js:44:21(8)  executor=per-vu-iterations scenario=default source=stacktrace
INFO[0042] returning, ctx.Err: "context canceled"        category="connection:sendLoop" elapsed="0 ms" goroutine=66

...

INFO[0042] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid: wsURL:"ws://127.0.0.1:50119/devtools/browser/7a9081be-5e4e-4346-bf52-96e1a04c2cbe" err:context canceled  category="Connection:send:<-c.ctx.Done()" elapsed="0 ms" goroutine=47
INFO[0042] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid:A3090F4ECB94747A6660763EA5A92D8B err:unable to add script to evaluate for isolated world: context canceled  category="NewFrameSession:initIsolatedWorld" elapsed="0 ms" goroutine=47
INFO[0042] sid:28234C8BA995F6FE6E9CDF4C01592852 tid:2AC2D468203DA753654C16F69409EE55, returns  category="NewFrameSession:initEvents:go" elapsed="0 ms" goroutine=47
INFO[0042] sid:C2EEAA73BF1B1ECE0FC2A188FA7A8E94 tid:A3090F4ECB94747A6660763EA5A92D8B method:"Page.addScriptToEvaluateOnNewDocument", returns  category="Session:Execute:<-evCancelCtx.Done()" elapsed="0 ms" goroutine=1053
panic: cannot create frame session: unable to add script to evaluate for isolated world: context canceled

[inancgumus]

I fixed the problem, but I couldn't write a unit test because of the dependencies, and I didn't want to use a mocking framework either. So, I'll go with the integration test route.

[robingustafsson]

Looks mostly good, great that you fix all my go noob mistakes (make() etc.) 🙌😅

You mention two deprecated events, afaict Playwright doesn't handle these events either so should not be necessary to support Tom's script. I'd suggest running the equivalent of Tom's script in Playwright (I did that a lot with other scripts, analyzing the CDP traffic differences with xk6-browser).

[imiric]

Nice work! This does indeed work much better with the Vistaprint script. It's a shame it's difficult to add a test for this, as we could really use some. Maybe some smaller unit tests for specific method changes could be added?

Although I'm not sure it fixes the Cannot find context with specified id issue, since it failed for me with that error:

DEBU[0106] sid:85A2399926F5DB8BFC14DD8BB958EE64 tid:CA8F61C073936905D509C09E1BDA2141 wsURL:"ws://127.0.0.1:33215/devtools/browser/e750ffc1-e59e-4dd6-8e2c-5808bc23e6bb", msg err:Cannot find context with specified id (-32000)  category="Connection:send" elapsed="0 ms" goroutine=117
ERRO[0106] unable to evaluate expression: Cannot find context with specified id (-32000)
running at reflect.methodValueCall (native)
default at file:///home/ivan/Downloads/tom-12nov-original.js:198:26(9)
        at go.k6.io/k6/js/common.Bind.func1 (native)
        at customerReviewed (file:///home/ivan/Downloads/tom-12nov-original.js:195:17(34))
        at file:///home/ivan/Downloads/tom-12nov-original.js:23:19(26)  executor=per-vu-iterations scenario=default source=stacktrace

I'll make another pass or two of this soon, just left a few comments and suggestions for now.

Also, please try to leave large logging changes for separate PRs, since they clutter the purpose of a "fix" PR. Refactorings are mostly fine if they're relevant to the fix, but otherwise those also belong in separate PRs. I mostly review commit by commit anyway, but it's difficult to see the final picture if the code is changed in the final diff.

[imiric]

Nicely done, this works much better than on main from my tests.

Just left some minor things and nitpicks.

[imiric]

Here too we could use a nil check.

Since this is commonly used, let's add a Frame.getContext(world) method, and Frame.hasContext(world) could call it.

[inancgumus]

Thanks. Yeah, but we'll still need to check for nil and type the same errors. I'm not sure what benefit getContext will provide us.

[imiric]

I'm not sure what benefit getContext will provide us.

Encapsulate the usage of f.executionContextMu. But yeah, we'd still need to check for nil.

This is not a blocker for me, just a suggestion.

[imiric]

LGTM. It seems we hit #161 in CI.

Were you able to reproduce the issues reported on the forum? It would be great if we could add E2E tests for them in a follow-up PR, and probably do the E2E/example tests split at that point as well, which Robin suggested in a PR a few weeks ago.

[inancgumus]

😒 Any ideas on reproducing these errors in an E2E test without using an external website? I’d appreciate your help because I couldn’t reproduce these problems without using external websites.

Were you able to reproduce the issues reported on the forum?

Yes, I used the website the user tests on.

[imiric]

Any ideas on reproducing these errors in an E2E test without using an external website?

Ah, it's the same situation as with Vistaprint. 😞 I hoped some of these could be easily replicated.

We'd need to spend time reverse engineering each site and building a minimal test case that reproduced it, which would vary in complexity/effort.

Alternatively, we could try doing a WARC dump using something like ArchiveBox, and then testing against that. It probably won't work for the more complex cases, but should for a lot of them, and it would avoid spending time on re-implementing each scenario ourselves. Or by using some recording/replay proxy, maybe warcprox, though it doesn't inspire much confidence. Actually, pywb has recording capabilities as well and seems more reliable. This seems like the way to go.

Failing all of the above, we could just test against the sites themselves, and configure CI to run these jobs on, say, PR merge and release only, to minimize any impact it could have on them. This could of course break at any point, and we'd have to keep updating the tests, so probably not worthwhile. 😄

[inancgumus]

Thanks 😄 It seems like a lot of dead-ends. I can try WARC dump and then keep cleaning up the dump until the error doesn't fade away. Maybe we can have a reproducible result and then create a Go/JS test for it 🤷 😄

[imiric]

It seems like a lot of dead-ends.

Not really, I think pywb looks promising. I'll create an issue.

[inancgumus]

So pywb -> Clean up the dump -> Go/Js test?

[imiric]

I don't think any cleanup would be needed, we could load the archive as is. But let's discuss that in the issue whenever we start looking into this. I can't say for sure what the process is without giving it a try. :)