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

Status: RESOLVED FIXED

(Testing :: Marionette Client and Harness, defect, P1)

Description

[Treeherder Bug Filer]

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	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid host permission: resource://pdf.js/
[task 2018-12-05T23:17:31.895Z] 23:17:31     INFO -  1544051851892	[e-mail]	WARN	Loading extension '[e-mail]': Reading manifest: Invalid host permission: about:reader*

Comment 1

[Intermittent Failures Robot]

12 failures in 1862 pushes (0.006 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 4
* autoland: 8

Platform breakdown:
* windows10-64-ccov: 1
* linux64: 7
* linux32: 2
* linux64-nightly: 1
* macosx64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1512336&startday=2018-12-03&endday=2018-12-09&tree=all

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1]]

... 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 4

[Intermittent Failures Robot]

31 failures in 2485 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* autoland: 17
* mozilla-central: 8
* mozilla-inbound: 6

Platform breakdown:
* linux32-nightly: 1
* linux64-ccov: 2
* windows7-32: 2
* windows10-64-ccov: 2
* osx-10-10: 4
* linux64: 20

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1512336&startday=2018-12-10&endday=2018-12-16&tree=all

Comment 5

[Intermittent Failures Robot]

14 failures in 2648 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-central: 7
* try: 1
* mozilla-inbound: 2
* autoland: 4

Platform breakdown:
* linux64-ccov: 1
* windows10-64-ccov: 3
* linux32: 2
* linux64: 5
* osx-10-10: 2
* linux64-nightly: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1512336&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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.

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+1]]

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=221111094&repo=autoland&lineNumber=18446

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+1]]

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.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+1]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=c1992f74c46da816fd1dac788ffa2b9ecff02b20

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+1]]

Attachment: Bug 1512336 - [marionette] Fix hang in TestNavigate.test_set_location_through_execute_script. r?ato

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

[Pulsebot]

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

Comment 14

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/70cf6c6c51b4

Comment 15

[Intermittent Failures Robot]

11 failures in 2627 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6
• mozilla-inbound: 5

Platform breakdown:

• linux32: 2
• osx-10-10: 1
• linux64: 8

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1512336&startday=2019-01-07&endday=2019-01-13&tree=all

Comment 16

[Intermittent Failures Robot]

2 failures in 2378 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 2

Platform breakdown:

• linux64: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1512336&startday=2019-01-14&endday=2019-01-20&tree=all

Comment 17

[BMO Automation]

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