Closed Bug 1800257 Opened 3 years ago Closed 2 years ago

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)

x86_64
Linux
defect

Tracking

(Not tracked)

RESOLVED WONTFIX

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}

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?

Flags: needinfo?(emilio)

No, my patch only affects the profile manager sizing, effectively.

Flags: needinfo?(emilio)

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?

Flags: needinfo?(smaug)
OS: Unspecified → Linux
Hardware: Unspecified → x86_64

Tweaking that pref for testing sounds reasonable, unless there are tests which explicitly want to test that behavior of course :)

Flags: needinfo?(smaug)

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

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.

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.

As Julian mentioned in last week's meeting there is a waitForFunction call in this test which sometimes may cause this repeated execution.

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.

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.

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.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/bd4a97951c8a [puppeteer] Allow "Frame.waitForFunction should work when resolved right before execution context disposal" to fail r=webdriver-reviewers,jdescottes
Assignee: hskupin → nobody
Status: ASSIGNED → NEW

We are not going to fix this intermittent failure for CDP.

Status: NEW → RESOLVED
Closed: 2 years ago
Component: Agent → CDP
Resolution: --- → WONTFIX
Summary: Intermittent waittask specs Frame.waitForFunction should work when resolved right before execution context disposal (waittask.spec.js) | expected PASS → Intermittent [cdp] waittask specs Frame.waitForFunction should work when resolved right before execution context disposal (waittask.spec.js) | expected PASS
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: