Closed Bug 1559202 Opened 5 years ago Closed 5 years ago

Intermittent JavascriptException: JavaScriptError: Document was unloaded - DON'T USE FOR CLASSIFICATION

Categories

(Core :: DOM: Navigation, defect, P5)

Product:
Core
Component:
DOM: Navigation
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: regression)

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=251697910&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/RnCARvQjRqKw9Lezj8EOoQ/runs/0/artifacts/public/logs/live_backing.log

17:23:26 INFO - TEST-START | /fetch/corb/script-resource-with-json-parser-breaker.tentative.sub.html
17:23:26 INFO - Closing window 21474836481
17:23:26 INFO - PID 5408 | [Parent 2720, Gecko_IOThread] WARNING: pipe error: 109: file z:/task_1560438193/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
17:23:26 INFO - PID 5408 | [Child 5704, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1560438193/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
17:23:26 INFO - PID 5408 | [Child 5704, Chrome_ChildThread] WARNING: pipe error: 109: file z:/task_1560438193/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 341
17:23:26 WARNING - Traceback (most recent call last):
17:23:26 WARNING - File "Z:\task_1560440892\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 624, in _run
17:23:26 WARNING - self.result = True, self.func(self.protocol, self.url, self.timeout)
17:23:26 WARNING - File "Z:\task_1560440892\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 738, in do_testharness
17:23:26 WARNING - self.script_resume % format_map, async=True)
17:23:26 WARNING - File "Z:\task_1560440892\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py", line 61, in execute_script
17:23:26 WARNING - return method(script, new_sandbox=False, sandbox=None)
17:23:26 WARNING - File "Z:\task_1560440892\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1656, in execute_async_script
17:23:26 WARNING - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
17:23:26 WARNING - File "Z:\task_1560440892\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
17:23:26 WARNING - return func(*args, **kwargs)
17:23:26 WARNING - File "Z:\task_1560440892\build\venv\lib\site-packages\marionette_driver\marionette.py", line 598, in _send_message
17:23:26 WARNING - self._handle_error(err)
17:23:26 WARNING - File "Z:\task_1560440892\build\venv\lib\site-packages\marionette_driver\marionette.py", line 618, in _handle_error
17:23:26 WARNING - raise errors.lookup(error)(message, stacktrace=stacktrace)
17:23:26 WARNING - JavascriptException: TypeError: window.__wptrunner_process_next_event is not a function
17:23:26 WARNING - stacktrace:
17:23:26 WARNING - @Z:\task_1560440892\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py:66:8
17:23:26 WARNING - @Z:\task_1560440892\build\tests\web-platform\tests\tools\wptrunner\wptrunner\executors\executormarionette.py:67:8
17:23:26 WARNING -
17:23:26 WARNING -
17:23:26 INFO - TEST-ERROR | /fetch/corb/script-resource-with-json-parser-breaker.tentative.sub.html | took 197ms

Tentatively marked as regressed-by bug 1555287 (which went to m-c the 13th, the same day this started)

Regressed by: 1555287

Andreas, could you please take a look over this? It has 186 failures since the 13th of June. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-05-29&endday=2019-06-28&tree=all&bug=1559202
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=253827095&repo=mozilla-central&lineNumber=8920

[task 2019-06-28T00:17:06.187Z] 00:17:06 WARNING - JavascriptException: JavaScriptError: Document was unloaded
[task 2019-06-28T00:17:06.187Z] 00:17:06 WARNING - stacktrace:
[task 2019-06-28T00:17:06.187Z] 00:17:06 WARNING - WebDriverError@chrome://marionette/content/error.js:179:5
[task 2019-06-28T00:17:06.188Z] 00:17:06 WARNING - JavaScriptError@chrome://marionette/content/error.js:356:5
[task 2019-06-28T00:17:06.188Z] 00:17:06 WARNING - evaluate.sandbox/promise</unloadHandler<@chrome://marionette/content/evaluate.js:124:22
[task 2019-06-28T00:17:06.188Z] 00:17:06 WARNING - onStartRequest@resource://devtools/client/jsonview/converter-child.js:108:19

