1773012 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors

Status: RESOLVED DUPLICATE of bug 1772218

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

Description

[Treeherder Bug Filer]

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

---

[task 2022-06-07T11:40:20.906Z] 11:40:20     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set
[task 2022-06-07T11:40:20.907Z] 11:40:20     INFO -  1654602020907	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:52743
[task 2022-06-07T11:40:20.907Z] 11:40:20     INFO -  1654602020907	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-06-07T11:40:20.908Z] 11:40:20     INFO -  1654602020908	Marionette	DEBUG	Waiting for initial application window
[task 2022-06-07T11:40:20.909Z] 11:40:20     INFO -  1654602020908	RemoteAgent	TRACE	[24] Document already finished loading: about:blank
[task 2022-06-07T11:40:20.911Z] 11:40:20     INFO -  1654602020910	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"ff64e9ff-63d5-4ea4-a975-54f32536264f","capabilities":{"browserName":"firefox","browserVersion":"103.0 ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-06-07T11:40:20.911Z] 11:40:20     INFO -  1654602020911	Marionette	DEBUG	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-06-07T11:40:20.912Z] 11:40:20     INFO -  1654602020911	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
[task 2022-06-07T11:40:20.912Z] 11:40:20     INFO -  1654602020912	Marionette	DEBUG	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-06-07T11:40:20.913Z] 11:40:20     INFO -  1654602020912	Marionette	DEBUG	2 <- [1,3,null,{"value":null}]
[task 2022-06-07T11:40:20.913Z] 11:40:20     INFO -  1654602020913	Marionette	DEBUG	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-06-07T11:40:20.914Z] 11:40:20     INFO -  1654602020913	Marionette	DEBUG	2 <- [1,4,null,{"value":null}]
[task 2022-06-07T11:40:20.914Z] 11:40:20     INFO -  1654602020914	Marionette	DEBUG	2 -> [0,5,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-06-07T11:40:20.915Z] 11:40:20     INFO -  1654602020914	Marionette	DEBUG	2 <- [1,5,null,{"value":null}]
[task 2022-06-07T11:40:20.915Z] 11:40:20     INFO -  1654602020915	Marionette	DEBUG	2 -> [0,6,"Marionette:GetContext",{}]
[task 2022-06-07T11:40:20.916Z] 11:40:20     INFO -  1654602020915	Marionette	DEBUG	2 <- [1,6,null,{"value":"chrome"}]
<...>
[task 2022-06-07T11:40:24.093Z] 11:40:24     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change and awaiting all checkpoints written for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-07T11:40:24.106Z] 11:40:24     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2022-06-07T11:40:24.137Z] 11:40:24     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2022-06-07T11:40:24.148Z] 11:40:24     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2022-06-07T11:40:24.153Z] 11:40:24     INFO -  1654602024153	Marionette	INFO	Marionette enabled
[task 2022-06-07T11:40:24.155Z] 11:40:24     INFO -  1654602024155	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-06-07T11:40:24.156Z] 11:40:24     INFO -  1654602024156	Marionette	INFO	Listening on port 2828
[task 2022-06-07T11:40:24.156Z] 11:40:24     INFO -  1654602024157	Marionette	DEBUG	Marionette is listening
[task 2022-06-07T11:43:36.010Z] 11:43:36    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set | OSError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2022-06-07T11:43:36.010Z] 11:43:36     INFO -  Traceback (most recent call last):
[task 2022-06-07T11:43:36.016Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 235, in run
[task 2022-06-07T11:43:36.016Z] 11:43:36     INFO -      self.tearDown()
[task 2022-06-07T11:43:36.016Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_prefs_enforce.py", line 18, in tearDown
[task 2022-06-07T11:43:36.017Z] 11:43:36     INFO -      self.marionette.restart(clean=True)
[task 2022-06-07T11:43:36.017Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-06-07T11:43:36.017Z] 11:43:36     INFO -      m._handle_socket_failure()
[task 2022-06-07T11:43:36.018Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\marionette_driver\marionette.py", line 745, in _handle_socket_failure
[task 2022-06-07T11:43:36.018Z] 11:43:36     INFO -      reraise(
[task 2022-06-07T11:43:36.018Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-06-07T11:43:36.018Z] 11:43:36     INFO -      raise value.with_traceback(tb)
[task 2022-06-07T11:43:36.019Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-06-07T11:43:36.019Z] 11:43:36     INFO -      return func(*args, **kwargs)
[task 2022-06-07T11:43:36.019Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1171, in restart
[task 2022-06-07T11:43:36.019Z] 11:43:36     INFO -      self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
[task 2022-06-07T11:43:36.020Z] 11:43:36     INFO -    File "Z:\task_165459887385971\build\venv\lib\site-packages\marionette_driver\marionette.py", line 636, in raise_for_port
[task 2022-06-07T11:43:36.020Z] 11:43:36     INFO -      raise socket.timeout(
[task 2022-06-07T11:43:36.020Z] 11:43:36     INFO -  TEST-INFO took 195088ms
[task 2022-06-07T11:43:36.020Z] 11:43:36     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_restart_preserves_requested_capabilities

Comment 2

[BMO Automation]

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