1359607 - Intermittent toolkit/components/places/tests/unit/test_433317_query_title_update.js | assertNoUncaughtRejections - [assertNoUncaughtRejections : 224] A promise chain failed to handle a rejection: | NS_ERROR_STORAGE_BUSY

Status: RESOLVED FIXED

(Firefox :: Bookmarks & History, defect)

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://treeherder.mozilla.org/logviewer.html#?job_id=94173173&repo=autoland

Needinfo for Marco: Could this be related to your push from the weekend? There were more places xpcshell failures since then (but I couldn't find any filed bugs for them now).

[task 2017-04-25T20:48:42.525413Z] 20:48:42     INFO -  TEST-START | toolkit/components/places/tests/unit/test_433317_query_title_update.js
[task 2017-04-25T20:48:43.688208Z] 20:48:43  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/unit/test_433317_query_title_update.js | xpcshell return code: 0
[task 2017-04-25T20:48:43.688609Z] 20:48:43     INFO -  TEST-INFO took 1161ms
[task 2017-04-25T20:48:43.691202Z] 20:48:43     INFO -  >>>>>>>
[task 2017-04-25T20:48:43.697201Z] 20:48:43     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2017-04-25T20:48:43.699323Z] 20:48:43     INFO -  NS_ERROR_STORAGE_BUSY: Component returned failure code: 0x80630001 (NS_ERROR_STORAGE_BUSY) [nsINavBookmarksService.insertBookmark]
[task 2017-04-25T20:48:43.701477Z] 20:48:43     INFO -  run_test@/home/worker/workspace/build/tests/xpcshell/tests/toolkit/components/places/tests/unit/test_433317_query_title_update.js:18:17
[task 2017-04-25T20:48:43.703477Z] 20:48:43     INFO -  _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:536:7
[task 2017-04-25T20:48:43.705329Z] 20:48:43     INFO -  @-e:1:1
[task 2017-04-25T20:48:43.707256Z] 20:48:43     INFO -  PID 11733 | *************************
[task 2017-04-25T20:48:43.709166Z] 20:48:43     INFO -  PID 11733 | A coding exception was thrown and uncaught in a Task.
[task 2017-04-25T20:48:43.711069Z] 20:48:43     INFO -  PID 11733 | Full message: TypeError: db is undefined
[task 2017-04-25T20:48:43.713341Z] 20:48:43     INFO -  PID 11733 | Full stack: nsPlacesExpiration.prototype._loadPrefs<@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js:845:11
[task 2017-04-25T20:48:43.716009Z] 20:48:43     INFO -  PID 11733 | nsPlacesExpiration@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js:500:3
[task 2017-04-25T20:48:43.718226Z] 20:48:43     INFO -  PID 11733 | XPCU_SF_createInstance@resource://gre/modules/XPCOMUtils.jsm:439:28
[task 2017-04-25T20:48:43.720424Z] 20:48:43     INFO -  PID 11733 | _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:624:5
[task 2017-04-25T20:48:43.722603Z] 20:48:43     INFO -  PID 11733 | @-e:1:1
[task 2017-04-25T20:48:43.725216Z] 20:48:43     INFO -  PID 11733 | *************************
[task 2017-04-25T20:48:43.729551Z] 20:48:43     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "Phase "Sqlite.jsm: wait until all clients have completed their task" is finished, it is too late to register completion condition "PlacesUtils read-only connection must be closed before Sqlite.jsm"" {file: "resource://gre/modules/AsyncShutdown.jsm" line: 673}]
[task 2017-04-25T20:48:43.731504Z] 20:48:43     INFO -  addBlocker@resource://gre/modules/AsyncShutdown.jsm:673:15
[task 2017-04-25T20:48:43.733658Z] 20:48:43     INFO -  setupDbForShutdown@resource://gre/modules/PlacesUtils.jsm:2124:5
[task 2017-04-25T20:48:43.735501Z] 20:48:43     INFO -  @resource://gre/modules/PlacesUtils.jsm:2140:7
[task 2017-04-25T20:48:43.741140Z] 20:48:43     INFO -  observe@resource://gre/modules/AsyncShutdown.jsm:531:9
[task 2017-04-25T20:48:43.743108Z] 20:48:43     INFO -  _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:626:5
[task 2017-04-25T20:48:43.744925Z] 20:48:43     INFO -  @-e:1:1
[task 2017-04-25T20:48:43.746701Z] 20:48:43     INFO -  "
[task 2017-04-25T20:48:43.748769Z] 20:48:43     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "db is undefined" {file: "jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js" line: 845}]
[task 2017-04-25T20:48:43.750788Z] 20:48:43     INFO -  nsPlacesExpiration.prototype._loadPrefs<@jar:file:///home/worker/workspace/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js:845:11
[task 2017-04-25T20:48:43.752646Z] 20:48:43     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:319:42
[task 2017-04-25T20:48:43.757044Z] 20:48:43     INFO -  observe@resource://gre/modules/AsyncShutdown.jsm:531:9
[task 2017-04-25T20:48:43.758992Z] 20:48:43     INFO -  _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:626:5
[task 2017-04-25T20:48:43.760823Z] 20:48:43     INFO -  @-e:1:1
[task 2017-04-25T20:48:43.762616Z] 20:48:43     INFO -  "
[task 2017-04-25T20:48:43.765142Z] 20:48:43  WARNING -  TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/unit/test_433317_query_title_update.js | assertNoUncaughtRejections - [assertNoUncaughtRejections : 224] A promise chain failed to handle a rejection: Error: Phase "places-will-close-connection" is finished, it is too late to register completion condition "PlacesUtils read-only connection closing as part of Places shutdown" - rejection date: Tue Apr 25 2017 20:48:43 GMT+0000 (UTC) - stack: addBlocker@resource://gre/modules/AsyncShutdown.jsm:673:15
[task 2017-04-25T20:48:43.767282Z] 20:48:43     INFO -  addBlocker@resource://gre/modules/AsyncShutdown.jsm:484:5
[task 2017-04-25T20:48:43.769448Z] 20:48:43     INFO -  addBlocker@resource://gre/modules/AsyncShutdown.jsm:426:7
[task 2017-04-25T20:48:43.773300Z] 20:48:43     INFO -  setupDbForShutdown/promiseClosed<@resource://gre/modules/PlacesUtils.jsm:2102:9
[task 2017-04-25T20:48:43.775268Z] 20:48:43     INFO -  Promise@resource://gre/modules/Promise.jsm -> resource://gre/modules/Promise-backend.js:390:5
[task 2017-04-25T20:48:43.777159Z] 20:48:43     INFO -  setupDbForShutdown@resource://gre/modules/PlacesUtils.jsm:2097:25
[task 2017-04-25T20:48:43.781006Z] 20:48:43     INFO -  @resource://gre/modules/PlacesUtils.jsm:2140:7
[task 2017-04-25T20:48:43.782886Z] 20:48:43     INFO -  observe@resource://gre/modules/AsyncShutdown.jsm:531:9
[task 2017-04-25T20:48:43.784820Z] 20:48:43     INFO -  _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:626:5
[task 2017-04-25T20:48:43.786624Z] 20:48:43     INFO -  @-e:1:1
[task 2017-04-25T20:48:43.788986Z] 20:48:43     INFO -   - false == true
[task 2017-04-25T20:48:43.791327Z] 20:48:43     INFO -  resource://testing-common/PromiseTestUtils.jsm:assertNoUncaughtRejections:224
[task 2017-04-25T20:48:43.794399Z] 20:48:43     INFO -  /home/worker/workspace/build/tests/xpcshell/head.js:_execute_test:634
[task 2017-04-25T20:48:43.796213Z] 20:48:43     INFO -  -e:null:1
[task 2017-04-25T20:48:43.798029Z] 20:48:43     INFO -  exiting test
[task 2017-04-25T20:48:43.800070Z] 20:48:43     INFO -  PID 11733 | JavaScript error: , line 0: uncaught exception: 2147500036
[task 2017-04-25T20:48:43.802733Z] 20:48:43     INFO -  <<<<<<<

