1243485 - 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

Status: RESOLVED FIXED

(Toolkit :: Places, defect)

Description

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

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.

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

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.

Comment 2

[David Teller [:Yoric] - still alive but not very active]

So, apparently, sanitize.js's cookie cleaning fails to complete.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

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.

Comment 4

[Intermittent Failures Robot]

5 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-beta: 3
* mozilla-central: 1
* mozilla-aurora: 1

Platform breakdown:
* windows7-32: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1243485&startday=2016-01-25&endday=2016-01-31&tree=all

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

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.

Comment 6

[David Teller [:Yoric] - still alive but not very active]

I'm almost sure that this is the same thing as bug 1245065. Mak and myself are working on fixing this from both ends.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

Great! Thanks David for pointing that out.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

Talked with Marco on IRC and the causing bug which activated this crash for long shutdown times of sanitize actions is bug 1089695.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+1][away 07/22 - 07/26]]

This should be fixed across all branches now. Also haven't seen any single crash like that the last week.