Filed by: hskupin [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=221295551&repo=try

https://queue.taskcluster.net/v1/task/UdFtcwfTQdWl6Ecv54topw/runs/0/artifacts/public/logs/live_backing.log

[task 2019-01-11T11:37:42.797Z] 11:37:42 INFO - 1547206662786 Marionette DEBUG 71 -> [0,12,"WebDriver:NewWindow",{"type":"window","focus":false}]
[task 2019-01-11T11:37:42.839Z] 11:37:42 INFO - 1547206662832 Marionette TRACE Received DOM event activate for [object ChromeWindow]
[task 2019-01-11T11:37:42.843Z] 11:37:42 INFO - 1547206662832 Marionette TRACE Received DOM event focus for [object XULDocument]
[task 2019-01-11T11:37:42.988Z] 11:37:42 INFO - 1547206662986 Marionette TRACE Received observer notification browser-delayed-startup-finished
[task 2019-01-11T11:43:42.897Z] 11:43:42 INFO - 1547207022887 Marionette DEBUG Closed connection 71
[task 2019-01-11T11:44:53.979Z] 11:44:53 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_with_scopes | IOError: Failed to trigger opening a new window: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)

This happens because re-focusing the original window timed out. None of the activate and focus events seem to have fired.

Bug 1523234 will take care of it.

This only affects Linux but no other platform.

There are 26 total failures in the last 7 days

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=233031823&repo=mozilla-inbound&lineNumber=24526

[task 2019-03-11T03:01:06.026Z] 03:01:06 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_with_scopes
[task 2019-03-11T03:01:06.042Z] 03:01:06 INFO - 1552273266029 Marionette DEBUG Closed connection 70

[task 2019-03-11T03:08:17.276Z] 03:08:17 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_with_scopes | IOError: Failed to trigger opening a new window: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
[task 2019-03-11T03:08:17.276Z] 03:08:17 INFO - Traceback (most recent call last):
[task 2019-03-11T03:08:17.276Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-03-11T03:08:17.277Z] 03:08:17 INFO - testMethod()
[task 2019-03-11T03:08:17.277Z] 03:08:17 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py", line 43, in test_chrome_window_handles_with_scopes
[task 2019-03-11T03:08:17.277Z] 03:08:17 INFO - new_browser = self.open_window()
[task 2019-03-11T03:08:17.278Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 110, in open_window
[task 2019-03-11T03:08:17.278Z] 03:08:17 INFO - reraise(exc, 'Failed to trigger opening a new window: {}'.format(val), tb)
[task 2019-03-11T03:08:17.278Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 103, in open_window
[task 2019-03-11T03:08:17.278Z] 03:08:17 INFO - result = self.marionette.open(type="window", focus=focus)
[task 2019-03-11T03:08:17.280Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1448, in open
[task 2019-03-11T03:08:17.280Z] 03:08:17 INFO - return self._send_message("WebDriver:NewWindow", body)
[task 2019-03-11T03:08:17.281Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - m._handle_socket_failure()
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 849, in _handle_socket_failure
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - return func(*args, **kwargs)
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 761, in _send_message
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - msg = self.client.request(name, params)
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - return self.receive()
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
[task 2019-03-11T03:08:17.284Z] 03:08:17 INFO - TEST-INFO took 431244ms
[task 2019-03-11T03:08:17.284Z] 03:08:17 ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_with_scopes logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_window_handles_chrome.TestWindowHandles", "method_name": "test_chrome_window_handles_with_scopes"}, "expected": "PASS", "test": "testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_with_scopes", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 190, in run\n self.tearDown()\n File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py", line 24, in tearDown\n self.close_all_windows()\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 48, in close_all_windows\n current_chrome_window_handles = self.marionette.chrome_window_handles\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1428, in chrome_window_handles\n return self._send_message("WebDriver:GetChromeWindowHandles")\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _\n return func(*args, **kwargs)\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 758, in _send_message\n raise errors.InvalidSessionIdException("Please start a session")\n"}

Henrik are you still working on this?

I haven't gotten a reply from Neil Deakin for 13 days over on bug 1523234. So I might try to experiment something this week.

No more failures since bug 1523234 has been fixed.