Filed by: rmaries [at] mozilla.com

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

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

[task 2019-01-21T14:58:42.383Z] 14:58:42 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_after_opening_new_window
[task 2019-01-21T14:58:42.384Z] 14:58:42 INFO - 1548082722353 Marionette DEBUG Closed connection 69
[task 2019-01-21T14:58:42.388Z] 14:58:42 INFO - 1548082722361 Marionette DEBUG Accepted connection 70 from 127.0.0.1:53366
[task 2019-01-21T14:58:42.389Z] 14:58:42 INFO - 1548082722369 Marionette DEBUG 70 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-01-21T14:58:42.390Z] 14:58:42 INFO - 1548082722373 Marionette TRACE [2147483649] Frame script loaded
[task 2019-01-21T14:58:42.392Z] 14:58:42 INFO - 1548082722381 Marionette TRACE [2147483649] Frame script registered
[task 2019-01-21T14:58:42.393Z] 14:58:42 INFO - 1548082722384 Marionette DEBUG 70 <- [1,1,null,{"sessionId":"4f0d5a05-26e7-467d-a938-01bf5394dc81","capabilities":{"browserName":"firefox","browserVersion":"66.0" ... mp/tmptWVUE2.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-01-21T14:58:42.394Z] 14:58:42 INFO - 1548082722387 Marionette DEBUG 70 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-01-21T14:58:42.395Z] 14:58:42 INFO - 1548082722387 Marionette DEBUG 70 <- [1,2,null,{"value":null}]
[task 2019-01-21T14:58:42.397Z] 14:58:42 INFO - 1548082722388 Marionette DEBUG 70 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-01-21T14:58:42.399Z] 14:58:42 INFO - 1548082722394 Marionette DEBUG 70 <- [1,3,null,{"value":null}]
[task 2019-01-21T14:58:42.400Z] 14:58:42 INFO - 1548082722396 Marionette DEBUG 70 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-01-21T14:58:42.402Z] 14:58:42 INFO - 1548082722397 Marionette DEBUG 70 <- [1,4,null,{"value":null}]
[task 2019-01-21T14:58:42.403Z] 14:58:42 INFO - 1548082722398 Marionette DEBUG 70 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2019-01-21T14:58:42.404Z] 14:58:42 INFO - 1548082722398 Marionette DEBUG 70 <- [1,5,null,{"value":"3"}]
[task 2019-01-21T14:58:42.405Z] 14:58:42 INFO - 1548082722400 Marionette DEBUG 70 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2019-01-21T14:58:42.406Z] 14:58:42 INFO - 1548082722401 Marionette DEBUG 70 <- [1,6,null,["3"]]
[task 2019-01-21T14:58:42.408Z] 14:58:42 INFO - 1548082722402 Marionette DEBUG 70 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2019-01-21T14:58:42.409Z] 14:58:42 INFO - 1548082722403 Marionette DEBUG 70 <- [1,7,null,{"value":"2147483649"}]
[task 2019-01-21T14:58:42.410Z] 14:58:42 INFO - 1548082722404 Marionette DEBUG 70 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2019-01-21T14:58:42.411Z] 14:58:42 INFO - 1548082722405 Marionette DEBUG 70 <- [1,8,null,["2147483649"]]
[task 2019-01-21T14:58:42.412Z] 14:58:42 INFO - 1548082722407 Marionette DEBUG 70 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2019-01-21T14:58:42.413Z] 14:58:42 INFO - 1548082722407 Marionette DEBUG 70 <- [1,9,null,{"value":null}]
[task 2019-01-21T14:58:42.415Z] 14:58:42 INFO - 1548082722409 Marionette DEBUG 70 -> [0,10,"WebDriver:GetChromeWindowHandles",{}]
[task 2019-01-21T14:58:42.416Z] 14:58:42 INFO - 1548082722410 Marionette DEBUG 70 <- [1,10,null,["3"]]
[task 2019-01-21T14:58:42.417Z] 14:58:42 INFO - 1548082722412 Marionette DEBUG 70 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2019-01-21T14:58:42.417Z] 14:58:42 INFO - 1548082722412 Marionette DEBUG 70 <- [1,11,null,["2147483649"]]
[task 2019-01-21T14:58:42.418Z] 14:58:42 INFO - 1548082722413 Marionette DEBUG 70 -> [0,12,"WebDriver:NewWindow",{"type":"window","focus":false}]
[task 2019-01-21T14:58:42.439Z] 14:58:42 INFO - 1548082722436 Marionette TRACE Received DOM event activate for [object ChromeWindow]
[task 2019-01-21T14:58:42.441Z] 14:58:42 INFO - 1548082722436 Marionette TRACE Received DOM event focus for [object HTMLDocument]
[task 2019-01-21T14:58:42.622Z] 14:58:42 INFO - 1548082722619 Marionette TRACE Received observer notification browser-delayed-startup-finished
[task 2019-01-21T15:04:42.520Z] 15:04:42 INFO - 1548083082516 Marionette DEBUG Closed connection 70
[task 2019-01-21T15:05:53.595Z] 15:05:53 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_after_opening_new_window | 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-01-21T15:05:53.595Z] 15:05:53 INFO - Traceback (most recent call last):
[task 2019-01-21T15:05:53.596Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-01-21T15:05:53.596Z] 15:05:53 INFO - testMethod()
[task 2019-01-21T15:05:53.596Z] 15:05:53 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py", line 88, in test_chrome_window_handles_after_opening_new_window
[task 2019-01-21T15:05:53.596Z] 15:05:53 INFO - new_window = self.open_window()
[task 2019-01-21T15:05:53.596Z] 15:05:53 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-01-21T15:05:53.597Z] 15:05:53 INFO - reraise(exc, 'Failed to trigger opening a new window: {}'.format(val), tb)
[task 2019-01-21T15:05:53.597Z] 15:05:53 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-01-21T15:05:53.597Z] 15:05:53 INFO - result = self.marionette.open(type="window", focus=focus)
[task 2019-01-21T15:05:53.597Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1443, in open
[task 2019-01-21T15:05:53.597Z] 15:05:53 INFO - return self._send_message("WebDriver:NewWindow", body)
[task 2019-01-21T15:05:53.599Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2019-01-21T15:05:53.599Z] 15:05:53 INFO - m._handle_socket_failure()
[task 2019-01-21T15:05:53.600Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 844, in _handle_socket_failure
[task 2019-01-21T15:05:53.601Z] 15:05:53 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2019-01-21T15:05:53.601Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-01-21T15:05:53.602Z] 15:05:53 INFO - return func(*args, **kwargs)
[task 2019-01-21T15:05:53.602Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 756, in _send_message
[task 2019-01-21T15:05:53.603Z] 15:05:53 INFO - msg = self.client.request(name, params)
[task 2019-01-21T15:05:53.603Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
[task 2019-01-21T15:05:53.604Z] 15:05:53 INFO - return self.receive()
[task 2019-01-21T15:05:53.604Z] 15:05:53 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive
[task 2019-01-21T15:05:53.605Z] 15:05:53 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
[task 2019-01-21T15:05:53.607Z] 15:05:53 INFO - TEST-INFO took 431240ms
[task 2019-01-21T15:05:53.608Z] 15:05:53 ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_after_opening_new_window logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_window_handles_chrome.TestWindowHandles", "method_name": "test_chrome_window_handles_after_opening_new_window"}, "expected": "PASS", "test": "testing/marionette/harness/marionette_harness/tests/unit/test_window_handles_chrome.py TestWindowHandles.test_chrome_window_handles_after_opening_new_window", "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 1423, 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 753, in _send_message\n raise errors.InvalidSessionIdException("Please start a session")\n"}

There are no focus events when switching back to the original window after opening a new top-level browsing context.

This only affects Linux, but no other platform.

Actually this is only present on beta and for the beta simluations, but not on mozilla-central.

No failures anymore, and bug 1523234 should have fixed it completely.