1772218 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py <test-name> | OSError: Process killed because the connection to Marionette server is lost

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=379946139&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BXWB_KFwTZqn3VnVmDsDyw/runs/0/artifacts/public/logs/live_backing.log

---

[task 2022-06-01T20:56:26.988Z] 20:56:26     INFO -  Application command: Z:\task_165411596392701\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_165411596392701\AppData\Local\Temp\tmp1hbj7n4w.mozrunner
[task 2022-06-01T20:56:27.137Z] 20:56:27     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-06-01T20:56:27.160Z] 20:56:27     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2022-06-01T20:56:27.166Z] 20:56:27     INFO -  DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2022-06-01T20:56:27.194Z] 20:56:27     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-06-01T20:56:27.292Z] 20:56:27     INFO -  DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2022-06-01T20:56:27.304Z] 20:56:27     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2022-06-01T20:56:27.308Z] 20:56:27     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2022-06-01T20:56:27.310Z] 20:56:27     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-06-01T20:56:27.310Z] 20:56:27     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2022-06-01T20:56:27.312Z] 20:56:27     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-01T20:56:27.325Z] 20:56:27     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2022-06-01T20:56:27.357Z] 20:56:27     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2022-06-01T20:56:27.369Z] 20:56:27     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2022-06-01T20:56:27.373Z] 20:56:27     INFO -  1654116987373	Marionette	INFO	Marionette enabled
[task 2022-06-01T20:56:27.375Z] 20:56:27     INFO -  1654116987375	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-06-01T20:56:27.376Z] 20:56:27     INFO -  1654116987376	Marionette	INFO	Listening on port 2828
[task 2022-06-01T20:56:27.376Z] 20:56:27     INFO -  1654116987376	Marionette	DEBUG	Marionette is listening
[task 2022-06-01T20:59:39.145Z] 20:59:39    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_change_enforced_preference | 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-01T20:59:39.145Z] 20:59:39     INFO -  Traceback (most recent call last):
[task 2022-06-01T20:59:39.145Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-06-01T20:59:39.157Z] 20:59:39     INFO -      testMethod()
[task 2022-06-01T20:59:39.157Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_prefs_enforce.py", line 38, in test_change_enforced_preference
[task 2022-06-01T20:59:39.157Z] 20:59:39     INFO -      self.enforce_prefs()
[task 2022-06-01T20:59:39.157Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_prefs_enforce.py", line 29, in enforce_prefs
[task 2022-06-01T20:59:39.158Z] 20:59:39     INFO -      self.marionette.enforce_gecko_prefs(prefs or test_prefs)
[task 2022-06-01T20:59:39.158Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-06-01T20:59:39.158Z] 20:59:39     INFO -      m._handle_socket_failure()
[task 2022-06-01T20:59:39.158Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\marionette_driver\marionette.py", line 745, in _handle_socket_failure
[task 2022-06-01T20:59:39.158Z] 20:59:39     INFO -      reraise(
[task 2022-06-01T20:59:39.159Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-06-01T20:59:39.159Z] 20:59:39     INFO -      raise value.with_traceback(tb)
[task 2022-06-01T20:59:39.159Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-06-01T20:59:39.159Z] 20:59:39     INFO -      return func(*args, **kwargs)
[task 2022-06-01T20:59:39.160Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\marionette_driver\marionette.py", line 941, in enforce_gecko_prefs
[task 2022-06-01T20:59:39.160Z] 20:59:39     INFO -      self.raise_for_port()
[task 2022-06-01T20:59:39.160Z] 20:59:39     INFO -    File "Z:\task_165411596392701\build\venv\lib\site-packages\marionette_driver\marionette.py", line 636, in raise_for_port
[task 2022-06-01T20:59:39.160Z] 20:59:39     INFO -      raise socket.timeout(
[task 2022-06-01T20:59:39.160Z] 20:59:39     INFO -  TEST-INFO took 192264ms
[task 2022-06-01T20:59:39.162Z] 20:59:39     INFO -  test_end for testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_change_enforced_preference 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_165411596392701\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 235, in run\n    self.tearDown()\n  File \"Z:\\task_165411596392701\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_prefs_enforce.py\", line 18, in tearDown\n    self.marionette.restart(clean=True)\n  File \"Z:\\task_165411596392701\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_165411596392701\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 1090, in restart\n    context = self._send_message(\"Marionette:GetContext\", key=\"value\")\n  File \"Z:\\task_165411596392701\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_165411596392701\\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_prefs_enforce.TestEnforcePreferences", "method_name": "test_change_enforced_preference"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_change_enforced_preference", "status": "ERROR"}
[task 2022-06-01T20:59:39.162Z] 20:59:39     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set

Comment 1

[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=1772218&startday=2022-05-30&endday=2022-06-05&tree=all

Comment 3

[Intermittent Failures Robot]

1 failures in 3336 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=1772218&startday=2022-06-06&endday=2022-06-12&tree=all

Comment 4

[Intermittent Failures Robot]

1 failures in 3075 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=1772218&startday=2022-06-20&endday=2022-06-26&tree=all

Comment 5

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

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

Comment 6

[Treeherder Bug Filer]

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

Comment 7

[Intermittent Failures Robot]

1 failures in 2999 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=1772218&startday=2022-12-19&endday=2022-12-25&tree=all

Comment 8

[Intermittent Failures Robot]

1 failures in 2607 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=1772218&startday=2023-01-02&endday=2023-01-08&tree=all

Comment 9

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

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

Comment 10

[BMO Automation]

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

Comment 11

[Treeherder Bug Filer]

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

Comment 12

[Intermittent Failures Robot]

1 failures in 3643 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=1772218&startday=2023-02-20&endday=2023-02-26&tree=all

Comment 13

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

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

Comment 14

[Treeherder Bug Filer]

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

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1772218&startday=2023-04-03&endday=2023-04-09&tree=all

Comment 16

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

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