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

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2020-06-09T20:12:54.330Z] 20:12:54 INFO - DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2020-06-09T20:12:54.340Z] 20:12:54 INFO - DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange
[task 2020-06-09T20:16:04.199Z] 20:16:04 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set | IOError: 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 2020-06-09T20:16:04.200Z] 20:16:04 INFO - Traceback (most recent call last):
[task 2020-06-09T20:16:04.200Z] 20:16:04 INFO - File "Z:\task_1591732294\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 177, in run
[task 2020-06-09T20:16:04.201Z] 20:16:04 INFO - self.setUp()
[task 2020-06-09T20:16:04.201Z] 20:16:04 INFO - File "Z:\task_1591732294\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_prefs_enforce.py", line 20, in setUp
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - "marionette.test.string": "testing",
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - File "Z:\task_1591732294\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - m._handle_socket_failure()
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - File "Z:\task_1591732294\build\venv\lib\site-packages\marionette_driver\marionette.py", line 682, in _handle_socket_failure
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - reraise(IOError, IOError(message.format(returncode=returncode, reason=exc)), tb)
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - File "Z:\task_1591732294\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-06-09T20:16:04.202Z] 20:16:04 INFO - return func(*args, **kwargs)
[task 2020-06-09T20:16:04.203Z] 20:16:04 INFO - File "Z:\task_1591732294\build\venv\lib\site-packages\marionette_driver\marionette.py", line 856, in enforce_gecko_prefs
[task 2020-06-09T20:16:04.203Z] 20:16:04 INFO - self.raise_for_port()
[task 2020-06-09T20:16:04.203Z] 20:16:04 INFO - File "Z:\task_1591732294\build\venv\lib\site-packages\marionette_driver\marionette.py", line 573, in raise_for_port
[task 2020-06-09T20:16:04.203Z] 20:16:04 INFO - self.host, self.port))
[task 2020-06-09T20:16:04.203Z] 20:16:04 INFO - TEST-INFO took 191546ms

[task 2020-06-09T20:12:52.652Z] 20:12:52 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set

Comment 1

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

This is a startup hang and happens between the following shutdown blocker registrations:

[task 2020-06-09T20:40:59.399Z] 20:40:59     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange
[task 2020-06-09T20:40:59.560Z] 20:40:59     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry

Here the failing case:

[task 2020-06-09T20:12:54.340Z] 20:12:54     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange
[task 2020-06-09T20:16:04.199Z] 20:16:04    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_prefs_enforce.py TestEnforcePreferences.test_preferences_are_set | IOError: 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!)

The TelemetryController shutdown blocker never gets added even after 4 minutes. No idea which code runs between those two registrations. Maybe a lot. Florian, do you have an idea?

Comment 2

[Florian Quèze [:florian]]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #1)

[task 2020-06-09T20:40:59.399Z] 20:40:59     INFO -  DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase OS.File: Waiting for clients before profileBeforeChange

This is from https://searchfox.org/mozilla-central/rev/fac90408bcf52ca88a3dcd2ef30a379b68ab24e2/toolkit/components/crashmonitor/CrashMonitor.jsm#177

[task 2020-06-09T20:40:59.560Z] 20:40:59     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry

This is from https://searchfox.org/mozilla-central/rev/fac90408bcf52ca88a3dcd2ef30a379b68ab24e2/toolkit/components/telemetry/app/TelemetryController.jsm#952

Both of these things are triggered off of the profile-after-change category notifications. Looking at a startup profile on Windows (same platform as the failure in comment 0; hopefully the order is the same), we have quite a few things running during that time: https://share.firefox.dev/3hfrCy0

Comment 3

[Florian Quèze [:florian]]

In the profile in comment 2 it looks like the GPU process is starting up in the interesting interval, but this is just a coincidence, I captured another one where the GPU process has already started: https://share.firefox.dev/30qirEZ

Comment 4

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1644580&startday=2020-06-08&endday=2020-06-14&tree=all

Comment 5

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

Florian, at this stage would it make sense to file new bugs for such hangs under the Firefox / General or startup component? We have a couple of those hangs, and partly investigated. But then if the failure doesn't happen for a while the intermittent bugs get closed and we might loose this information. Or is it too less information?

Comment 6

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

Single failure only that happened 4 months ago. Closing as incomplete.

Comment 7

[BMO Automation]

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