Intermittent 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)

RESOLVED FIXED in Firefox 66

Status

defect
P1
normal
RESOLVED FIXED
7 months ago
4 months ago

People

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

Tracking

(Depends on 1 bug, Blocks 1 bug, {intermittent-failure, regression})

Version 3
mozilla66
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr60 unaffected, firefox64 unaffected, firefox65 unaffected, firefox66 fixed)

Details

Attachments

(1 attachment)

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
Status: NEW → RESOLVED
Closed: 7 months ago
Keywords: regression
Resolution: --- → WORKSFORME
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.
Blocks: 1504756
Assignee: nobody → hskupin
Resolution: WORKSFORME → FIXED
Target Milestone: --- → mozilla66

Sorry, I missed to address this regression before landing the patch series on bug 1504756 again. I will check that failure soon.

Status: RESOLVED → REOPENED
Resolution: FIXED → ---

The solution here would be to pre-load a web page which already causes a remoteness change to happen. As such loading another page through the location bar won't trigger a remoteness change, which then prevents us from hanging in WebDriver:FindElement.

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
Status: ASSIGNED → RESOLVED
Closed: 7 months ago6 months ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.