High Frequency wpt | TypeError: window.__wptrunner_process_next_event is not a function
Categories
(Testing :: web-platform-tests, defect, P5)
Tracking
(firefox79 fixed)
Tracking | Status | |
---|---|---|
firefox79 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: whimboo)
References
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell disable-recommended], [wptsync upstream])
Attachments
(1 file)
(deleted),
text/x-phabricator-request
|
Details |
Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=304223803&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/QF7XntSISwGey-2kTdyuXg/runs/0/artifacts/public/logs/live_backing.log
...
[task 2020-05-29T07:23:03.465Z] 07:23:03 WARNING - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 622, in _handle_error
[task 2020-05-29T07:23:03.465Z] 07:23:03 WARNING - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-05-29T07:23:03.466Z] 07:23:03 WARNING - JavascriptException: TypeError: window.__wptrunner_process_next_event is not a function
[task 2020-05-29T07:23:03.466Z] 07:23:03 WARNING - stacktrace:
[task 2020-05-29T07:23:03.466Z] 07:23:03 WARNING - @tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py:72:8
[task 2020-05-29T07:23:03.467Z] 07:23:03 WARNING - @tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py:73:8
[task 2020-05-29T07:23:03.467Z] 07:23:03 WARNING -
[task 2020-05-29T07:23:03.467Z] 07:23:03 WARNING -
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - TEST-UNEXPECTED-ERROR | /import-maps/csp/applied-to-target-dynamic.sub.tentative.html | TypeError: window.__wptrunner_process_next_event is not a function
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - Traceback (most recent call last):
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 642, in run_func
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - self.result = True, self.func(self.protocol, self.url, self.timeout)
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 753, in do_testharness
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - self.script_resume % format_map, asynchronous=True)
[task 2020-05-29T07:23:03.471Z] 07:23:03 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 67, in execute_script
[task 2020-05-29T07:23:03.472Z] 07:23:03 INFO - return method(script, new_sandbox=False, sandbox=None)
[task 2020-05-29T07:23:03.472Z] 07:23:03 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1661, in execute_async_script
[task 2020-05-29T07:23:03.473Z] 07:23:03 INFO - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2020-05-29T07:23:03.473Z] 07:23:03 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2020-05-29T07:23:03.473Z] 07:23:03 INFO - return func(*args, **kwargs)
[task 2020-05-29T07:23:03.473Z] 07:23:03 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 602, in _send_message
[task 2020-05-29T07:23:03.473Z] 07:23:03 INFO - self._handle_error(err)
[task 2020-05-29T07:23:03.473Z] 07:23:03 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 622, in _handle_error
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO - JavascriptException: TypeError: window.__wptrunner_process_next_event is not a function
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO - stacktrace:
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO - @tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py:72:8
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO - @tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py:73:8
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO -
[task 2020-05-29T07:23:03.474Z] 07:23:03 INFO - TEST-INFO took 387ms
Comment hidden (Intermittent Failures Robot) |
Updated•4 years ago
|
Updated•4 years ago
|
Comment 2•4 years ago
|
||
It seems that this failure spike starts with the changes from bug 1519335.
whimboo, could you, please, take a look?
Comment 3•4 years ago
|
||
FWIW, __wptrunner_process_next_event
is defined at [1] which is loaded from the top-level test documents. Then we call it in the webdriver_script_resume script at [2]. So the obvious reasons this might be missing are that we're returning too early from the load (i.e. before this code has run) or the page is being navigated (but it's hard to see why that would be intermittent).
[1] https://searchfox.org/mozilla-central/source/testing/web-platform/tests/tools/wptrunner/wptrunner/testharnessreport.js#20
[2] https://searchfox.org/mozilla-central/source/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py#752
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 5•4 years ago
|
||
There is indeed a problem with the navigation. I pushed a try build with some debug lines and the marionette.log.level=Trace
preference set. And here one of the failures with details:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=305017345&repo=try&lineNumber=52774-52783
[task 2020-06-04T09:09:03.181Z] 09:09:03 INFO - STDOUT: *** before navigate to http://web-platform.test:8000/pointerevents/pointerevent_pointerleave_descendant_over.html
[task 2020-06-04T09:09:03.232Z] 09:09:03 INFO - PID 2257 | 1591261743224 Marionette TRACE [20] Frame script loaded
[task 2020-06-04T09:09:03.332Z] 09:09:03 INFO - PID 2257 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-06-04T09:09:03.332Z] 09:09:03 INFO - PID 2257 | [Child 2269, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp, line 377
[task 2020-06-04T09:09:03.382Z] 09:09:03 INFO - PID 2257 | 1591261743323 Marionette TRACE [20] Frame script registered
[task 2020-06-04T09:09:03.432Z] 09:09:03 INFO - PID 2257 | 1591261743395 Marionette DEBUG 2 -> [0,11,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/pointerevents/pointerevent_pointerleave_descendant_over.html"}]
[task 2020-06-04T09:09:03.519Z] 09:09:03 INFO - PID 2257 | 1591261743500 Marionette TRACE [20] Received DOM event beforeunload for about:blank
[task 2020-06-04T09:09:03.520Z] 09:09:03 INFO - PID 2257 | 1591261743506 Marionette TRACE [20] Check readyState complete for about:blank
[task 2020-06-04T09:09:03.541Z] 09:09:03 INFO - PID 2257 | 1591261743533 Marionette DEBUG 2 <- [1,11,null,{"value":null}]
[task 2020-06-04T09:09:03.564Z] 09:09:03 INFO - STDOUT: *** after navigate to http://web-platform.test:8000/pointerevents/pointerevent_pointerleave_descendant_over.html
Somehow the navigate command returns already when about:blank
reaches readyState
=complete
. So the expected page hasn't been loaded at all. This specific check is done in listener.js:
That means tracking for the navigation progress has been started with waitForUnloaded=false
. Maybe this is related to frame script registering some milliseconds before, and that we have an overlap between the initial load of about:blank
and the requested navigation.
Assignee | ||
Comment 6•4 years ago
|
||
In a working case on my local machine I get:
0:10.59 pid:9743 1591263535015 Marionette TRACE [20] Frame script loaded
0:10.59 pid:9743 1591263535016 Marionette TRACE [20] Frame script registered
0:10.61 pid:9743 1591263535033 Marionette TRACE [20] Received DOM event beforeunload for about:blank
0:10.61 pid:9743 1591263535034 Marionette TRACE [20] Check readyState uninitialized for about:blank
0:10.62 pid:9743 1591263535043 Marionette TRACE [20] Received DOM event pagehide for about:blank
0:10.62 pid:9743 1591263535044 Marionette TRACE [20] Received DOM event unload for about:blank
0:10.71 pid:9743 1591263535125 Marionette TRACE [20] Received DOM event DOMContentLoaded for http://web-platform.test:8000/pointerevents/pointerevent_pointerleave_descendant_over.html
Note that in the failing case the check for the readyState
happened after around 200ms, and here right away. I will try to replicate it locally with an additional sleep. Maybe I can force this failure.
Assignee | ||
Comment 7•4 years ago
|
||
So there is clearly a race here. The test window gets opened as a tab via window.open()
but the script doesn't wait until the tab is loaded. As such we have the conflict with the immediate navigation request for the test page and the ongoing navigation for about:blank
.
For a while we already have the new window command in Marionette implemented, and actually should make use of it. It will open the tab, and return the handle when it's ready. By using this method we should no longer face this problem. Here a try build on top of my changes, which seem to make this failure more prominent:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=90f1692e8af69d18c5dc696ec4a8751aa07f4b72
Assignee | ||
Comment 8•4 years ago
|
||
Assignee | ||
Comment 9•4 years ago
|
||
The try job looks great. So I already uploaded the patch and triggered another try job with a lot more different tests:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f229e666011eedd38b6774c27f0200baa4ad0af2
Updated•4 years ago
|
Updated•4 years ago
|
Updated•4 years ago
|
Updated•4 years ago
|
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 11•4 years ago
|
||
The try build works great but there is a single test that unexpectedly passes now for Fission:
Given that it is perma passing now, I would assume we can remove the expected fail entry from the test manifest.
Comment 13•4 years ago
|
||
Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/3cbc95109a5e [wptrunner] Wait for "about:blank" being loaded after opening testrunner tab. r=jgraham
Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/24031 for changes under testing/web-platform/tests
Upstream web-platform-tests status checks passed, PR will merge once commit reaches central.
Comment 16•4 years ago
|
||
bugherder |
Upstream PR merged by moz-wptsync-bot
Description
•