Closed Bug 1770753 Opened 3 years ago Closed 3 years ago

Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_clean_creates_new_profile | OSError: Process killed because the connection to Marionette server is lost. Check ge

Categories

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

Product:
Testing
Component:
Marionette Client and Harness
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2022-05-23T11:27:10.944Z] 11:27:10     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_clean_creates_new_profile
[task 2022-05-23T11:27:10.945Z] 11:27:10     INFO -  1653305230945	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:51777
[task 2022-05-23T11:27:10.945Z] 11:27:10     INFO -  1653305230946	Marionette	DEBUG	3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-05-23T11:27:10.946Z] 11:27:10     INFO -  1653305230946	Marionette	DEBUG	Waiting for initial application window
[task 2022-05-23T11:27:10.946Z] 11:27:10     INFO -  1653305230947	RemoteAgent	TRACE	[24] Document already finished loading: about:blank
[task 2022-05-23T11:27:10.948Z] 11:27:10     INFO -  1653305230948	Marionette	DEBUG	3 <- [1,1,null,{"sessionId":"876a9627-c6d6-4861-8df6-af1d33cce947","capabilities":{"browserName":"firefox","browserVersion":"102.0 ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-05-23T11:27:10.948Z] 11:27:10     INFO -  1653305230949	Marionette	DEBUG	3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-05-23T11:27:10.949Z] 11:27:10     INFO -  1653305230949	Marionette	DEBUG	3 <- [1,2,null,{"value":null}]
[task 2022-05-23T11:27:10.949Z] 11:27:10     INFO -  1653305230950	Marionette	DEBUG	3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-05-23T11:27:10.949Z] 11:27:10     INFO -  1653305230950	Marionette	DEBUG	3 <- [1,3,null,{"value":null}]
[task 2022-05-23T11:27:10.950Z] 11:27:10     INFO -  1653305230951	Marionette	DEBUG	3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-05-23T11:27:10.950Z] 11:27:10     INFO -  1653305230951	Marionette	DEBUG	3 <- [1,4,null,{"value":null}]
[task 2022-05-23T11:27:10.951Z] 11:27:10     INFO -  DEBUG: Completed blocker Transaction (16) for phase places.sqlite#0: waiting for clients
[task 2022-05-23T11:27:10.951Z] 11:27:10     INFO -  DEBUG: Completed blocker places.sqlite#0: Bookmarks.jsm: insertBookmarkTree (17) for phase places.sqlite#0: waiting for clients
[task 2022-05-23T11:27:10.951Z] 11:27:10     INFO -  DEBUG: Adding blocker places.sqlite#0: GuidHelper.getItemId (18) for phase places.sqlite#0: waiting for clients
[task 2022-05-23T11:27:10.952Z] 11:27:10     INFO -  1653305230952	Marionette	DEBUG	3 -> [0,5,"Marionette:GetContext",{}]
[task 2022-05-23T11:27:10.952Z] 11:27:10     INFO -  1653305230952	Marionette	DEBUG	3 <- [1,5,null,{"value":"content"}]
[task 2022-05-23T11:27:10.952Z] 11:27:10     INFO -  1653305230953	Marionette	DEBUG	3 -> [0,6,"WebDriver:DeleteSession",{}]
[task 2022-05-23T11:27:10.954Z] 11:27:10     INFO -  1653305230954	Marionette	DEBUG	3 <- [1,6,null,{"value":null}]
[task 2022-05-23T11:27:10.954Z] 11:27:10     INFO -  DEBUG: Completed blocker places.sqlite#0: GuidHelper.getItemId (18) for phase places.sqlite#0: waiting for clients
[task 2022-05-23T11:27:10.959Z] 11:27:10     INFO -  1653305230959	Marionette	DEBUG	Closed connection 3
[task 2022-05-23T11:27:11.024Z] 11:27:11     INFO -  Application command: Z:\task_165330328490484\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_165330328490484\AppData\Local\Temp\tmpwxcghub6.mozrunner
[task 2022-05-23T11:27:11.151Z] 11:27:11     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-05-23T11:27:11.173Z] 11:27:11     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2022-05-23T11:27:11.176Z] 11:27:11     INFO -  DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2022-05-23T11:27:11.205Z] 11:27:11     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-05-23T11:27:11.283Z] 11:27:11     INFO -  DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2022-05-23T11:27:11.289Z] 11:27:11     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2022-05-23T11:27:11.292Z] 11:27:11     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2022-05-23T11:27:11.293Z] 11:27:11     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-05-23T11:27:11.294Z] 11:27:11     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2022-05-23T11:27:11.295Z] 11:27:11     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-05-23T11:27:11.311Z] 11:27:11     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2022-05-23T11:27:11.344Z] 11:27:11     INFO -  DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2022-05-23T11:27:11.348Z] 11:27:11     INFO -  DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2022-05-23T11:27:11.351Z] 11:27:11     INFO -  1653305231352	Marionette	INFO	Marionette enabled
[task 2022-05-23T11:27:11.353Z] 11:27:11     INFO -  1653305231353	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-23T11:27:11.354Z] 11:27:11     INFO -  1653305231355	Marionette	INFO	Listening on port 2828
[task 2022-05-23T11:27:11.354Z] 11:27:11     INFO -  1653305231355	Marionette	DEBUG	Marionette is listening
[task 2022-05-23T11:30:23.269Z] 11:30:23    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_clean_creates_new_profile | 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-05-23T11:30:23.269Z] 11:30:23     INFO -  Traceback (most recent call last):
[task 2022-05-23T11:30:23.272Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2022-05-23T11:30:23.272Z] 11:30:23     INFO -      testMethod()
[task 2022-05-23T11:30:23.272Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py", line 103, in test_restart_clean_creates_new_profile
[task 2022-05-23T11:30:23.272Z] 11:30:23     INFO -      self.marionette.restart(clean=True)
[task 2022-05-23T11:30:23.273Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-05-23T11:30:23.273Z] 11:30:23     INFO -      m._handle_socket_failure()
[task 2022-05-23T11:30:23.273Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\marionette_driver\marionette.py", line 745, in _handle_socket_failure
[task 2022-05-23T11:30:23.273Z] 11:30:23     INFO -      reraise(
[task 2022-05-23T11:30:23.273Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-05-23T11:30:23.274Z] 11:30:23     INFO -      raise value.with_traceback(tb)
[task 2022-05-23T11:30:23.274Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-05-23T11:30:23.274Z] 11:30:23     INFO -      return func(*args, **kwargs)
[task 2022-05-23T11:30:23.274Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1171, in restart
[task 2022-05-23T11:30:23.274Z] 11:30:23     INFO -      self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
[task 2022-05-23T11:30:23.275Z] 11:30:23     INFO -    File "Z:\task_165330328490484\build\venv\lib\site-packages\marionette_driver\marionette.py", line 636, in raise_for_port
[task 2022-05-23T11:30:23.275Z] 11:30:23     INFO -      raise socket.timeout(
[task 2022-05-23T11:30:23.275Z] 11:30:23     INFO -  TEST-INFO took 192309ms
<...>
[task 2022-05-23T11:30:29.739Z] 11:30:29     INFO -  DEBUG: Adding blocker ScriptPreloader: Saving bytecode cache for phase xpcom-will-shutdown
[task 2022-05-23T11:30:29.744Z] 11:30:29     INFO -  1653305429744	RemoteAgent	TRACE	[24] Document already finished loading: about:blank
[task 2022-05-23T11:30:29.751Z] 11:30:29     INFO -  1653305429750	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"bbe20fe7-27ce-4698-843d-58ca4fa3e2b1","capabilities":{"browserName":"firefox","browserVersion":"102.0 ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-05-23T11:30:29.755Z] 11:30:29     INFO -  1653305429755	Marionette	DEBUG	2 -> [0,2,"WebDriver:DeleteSession",{}]
[task 2022-05-23T11:30:29.759Z] 11:30:29     INFO -  1653305429759	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
[task 2022-05-23T11:30:29.759Z] 11:30:29     INFO -  1653305429759	Marionette	DEBUG	Closed connection 2
[task 2022-05-23T11:30:29.760Z] 11:30:29     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestQuitRestartWithoutWorkspace.test_restart_keeps_same_profile | took 4263ms
[task 2022-05-23T11:30:29.760Z] 11:30:29     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_profile_management.py TestSwitchProfileFailures.test_raise_for_switching_profile_while_instance_is_running
[task 2022-05-23T11:30:29.761Z] 11:30:29     INFO -  1653305429761	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:51832

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

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.