Component: web-platform-tests → Document Navigation
Flags: needinfo?(afarre)
Product: Testing → Core
Whiteboard: [stockwell disable-recommended]
Version: Version 3 → unspecified

If it starts at Jun 13th, it can be that it is the same as Bug 1555287, which had the broken version back out at the 24th.

I'm PTO until Jul 14th. Nika, Kashav, can maybe look at it, otherwise I'll get back to it in two weeks time.

Flags: needinfo?(nika)
Flags: needinfo?(kmadan)

Given the recent failure in central, which shouldn't have the broken version, I'm guessing it's not directly linked to that issue. I've tried to look into it a bit, and here are my notes.

This error is happening due to the document which an async marionette script is running in being unloaded before resolving it's finished promise. Given the stack traces & the fact that it's an async execution, I'm guessing we're looking at https://searchfox.org/mozilla-central/rev/f91bd38732d4a330eba4e780812274b98eb81274/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py#737-738.

The script in question being run is here: https://searchfox.org/mozilla-central/rev/f91bd38732d4a330eba4e780812274b98eb81274/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/testharness_webdriver_resume.js - the resolve callback which is not being called is arguments[arguments.length - 1].

That callback should be called by testharnessreport.js from a call to __wptrunner_process_next_event(): https://searchfox.org/mozilla-central/rev/f91bd38732d4a330eba4e780812274b98eb81274/testing/web-platform/tests/tools/wptrunner/wptrunner/testharnessreport.js#63-65

It appears as though something in the failing test is causing the document which is running the test to navigate before the test runner thinks the test is complete.

Looking at the test itself, it appears as though the test is a known failure. We don't support the TrustedTypes API which it's expecting. This means that the test should synchronously throw, fire the error event, and exit the test due to the test runner's error_handler: https://searchfox.org/mozilla-central/rev/f91bd38732d4a330eba4e780812274b98eb81274/testing/web-platform/tests/resources/testharness.js#3350-3383

However, looking at the test body, it appears as though some of the tests expect location.assign("A string") to raise an exception. Based on a quick test, we don't have that behaviour. Attempting to do so will create a URI using the document's base URI, and will cause document navigation. Without knowing the trusted types spec, I'm guessing that the trusted-types CSP modifies that behaviour.

Thus, the second test in most of the failing tests will actually trigger a document navigation. If that navigation firing an unload races with the error handler (which it appears to do), the document may unload before the test error is reported, causing the marionette error to fire. I'm not sure why occurrences of this failure only started appearing recently though, as these tests appear to have been around for some time.

:jgraham, I'm guessing the fix for this would be to catch and reject attempts to navigate away from the current document before reporting failure as WPT test failures. Would that be a simple-ish thing to do in the test runner?

Flags: needinfo?(nika) → needinfo?(james)
Flags: needinfo?(afarre)
Flags: needinfo?(kmadan)

Failure rate has consistently decreased since June 28th. We'll continue to monitor this. Removing disable-recommended in the meantime.

Whiteboard: [stockwell disable-recommended] → [stockwell unknown]
Keywords: intermittent-failure
Summary: Intermittent JavascriptException: JavaScriptError: Document was unloaded → Intermittent JavascriptException: JavaScriptError: Document was unloaded - DON'T USE FOR CLASSIFICATION

Given Comment 10 this is not a regression caused by Bug 1555287.

No longer regressed by: 1555287

:jgraham, I'm guessing the fix for this would be to catch and reject attempts to navigate away from the current document before reporting failure as WPT test failures. Would that be a simple-ish thing to do in the test runner?

I don't think we can actually prevent navigations; content script can't actually cancel a navigation, and although we could consider adding a feature to marionette to do that from chrome, where I assume it's possible, I'm not sure it's worth the effort. But we certainly can try to make the harness report a more useful error in this case; https://treeherder.mozilla.org/#/jobs?repo=try&selectedJob=255911557&revision=54cf6d7a16507191ed6e5184ca522e9296e3f45c is a patch in that direction, although it looks like it's breaking some tests at the moment.

Flags: needinfo?(james)

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.