1848250 - Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: [WinError 10053] An established connection was aborte

Status: RESOLVED DUPLICATE of bug 1635776

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

---

[task 2023-08-10T21:08:27.776Z] 21:08:27     INFO -  DEBUG: Spinning the event loop
[task 2023-08-10T21:08:27.777Z] 21:08:27     INFO -  DEBUG: Completed blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2023-08-10T21:08:27.777Z] 21:08:27     INFO -  DEBUG: Completed blocker PageActions: purging unregistered actions from cache for phase profile-before-change
[task 2023-08-10T21:08:27.777Z] 21:08:27     INFO -  DEBUG: Completed blocker Places Expiration: shutdown for phase Places Connection shutdown
[task 2023-08-10T21:08:27.778Z] 21:08:27     INFO -  DEBUG: Completed blocker JSON store: writing data for 'handlers' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.778Z] 21:08:27     INFO -  DEBUG: Completed blocker JSON store: writing data for 'shieldpreferenceexperiments' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.778Z] 21:08:27     INFO -  DEBUG: Completed blocker JSON store: writing data for 'ExperimentStoreData' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.779Z] 21:08:27     INFO -  DEBUG: Completed blocker JSON store: writing data for 'logins' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.779Z] 21:08:27     INFO -  DEBUG: Completed blocker JSON store: writing data for 'extensionsettings' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.779Z] 21:08:27     INFO -  DEBUG: Completed blocker JSON store: writing data for 'broadcastlisteners' for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.779Z] 21:08:27     INFO -  DEBUG: Completed blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2023-08-10T21:08:27.779Z] 21:08:27     INFO -  DEBUG: Completed blocker Remote Settings profile-before-change for phase profile-before-change
[task 2023-08-10T21:08:27.780Z] 21:08:27     INFO -  DEBUG: Completed blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2023-08-10T21:08:27.780Z] 21:08:27     INFO -  DEBUG: Completed blocker Search service: shutting down for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2023-08-10T21:08:27.780Z] 21:08:27     INFO -  DEBUG: Completed blocker places.sqlite#1: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-08-10T21:08:27.784Z] 21:08:27     INFO -  DEBUG: Completed blocker PlacesUtils wrapped connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2023-08-10T21:08:27.786Z] 21:08:27     INFO -  DEBUG: Completed blocker PlacesUtils wrapped connection must be closed before Sqlite.sys.mjs for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-08-10T21:08:27.786Z] 21:08:27     INFO -  DEBUG: Completed blocker SitePermsAddonProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-08-10T21:08:27.786Z] 21:08:27     INFO -  DEBUG: Completed blocker GMPProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-08-10T21:08:27.786Z] 21:08:27     INFO -  DEBUG: Completed blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2023-08-10T21:08:27.786Z] 21:08:27     INFO -  DEBUG: Completed blocker AddonManager: shutting down. for phase profile-before-change
[task 2023-08-10T21:08:27.793Z] 21:08:27     INFO -  DEBUG: Completed blocker protections.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-08-10T21:08:27.796Z] 21:08:27     INFO -  DEBUG: Completed blocker TrackingDBService: Shutting down the content blocking database. for phase profile-before-change
[task 2023-08-10T21:08:27.796Z] 21:08:27     INFO -  DEBUG: Completed blocker content-prefs.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-08-10T21:08:27.796Z] 21:08:27     INFO -  DEBUG: Completed blocker Closing ContentPrefService2 connection. for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-08-10T21:08:27.796Z] 21:08:27     INFO -  DEBUG: Completed blocker places.sqlite#0: waiting for shutdown for phase Sqlite.sys.mjs: wait until all connections are closed
[task 2023-08-10T21:08:27.797Z] 21:08:27     INFO -  DEBUG: Completed blocker PlacesUtils read-only connection closing as part of Places shutdown for phase Places Connection shutdown
[task 2023-08-10T21:08:27.797Z] 21:08:27     INFO -  DEBUG: Completed blocker PlacesUtils read-only connection must be closed before Sqlite.sys.mjs for phase Sqlite.sys.mjs: wait until all clients have completed their task
[task 2023-08-10T21:08:27.797Z] 21:08:27     INFO -  DEBUG: Completed blocker Sqlite.sys.mjs shutdown blocker for phase profile-before-change
[task 2023-08-10T21:08:27.797Z] 21:08:27     INFO -  DEBUG: Completed 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 2023-08-10T21:08:28.025Z] 21:08:28     INFO -  DEBUG: Finished phase profile-before-change
[task 2023-08-10T21:08:28.088Z] 21:08:28     INFO -  DEBUG: Starting phase profile-before-change-telemetry
[task 2023-08-10T21:08:28.089Z] 21:08:28     INFO -  DEBUG: Spinning the event loop
[task 2023-08-10T21:08:28.119Z] 21:08:28     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-08-10T21:08:28.133Z] 21:08:28     INFO -  DEBUG: Adding blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-08-10T21:08:28.135Z] 21:08:28     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-08-10T21:08:28.136Z] 21:08:28     INFO -  DEBUG: Completed blocker Waiting for ping task for phase TelemetryController: Waiting for pending ping activity
[task 2023-08-10T21:08:28.142Z] 21:08:28     INFO -  DEBUG: Completed blocker TelemetryController: shutting down for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2023-08-10T21:08:28.142Z] 21:08:28     INFO -  DEBUG: Finished phase profile-before-change-telemetry
[task 2023-08-10T21:08:28.143Z] 21:08:28     INFO -  DEBUG: Starting phase xpcom-will-shutdown
[task 2023-08-10T21:08:28.143Z] 21:08:28     INFO -  DEBUG: Spinning the event loop
[task 2023-08-10T21:08:28.144Z] 21:08:28     INFO -  DEBUG: Finished phase xpcom-will-shutdown
[task 2023-08-10T21:08:28.148Z] 21:08:28     INFO -  DEBUG: Starting phase web-workers-shutdown
[task 2023-08-10T21:08:28.148Z] 21:08:28     INFO -  DEBUG: Spinning the event loop
[task 2023-08-10T21:08:28.148Z] 21:08:28     INFO -  DEBUG: Finished phase web-workers-shutdown
[task 2023-08-10T21:11:44.005Z] 21:11:44     INFO -  WARNING | IO Completion Port failed to signal process shutdown
[task 2023-08-10T21:11:44.005Z] 21:11:44     INFO -  Parent process 9268 exited with children alive:
[task 2023-08-10T21:11:44.005Z] 21:11:44     INFO -  PIDS: 2552, 4756, 9564
[task 2023-08-10T21:11:44.006Z] 21:11:44     INFO -  Attempting to kill them, but no guarantee of success
[task 2023-08-10T21:11:44.011Z] 21:11:44    ERROR -  TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation | OSError: Process has been unexpectedly closed (Exit code: 0) (Reason: [WinError 10053] An established connection was aborted by the software in your host machine)
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -  Traceback (most recent call last):
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -      testMethod()
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_harness\marionette_test\decorators.py", line 59, in skip_wrapper
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -      return test_item(self, *args, **kwargs)
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_navigation.py", line 317, in test_focus_after_navigation
[task 2023-08-10T21:11:44.012Z] 21:11:44     INFO -      self.marionette.restart()
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\decorators.py", line 34, in _
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -      m._handle_socket_failure()
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\marionette.py", line 769, in _handle_socket_failure
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -      reraise(
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -      raise value.with_traceback(tb)
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-08-10T21:11:44.013Z] 21:11:44     INFO -      return func(*args, **kwargs)
[task 2023-08-10T21:11:44.014Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1195, in restart
[task 2023-08-10T21:11:44.014Z] 21:11:44     INFO -      self._send_message("Marionette:AcceptConnections", {"value": True})
[task 2023-08-10T21:11:44.014Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-08-10T21:11:44.014Z] 21:11:44     INFO -      return func(*args, **kwargs)
[task 2023-08-10T21:11:44.014Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\marionette.py", line 685, in _send_message
[task 2023-08-10T21:11:44.014Z] 21:11:44     INFO -      msg = self.client.request(name, params)
[task 2023-08-10T21:11:44.015Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\transport.py", line 381, in request
[task 2023-08-10T21:11:44.015Z] 21:11:44     INFO -      self.send(cmd)
[task 2023-08-10T21:11:44.015Z] 21:11:44     INFO -    File "Z:\task_169170020544036\build\venv\lib\site-packages\marionette_driver\transport.py", line 352, in send
[task 2023-08-10T21:11:44.015Z] 21:11:44     INFO -      sent = sock.send(payload[totalsent:])
[task 2023-08-10T21:11:44.015Z] 21:11:44     INFO -  TEST-INFO took 196467ms
[task 2023-08-10T21:11:44.017Z] 21:11:44     INFO -  test_end for testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation 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_169170020544036\\build\\venv\\lib\\site-packages\\marionette_harness\\marionette_test\\testcases.py\", line 231, in run\n    self.tearDown()\n  File \"Z:\\task_169170020544036\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_navigation.py\", line 63, in tearDown\n    self.marionette.timeout.reset()\n  File \"Z:\\task_169170020544036\\build\\venv\\lib\\site-packages\\marionette_driver\\timeout.py\", line 101, in reset\n    self.script = DEFAULT_SCRIPT_TIMEOUT\n  File \"Z:\\task_169170020544036\\build\\venv\\lib\\site-packages\\marionette_driver\\timeout.py\", line 54, in script\n    self._set(\"script\", sec)\n  File \"Z:\\task_169170020544036\\build\\venv\\lib\\site-packages\\marionette_driver\\timeout.py\", line 30, in _set\n    self._marionette._send_message(\"WebDriver:SetTimeouts\", {name: ms})\n  File \"Z:\\task_169170020544036\\build\\venv\\lib\\site-packages\\marionette_driver\\decorators.py\", line 24, in _\n    return func(*args, **kwargs)\n  File \"Z:\\task_169170020544036\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py\", line 682, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_navigation.TestNavigate", "method_name": "test_focus_after_navigation"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_focus_after_navigation", "status": "ERROR"}
[task 2023-08-10T21:11:44.018Z] 21:11:44     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_get_current_url

Comment 1

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

The failure here is IO Completion Port failed to signal process shutdown.