Closed Bug 1669326 Opened 4 years ago Closed 4 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_remoteness_change | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connect

Categories

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

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: nbeleuzu [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=317650323&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Tl9VzndiQaWPWCFR-MhzmQ/runs/0/artifacts/public/logs/live_backing.log

[task 2020-10-05T17:50:44.516Z] 17:50:44     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-05T17:50:44.531Z] 17:50:44     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-10-05T17:56:26.279Z] 17:56:26     INFO -  1601920586274	Marionette	DEBUG	Closed connection 201
[task 2020-10-05T17:57:37.340Z] 17:57:37     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click.py TestClickNavigation.test_click_remoteness_change | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
[task 2020-10-05T17:57:37.340Z] 17:57:37     INFO - Traceback (most recent call last):
[task 2020-10-05T17:57:37.340Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 196, in run
[task 2020-10-05T17:57:37.341Z] 17:57:37     INFO -     testMethod()
[task 2020-10-05T17:57:37.342Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_click.py", line 467, in test_click_remoteness_change
[task 2020-10-05T17:57:37.342Z] 17:57:37     INFO -     self.marionette.find_element(By.ID, "anchor")
[task 2020-10-05T17:57:37.343Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1691, in find_element
[task 2020-10-05T17:57:37.343Z] 17:57:37     INFO -     body, key="value")
[task 2020-10-05T17:57:37.344Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2020-10-05T17:57:37.344Z] 17:57:37     INFO -     m._handle_socket_failure()
[task 2020-10-05T17:57:37.344Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 682, in _handle_socket_failure
[task 2020-10-05T17:57:37.345Z] 17:57:37     INFO -     reraise(IOError, IOError(message.format(returncode=returncode, reason=exc)), tb)
[task 2020-10-05T17:57:37.345Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2020-10-05T17:57:37.346Z] 17:57:37     INFO -     return func(*args, **kwargs)
[task 2020-10-05T17:57:37.346Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 594, in _send_message
[task 2020-10-05T17:57:37.347Z] 17:57:37     INFO -     msg = self.client.request(name, params)
[task 2020-10-05T17:57:37.347Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 276, in request
[task 2020-10-05T17:57:37.347Z] 17:57:37     INFO -     return self.receive()
[task 2020-10-05T17:57:37.347Z] 17:57:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 186, in receive
[task 2020-10-05T17:57:37.347Z] 17:57:37     INFO -     raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
[task 2020-10-05T17:57:37.348Z] 17:57:37     INFO - TEST-INFO took 432672ms```

Here the real failing lines:

[task 2020-10-05T17:50:25.963Z] 17:50:25     INFO -  1601920225959	Marionette	DEBUG	201 -> [0,23,"WebDriver:ElementClick",{"id":"9c83bb46-cc12-43c6-82f0-2e39d3e05ad5"}]
[task 2020-10-05T17:50:25.999Z] 17:50:25     INFO -  1601920225990	Marionette	TRACE	Received DOM event click for javascript:history.back();
[task 2020-10-05T17:50:25.999Z] 17:50:25     INFO -  DEBUG: Adding blocker UserInteractionTimer 18 for document 7f28e8d38000 for phase xpcom-will-shutdown
[task 2020-10-05T17:50:26.176Z] 17:50:26     INFO -  [Child 2111, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 348
[task 2020-10-05T17:50:26.177Z] 17:50:26     INFO -  [Child 2111, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 348
[task 2020-10-05T17:50:26.178Z] 17:50:26     INFO -  1601920226173	Marionette	TRACE	Canceled page load listener because no navigation has been detected
[task 2020-10-05T17:50:26.178Z] 17:50:26     INFO -  1601920226173	Marionette	DEBUG	201 <- [1,23,null,{"value":null}]
[task 2020-10-05T17:50:26.179Z] 17:50:26     INFO -  1601920226177	Marionette	DEBUG	201 -> [0,24,"WebDriver:FindElement",{"using":"id","value":"anchor"}]
[task 2020-10-05T17:50:26.187Z] 17:50:26     INFO -  1601920226183	Marionette	TRACE	[172] Frame script unloaded
[task 2020-10-05T17:50:26.195Z] 17:50:26     INFO -  1601920226193	Marionette	TRACE	[174] Frame script loaded
[task 2020-10-05T17:50:26.210Z] 17:50:26     INFO -  updateSessionStoreFromTablistener() with sHistoryNeeded, but no sessionHistory.
[task 2020-10-05T17:50:26.211Z] 17:50:26     INFO -  1601920226205	Marionette	TRACE	Detected remoteness change. New browsing context: 174

As it can be seen the command WebDriver:FindElement just hangs due to a remoteness change. As such this needs a solution on bug 1519354.

Depends on: 1519354

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.