1757625 - Perma [tier 2] testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_return_value_on_alert | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for

Status: RESOLVED DUPLICATE of bug 1757561

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

Description

[Treeherder Bug Filer]

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

---

[task 2022-03-01T17:20:22.680Z] 17:20:22     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_return_value_on_alert
[task 2022-03-01T17:20:22.681Z] 17:20:22     INFO -  1646155222680	Marionette	DEBUG	Accepted connection 355 from 127.0.0.1:45968
[task 2022-03-01T17:20:22.682Z] 17:20:22     INFO -  1646155222681	Marionette	DEBUG	355 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-03-01T17:20:22.684Z] 17:20:22     INFO -  1646155222684	RemoteAgent	TRACE	[24] Document already finished loading: about:blank
[task 2022-03-01T17:20:22.686Z] 17:20:22     INFO -  1646155222685	Marionette	DEBUG	355 <- [1,1,null,{"sessionId":"85bb7280-8deb-4d5b-9b97-d79c73bc5c33","capabilities":{"browserName":"firefox","browserVersion":"99.0a ... u.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-03-01T17:20:22.687Z] 17:20:22     INFO -  1646155222686	Marionette	DEBUG	355 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-03-01T17:20:22.687Z] 17:20:22     INFO -  1646155222687	Marionette	DEBUG	355 <- [1,2,null,{"value":null}]
[task 2022-03-01T17:20:22.688Z] 17:20:22     INFO -  1646155222688	Marionette	DEBUG	355 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-03-01T17:20:22.689Z] 17:20:22     INFO -  1646155222688	Marionette	DEBUG	355 <- [1,3,null,{"value":null}]
[task 2022-03-01T17:20:22.690Z] 17:20:22     INFO -  1646155222689	Marionette	DEBUG	355 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-03-01T17:20:22.690Z] 17:20:22     INFO -  1646155222689	Marionette	DEBUG	355 <- [1,4,null,{"value":null}]
[task 2022-03-01T17:20:22.691Z] 17:20:22     INFO -  1646155222691	Marionette	DEBUG	355 -> [0,5,"WebDriver:SetTimeouts",{"script":1000}]
[task 2022-03-01T17:20:22.692Z] 17:20:22     INFO -  1646155222691	Marionette	DEBUG	355 <- [1,5,null,{"value":null}]
[task 2022-03-01T17:20:22.693Z] 17:20:22     INFO -  1646155222693	Marionette	DEBUG	355 -> [0,6,"WebDriver:ExecuteAsyncScript",{"script":"alert()","args":[],"newSandbox":true,"sandbox":"default","scriptTimeout":null,"line":207,"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py"}]
[task 2022-03-01T17:20:22.697Z] 17:20:22     INFO -  1646155222694	Marionette	TRACE	[24] MarionetteCommands actor created for window id 4294967421
[task 2022-03-01T17:20:22.725Z] 17:20:22     INFO -  JavaScript error: resource://gre/modules/XPCOMUtils.jsm, line 161: NS_ERROR_XPC_GS_RETURNED_FAILURE: ServiceManager::GetService returned failure code:
[task 2022-03-01T17:20:23.695Z] 17:20:23     INFO -  JavaScript error: chrome://remote/content/shared/webdriver/Errors.jsm, line 183: ScriptTimeoutError: Timed out after 1000 ms
[task 2022-03-01T17:20:35.782Z] 17:20:35     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-03-01T17:20:35.785Z] 17:20:35     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-03-01T17:20:50.787Z] 17:20:50     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-03-01T17:20:50.791Z] 17:20:50     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-03-01T17:26:22.781Z] 17:26:22     INFO -  1646155582780	Marionette	DEBUG	355 <- [1,6,null,{"value":null}]
[task 2022-03-01T17:26:22.783Z] 17:26:22     INFO -  1646155582782	Marionette	DEBUG	Closed connection 355
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_return_value_on_alert | 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-03-01T17:27:33.846Z] 17:27:33     INFO - Traceback (most recent call last):
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -     testMethod()
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py", line 207, in test_return_value_on_alert
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -     res = self.marionette.execute_async_script("alert()")
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1763, in execute_async_script
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -     m._handle_socket_failure()
[task 2022-03-01T17:27:33.846Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 745, in _handle_socket_failure
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 702, in reraise
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -     raise value.with_traceback(tb)
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -     return func(*args, **kwargs)
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 661, in _send_message
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -     msg = self.client.request(name, params)
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 383, in request
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -     return self.receive()
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/transport.py", line 221, in receive
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO -     "Connection timed out after {}s".format(self.socket_timeout)
[task 2022-03-01T17:27:33.847Z] 17:27:33     INFO - TEST-INFO took 431162ms
[task 2022-03-01T17:27:33.847Z] 17:27:33    ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_return_value_on_alert 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 \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py\", line 235, in run\n    self.tearDown()\n  File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py\", line 22, in tearDown\n    if self.alert_present():\n  File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py\", line 29, in alert_present\n    Alert(self.marionette).text\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 430, in text\n    return self.marionette._send_message(\"WebDriver:GetAlertText\", key=\"value\")\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 658, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_execute_async_script.TestExecuteAsyncContent", "method_name": "test_return_value_on_alert"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_return_value_on_alert", "status": "ERROR"}
[task 2022-03-01T17:27:33.848Z] 17:27:33     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncContent.test_same_context

Comment 1

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

Same underlying issue as bug 1757561 and fixed with the backout of the offending patch.

Comment 2

[Cristian Tuns]

Thank you for investigating, Whimboo!

Comment 3

[BMO Automation]

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