Comment 1

[Marco Bonardo [:mak]]

the expiration failure is due to the expiration service being initialized too late in the shutdown process (we don't have an easy way to know where we are in the app life-cycle), that makes promiseDBConnection fail because it's too late.
Since I'm already looking at bug 1284083, I'll fix that there by handling the exception.

Instead the NS_ERROR_STORAGE_BUSY is something new that I didn't really expect. I'm not yet sure what causes it, we may have to increase the busy_timeout pragma, at least until we keep having 2 concurrent APIs on 2 concurrent threads.
I'd suggest to coalesce all the failures with NS_ERROR_STORAGE_BUSY in Places tests in a single bug, since it's likely they are all related to the same problem, if possible.

Comment 2

[Marco Bonardo [:mak]]

Bug 1275878 would probably help with the expiration problem, but it's blocked on an unreproducible leak (maybe it's gone in the meanwhile, not sure).

Comment 4

[Intermittent Failures Robot]

7 failures in 883 pushes (0.008 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* mozilla-inbound: 2
* autoland: 2
* try: 1
* mozilla-central: 1
* graphics: 1

Platform breakdown:
* linux64: 6
* linux32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1359607&startday=2017-04-24&endday=2017-04-30&tree=all

Comment 5

[Marco Bonardo [:mak]]

Should have been fixed by bug 1359887

Comment 6

[Intermittent Failures Robot]

12 failures in 770 pushes (0.016 failures/push) were associated with this bug in the last 7 days.   

Repository breakdown:
* try: 11
* autoland: 1

Platform breakdown:
* linux64: 6
* windows7-32-vm: 3
* linux32: 2
* osx-10-10: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1359607&startday=2017-05-01&endday=2017-05-07&tree=all