1772220 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_click_number_link | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection time

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-01T21:17:39.578Z] 21:17:39     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-01T21:17:39.585Z] 21:17:39     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-01T21:17:42.641Z] 21:17:42     INFO -  DEBUG: Adding blocker JSON store: writing data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-01T21:17:54.587Z] 21:17:54     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-01T21:17:54.594Z] 21:17:54     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-01T21:23:30.466Z] 21:23:30     INFO -  1654118610468	Marionette	TRACE	Retrying "getElementAttribute", attempt: 1
[task 2022-06-01T21:23:30.470Z] 21:23:30     INFO -  1654118610469	Marionette	DEBUG	143 <- [1,37,{"error":"unknown error","message":"NotFoundError: WindowGlobalParent.getActor: No such JSWindowActor 'MarionetteComman ... e/content/marionette/transport.js:221:18\nonInputStreamReady@chrome://remote/content/marionette/transport.js:375:14\n"},null]
[task 2022-06-01T21:23:30.470Z] 21:23:30     INFO -  Marionette threw an error: NotFoundError: WindowGlobalParent.getActor: No such JSWindowActor 'MarionetteCommands'
[task 2022-06-01T21:23:30.471Z] 21:23:30     INFO -  getMarionetteCommandsActorProxy/get/<@chrome://remote/content/marionette/actors/MarionetteCommandsParent.jsm:332:65
[task 2022-06-01T21:23:30.471Z] 21:23:30     INFO -  unregisterCommandsActor@chrome://remote/content/marionette/actors/MarionetteCommandsParent.jsm:396:15
[task 2022-06-01T21:23:30.472Z] 21:23:30     INFO -  GeckoDriver.prototype.deleteSession@chrome://remote/content/marionette/driver.js:2147:3
[task 2022-06-01T21:23:30.472Z] 21:23:30     INFO -  onClosed@chrome://remote/content/marionette/server.js:205:17
[task 2022-06-01T21:23:30.472Z] 21:23:30     INFO -  close@chrome://remote/content/marionette/transport.js:221:18
[task 2022-06-01T21:23:30.473Z] 21:23:30     INFO -  onInputStreamReady@chrome://remote/content/marionette/transport.js:375:14
[task 2022-06-01T21:23:30.473Z] 21:23:30     INFO -  1654118610471	Marionette	DEBUG	Closed connection 143
[task 2022-06-01T21:24:41.823Z] 21:24:41    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_click_number_link | 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-06-01T21:24:41.834Z] 21:24:41     INFO -  Traceback (most recent call last):
[task 2022-06-01T21:24:41.834Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-06-01T21:24:41.834Z] 21:24:41     INFO -      testMethod()
[task 2022-06-01T21:24:41.834Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_click.py", line 119, in test_click_number_link
[task 2022-06-01T21:24:41.835Z] 21:24:41     INFO -      self.marionette.find_element(By.LINK_TEXT, "333333").click()
[task 2022-06-01T21:24:41.835Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\marionette.py", line 261, in click
[task 2022-06-01T21:24:41.835Z] 21:24:41     INFO -      self.marionette._send_message("WebDriver:ElementClick", {"id": self.id})
[task 2022-06-01T21:24:41.835Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-06-01T21:24:41.836Z] 21:24:41     INFO -      m._handle_socket_failure()
[task 2022-06-01T21:24:41.836Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\marionette.py", line 745, in _handle_socket_failure
[task 2022-06-01T21:24:41.836Z] 21:24:41     INFO -      reraise(
[task 2022-06-01T21:24:41.836Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-06-01T21:24:41.837Z] 21:24:41     INFO -      raise value.with_traceback(tb)
[task 2022-06-01T21:24:41.837Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-06-01T21:24:41.837Z] 21:24:41     INFO -      return func(*args, **kwargs)
[task 2022-06-01T21:24:41.837Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\marionette.py", line 661, in _send_message
[task 2022-06-01T21:24:41.837Z] 21:24:41     INFO -      msg = self.client.request(name, params)
[task 2022-06-01T21:24:41.838Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\transport.py", line 383, in request
[task 2022-06-01T21:24:41.838Z] 21:24:41     INFO -      return self.receive()
[task 2022-06-01T21:24:41.838Z] 21:24:41     INFO -    File "Z:\task_165411732986177\build\venv\lib\site-packages\marionette_driver\transport.py", line 220, in receive
[task 2022-06-01T21:24:41.838Z] 21:24:41     INFO -      raise socket.timeout(
[task 2022-06-01T21:24:41.838Z] 21:24:41     INFO -  TEST-INFO took 431607ms
[task 2022-06-01T21:24:41.848Z] 21:24:41     INFO -  test_end for testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_click_number_link 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_165411732986177\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 235, in run\n    self.tearDown()\n  File \"Z:\\task_165411732986177\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_click.py\", line 95, in tearDown\n    self.close_all_tabs()\n  File \"Z:\\task_165411732986177\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\mixins\\window_manager.py\", line 33, in close_all_tabs\n    current_window_handles = self.marionette.window_handles\n  File \"Z:\\task_165411732986177\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1383, in window_handles\n    with self.using_context(\"content\"):\n  File \"c:\\mozilla-build\\python3\\lib\\contextlib.py\", line 117, in __enter__\n    return next(self.gen)\n  File \"Z:\\task_165411732986177\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1464, in using_context\n    scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\n  File \"Z:\\task_165411732986177\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_165411732986177\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 658, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_click.ClickBaseTestCase", "method_name": "test_click_number_link"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_click_number_link", "status": "ERROR"}
[task 2022-06-01T21:24:41.848Z] 21:24:41     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_click.py ClickBaseTestCase.test_clicking_an_element_that_is_not_displayed_raises

Comment 1

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

The socket timed out when trying to delete the active WebDriver session. This failure happened on the same changeset as the newly filed intermittent failure on bug 1772218.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1772220&startday=2022-05-30&endday=2022-06-05&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

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=382710835&repo=autoland

Comment 5

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1772220&startday=2022-06-27&endday=2022-07-03&tree=all

Comment 6

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

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

Comment 7

[BMO Automation]

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