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
6 months ago
3 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)

Reporter

Description

6 months ago
treeherder
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*
Comment hidden (Intermittent Failures Robot)
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.
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
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
Last Resolved: 5 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.

Depends on: 1519354
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.

Comment 13

5 months ago
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

Comment 14

4 months ago
bugherder
Status: ASSIGNED → RESOLVED
Last Resolved: 5 months ago4 months ago
Resolution: --- → FIXED
Comment hidden (Intermittent Failures Robot)
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.