Filed by: nbeleuzu [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=215657372&repo=autoland https://queue.taskcluster.net/v1/task/TcX1OX0DTUu1zZ8dtrJ9uA/runs/0/artifacts/public/logs/live_backing.log [task 2018-12-05T23:16:19.150Z] 23:16:19 INFO - 1544051779148 Marionette DEBUG Closed connection 17 [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_set_location_through_execute_script | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s) [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - Traceback (most recent call last): [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - testMethod() [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 131, in test_set_location_through_execute_script [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - message="Target element 'testh1' has not been found") [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/wait.py", line 129, in until [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - rv = condition(self.marionette) [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/expected.py", line 48, in __call__ [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - return _find(marionette, self.locator) [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/expected.py", line 309, in _find [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - el = func(marionette) [task 2018-12-05T23:17:30.259Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/expected.py", line 45, in <lambda> [task 2018-12-05T23:17:30.260Z] 23:17:30 INFO - self.locator = lambda m: m.find_element(*args) [task 2018-12-05T23:17:30.260Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1836, in find_element [task 2018-12-05T23:17:30.260Z] 23:17:30 INFO - body, key="value") [task 2018-12-05T23:17:30.260Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _ [task 2018-12-05T23:17:30.260Z] 23:17:30 INFO - m._handle_socket_failure() [task 2018-12-05T23:17:30.260Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 844, in _handle_socket_failure [task 2018-12-05T23:17:30.261Z] 23:17:30 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb) [task 2018-12-05T23:17:30.261Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _ [task 2018-12-05T23:17:30.261Z] 23:17:30 INFO - return func(*args, **kwargs) [task 2018-12-05T23:17:30.262Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 756, in _send_message [task 2018-12-05T23:17:30.262Z] 23:17:30 INFO - msg = self.client.request(name, params) [task 2018-12-05T23:17:30.263Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request [task 2018-12-05T23:17:30.263Z] 23:17:30 INFO - return self.receive() [task 2018-12-05T23:17:30.263Z] 23:17:30 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive [task 2018-12-05T23:17:30.264Z] 23:17:30 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout)) [task 2018-12-05T23:17:30.264Z] 23:17:30 INFO - TEST-INFO took 431900ms [task 2018-12-05T23:17:30.265Z] 23:17:30 ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_set_location_through_execute_script logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_navigation.TestNavigate", "method_name": "test_set_location_through_execute_script"}, "expected": "PASS", "test": "testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_set_location_through_execute_script", "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_navigation.py\", line 66, in tearDown\n self.marionette.timeout.reset()\n File \"/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/timeout.py\", line 104, in reset\n self.script = DEFAULT_SCRIPT_TIMEOUT\n File \"/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/timeout.py\", line 57, in script\n self._set(\"script\", sec)\n File \"/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/timeout.py\", line 33, in _set\n self._marionette._send_message(\"WebDriver:SetTimeouts\", {name: ms})\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"} [task 2018-12-05T23:17:30.266Z] 23:17:30 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_non_remote_tab [task 2018-12-05T23:17:30.266Z] 23:17:30 INFO - TEST-SKIP | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_non_remote_tab | took 0ms [task 2018-12-05T23:17:30.267Z] 23:17:30 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_remote_tab [task 2018-12-05T23:17:30.267Z] 23:17:30 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /tmp/tmpfTS1hV.mozrunner [task 2018-12-05T23:17:31.893Z] 23:17:31 INFO - 1544051851891 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: resource://pdf.js/ [task 2018-12-05T23:17:31.895Z] 23:17:31 INFO - 1544051851892 addons.webextension.screenshots@mozilla.org WARN Loading extension 'screenshots@mozilla.org': Reading manifest: Invalid host permission: about:reader*

Due to some reason the framescript got moved to a different process while the `Find Element` command was executing: > [task 2018-12-05T23:10:19.089Z] 23:10:19 INFO - 1544051419084 Marionette DEBUG 17 -> [0,18,"WebDriver:FindElement",{"using":"id","value":"testh1"}] [..] > [task 2018-12-05T23:10:19.625Z] 23:10:19 INFO - 1544051419611 Marionette TRACE [32212254721] Frame script loaded > [task 2018-12-05T23:10:19.626Z] 23:10:19 INFO - 1544051419614 Marionette TRACE [32212254721] Frame script registered

... Given that we don't expect that to be happen outside of any navigation request the `Find Element` command hangs. The only idea I have is that loading `http://127.0.0.1:44493/test.html` by setting the value via `window.location.href` caused us to return too early. Checking the test we indeed don't wait for page load events, which is a problem, and needs to be fixed. I will check that when I'm back next week.

The last failure as reported is from December 21st. As such this might have been a regression, and got fixed by a different bug. https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2018-12-03&endday=2019-01-02&tree=all&bug=1512336

Interestingly the failure time frame is equivalent to the life time of my new window patch (bug 1504756) on central. Once it got backed out the failures stopped. I will have to take care of this case before relanding the patch on bug 1504756.

An unexpected remoteness change can cause the "WebDriver:FindElement" command to hang forever. To avoid that already pre-load a web page which enables the remoteness flag.

Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/70cf6c6c51b4 [marionette] Fix hang in TestNavigate.test_set_location_through_execute_script. r=ato

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.