1796721 - Intermittent dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py CachesDeleteCleanupAtShutdownTestCase.test_ensure_cache_cleanup_after_unclean_restart | OSError: Process killed because the connection to Marionette server is los

Status: RESOLVED INCOMPLETE

(Core :: Storage: Cache API, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-10-20T23:40:02.847Z] 23:40:02     INFO -  TEST-START | dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py CachesDeleteCleanupAtShutdownTestCase.test_ensure_cache_cleanup_after_unclean_restart
[task 2022-10-20T23:40:02.848Z] 23:40:02     INFO -  1666309202848	Marionette	DEBUG	Accepted connection 3 from 127.0.0.1:52270
[task 2022-10-20T23:40:02.861Z] 23:40:02     INFO -  1666309202860	Marionette	DEBUG	3 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-10-20T23:40:02.863Z] 23:40:02     INFO -  1666309202862	Marionette	DEBUG	Waiting for initial application window
[task 2022-10-20T23:40:02.864Z] 23:40:02     INFO -  1666309202864	RemoteAgent	TRACE	[9] ProgressListener Setting unload timer (3200ms)
[task 2022-10-20T23:40:02.865Z] 23:40:02     INFO -  1666309202864	RemoteAgent	TRACE	[9] Document already finished loading: about:blank
[task 2022-10-20T23:40:02.869Z] 23:40:02     INFO -  1666309202868	Marionette	DEBUG	3 <- [1,1,null,{"sessionId":"dee6e36c-73ef-47f7-a494-e63942ea3063","capabilities":{"browserName":"firefox","browserVersion":"108.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20221020215126","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":3232,"moz:profile":"C:\\Users\\task_166630711512908\\AppData\\Local\\Temp\\tmpnazj8lw8.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2022-10-20T23:40:02.870Z] 23:40:02     INFO -  1666309202869	Marionette	DEBUG	3 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-10-20T23:40:02.870Z] 23:40:02     INFO -  1666309202870	Marionette	DEBUG	3 <- [1,2,null,{"value":null}]
[task 2022-10-20T23:40:02.872Z] 23:40:02     INFO -  1666309202872	Marionette	DEBUG	3 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-10-20T23:40:02.872Z] 23:40:02     INFO -  1666309202872	Marionette	DEBUG	3 <- [1,3,null,{"value":null}]
[task 2022-10-20T23:40:02.874Z] 23:40:02     INFO -  1666309202873	Marionette	DEBUG	3 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-10-20T23:40:02.874Z] 23:40:02     INFO -  1666309202874	Marionette	DEBUG	3 <- [1,4,null,{"value":null}]
[task 2022-10-20T23:40:02.876Z] 23:40:02     INFO -  1666309202875	Marionette	DEBUG	3 -> [0,5,"Marionette:GetContext",{}]
[task 2022-10-20T23:40:02.876Z] 23:40:02     INFO -  1666309202876	Marionette	DEBUG	3 <- [1,5,null,{"value":"content"}]
[task 2022-10-20T23:40:02.878Z] 23:40:02     INFO -  1666309202878	Marionette	DEBUG	3 -> [0,6,"WebDriver:DeleteSession",{}]
[task 2022-10-20T23:40:02.882Z] 23:40:02     INFO -  1666309202881	Marionette	DEBUG	3 <- [1,6,null,{"value":null}]
[task 2022-10-20T23:40:02.950Z] 23:40:02     INFO -  Application command: Z:\task_166630711512908\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_166630711512908\AppData\Local\Temp\tmpml94dqcr.mozrunner
[task 2022-10-20T23:40:03.256Z] 23:40:03     INFO -  DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2022-10-20T23:40:03.283Z] 23:40:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2022-10-20T23:40:03.298Z] 23:40:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase profile-before-change-telemetry
[task 2022-10-20T23:40:03.298Z] 23:40:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase IOUtils: waiting for sendTelemetry IO to complete
[task 2022-10-20T23:40:03.298Z] 23:40:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2022-10-20T23:40:03.299Z] 23:40:03     INFO -  DEBUG: Adding blocker IOUtils Blocker (profile-before-change-telemetry) for phase IOUtils: waiting for xpcomWillShutdown IO to complete
[task 2022-10-20T23:40:03.373Z] 23:40:03     INFO -  DEBUG: Adding blocker Flush WebExtension StartupCache for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-10-20T23:40:03.621Z] 23:40:03     INFO -  DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2022-10-20T23:40:03.630Z] 23:40:03     INFO -  DEBUG: Adding blocker Update add-on blocklist state into add-on DB for phase AddonManager: Waiting to start provider shutdown.
[task 2022-10-20T23:40:03.640Z] 23:40:03     INFO -  DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2022-10-20T23:40:03.643Z] 23:40:03     INFO -  DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2022-10-20T23:40:03.645Z] 23:40:03     INFO -  DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2022-10-20T23:40:03.649Z] 23:40:03     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-10-20T23:40:03.694Z] 23:40:03     INFO -  DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2022-10-20T23:45:14.791Z] 23:45:14    ERROR -  TEST-UNEXPECTED-ERROR | dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py CachesDeleteCleanupAtShutdownTestCase.test_ensure_cache_cleanup_after_unclean_restart | 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-10-20T23:45:14.793Z] 23:45:14     INFO -  Traceback (most recent call last):
[task 2022-10-20T23:45:14.794Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 183, in run
[task 2022-10-20T23:45:14.794Z] 23:45:14     INFO -      self.setUp()
[task 2022-10-20T23:45:14.794Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\tests\marionette\tests\dom\cache\test\marionette\test_caches_delete_cleanup_after_shutdown.py", line 33, in setUp
[task 2022-10-20T23:45:14.794Z] 23:45:14     INFO -      self.marionette.restart(in_app=False, clean=True)
[task 2022-10-20T23:45:14.795Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\marionette_driver\decorators.py", line 37, in _
[task 2022-10-20T23:45:14.795Z] 23:45:14     INFO -      m._handle_socket_failure()
[task 2022-10-20T23:45:14.796Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\marionette_driver\marionette.py", line 745, in _handle_socket_failure
[task 2022-10-20T23:45:14.796Z] 23:45:14     INFO -      reraise(
[task 2022-10-20T23:45:14.797Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\six.py", line 702, in reraise
[task 2022-10-20T23:45:14.797Z] 23:45:14     INFO -      raise value.with_traceback(tb)
[task 2022-10-20T23:45:14.797Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\marionette_driver\decorators.py", line 27, in _
[task 2022-10-20T23:45:14.798Z] 23:45:14     INFO -      return func(*args, **kwargs)
[task 2022-10-20T23:45:14.798Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1194, in restart
[task 2022-10-20T23:45:14.798Z] 23:45:14     INFO -      self.raise_for_port(timeout=self.DEFAULT_STARTUP_TIMEOUT)
[task 2022-10-20T23:45:14.798Z] 23:45:14     INFO -    File "Z:\task_166630711512908\build\venv\lib\site-packages\marionette_driver\marionette.py", line 636, in raise_for_port
[task 2022-10-20T23:45:14.799Z] 23:45:14     INFO -      raise socket.timeout(
[task 2022-10-20T23:45:14.799Z] 23:45:14     INFO -  TEST-INFO took 311930ms
[task 2022-10-20T23:45:14.799Z] 23:45:14     INFO -  TEST-START | dom/workers/test/marionette/test_service_workers_at_startup.py ServiceWorkerAtStartupTestCase.test_registered_service_worker_after_restart

Comment 1

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows10-64-2004-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1796721&startday=2022-10-17&endday=2022-10-23&tree=all

Comment 2

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

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

Comment 3

[Norisz Fay [:noriszfay]]

Tier 1 failure here

Comment 4

[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=1796721&startday=2023-01-02&endday=2023-01-08&tree=all

Comment 5

[Intermittent Failures Robot]

1 failures in 3530 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=1796721&startday=2023-01-09&endday=2023-01-15&tree=all

Comment 6

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

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

Comment 7

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=414723954&repo=mozilla-central

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1796721&startday=2023-05-01&endday=2023-05-07&tree=all

Comment 9

[Intermittent Failures Robot]

1 failures in 3578 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-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1796721&startday=2023-05-15&endday=2023-05-21&tree=all

Comment 10

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

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