Closed Bug 2013184 Opened 12 days ago Closed 11 days ago

Storage connection not closed: memory[pid] Hit MOZ_CRASH() at /home/morbo/git/firefox/storage/mozStorageService.cpp:736

Categories

(Core :: DOM: Credential Management, defect)

Product:
Core
Component:
DOM: Credential Management
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
149 Branch
Tracking Flags:
Tracking Status
firefox149 --- fixed

People

(Reporter: gcp, Assigned: gcp)

Details

Attachments

(1 file)

Bug 2013184 - Close IdentityCredentialStorageService memory connection on shutdown even if init failed. r?bvandersloot
48 bytes, text/x-phabricator-request
Details | Review

While running tests for Firefox Enterprise, we keep running into the following, pre-existing issue:

Crash reported at => Storage connection not closed: memory[2289567] Hit MOZ_CRASH() at /home/morbo/git/firefox/storage/mozStorageService.cpp:736

Given that we have a near-100% repro of the issue, I let Claude churn on it for a few hours, and it gave me a theory. I asked it to show the code snippets so I could trace through to verify its theory, and somewhere along the way it realized it was wrong, and went off for another few hours. It ended up with the following. I've manually verified this analysis and as far as I can tell, it is correct.

Bug: "Storage connection not closed: memory" crash during shutdown

Summary

IdentityCredentialStorageService::BlockShutdown fails to close its in-memory SQLite connection when initialization failed, causing a crash at xpcom-shutdown-threads.

Root Cause Analysis

1. Initialization Flow (Init() at line 132)

// Line 163: Memory connection created FIRST (synchronously on main thread)
rv = GetMemoryDatabaseConnection();
if (NS_WARN_IF(NS_FAILED(rv))) {
  MonitorAutoLock lock(mMonitor);
  mErrored.Flip();
  return rv;
}

// Line 170: Background thread created
NS_ENSURE_SUCCESS(
    NS_CreateBackgroundTaskQueue("IdentityCredentialStorage",
                                 getter_AddRefs(mBackgroundThread)),
    NS_ERROR_FAILURE);

// Line 177: Async task to open disk connection
mBackgroundThread->Dispatch(
    NS_NewRunnableFunction("IdentityCredentialStorageService::Init",
                           [self]() {
                             nsresult rv = self->GetDiskDatabaseConnection();
                             if (NS_WARN_IF(NS_FAILED(rv))) {
                               self->mErrored.Flip();  // Line 182: Sets error flag
                               self->mMonitor.NotifyAll();
                               return;
                             }
                             // ...
                           }),
    NS_DISPATCH_EVENT_MAY_BLOCK);

Key observation: Memory connection is created before the background thread attempts to open the disk connection.

2. Shutdown Flow (BlockShutdown() at line 69) - BUGGY

NS_IMETHODIMP IdentityCredentialStorageService::BlockShutdown(
    nsIAsyncShutdownClient* aClient) {
  MOZ_ASSERT(NS_IsMainThread());
  nsresult rv = WaitForInitialization();  // Line 72
  NS_ENSURE_SUCCESS(rv, rv);              // Line 73: RETURNS EARLY IF INIT FAILED!

  // Lines 78-81: This code is NEVER REACHED if init failed
  if (mMemoryDatabaseConnection) {
    (void)mMemoryDatabaseConnection->Close();
    mMemoryDatabaseConnection = nullptr;
  }
  // ...
}

3. WaitForInitialization() (line 206)

nsresult IdentityCredentialStorageService::WaitForInitialization() {
  MonitorAutoLock lock(mMonitor);
  while (!mInitialized && !mErrored && !mShuttingDown) {
    mMonitor.Wait();
  }
  if (mErrored) {
    return NS_ERROR_FAILURE;  // Line 210: Returns error when disk init failed
  }
  // ...
}

Bug Sequence

  1. Init() called → memory connection created successfully
  2. Background thread tries to open disk connection → fails (e.g., NS_ERROR_FILE_ACCESS_DENIED)
  3. mErrored.Flip() called on background thread
  4. Shutdown begins → BlockShutdown() called
  5. WaitForInitialization() returns NS_ERROR_FAILURE because mErrored is true
  6. NS_ENSURE_SUCCESS at line 73 causes early return
  7. Memory connection never closed
  8. mozStorageService detects unclosed connection at xpcom-shutdown-threads → CRASH

Evidence from Logs

[Parent 3208595] WARNING: NS_ENSURE_SUCCESS failed: .../IdentityCredentialStorageService.cpp:276
[Parent 3208595] WARNING: NS_ENSURE_SUCCESS failed: .../IdentityCredentialStorageService.cpp:73
=== Storage shutdown: 5 connections ===
  Connection[0]: places.sqlite (isClosing=0, isClosed=1)
  Connection[1]: places.sqlite (isClosing=0, isClosed=1)
  Connection[2]: content-prefs.sqlite (isClosing=0, isClosed=1)
  Connection[3]: protections.sqlite (isClosing=0, isClosed=1)
  Connection[4]: memory (isClosing=0, isClosed=0)  ← UNCLOSED!

Fix

Close the memory connection before checking initialization status:

