Closed Bug 1595885 Opened 3 months ago Closed 3 months ago

Perma [tier2] Linux asan NoSuchWindowException: Browsing context has been discarded - /shadow-dom/untriaged/shadow-trees/nested-shadow-trees/nested_tree_reftest.html

Categories

(Testing :: Marionette, defect, P2)

defect

Tracking

(firefox72 fixed)

RESOLVED FIXED
mozilla72
Tracking Status
firefox72 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: jgraham)

References

(Regression)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell needswork:owner])

Attachments

(2 files)

Filed by: csabou [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=275851341&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fZwzSJbzQ_2waGoyEEvImA/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fZwzSJbzQ_2waGoyEEvImA/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2019-11-12T19:34:07.372Z] 19:34:07 INFO - TEST-TIMEOUT | /portals/portals-rendering.html | took 40202ms
[task 2019-11-12T19:34:07.373Z] 19:34:07 INFO - TEST-START | /shadow-dom/untriaged/shadow-trees/nested-shadow-trees/nested_tree_reftest.html
[task 2019-11-12T19:34:07.430Z] 19:34:07 CRITICAL - Traceback (most recent call last):
[task 2019-11-12T19:34:07.431Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 126, in run_test
[task 2019-11-12T19:34:07.433Z] 19:34:07 CRITICAL - return self.executor.run_test(test)
[task 2019-11-12T19:34:07.434Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/base.py", line 191, in run_test
[task 2019-11-12T19:34:07.435Z] 19:34:07 CRITICAL - self.on_environment_change(test.environment)
[task 2019-11-12T19:34:07.437Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 812, in on_environment_change
[task 2019-11-12T19:34:07.438Z] 19:34:07 CRITICAL - self.protocol.on_environment_change(self.last_environment, new_environment)
[task 2019-11-12T19:34:07.440Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 565, in on_environment_change
[task 2019-11-12T19:34:07.441Z] 19:34:07 CRITICAL - self.executor.original_pref_values[name] = self.prefs.get(name)
[task 2019-11-12T19:34:07.443Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 313, in get
[task 2019-11-12T19:34:07.444Z] 19:34:07 CRITICAL - self.marionette.execute_script(script)
[task 2019-11-12T19:34:07.446Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1596, in execute_script
[task 2019-11-12T19:34:07.446Z] 19:34:07 CRITICAL - rv = self._send_message("WebDriver:ExecuteScript", body, key="value")
[task 2019-11-12T19:34:07.447Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-11-12T19:34:07.447Z] 19:34:07 CRITICAL - return func(*args, **kwargs)
[task 2019-11-12T19:34:07.448Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 598, in _send_message
[task 2019-11-12T19:34:07.448Z] 19:34:07 CRITICAL - self._handle_error(err)
[task 2019-11-12T19:34:07.448Z] 19:34:07 CRITICAL - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 618, in handle_error
[task 2019-11-12T19:34:07.449Z] 19:34:07 CRITICAL - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2019-11-12T19:34:07.449Z] 19:34:07 CRITICAL - NoSuchWindowException: Browsing context has been discarded
[task 2019-11-12T19:34:07.450Z] 19:34:07 CRITICAL - stacktrace:
[task 2019-11-12T19:34:07.450Z] 19:34:07 CRITICAL - WebDriverError@chrome://marionette/content/error.js:175:5
[task 2019-11-12T19:34:07.451Z] 19:34:07 CRITICAL - NoSuchWindowError@chrome://marionette/content/error.js:409:5
[task 2019-11-12T19:34:07.451Z] 19:34:07 CRITICAL - assert.that/<@chrome://marionette/content/assert.js:428:13
[task 2019-11-12T19:34:07.452Z] 19:34:07 CRITICAL - assert.open@chrome://marionette/content/assert.js:183:72
[task 2019-11-12T19:34:07.452Z] 19:34:07 CRITICAL - GeckoDriver.prototype.execute
@chrome://marionette/content/driver.js:1023:10
[task 2019-11-12T19:34:07.452Z] 19:34:07 CRITICAL - GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:943:30
[task 2019-11-12T19:34:07.453Z] 19:34:07 CRITICAL - despatch@chrome://marionette/content/server.js:305:40
[task 2019-11-12T19:34:07.453Z] 19:34:07 CRITICAL - execute@chrome://marionette/content/server.js:275:16
[task 2019-11-12T19:34:07.454Z] 19:34:07 CRITICAL - onPacket/<@chrome://marionette/content/server.js:248:20
[task 2019-11-12T19:34:07.454Z] 19:34:07 CRITICAL - onPacket@chrome://marionette/content/server.js:249:9
[task 2019-11-12T19:34:07.455Z] 19:34:07 CRITICAL - _onJSONObjectReady/<@chrome://marionette/content/transport.js:501

Looks like the stack trace stops at marionette, it doesn't give me enough information to determine where is the root cause. Keep NI to me, I'll trace into that.

I could reproduce this one locally with Linux asan+debug build by the following command,
./mach wpt --test-types reftest --include testing/web-platform/tests/portals/ --include testing/web-platform/tests/shadow-dom/

And it seems that testrunner tries to setup perf for shadow-dom tests but failed.

0:51.85 CRITICAL Traceback (most recent call last):
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 126, in run_test
return self.executor.run_test(test)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/base.py", line 191, in run_test
self.on_environment_change(test.environment)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 812, in on_environment_change
self.protocol.on_environment_change(self.last_environment, new_environment)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 565, in on_environment_change
self.executor.original_pref_values[name] = self.prefs.get(name)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/web-platform/tests/tools/wptrunner/wptrunner/executors/executormarionette.py", line 313, in get
self.marionette.execute_script(script)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/marionette/client/marionette_driver/marionette.py", line 1596, in execute_script
rv = self._send_message("WebDriver:ExecuteScript", body, key="value")
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/marionette/client/marionette_driver/decorators.py", line 26, in _
return func(*args, **kwargs)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/marionette/client/marionette_driver/marionette.py", line 598, in _send_message
self._handle_error(err)
File "/home/edgar/Workspace/mercurial/mozilla-central_asan/testing/marionette/client/marionette_driver/marionette.py", line 618, in handle_error
raise errors.lookup(error)(message, stacktrace=stacktrace)
NoSuchWindowException: Browsing context has been discarded
stacktrace:
WebDriverError@chrome://marionette/content/error.js:175:5
NoSuchWindowError@chrome://marionette/content/error.js:409:5
assert.that/<@chrome://marionette/content/assert.js:428:13
assert.open@chrome://marionette/content/assert.js:183:72
GeckoDriver.prototype.execute
@chrome://marionette/content/driver.js:1023:10
GeckoDriver.prototype.executeScript@chrome://marionette/content/driver.js:943:30
despatch@chrome://marionette/content/server.js:305:40
execute@chrome://marionette/content/server.js:275:16
onPacket/<@chrome://marionette/content/server.js:248:20
onPacket@chrome://marionette/content/server.js:249:9
_onJSONObjectReady/<@chrome://marionette/content/transport.js:501:20

Priority: -- → P2

Hi :jgraham,
You're the person who recently changed marionette reftest code. Per comment 7, it seems the problem happened at marionette, I also have a try with marionette log level = trace at [1]. Could you help to take a look? Thank you.

[1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=86025632bbcb60070691a5e14cd3b968c57baaef&selectedJob=276036693

Flags: needinfo?(jdai) → needinfo?(james)

It seems the test runner tries to run shadow-dom tests and also restart runner at the same time? I guess maybe there is some racing/timing issue in test runner for TIMEOUT handling?

take https://firefoxci.taskcluster-artifacts.net/fZwzSJbzQ_2waGoyEEvImA/0/public/logs/live_backing.log as an example.

[task 2019-11-12T19:32:37.193Z] 19:32:37 INFO - TEST-TIMEOUT | /portals/portals-rendering.html | took 40188ms
[task 2019-11-12T19:32:37.193Z] 19:32:37 INFO - TEST-START | /shadow-dom/untriaged/shadow-trees/nested-shadow-trees/nested_tree_reftest.html

Test starts immediately after /portals/portals-rendering.html which is an expected TIMEOUT test.

[task 2019-11-12T19:32:37.318Z] 19:32:37 INFO - queue closed
[task 2019-11-12T19:32:37.318Z] 19:32:37 INFO - PROCESS LEAKS None
[task 2019-11-12T19:32:37.319Z] 19:32:37 INFO - Got 0 unexpected results
[task 2019-11-12T19:32:37.319Z] 19:32:37 INFO - SUITE-END | took 1662s
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - STDERR: Exception in thread TestRunnerManager-1:
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - Traceback (most recent call last):
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - File "/usr/lib/python2.7/threading.py", line 801, in __bootstrap_inner
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - self.run()
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 386, in run
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - new_state = self.wait_event()
[task 2019-11-12T19:32:37.335Z] 19:32:37 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 461, in wait_event
[task 2019-11-12T19:32:37.336Z] 19:32:37 INFO - return f(*data)
[task 2019-11-12T19:32:37.336Z] 19:32:37 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 682, in error
[task 2019-11-12T19:32:37.336Z] 19:32:37 INFO - self.restart_runner()
[task 2019-11-12T19:32:37.337Z] 19:32:37 INFO - File "/builds/worker/workspace/build/tests/web-platform/tests/tools/wptrunner/wptrunner/testrunner.py", line 673, in restart_runner
[task 2019-11-12T19:32:37.337Z] 19:32:37 INFO - assert isinstance(self.state, RunnerManagerState.restarting)
[task 2019-11-12T19:32:37.337Z] 19:32:37 INFO - AssertionError
[task 2019-11-12T19:32:37.398Z] 19:32:37 INFO - Closing logging queue
[task 2019-11-12T19:32:37.398Z] 19:32:37 INFO - queue closed

And it seems test runner tried to restartrunner at the same time.

The problem seems to be that we get a TIMEOUT and then the document gets unloaded so when we come to set prefs there isn't a current window and marionette errors (even though it probably doesn't actually need to at that point). So I think that this was maybe always broken and all that changed is that before we didn't have the situation where we have a timeout followed by setting some prefs.

Flags: needinfo?(james)

Typically we can close the wpt reftest window at the end of a test and
open a new one for the follwing test. But that interacts badly with
the harness trying to run marionette commands before the test starts;
for example when it tries to set a pref. So we were hitting a
situation where tests that TIMEOUT followed by tests that require a
pref end up erroring. To avoid this make sure to set the original
opener window as the marionette window when we close the reftest window.

Component: DOM: Core & HTML → Marionette
Product: Core → Testing
Blocks: 1596424
Pushed by james@hoppipolla.co.uk:
https://hg.mozilla.org/integration/autoland/rev/cc9330b5decd
Ensure we have a valid window after wpt reftest timeout, r=webdriver-reviewers,maja_zf
Duplicate of this bug: 1596424
Status: NEW → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla72
You need to log in before you can comment on or make changes to this bug.