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

It seems that this failure spike starts with the changes from bug 1519335.

https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&searchStr=windows%2C7%2Cdebug%2Cweb%2Cplatform%2Ctests%2Ctest-windows7-32%2Fdebug-web-platform-tests-e10s-4%2Cw%28wpt4%29&tochange=8613e718e4b14d1d6ca0038960eb2ce7edea75c5&fromchange=7e89a7274770f7db5cb0691fe8e064ef29ce8cb2&selectedTaskRun=eAnSdUclR0aaiH6ZJFagag-0

whimboo, could you, please, take a look?

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

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:

https://searchfox.org/mozilla-central/rev/7cadba1d8b8feaec4615f5bb98aac4b8a719793c/testing/marionette/listener.js#172

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.

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.

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

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

The try build works great but there is a single test that unexpectedly passes now for Fission:

https://treeherder.mozilla.org/#/jobs?repo=try&selectedTaskRun=ACdXgYzxRDSy0m4OgovlhQ-0&revision=08dc4d60f3c00a781ebe5ac94f8e399fcc658e2f

Given that it is perma passing now, I would assume we can remove the expected fail entry from the test manifest.

Yes.

https://hg.mozilla.org/mozilla-central/rev/3cbc95109a5e