1787749 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem | OSError: Process killed because the connection (hang in WebDriver:ElementClick)

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=388758142&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/EnkLmVSVRZOIFaJLtL6LBA/runs/0/artifacts/public/logs/live_backing.log

---

[task 2022-08-29T12:19:32.372Z] 12:19:32     INFO -  1661775572372	Marionette	DEBUG	10 <- [1,54,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"970e3be2-5ded-4ee8-a079-79a51bcfb7bd"}}]
[task 2022-08-29T12:19:32.372Z] 12:19:32     INFO -  1661775572372	Marionette	DEBUG	10 -> [0,55,"WebDriver:FindElement",{"value":"options-menupopup","using":"id"}]
[task 2022-08-29T12:19:32.373Z] 12:19:32     INFO -  1661775572373	Marionette	DEBUG	10 <- [1,55,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"64976e23-f7a8-4216-837e-50d196d86a23"}}]
[task 2022-08-29T12:19:32.374Z] 12:19:32     INFO -  1661775572374	Marionette	DEBUG	10 -> [0,56,"WebDriver:FindElement",{"value":"test-window","using":"id"}]
[task 2022-08-29T12:19:32.374Z] 12:19:32     INFO -  1661775572374	Marionette	DEBUG	10 <- [1,56,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"52f1b3c9-7703-4e04-b15e-7a525b38e640"}}]
[task 2022-08-29T12:19:32.375Z] 12:19:32     INFO -  1661775572375	Marionette	DEBUG	10 -> [0,57,"WebDriver:GetElementProperty",{"id":"64976e23-f7a8-4216-837e-50d196d86a23","name":"state"}]
[task 2022-08-29T12:19:32.375Z] 12:19:32     INFO -  1661775572376	Marionette	DEBUG	10 <- [1,57,null,{"value":"closed"}]
[task 2022-08-29T12:19:32.377Z] 12:19:32     INFO -  1661775572376	Marionette	DEBUG	10 -> [0,58,"WebDriver:ElementClick",{"id":"347937a2-b9e7-4f55-b0b9-91f0ecaff83f"}]
[task 2022-08-29T12:25:32.381Z] 12:25:32     INFO -  1661775932382	Marionette	DEBUG	Closed connection 10
[task 2022-08-29T12:26:44.051Z] 12:26:44    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
[task 2022-08-29T12:26:44.062Z] 12:26:44     INFO -  Traceback (most recent call last):
[task 2022-08-29T12:26:44.063Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-08-29T12:26:44.063Z] 12:26:44     INFO -      testMethod()
[task 2022-08-29T12:26:44.063Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_sendkeys_menupopup_chrome.py", line 100, in test_sendkeys_hidden_disabled_menuitem
[task 2022-08-29T12:26:44.063Z] 12:26:44     INFO -      self.open_context_menu()
[task 2022-08-29T12:26:44.064Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_sendkeys_menupopup_chrome.py", line 50, in open_context_menu
[task 2022-08-29T12:26:44.064Z] 12:26:44     INFO -      attempt_open_context_menu()
[task 2022-08-29T12:26:44.064Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_sendkeys_menupopup_chrome.py", line 43, in attempt_open_context_menu
[task 2022-08-29T12:26:44.065Z] 12:26:44     INFO -      self.click_el.click()
[task 2022-08-29T12:26:44.065Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\marionette.py", line 261, in click
[task 2022-08-29T12:26:44.067Z] 12:26:44     INFO -      self.marionette._send_message("WebDriver:ElementClick", {"id": self.id})
[task 2022-08-29T12:26:44.067Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-08-29T12:26:44.068Z] 12:26:44     INFO -      m._handle_socket_failure()
[task 2022-08-29T12:26:44.068Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\marionette.py", line 743, in _handle_socket_failure
[task 2022-08-29T12:26:44.068Z] 12:26:44     INFO -      reraise(
[task 2022-08-29T12:26:44.069Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-08-29T12:26:44.069Z] 12:26:44     INFO -      raise value.with_traceback(tb)
[task 2022-08-29T12:26:44.070Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-08-29T12:26:44.070Z] 12:26:44     INFO -      return func(*args, **kwargs)
[task 2022-08-29T12:26:44.070Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\marionette.py", line 659, in _send_message
[task 2022-08-29T12:26:44.070Z] 12:26:44     INFO -      msg = self.client.request(name, params)
[task 2022-08-29T12:26:44.071Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\transport.py", line 383, in request
[task 2022-08-29T12:26:44.071Z] 12:26:44     INFO -      return self.receive()
[task 2022-08-29T12:26:44.071Z] 12:26:44     INFO -    File "Z:\task_166177308130938\build\venv\lib\site-packages\marionette_driver\transport.py", line 220, in receive
[task 2022-08-29T12:26:44.072Z] 12:26:44     INFO -      raise socket.timeout(
[task 2022-08-29T12:26:44.072Z] 12:26:44     INFO -  TEST-INFO took 431797ms
[task 2022-08-29T12:26:44.075Z] 12:26:44     INFO -  test_end for testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n  File \"Z:\\task_166177308130938\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 235, in run\n    self.tearDown()\n  File \"Z:\\task_166177308130938\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_sendkeys_menupopup_chrome.py\", line 67, in tearDown\n    super(TestSendkeysMenupopup, self).tearDown()\n  File \"Z:\\task_166177308130938\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\mixins\\window_manager.py\", line 24, in tearDown\n    if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n  File \"Z:\\task_166177308130938\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1393, in chrome_window_handles\n    with self.using_context(\"chrome\"):\n  File \"c:\\mozilla-build\\python3\\lib\\contextlib.py\", line 117, in __enter__\n    return next(self.gen)\n  File \"Z:\\task_166177308130938\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1462, in using_context\n    scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\n  File \"Z:\\task_166177308130938\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_166177308130938\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 656, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_sendkeys_menupopup_chrome.TestSendkeysMenupopup", "method_name": "test_sendkeys_hidden_disabled_menuitem"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_hidden_disabled_menuitem", "status": "ERROR"}
[task 2022-08-29T12:26:44.076Z] 12:26:44     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_sendkeys_menupopup_chrome.py TestSendkeysMenupopup.test_sendkeys_menuitem
[task 2022-08-29T12:26:44.076Z] 12:26:44     INFO -  Application command: Z:\task_166177308130938\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_166177308130938\AppData\Local\Temp\tmpp4bsdwah.mozrunner
[task 2022-08-29T12:26:44.259Z] 12:26:44     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-08-29T12:26:44.272Z] 12:26:44     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change

Comment 1

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

There is a hang in WebDriver:ElementClick. Lets see how often it fails.

Comment 2

[Intermittent Failures Robot]

1 failures in 3537 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1787749&startday=2022-08-29&endday=2022-09-04&tree=all

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 4

[BMO Automation]

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