NS_IMETHODIMP IdentityCredentialStorageService::BlockShutdown(
    nsIAsyncShutdownClient* aClient) {
  MOZ_ASSERT(NS_IsMainThread());

  // Always close memory connection first, even if init failed
  {
    MonitorAutoLock lock(mMonitor);
    mShuttingDown.Flip();
    if (mMemoryDatabaseConnection) {
      (void)mMemoryDatabaseConnection->Close();
      mMemoryDatabaseConnection = nullptr;
    }
  }

  nsresult rv = WaitForInitialization();
  if (NS_FAILED(rv)) {
    // Init failed but we've closed connections. Remove blocker if no bg thread.
    if (!mBackgroundThread) {
      DebugOnly<nsresult> removeRv = aClient->RemoveBlocker(this);
      MOZ_ASSERT(NS_SUCCEEDED(removeRv));
      return NS_OK;
    }
    // Fall through to dispatch finalization on background thread
  }
  // ... rest of shutdown
}

BlockShutdown was returning early if WaitForInitialization() failed, without
closing the in-memory SQLite connection. This caused a crash at
xpcom-shutdown-threads when mozStorageService detected an unclosed connection.

The memory connection is created synchronously during Init() before the
background thread attempts to open the disk connection. If the disk connection
fails, mErrored is set, causing WaitForInitialization() to return an error.
The fix closes the memory connection before checking initialization status.

Assignee: nobody → gpascutto
Status: NEW → ASSIGNED
Pushed by alissy@mozilla.com: https://github.com/mozilla-firefox/firefox/commit/7b5dbd8b61a7 https://hg.mozilla.org/integration/autoland/rev/0049d030fd32 Close IdentityCredentialStorageService memory connection on shutdown even if init failed. r=bvandersloot

I'm wondering how much those are related:

[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - TEST-UNEXPECTED-ERROR | dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py CachesDeleteCleanupAtShutdownTestCase.test_ensure_cache_cleanup_after_unclean_restart | marionette_driver.errors.JavascriptException: [Exception... "Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIQuotaManagerService.storageInitialized]"  nsresult: "0x8000ffff (NS_ERROR_UNEXPECTED)"  location: "JS frame :: tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py :: <TOP_LEVEL> :: line 137"  data: no]
[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - stacktrace:
[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - 	@tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py:137:46
[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - 	@tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py:141:8
[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - 	evaluate.sandbox/promise<@chrome://remote/content/marionette/evaluate.sys.mjs:127:10
[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - 	evaluate.sandbox@chrome://remote/content/marionette/evaluate.sys.mjs:103:17
[task 2026-01-29T16:12:05.578+00:00] 16:12:05     INFO - 	executeScript@chrome://remote/content/marionette/actors/MarionetteCommandsChild.sys.mjs:346:26
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO - 	receiveMessage@chrome://remote/content/marionette/actors/MarionetteCommandsChild.sys.mjs:209:31
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO - Traceback (most recent call last):
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/venv/lib/python3.11/site-packages/marionette_harness/marionette_test/testcases.py", line 192, in run
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     testMethod()
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/tests/marionette/tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py", line 220, in test_ensure_cache_cleanup_after_unclean_restart
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     if not self.create_and_cleanup_cache(ensureCleanCallback, False):
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/tests/marionette/tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py", line 162, in create_and_cleanup_cache
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     return ensureCleanCallback()
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -            ^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/tests/marionette/tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py", line 209, in ensureCleanCallback
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     Wait(self.marionette, interval=1, timeout=60).until(
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/venv/lib/python3.11/site-packages/marionette_driver/wait.py", line 130, in until
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     rv = condition(self.marionette)
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -          ^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/tests/marionette/tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py", line 210, in <lambda>
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     lambda _: self.afterCleanupClosure(self.getUsage() - beforeUsage),
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/tests/marionette/tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py", line 166, in afterCleanupClosure
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     f"Storage initialized = {self.isStorageInitialized()}, temporary storage initialized = {self.isStorageInitialized(True)}"
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/tests/marionette/tests/dom/cache/test/marionette/test_caches_delete_cleanup_after_shutdown.py", line 135, in isStorageInitialized
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     return self.marionette.execute_async_script(
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/venv/lib/python3.11/site-packages/marionette_driver/marionette.py", line 1946, in execute_async_script
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/venv/lib/python3.11/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     return func(*args, **kwargs)
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -            ^^^^^^^^^^^^^^^^^^^^^
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/venv/lib/python3.11/site-packages/marionette_driver/marionette.py", line 771, in _send_message
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     self._handle_error(err)
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -   File "/opt/worker/tasks/cltbld/build/venv/lib/python3.11/site-packages/marionette_driver/marionette.py", line 783, in _handle_error
[task 2026-01-29T16:12:05.579+00:00] 16:12:05     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)

Reported on marionette tests: https://treeherder.mozilla.org/logviewer?job_id=546103797&repo=enterprise-firefox&task=NXTbxvX-SPeC86-qnbT7Dg.0&lineNumber=14468

e.g. https://bugzilla.mozilla.org/show_bug.cgi?id=2007259

There may be some relation in that the same underlying cause that causes this error path (memory succeeds, disk fails) is causing the marionette failure.

https://hg.mozilla.org/mozilla-central/rev/0049d030fd32

Status: ASSIGNED → RESOLVED
Closed: 11 days ago
status-firefox149: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 149 Branch
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: