Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG] [PW 1.7.0] [WebKit] page.waitForSelector: Protocol error (Runtime.evaluate): The page has been closed. #4764

Closed
creage opened this issue Dec 18, 2020 · 8 comments
Assignees

Comments

@creage
Copy link

creage commented Dec 18, 2020

Context:

  • Playwright Version: 1.7.0
  • Operating System: Windows
  • Node.js version: 14.15.1
  • Browser: WebKit
  • Extra: jest-playwright

Code Snippet
Simple launching a browser and navigating to a page using proxy (both for browser, and for context).

Describe the bug

Test passes on Chrome and Firefox, but fails on WebKit, with error

2020-12-18T12:12:51.5694078Z FAIL tests/Detail Page/Case/148747.js
2020-12-18T12:12:51.5694922Z 
2020-12-18T12:12:51.6015776Z   â—� [webkit] 148747: Create Case - basic functionality, CommonAT
2020-12-18T12:12:51.6017005Z 
2020-12-18T12:12:51.6327874Z 
2020-12-18T12:12:51.6332102Z 
2020-12-18T12:12:51.6529116Z     page.waitForSelector: Protocol error (Runtime.evaluate): The page has been closed.
2020-12-18T12:12:51.6531114Z 
2020-12-18T12:12:51.6786310Z     =========================== logs ===========================
2020-12-18T12:12:51.6788408Z 
2020-12-18T12:12:51.6980965Z     waiting for selector ".client-loaded" to be visible
2020-12-18T12:12:51.6983179Z 
2020-12-18T12:12:51.7184853Z     ============================================================
2020-12-18T12:12:51.7186594Z 
2020-12-18T12:12:51.7478172Z     Note: use DEBUG=pw:api environment variable and rerun to capture Playwright logs.:
2020-12-18T12:12:51.7479474Z 
2020-12-18T12:12:51.7659094Z 
2020-12-18T12:12:51.7661443Z 
2020-12-18T12:12:51.7826916Z       279 | 
2020-12-18T12:12:51.7829375Z 
2020-12-18T12:12:51.8001431Z       280 | 	static async isLoaded() {
2020-12-18T12:12:51.8005670Z 
2020-12-18T12:12:51.8179195Z     > 281 | 		return page.waitForSelector('.client-loaded');
2020-12-18T12:12:51.8180685Z 
2020-12-18T12:12:51.8337950Z           | 		            ^
2020-12-18T12:12:51.8338374Z 
2020-12-18T12:12:51.8496593Z       282 | 	}
2020-12-18T12:12:51.8497085Z 
2020-12-18T12:12:51.8662111Z       283 | 
2020-12-18T12:12:51.8664294Z 
2020-12-18T12:12:51.8998374Z       284 | 	static async startCreating(register, template) {
2020-12-18T12:12:51.9001412Z 
2020-12-18T12:12:51.9249812Z 
2020-12-18T12:12:51.9251934Z 
2020-12-18T12:12:51.9459159Z       at Connection.sendMessageToServer (node_modules/playwright/lib/client/connection.js:69:15)
2020-12-18T12:12:51.9461196Z 
2020-12-18T12:12:51.9648562Z       at Proxy.<anonymous> (node_modules/playwright/lib/client/channelOwner.js:44:61)
2020-12-18T12:12:51.9652344Z 
2020-12-18T12:12:51.9875991Z       at node_modules/playwright/lib/client/frame.js:180:48
2020-12-18T12:12:51.9876728Z 
2020-12-18T12:12:52.0116697Z       at Frame._wrapApiCall (node_modules/playwright/lib/client/channelOwner.js:72:34)
2020-12-18T12:12:52.0118890Z 
2020-12-18T12:12:52.0315853Z       at Frame.waitForSelector (node_modules/playwright/lib/client/frame.js:175:21)
2020-12-18T12:12:52.0316286Z 
2020-12-18T12:12:52.0660147Z       at node_modules/playwright/lib/client/page.js:212:60
2020-12-18T12:12:52.0661693Z 
2020-12-18T12:12:52.0847719Z       at Page._attributeToPage (node_modules/playwright/lib/client/page.js:202:20)
2020-12-18T12:12:52.0849762Z 
2020-12-18T12:12:52.1035826Z       at Page.waitForSelector (node_modules/playwright/lib/client/page.js:212:21)
2020-12-18T12:12:52.1038133Z 
2020-12-18T12:12:52.1206773Z       at Function.isLoaded (framework/contexts/App.js:281:15)

Test passes fine on PlayWright v1.6.2, in all browsers.

P.S.

Here is DEBUG=pw:api output (test retries itself 3 times before it fails):

2020-12-18T12:12:29.6390730Z 2020-12-18T12:15:23.407Z pw:api => browserType.launch started
2020-12-18T12:12:29.6392938Z 
2020-12-18T12:12:29.6570752Z 2020-12-18T12:15:23.730Z pw:api <= browserType.launch succeeded
2020-12-18T12:12:29.6573122Z 
2020-12-18T12:12:29.6729726Z 2020-12-18T12:15:23.730Z pw:api => browser.newContext started
2020-12-18T12:12:29.6730553Z 
2020-12-18T12:12:29.6909540Z 2020-12-18T12:15:23.730Z pw:api <= browser.newContext succeeded
2020-12-18T12:12:29.6912029Z 
2020-12-18T12:12:29.7062837Z 2020-12-18T12:15:23.730Z pw:api => browserContext.newPage started
2020-12-18T12:12:29.7063166Z 
2020-12-18T12:12:29.7321030Z 2020-12-18T12:15:23.840Z pw:api <= browserContext.newPage succeeded
2020-12-18T12:12:29.7321289Z 
2020-12-18T12:12:29.7589210Z 2020-12-18T12:15:23.840Z pw:api => page.goto started
2020-12-18T12:12:29.7590553Z 
2020-12-18T12:12:29.7834714Z 2020-12-18T12:15:23.841Z pw:api navigating to "http://db01.lmdom.local/app/client", waiting until "load"
2020-12-18T12:12:29.7836197Z 
2020-12-18T12:12:29.8017537Z 2020-12-18T12:15:23.878Z pw:api   navigated to "http://db01.lmdom.local/app/client/"
2020-12-18T12:12:29.8018978Z 
2020-12-18T12:12:29.8196068Z 2020-12-18T12:15:24.170Z pw:api   "domcontentloaded" event fired
2020-12-18T12:12:29.8196317Z 
2020-12-18T12:12:29.8368774Z 2020-12-18T12:15:24.170Z pw:api   "load" event fired
2020-12-18T12:12:29.8370197Z 
2020-12-18T12:12:29.8588858Z 2020-12-18T12:15:24.170Z pw:api <= page.goto succeeded
2020-12-18T12:12:29.8589117Z 
2020-12-18T12:12:29.8743748Z 2020-12-18T12:15:24.171Z pw:api => page.waitForSelector started
2020-12-18T12:12:29.8744835Z 
2020-12-18T12:12:29.9021221Z 2020-12-18T12:15:24.171Z pw:api waiting for selector ".client-loaded" to be visible
2020-12-18T12:12:29.9023218Z 
2020-12-18T12:12:29.9213998Z 2020-12-18T12:15:24.185Z pw:api <= page.waitForSelector failed
2020-12-18T12:12:29.9216664Z 
2020-12-18T12:12:29.9415402Z 2020-12-18T12:15:24.185Z pw:api => page.screenshot started
2020-12-18T12:12:29.9416116Z 
2020-12-18T12:12:29.9593595Z 2020-12-18T12:15:24.185Z pw:api <= page.screenshot failed
2020-12-18T12:12:29.9593987Z 
2020-12-18T12:12:29.9803583Z 2020-12-18T12:15:24.185Z pw:api => browserContext.close started
2020-12-18T12:12:29.9806014Z 
2020-12-18T12:12:30.0107271Z 2020-12-18T12:15:24.185Z pw:api <= browserContext.close succeeded
2020-12-18T12:12:30.0108115Z 
2020-12-18T12:12:30.0308010Z 2020-12-18T12:15:24.185Z pw:api => browser.newContext started
2020-12-18T12:12:30.0309598Z 
2020-12-18T12:12:30.0514370Z 2020-12-18T12:15:24.185Z pw:api <= browser.newContext succeeded
2020-12-18T12:12:30.0517689Z 
2020-12-18T12:12:30.0893799Z 2020-12-18T12:15:24.185Z pw:api => page.close started
2020-12-18T12:12:30.0895362Z 
2020-12-18T12:12:30.1124344Z 2020-12-18T12:15:24.185Z pw:api <= page.close failed
2020-12-18T12:12:30.1125197Z 
2020-12-18T12:12:30.1299335Z 2020-12-18T12:15:24.185Z pw:api => browserContext.newPage started
2020-12-18T12:12:30.1299618Z 
2020-12-18T12:12:30.1441881Z 2020-12-18T12:15:24.271Z pw:api <= browserContext.newPage succeeded
2020-12-18T12:12:30.1443747Z 
2020-12-18T12:12:30.1611344Z 2020-12-18T12:15:24.271Z pw:api => page.goto started
2020-12-18T12:12:30.1612297Z 
2020-12-18T12:12:30.1803940Z 2020-12-18T12:15:24.272Z pw:api navigating to "http://db01.lmdom.local/app/client", waiting until "load"
2020-12-18T12:12:30.1804303Z 
2020-12-18T12:12:30.1987261Z 2020-12-18T12:15:24.302Z pw:api   navigated to "http://db01.lmdom.local/app/client/"
2020-12-18T12:12:30.1988200Z 
2020-12-18T12:12:30.2315452Z 2020-12-18T12:15:24.586Z pw:api   "domcontentloaded" event fired
2020-12-18T12:12:30.2316970Z 
2020-12-18T12:12:30.2571242Z 2020-12-18T12:15:24.588Z pw:api   "load" event fired
2020-12-18T12:12:30.2572302Z 
2020-12-18T12:12:30.2841935Z 2020-12-18T12:15:24.588Z pw:api <= page.goto succeeded
2020-12-18T12:12:30.2843455Z 
2020-12-18T12:12:30.3137982Z 2020-12-18T12:15:24.588Z pw:api => page.waitForSelector started
2020-12-18T12:12:30.3139601Z 
2020-12-18T12:12:30.3379671Z 2020-12-18T12:15:24.588Z pw:api waiting for selector ".client-loaded" to be visible
2020-12-18T12:12:30.3380086Z 
2020-12-18T12:12:30.3577553Z 2020-12-18T12:15:24.607Z pw:api <= page.waitForSelector failed
2020-12-18T12:12:30.3579989Z 
2020-12-18T12:12:30.3759624Z 2020-12-18T12:15:24.607Z pw:api => page.screenshot started
2020-12-18T12:12:30.3761718Z 
2020-12-18T12:12:30.3974888Z 2020-12-18T12:15:24.607Z pw:api <= page.screenshot failed
2020-12-18T12:12:30.3977494Z 
2020-12-18T12:12:30.4297622Z 2020-12-18T12:15:24.607Z pw:api => browserContext.close started
2020-12-18T12:12:30.4299046Z 
2020-12-18T12:12:30.4497907Z 2020-12-18T12:15:24.607Z pw:api <= browserContext.close succeeded
2020-12-18T12:12:30.4500141Z 
2020-12-18T12:12:30.4706424Z 2020-12-18T12:15:24.607Z pw:api => browser.newContext started
2020-12-18T12:12:30.4708179Z 
2020-12-18T12:12:30.4879035Z 2020-12-18T12:15:24.607Z pw:api <= browser.newContext succeeded
2020-12-18T12:12:30.4883379Z 
2020-12-18T12:12:30.5080246Z 2020-12-18T12:15:24.607Z pw:api => page.close started
2020-12-18T12:12:30.5082683Z 
2020-12-18T12:12:30.5247269Z 2020-12-18T12:15:24.607Z pw:api <= page.close failed
2020-12-18T12:12:30.5248226Z 
2020-12-18T12:12:30.5468831Z 2020-12-18T12:15:24.607Z pw:api => browserContext.newPage started
2020-12-18T12:12:30.5470853Z 
2020-12-18T12:12:30.5681926Z 2020-12-18T12:15:24.694Z pw:api <= browserContext.newPage succeeded
2020-12-18T12:12:30.5683810Z 
2020-12-18T12:12:30.6019428Z 2020-12-18T12:15:24.694Z pw:api => page.goto started
2020-12-18T12:12:30.6019679Z 
2020-12-18T12:12:30.6181771Z 2020-12-18T12:15:24.695Z pw:api navigating to "http://db01.lmdom.local/app/client", waiting until "load"
2020-12-18T12:12:30.6182795Z 
2020-12-18T12:12:30.6348622Z 2020-12-18T12:15:24.721Z pw:api   navigated to "http://db01.lmdom.local/app/client/"
2020-12-18T12:12:30.6358822Z 
2020-12-18T12:12:30.6516721Z 2020-12-18T12:15:25.005Z pw:api   "domcontentloaded" event fired
2020-12-18T12:12:30.6517069Z 
2020-12-18T12:12:30.6739211Z 2020-12-18T12:15:25.007Z pw:api   "load" event fired
2020-12-18T12:12:30.6740719Z 
2020-12-18T12:12:30.6911893Z 2020-12-18T12:15:25.007Z pw:api <= page.goto succeeded
2020-12-18T12:12:30.6912217Z 
2020-12-18T12:12:30.7087843Z 2020-12-18T12:15:25.007Z pw:api => page.waitForSelector started
2020-12-18T12:12:30.7089552Z 
2020-12-18T12:12:30.7266556Z 2020-12-18T12:15:25.008Z pw:api waiting for selector ".client-loaded" to be visible
2020-12-18T12:12:30.7268085Z 
2020-12-18T12:12:30.7598576Z 2020-12-18T12:15:25.023Z pw:api <= page.waitForSelector failed
2020-12-18T12:12:30.7601512Z 
2020-12-18T12:12:30.7904410Z 2020-12-18T12:15:25.023Z pw:api => page.screenshot started
2020-12-18T12:12:30.7905760Z 
2020-12-18T12:12:30.8091268Z 2020-12-18T12:15:25.023Z pw:api <= page.screenshot failed
2020-12-18T12:12:30.8092599Z 
2020-12-18T12:12:30.8277389Z 2020-12-18T12:15:25.027Z pw:api => browserContext.close started
2020-12-18T12:12:30.8278905Z 
2020-12-18T12:12:30.8473427Z 2020-12-18T12:15:25.027Z pw:api <= browserContext.close succeeded
2020-12-18T12:12:30.8474538Z 
2020-12-18T12:12:30.8679201Z 2020-12-18T12:15:25.027Z pw:api => browser.newContext started
2020-12-18T12:12:30.8683673Z 
2020-12-18T12:12:30.8912254Z 2020-12-18T12:15:25.027Z pw:api <= browser.newContext succeeded
2020-12-18T12:12:30.8912971Z 
2020-12-18T12:12:30.9253484Z 2020-12-18T12:15:25.027Z pw:api => page.close started
2020-12-18T12:12:30.9256598Z 
2020-12-18T12:12:30.9479832Z 2020-12-18T12:15:25.027Z pw:api <= page.close failed
2020-12-18T12:12:30.9481299Z 
2020-12-18T12:12:30.9677135Z 2020-12-18T12:15:25.027Z pw:api => browserContext.newPage started
2020-12-18T12:12:30.9677612Z 
2020-12-18T12:12:30.9842953Z 2020-12-18T12:15:25.103Z pw:api <= browserContext.newPage succeeded
2020-12-18T12:12:30.9843522Z 
2020-12-18T12:12:31.0022175Z 2020-12-18T12:15:25.104Z pw:api => page.goto started
2020-12-18T12:12:31.0023243Z 
2020-12-18T12:12:31.0189059Z 2020-12-18T12:15:25.104Z pw:api navigating to "http://db01.lmdom.local/app/client", waiting until "load"
2020-12-18T12:12:31.0190726Z 
2020-12-18T12:12:31.0383047Z 2020-12-18T12:15:25.133Z pw:api   navigated to "http://db01.lmdom.local/app/client/"
2020-12-18T12:12:31.0387560Z 
2020-12-18T12:12:31.0640556Z 2020-12-18T12:15:25.425Z pw:api   "domcontentloaded" event fired
2020-12-18T12:12:31.0642955Z 
2020-12-18T12:12:31.0979814Z 2020-12-18T12:15:25.427Z pw:api   "load" event fired
2020-12-18T12:12:31.0981884Z 
2020-12-18T12:12:31.1202121Z 2020-12-18T12:15:25.427Z pw:api <= page.goto succeeded
2020-12-18T12:12:31.1206695Z 
2020-12-18T12:12:31.1459708Z 2020-12-18T12:15:25.427Z pw:api => page.waitForSelector started
2020-12-18T12:12:31.1461756Z 
2020-12-18T12:12:31.1729882Z 2020-12-18T12:15:25.428Z pw:api waiting for selector ".client-loaded" to be visible
2020-12-18T12:12:31.1730240Z 
2020-12-18T12:12:31.1949528Z 2020-12-18T12:15:25.444Z pw:api <= page.waitForSelector failed
2020-12-18T12:12:31.1949912Z 
2020-12-18T12:12:31.2156976Z 2020-12-18T12:15:25.444Z pw:api => page.screenshot started
2020-12-18T12:12:31.2157325Z 
2020-12-18T12:12:31.2369706Z 2020-12-18T12:15:25.444Z pw:api <= page.screenshot failed
2020-12-18T12:12:31.2371759Z 
2020-12-18T12:12:31.2553168Z 2020-12-18T12:15:25.459Z pw:api => browser.close started
2020-12-18T12:12:31.2556288Z 
2020-12-18T12:12:31.3165220Z 2020-12-18T12:15:25.459Z pw:api <= browser.close succeeded
2020-12-18T12:12:31.3165781Z 
2020-12-18T12:12:31.3482665Z 2020-12-18T12:15:25.459Z pw:api => browser.close started
2020-12-18T12:12:31.3484016Z 
2020-12-18T12:12:31.3693927Z 2020-12-18T12:15:25.459Z pw:api <= browser.close failed
@aslushnikov
Copy link
Collaborator

@creage can we have a script that we can run locally to reproduce this? It would be hard to understand what's going on without a local repro.

@creage
Copy link
Author

creage commented Dec 21, 2020

@aslushnikov I was trying hard to reproduce it manually, but with no success.

And by manually I mean running a test on my machine locally. But the issue is constantly reproducible in our CI pipeline, which is Azure DevOps based, and is executed by remote PowerShell script.

But still - running same set of tests on same hardware/software environment, ends green running PW 1.6.2, but fails on 1.7.0.

So, I took deeper debugging using pw:* flag, but that didn't help much. What I noticed, is that WebKitWebProcess shows unexpectedly high CPU usage up to 100%, which apparently causes browser crashes. And I was not able to reproduce it locally since I'm running on quite more powerful hardware than we have on our CI machines.

I have a ~40MB log file, hope it helps.

@dgozman
Copy link
Contributor

dgozman commented Dec 23, 2020

Logs show that the page has crashed. We should say "crashed" instead of "closed" in the error message. The only browser log line is about EGL, not very helpful.

pw:browser [err] Could not create EGL context.

@creage If you could share the page url or some test setup where we can try to repro, we could look into why it did crash. Otherwise, the most likely reason is out of memory.

@yury-s Any ideas?

@creage
Copy link
Author

creage commented Dec 24, 2020

@dgozman I'm not sure I can share the page itself, as it is an enterprise application installed on-prem only. And test setup is really not important, except it being an HTTPS, and manual playing with WebKit executable (WebKit 14.1) gives same results - page refuses to load with some really weird behavior, like scripts are stopping loading in half of the way, style are not rendered, etc. I was monitoring the system, and I never saw any memory issues - it was around 70-80%. But CPU was 100% most of the time.

And machine specs are quite normal - they work fine with WebKit 14.0:

image

@creage
Copy link
Author

creage commented Dec 24, 2020

And console is full of very strange errors. Look at the primary.dafcce.js
image

When I try to see what is the problem - it shows me a CSS file, not JS!

image

@pavelfeldman
Copy link
Member

Looks like we need more details to address this one... Closing in hopes that another issue with a repro is filed

@imWildCat
Copy link

Hello, I can repro similar bugs using the webkit driver.

Error: 
    at Object.captureStackTrace (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/utils/stackTrace.js:51:19)
    at Connection.sendMessageToServer (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/connection.js:69:48)
    at Proxy.<anonymous> (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/channelOwner.js:64:61)
    at /Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/frame.js:193:42
    at Frame._wrapApiCall (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/channelOwner.js:77:34)
    at Frame.waitForSelector (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/frame.js:188:21)
    at /Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/page.js:212:60
    at Page._attributeToPage (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/page.js:202:20)
    at Page.waitForSelector (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/playwright/lib/client/page.js:212:21)
    at step (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/tslib/tslib.js:143:27)
    at Object.next (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/tslib/tslib.js:124:57)
    at /Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/tslib/tslib.js:117:75
    at new Promise (<anonymous>)
    at Object.__awaiter (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/tslib/tslib.js:113:16)
    at Object.asyncJestTest (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/jest-jasmine2/build/jasmineAsyncInstall.js:106:37)
    at /Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/jest-jasmine2/build/queueRunner.js:45:12
    at new Promise (<anonymous>)
    at mapper (/Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/jest-jasmine2/build/queueRunner.js:28:19)
    at /Users/[redacted]/workspace/[redacted_project_name]/[redacted_project_name]/node_modules/jest-jasmine2/build/queueRunner.js:75:41
(Use `node --trace-warnings ...` to show where the warning was created)

(I removed two lines of the log to protect our privacy)

I'm not using playwright directly. Instead, we use jest with playwright to run e2e tests for our project:

        "jest": "^26.6.3",
        "jest-junit": "^12.2.0",
        "jest-playwright-preset": "^1.6.1",
        "playwright": "^1.12.2",

System: macOS 11.4 (20F71)

$ npm -v
6.14.12
$ node -v
v14.16.1

@dipiash
Copy link

dipiash commented Nov 15, 2021

Hello! Our team have the same issue.

Local test pass. Remote test (on the https://aerokube.com/moon/) fail because can't wait when page loaded.

Tests was start for the same page: https://dasreda.ru/

Context:
Playwright Version: 1.16.3 (the same behavior on 1.8.0)
Operating System: Windows
Node.js version: v14.18.1
Browser: chromium
Extra: codeceptjs (3.0.4 / the same behavior on 3.1.3)

Code Snippet
Simple launching a browser and navigating to a page.

LOGs
Success (local) - local-log.log
Error (Remote) - remote-moon-log.log

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants