Closed Bug 1243485 Opened 4 years ago Closed 4 years ago

Intermittent crash [@ mozalloc_abort(char const * const)] | test_ssl_status_after_restart.py TestSSLStatusAfterRestart.test_ssl_status_after_restart | ###!!! ABORT: file chrome://browser/content/sanitize.js, line 77

Categories

(Toolkit :: Places, defect, critical)

44 Branch
defect
Not set
critical

Tracking

()

RESOLVED FIXED
Tracking Status
firefox45 --- fixed
firefox46 --- fixed
firefox47 --- fixed

People

(Reporter: whimboo, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: crash, intermittent-failure)

Seen today in Treeherder by running our Fx UI Tests:
https://treeherder.mozilla.org/logviewer.html#?job_id=3187166&repo=mozilla-central

 07:08:18     INFO -  FATAL ERROR: AsyncShutdown timeout in Places Database shutdown Conditions: [{"name":"sanitize.js: Sanitize","state":{"progress":{"cookies":"ready"}},"filename":"chrome://browser/content/sanitize.js","lineNumber":77,"stack":["chrome://browser/content/sanitize.js:Sanitizer.prototype.sanitize<:77","resource://gre/modules/Task.jsm:TaskImpl_run:319","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","utils.py:__marionetteFunc:35","utils.py:null:46","chrome://marionette/content/driver.js:GeckoDriver.prototype.executeScriptInSandbox:852","chrome://marionette/content/driver.js:GeckoDriver.prototype.executeWithCallback/res<:1176","chrome://marionette/content/driver.js:GeckoDriver.prototype.executeWithCallback:1092","resource://gre/modules/Task.jsm:TaskImpl_run:335","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","resource://gre/modules/Task.jsm:TaskImpl_handleResultValue:388","resource://gre/modules/Task.jsm:TaskImpl_run:327","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","chrome://marionette/content/dispatcher.js:Dispatcher.prototype.execute:120","chrome://marionette/content/dispatcher.js:Dispatcher.prototype.onPacket:91","chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:DebuggerTransport.prototype._onJSONObjectReady/<:479","resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:exports.makeInfallible/<:101","resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:exports.makeInfallible/<:101"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.

 07:08:18     INFO -  [760] ###!!! ABORT: file chrome://browser/content/sanitize.js, line 77

 07:08:18     INFO - TEST-UNEXPECTED-ERROR | test_submit_unencrypted_info_warning.py TestSubmitUnencryptedInfoWarning.test_submit_unencrypted_info_warning | error: [Errno 10061] No connection could be made because the target machine actively refused it

It looks like the problem originally got triggered by the test test_ssl_status_after_restart.py:

https://dxr.mozilla.org/mozilla-central/source/testing/firefox-ui/tests/firefox_ui_tests/functional/security/test_ssl_status_after_restart.py?from=test_ssl_status_after_restart.py

Which caused the following output:

 07:07:27     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"sanitize.js: Sanitize","state":{"progress":{"cookies":"ready"}},"filename":"chrome://browser/content/sanitize.js","lineNumber":77,"stack":["chrome://browser/content/sanitize.js:Sanitizer.prototype.sanitize<:77","resource://gre/modules/Task.jsm:TaskImpl_run:319","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","utils.py:__marionetteFunc:35","utils.py:null:46","chrome://marionette/content/driver.js:GeckoDriver.prototype.executeScriptInSandbox:852","chrome://marionette/content/driver.js:GeckoDriver.prototype.executeWithCallback/res<:1176","chrome://marionette/content/driver.js:GeckoDriver.prototype.executeWithCallback:1092","resource://gre/modules/Task.jsm:TaskImpl_run:335","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","resource://gre/modules/Task.jsm:TaskImpl_handleResultValue:388","resource://gre/modules/Task.jsm:TaskImpl_run:327","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","chrome://marionette/content/dispatcher.js:Dispatcher.prototype.execute:120","chrome://marionette/content/dispatcher.js:Dispatcher.prototype.onPacket:91","chrome://marionette/content/server.js -> resource://devtools/shared/transport/transport.js:DebuggerTransport.prototype._onJSONObjectReady/<:479","resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:exports.makeInfallible/<:101","resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:exports.makeInfallible/<:101"]}] Barrier: Places Database shutdown

 07:07:27     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"PlacesUtils wrapped connection must be closed before Sqlite.jsm","state":"0. Not started.","filename":"resource://gre/modules/PlacesUtils.jsm","lineNumber":2078,"stack":["resource://gre/modules/PlacesUtils.jsm:setupDbForShutdown:2078","resource://gre/modules/PlacesUtils.jsm:null:2103"]},{"name":"PlacesUtils read-only connection must be closed before Sqlite.jsm","state":"0. Not started.","filename":"resource://gre/modules/PlacesUtils.jsm","lineNumber":2078,"stack":["resource://gre/modules/PlacesUtils.jsm:setupDbForShutdown:2078","resource://gre/modules/PlacesUtils.jsm:null:2094"]}] Barrier: Sqlite.jsm: wait until all clients have completed their task

 07:07:27     INFO -  WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"Places DatabaseShutdown: Blocking profile-before-change","state":"(none)","filename":"c:/builds/moz2_slave/m-cen-w32-ntly-000000000000000/build/src/toolkit/components/places/Database.cpp","lineNumber":597,"stack":["resource://gre/components/nsAsyncShutdown.js:nsAsyncShutdownClient.prototype.addBlocker:163","chrome://browser/content/sanitize.js:Sanitizer.onStartup<:687","resource://gre/modules/Task.jsm:TaskImpl_run:319","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://app/components/nsBrowserGlue.js:BG__finalUIStartup:725","resource://app/components/nsBrowserGlue.js:BG_observe:282"]},{"name":"Sqlite.jsm shutdown blocker","state":{"description":"Waiting for the barrier to be lifted","state":[{"name":"PlacesUtils wrapped connection must be closed before Sqlite.jsm","state":"0. Not started.","filename":"resource://gre/modules/PlacesUtils.jsm","lineNumber":2078,"stack":["resource://gre/modules/PlacesUtils.jsm:setupDbForShutdown:2078","resource://gre/modules/PlacesUtils.jsm:null:2103"]},{"name":"PlacesUtils read-only connection must be closed before Sqlite.jsm","state":"0. Not started.","filename":"resource://gre/modules/PlacesUtils.jsm","lineNumber":2078,"stack":["resource://gre/modules/PlacesUtils.jsm:setupDbForShutdown:2078","resource://gre/modules/PlacesUtils.jsm:null:2094"]}]},"filename":"resource://gre/modules/Sqlite.jsm","lineNumber":157,"stack":["resource://gre/modules/Sqlite.jsm:null:157","resource://gre/modules/XPCOMUtils.jsm:XPCU_defineLazyGetter/<.get:198","resource://gre/modules/Sqlite.jsm:ConnectionData:259","resource://gre/modules/Sqlite.jsm:OpenedConnection:1122","resource://gre/modules/Sqlite.jsm:wrapStorageConnection/<:1058","resource://gre/modules/Sqlite.jsm:wrapStorageConnection:1055","resource://gre/modules/PlacesUtils.jsm:null:2100","resource://gre/modules/XPCOMUtils.jsm:XPCU_defineLazyGetter/<.get:198","resource://gre/modules/PlacesUtils.jsm:this.PlacesUtils.withConnectionWrapper/<:1424","resource://gre/modules/Task.jsm:TaskImpl_run:319","resource://gre/modules/Task.jsm:TaskImpl:280","resource://gre/modules/Task.jsm:createAsyncFunction/asyncFunction:254","resource://gre/modules/Task.jsm:Task_spawn:168","resource://gre/modules/PlacesUtils.jsm:this.PlacesUtils.withConnectionWrapper:1423","resource://gre/modules/PlacesUtils.jsm:null:2293","resource://gre/modules/XPCOMUtils.jsm:XPCU_defineLazyGetter/<.get:198","resource://gre/modules/PlacesUtils.jsm:PU_observe:389","resource://gre/components/PlacesCategoriesStarter.js:PlacesCategoriesStarter/notify:51","resource://gre/modules/BookmarkHTMLUtils.jsm:walkTreeForImport:935","resource://gre/modules/BookmarkHTMLUtils.jsm:BookmarkImporter.prototype.importFromURL</</xhr.onload:945"]}] Barrier: profile-before-change

The shutdown for the restart took too long so Marionette lost the connection, and Firefox crashed a little while later.
Also seen with the new Firefox 45.0 Beta 1 build from yesterday:

https://treeherder.mozilla.org/#/jobs?repo=mozilla-beta&filter-searchStr=Firefox%20UI&filter-tier=2&filter-tier=3&selectedJob=749427

So I assume mozilla-aurora will also be affected.
So, apparently, sanitize.js's cookie cleaning fails to complete.
The one and only test we have which makes use of a cookie is:
https://dxr.mozilla.org/mozilla-central/source/testing/firefox-ui/tests/firefox_ui_tests/puppeteer/test_utils.py

Otherwise no other test loads this or a remote page which is using cookies. That means at maximum we have a single cookie stored.
Summary: Intermittent crash [@ mozalloc_abort(char const * const)] |test_ssl_status_after_restart.py | ###!!! ABORT: file chrome://browser/content/sanitize.js, line 77 → Intermittent crash [@ mozalloc_abort(char const * const)] | test_ssl_status_after_restart.py TestSSLStatusAfterRestart.test_ssl_status_after_restart | ###!!! ABORT: file chrome://browser/content/sanitize.js, line 77
Interesting here is that we run a sanitize test for history early in the fx ui testrun, which actually times out. As result we get a test failure. But then at the end of the testrun about 2 minutes later we have a restart test. Here Firefox does not shutdown but keeps hanging in exactly that timed out sanitize action. I assume that the sanitize action we triggered early is still running here and stops Firefox from correctly shutting down.
I'm almost sure that this is the same thing as bug 1245065. Mak and myself are working on fixing this from both ends.
Depends on: 1245065
Great! Thanks David for pointing that out.
Duplicate of this bug: 1248720
Duplicate of this bug: 1248479
Depends on: 1250424
Talked with Marco on IRC and the causing bug which activated this crash for long shutdown times of sanitize actions is bug 1089695.
Blocks: 1089695
This should be fixed across all branches now. Also haven't seen any single crash like that the last week.
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.