1197637 - Bookmark corruption can cause permanent sync failure (NS_ERROR_MALFORMED_URI - nsINavBookmarksService.getBookmarkURI)

Status: RESOLVED DUPLICATE of bug 1182366

(Firefox :: Sync, defect)

Description

[Anthony Lieuallen]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:40.0) Gecko/20100101 Firefox/40.0
Build ID: 20150812163655

Steps to reproduce:

More or less nothing, one day Sync started reporting consistent failures on one of my machines, of the form (truncated sync error log):


...
1440364588048	Sync.Synchronizer	DEBUG	Refreshing client list.
1440364588048	Sync.Engine.Clients	INFO	0 outgoing items pre-reconciliation
1440364588049	Sync.Engine.Clients	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1440364588049	Sync.Synchronizer	INFO	Updating enabled engines: 10 clients.
1440364588050	Sync.EngineManager	DEBUG	Could not get engine: greasemonkey
1440364588050	Sync.EngineManager	DEBUG	Engines are: ["bookmarks","forms","history","passwords","prefs","tabs","addons"]
1440364588051	Sync.Engine.Prefs	INFO	0 outgoing items pre-reconciliation
1440364588052	Sync.Engine.Prefs	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1440364588053	Sync.Engine.Passwords	INFO	0 outgoing items pre-reconciliation
1440364588053	Sync.Engine.Passwords	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1440364588054	Sync.Engine.Tabs	INFO	1 outgoing items pre-reconciliation
1440364588054	Sync.Engine.Tabs	INFO	Records: 0 applied, 0 successfully, 0 failed to apply, 0 newly failed to apply, 0 reconciled.
1440364588071	Sync.Engine.Tabs	INFO	Uploading all of 1 records
1440364588071	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1440364588071	Sync.Collection	DEBUG	POST Length: 13816
1440364588335	Sync.Collection	DEBUG	mesg: POST success 200 https://sync-222-us-west-2.sync.services.mozilla.com/1.5/23866577/storage/tabs
1440364588336	Sync.Collection	DEBUG	POST success 200 https://sync-222-us-west-2.sync.services.mozilla.com/1.5/23866577/storage/tabs
1440364588339	Sync.Engine.Bookmarks	INFO	607 outgoing items pre-reconciliation
1440364588342	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1440364588352	Sync.Engine.Bookmarks	ERROR	null
1440364588774	Sync.Engine.Bookmarks	WARN	Got exception "[Exception... "Component returned failure code: 0x804b000a (NS_ERROR_MALFORMED_URI) [nsINavBookmarksService.getBookmarkURI]"  nsresult: "0x804b000a (NS_ERROR_MALFORMED_URI)"  location: "JS frame :: resource://gre/modules/services-sync/engines/bookmarks.js :: _buildGUIDMap :: line 275"  data: no] Stack trace: _buildGUIDMap()@resource://gre/modules/services-sync/engines/bookmarks.js:275 < _syncStart/<()@resource://gre/modules/services-sync/engines/bookmarks.js:402 < _mapDupe()@resource://gre/modules/services-sync/engines/bookmarks.js:342 < _createRecord()@resource://gre/modules/services-sync/engines/bookmarks.js:442 < SyncEngine.prototype._reconcile()@resource://services-sync/engines.js:1374 < SyncEngine.prototype._processIncoming/newitems.recordHandler()@resource://services-sync/engines.js:1080 < Collection.prototype.recordHandler/this._onProgress()@resource://services-sync/record.js:624 < Channel_onDataAvail()@resource://services-sync/resource.js:558 < waitForSyncCallback()@resource://services-common/async.js:102 < Res__request()@resource://services-sync/resource.js:405 < Res_get()@resource://services-sync/resource.js:429 < SyncEngine.prototype._processIncoming()@resource://services-sync/engines.js:1108 < BookmarksEngine.prototype._processIncoming()@resource://gre/modules/services-sync/engines/bookmarks.js:419 < SyncEngine.prototype._sync()@resource://services-sync/engines.js:1520 < wrappedSync()@resource://gre/modules/services-sync/engines/bookmarks.js:229 < _sync()@resource://gre/modules/services-sync/engines/bookmarks.js:226 < WrappedNotify()@resource://services-sync/util.js:148 < Engine.prototype.sync()@resource://services-sync/engines.js:668 < _syncEngine()@resource://services-sync/stages/enginesync.js:199 < sync()@resource://services-sync/stages/enginesync.js:149 < onNotify()@resource://gre/modules/services-sync/service.js:1298 < WrappedNotify()@resource://services-sync/util.js:148 < WrappedLock()@resource://services-sync/util.js:103 < _lockedSync()@resource://gre/modules/services-sync/service.js:1288 < sync/<()@resource://gre/modules/services-sync/service.js:1280 < WrappedCatch()@resource://services-sync/util.js:77 < sync()@resource://gre/modules/services-sync/service.js:1268 < <file:unknown>" building GUID map. Skipping all other incoming items.
1440364588774	Sync.Engine.Bookmarks	WARN	Reconciliation failed: aborting incoming processing.
...

Somehow places.sqlite is corrupted on this machine.  I copied the bookmarks.js sync service into scratchpad so that I could modify and run it, which revealed to me that the error was with bookmark store ID 263.  I opened up places.sqlite, and examined the source for the failing PlacesUtils.bookmarks.getBookmarkURI() method and the result is that I see:

sqlite> select * from moz_bookmarks where id=263;
263|1|109283|5|174|Google Code Search|5||1349733914103000|1439407136808000|VJ0jsKhPtRWJ
sqlite> select * from moz_places where id=109283;
sqlite> select * from moz_bookmarks where id=5;
5|2||1|9|Unsorted Bookmarks|||1212716680328000|1439775372884000|unfiled_____

Something in my unsorted bookmarks has a moz_bookmarks entry (ID 263) but no matching moz_places ID.  It's in my unsorted bookmarks folder.  When I open that in the all bookmarks UI and find it by sorting by name, the UI is clearly confused: There's no favicon (not even the empty blank one) and nothing in the location column.  The fields at the bottom don't change when I select this line, keeping whatever was selected previously there.

After I do:

sqlite> delete from moz_bookmarks where id=263;

Sync completes normally as expected.  Were I not a developer, how could I have possibly diagnosed/fixed this?


Actual results:

Sync failed, and it informed me of this fact every few minutes with an infobar.


Expected results:

The failure to call getBookmarkUri() should have been gracefully ignored, skipping that record, and Sync should have completed.