Closed Bug 1359607 Opened 5 years ago Closed 5 years ago

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

Categories

(Firefox :: Bookmarks & History, defect)

defect
Not set
normal

Tracking

()

RESOLVED FIXED
Firefox 55
Tracking Status
firefox53 --- unaffected
firefox54 --- unaffected
firefox55 --- fixed

People

(Reporter: aryx, Unassigned)

References

Details

(Keywords: intermittent-failure)

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 -  <<<<<<<
Flags: needinfo?(mak77)
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.
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).
Flags: needinfo?(mak77)
Summary: Intermittent 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 → 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
Depends on: 1284083
Depends on: 1359887
Should have been fixed by bug 1359887
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
You need to log in before you can comment on or make changes to this bug.