Intermittent [cdp] waittask specs Frame.waitForFunction should work when resolved right before execution context disposal (waittask.spec.js) | expected PASS
Categories
(Remote Protocol :: CDP, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure, Whiteboard: [retriggered])
Attachments
(1 file)
Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=396300236&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/a--rRqUzTr6ooP4Zdm-ykw/runs/0/artifacts/public/logs/live_backing.log
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"d8605291-da8a-4366-a194-561e76115379","message":"{\"method\":\"Page.lifecycleEvent\",\"params\":{\"frameId\":\"13\",\"name\":\"DOMContentLoaded\",\"timestamp\":1668180075.403}}"}}
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Page.loadEventFired","params":{"timestamp":1668180075.404},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"d8605291-da8a-4366-a194-561e76115379","message":"{\"method\":\"Page.loadEventFired\",\"params\":{\"timestamp\":1668180075.404}}"}}
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Page.lifecycleEvent","params":{"frameId":"13","name":"load","timestamp":1668180075.404},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"d8605291-da8a-4366-a194-561e76115379","message":"{\"method\":\"Page.lifecycleEvent\",\"params\":{\"frameId\":\"13\",\"name\":\"load\",\"timestamp\":1668180075.404}}"}}
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Page.frameStoppedLoading","params":{"frameId":"13"},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.410Z] PID 657 | 1668180075407 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"d8605291-da8a-4366-a194-561e76115379","message":"{\"method\":\"Page.frameStoppedLoading\",\"params\":{\"frameId\":\"13\"}}"}}
[task 2022-11-11T15:21:15.434Z] PID 657 | 1668180075433 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"sessionId":"d8605291-da8a-4366-a194-561e76115379","method":"Runtime.evaluate","params":{"expression":"\"use strict\";\nvar __defProp = Object.defineProperty;\nvar __export = (target, all) => {\n for (var name in all)\n __defProp( ... ports,\n ...util_exports,\n createDeferredPromise\n }\n })\n);\n\n//# sourceURL=pptr://__puppeteer_evaluation_script__","contextId":402,"returnByValue":true,"awaitPromise":true,"userGesture":true},"id":436}
[task 2022-11-11T15:21:15.434Z] PID 657 | 1668180075433 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"sessionId":"d8605291-da8a-4366-a194-561e76115379","method":"Runtime.callFunctionOn","params":{"functionDeclaration":"async function waitForPredicatePageFunction(root, predicateBody, predicateAcceptsContextElement, polling, timeout, ...args) { ... setTimeout(onTimeout, pollInterval);\n }\n }\n }\n}\n//# sourceURL=pptr://__puppeteer_evaluation_script__\n","executionContextId":401,"arguments":[{"value":null},{"value":"return (() => {\n if (!globalThis.__RELOADED) {\n window.location.reload();\n }\n return true;\n })(...args);"},{"value":false},{"value":"raf"},{"value":30000}],"returnByValue":false,"awaitPromise":true,"userGesture":true},"id":437}
[task 2022-11-11T15:21:15.436Z] PID 657 | 1668180075435 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":436,"error":{"message":"Object is not serializable","data":"_serialize@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:525:13\n_toRemoteObjectByValue@chrome: ... dp/domains/DomainCache.sys.mjs:95:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.sys.mjs:79:45\n"},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.437Z] PID 657 | 1668180075436 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":437,"error":{"message":"Debugger: expected Debugger.Object, got Proxy","data":"_returnError@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:179:22\ncallFunctionOn@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:254:23\n"},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.437Z] PID 657 | 1668180075437 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Log.entryAdded","params":{"entry":{"source":"other","level":"error","text":"Too many calls to Location or History APIs within a short timeframe.","timestamp":1668180075436,"url":"debugger eval code line 3 > Function","lineNumber":5}},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.437Z] PID 657 | 1668180075437 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"d8605291-da8a-4366-a194-561e76115379","message":"{\"method\":\"Log.entryAdded\",\"params\":{\"entry\":{\"source\":\"other\",\"level\":\"error\",\"text\":\"Too many calls to Location or History APIs within a short timeframe.\",\"timestamp\":1668180075436,\"url\":\"debugger eval code line 3 > Function\",\"lineNumber\":5}}}"}}
[task 2022-11-11T15:21:15.474Z] TEST-UNEXPECTED-FAIL | waittask specs Frame.waitForFunction should work when resolved right before execution context disposal (waittask.spec.js) | expected PASS
[task 2022-11-11T15:21:15.474Z] TEST-INFO took 8508ms
[task 2022-11-11T15:21:15.474Z] PID 657 | ["fail",{"title":"should work when resolved right before execution context disposal","fullTitle":"waittask specs Frame.waitForFunction should work when resolved right before execution context disposal","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/build/waittask.spec.js","duration":8251,"currentRetry":0,"err":"Protocol error (Runtime.callFunctionOn): Debugger: expected Debugger.Object, got Proxy _returnError@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:179:22\ncallFunctionOn@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:254:23\n","stack":"ProtocolError: Protocol error (Runtime.callFunctionOn): Debugger: expected Debugger.Object, got Proxy _returnError@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:179:22\ncallFunctionOn@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:254:23\n\n at /builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Connection.ts:359:16\n at new Promise (<anonymous>)\n at CDPSession.send (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/Connection.ts:355:12)\n at ExecutionContext._ExecutionContext_evaluate (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/ExecutionContext.ts:273:44)\n at ExecutionContext.evaluateHandle (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/ExecutionContext.ts:195:26)\n at WaitTask.rerun (/builds/worker/checkouts/gecko/remote/test/puppeteer/src/common/IsolatedWorld.ts:714:31)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)"}]
[task 2022-11-11T15:21:15.474Z] PID 657 | 1668180075473 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"method":"Target.disposeBrowserContext","params":{"browserContextId":7},"id":438}
[task 2022-11-11T15:21:15.481Z] PID 657 | 1668180075481 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.targetDestroyed","params":{"targetId":"23e27f46-fa25-4930-8921-4d94e0c81f89"}}
[task 2022-11-11T15:21:15.487Z] PID 657 | 1668180075486 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":438,"result":{}}
[task 2022-11-11T15:21:15.521Z] TEST-START | waittask specs Frame.waitForFunction should poll on interval (waittask.spec.js)
[task 2022-11-11T15:21:15.521Z] PID 657 | ["test-start",{"title":"should poll on interval","fullTitle":"waittask specs Frame.waitForFunction should poll on interval","file":"/builds/worker/checkouts/gecko/remote/test/puppeteer/test/build/waittask.spec.js","currentRetry":0}]
[task 2022-11-11T15:21:15.522Z] PID 657 | 1668180075521 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"method":"Target.createBrowserContext","params":{},"id":439}
[task 2022-11-11T15:21:15.522Z] PID 657 | 1668180075522 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":439,"result":{"browserContextId":8}}
[task 2022-11-11T15:21:15.523Z] PID 657 | 1668180075522 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"method":"Target.createTarget","params":{"url":"about:blank","browserContextId":8},"id":440}
[task 2022-11-11T15:21:15.532Z] PID 657 | 1668180075530 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.targetCreated","params":{"targetInfo":{"targetId":"651a155f-6f5e-4aa2-a394-416798a8f4d9","type":"page","title":"","url":"about:blank","attached":false,"browserContextId":8}}}
[task 2022-11-11T15:21:15.539Z] PID 657 | 1668180075539 RemoteAgent TRACE Received DOM event TabSelect for [object XULElement]
[task 2022-11-11T15:21:15.547Z] PID 657 | 1668180075547 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":440,"result":{"targetId":"651a155f-6f5e-4aa2-a394-416798a8f4d9"}}
[task 2022-11-11T15:21:15.569Z] PID 657 | 1668180075569 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"method":"Target.attachToTarget","params":{"targetId":"651a155f-6f5e-4aa2-a394-416798a8f4d9","flatten":true},"id":441}
Comment 1•3 years ago
|
||
First occurrence, so far, in this backfill range and retriggers: https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=Linux%2C18.04%2Cx64%2Copt%2CRemote%2Cdebugging%2Cprotocol%2Ctests%2Csource-test-remote-puppeteer%2Cpup&tochange=0926249d274594c994cb532eb35d1426026d78cc&fromchange=3107f2cb0ec9b46325929a12626da6aca04e5eae&group_state=expanded&selectedTaskRun=bCitzfn7RLulyg8HZSqEuw.0
| Comment hidden (Intermittent Failures Robot) |
Comment 3•3 years ago
|
||
The related test here is:
https://searchfox.org/mozilla-central/rev/219df29d0fb5d8928ae41bba4a605046de411cf0/remote/test/puppeteer/test/src/waittask.spec.ts#40-52
There are some failures returned including log errors:
https://treeherder.mozilla.org/logviewer?job_id=396300236&repo=autoland&lineNumber=87185-87189
[task 2022-11-11T15:21:15.434Z] PID 657 | 1668180075433 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 -> {"sessionId":"d8605291-da8a-4366-a194-561e76115379","method":"Runtime.callFunctionOn","params":{"functionDeclaration":"async function waitForPredicatePageFunction(root, predicateBody, predicateAcceptsContextElement, polling, timeout, ...args) { ... setTimeout(onTimeout, pollInterval);\n }\n }\n }\n}\n//# sourceURL=pptr://__puppeteer_evaluation_script__\n","executionContextId":401,"arguments":[{"value":null},{"value":"return (() => {\n if (!globalThis.__RELOADED) {\n window.location.reload();\n }\n return true;\n })(...args);"},{"value":false},{"value":"raf"},{"value":30000}],"returnByValue":false,"awaitPromise":true,"userGesture":true},"id":437}
[task 2022-11-11T15:21:15.436Z] PID 657 | 1668180075435 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":436,"error":{"message":"Object is not serializable","data":"_serialize@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:525:13\n_toRemoteObjectByValue@chrome: ... dp/domains/DomainCache.sys.mjs:95:25\nreceiveMessage@chrome://remote/content/cdp/sessions/ContentProcessSession.sys.mjs:79:45\n"},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.437Z] PID 657 | 1668180075436 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"id":437,"error":{"message":"Debugger: expected Debugger.Object, got Proxy","data":"_returnError@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:179:22\ncallFunctionOn@chrome://remote/content/cdp/domains/content/runtime/ExecutionContext.sys.mjs:254:23\n"},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.437Z] PID 657 | 1668180075437 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Log.entryAdded","params":{"entry":{"source":"other","level":"error","text":"Too many calls to Location or History APIs within a short timeframe.","timestamp":1668180075436,"url":"debugger eval code line 3 > Function","lineNumber":5}},"sessionId":"d8605291-da8a-4366-a194-561e76115379"}
[task 2022-11-11T15:21:15.437Z] PID 657 | 1668180075437 RemoteAgent TRACE CDPConnection 8c4a42f8-9f5d-427f-9e21-0afc170de8a3 <- {"method":"Target.receivedMessageFromTarget","params":{"sessionId":"d8605291-da8a-4366-a194-561e76115379","message":"{\"method\":\"Log.entryAdded\",\"params\":{\"entry\":{\"source\":\"other\",\"level\":\"error\",\"text\":\"Too many calls to Location or History APIs within a short timeframe.\",\"timestamp\":1668180075436,\"url\":\"debugger eval code line 3 > Function\",\"lineNumber\":5}}}"}}
As the backfill shows this looks to be related to bug 1799394. Emilio, could you imagine a regression based on your patch?
Comment 4•3 years ago
|
||
No, my patch only affects the profile manager sizing, effectively.
| Comment hidden (Intermittent Failures Robot) |
Comment 6•3 years ago
|
||
Thanks! So I had a look and in the passing cases the test sends a navigation command to grid.html which gets usually processed. But in case of a failure this navigation fails. The log event from above with Too many calls to Location or History APIs within a short timeframe for the URL debugger eval code line 3 > Function is causing that.
This error gets thrown at:
https://searchfox.org/mozilla-central/rev/83b86005c6913c2062419efb8aabdf2e683aa47f/docshell/base/BrowsingContext.cpp#3770-3778
The preference as used for this limit per browsing context is dom.navigation.locationChangeRateLimit.count and is set to 200 by default.
There is also dom.navigation.locationChangeRateLimit.timespan that is set to 10 seconds.
Nothing changed in those files so it's unclear to me why this intermittent failure sporadically started.
Given that tests are known to run a lot of code including usage of the location and history APIs we might want to lift this restriction for Remote Agent and set the limit to 0? I don't see that any configuration in /testing/profiles sets it for other harnesses and jobs, so I wonder if such a change would be fine thought.
Olli what do you think?
Comment 7•3 years ago
|
||
Tweaking that pref for testing sounds reasonable, unless there are tests which explicitly want to test that behavior of course :)
Comment 8•3 years ago
|
||
Sure. I'm not aware of any of such tests that are part of the Mn, Wd, pup and other Marionette driven test suites.
I pushed a try build to test the change with Puppeteer:
https://treeherder.mozilla.org/jobs?repo=try&revision=200d120decb114b9c4b358172957a0bedfa93a9f
Comment 9•3 years ago
|
||
The patch will actually not fix this particular issue but at least the failure is gone which might also have an affect for other tests. I'm going to upload the patch on a different bug.
Comment 10•3 years ago
|
||
In a working case both the Runtime.evaluate and Runtime.callFunctionOn commands return immediately. The former with a Object is not serializable response and the latter with "result":{"type":"boolean","value":true}}:
https://treeherder.mozilla.org/logviewer?job_id=397428878&repo=try&lineNumber=82305-82308
With my patch attached to bug 1802103 this will happen now as well, and the test only runs into a timeout because it seems to run the same test over and over again for about 25s:
https://treeherder.mozilla.org/logviewer?job_id=397428888&repo=try&lineNumber=82264-82298
It's not clear why that happens given that the test doesn't contain a loop nor bases the expected result on the returned value.
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
Comment 13•3 years ago
|
||
As Julian mentioned in last week's meeting there is a waitForFunction call in this test which sometimes may cause this repeated execution.
Comment 14•3 years ago
|
||
I had a closer look at the test and it actually requires to run a script on new document creation as set via Page.addScriptToEvaluateOnNewDocument. Given that bug 1601695 isn't fixed yet we do not run such added scripts yet. As such we won't set the __RELOADED flag after the page got reloaded. But also there is no assertion / check for a return value of the waitForFunction call, so maybe the test checks that the call of the method doesn't return a failure due to the triggered navigation.
Comment 15•3 years ago
|
||
This is actually a race condition in the test and in most cases causes the waitForFunction unexpectedly to repeat. Basically it should run until the return value is not falsy.
I pushed a fix upstream: https://github.com/puppeteer/puppeteer/pull/9368
We should skip the test on our side as well.
Comment 16•3 years ago
|
||
The test is currently broken and got fixed upstream for
a later Puppeteer release:
https://github.com/puppeteer/puppeteer/pull/9368
Until the fix got downstreamed this test will be flaky
and can pass and fail.
Updated•3 years ago
|
Updated•3 years ago
|
Comment 17•3 years ago
|
||
Comment 18•3 years ago
|
||
| bugherder | ||
Updated•3 years ago
|
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
Comment 22•2 years ago
|
||
We are not going to fix this intermittent failure for CDP.
Updated•2 years ago
|
Description
•