620938 - Bookmark sync: NS_ERROR_ILLEGAL_VALUE [nsINavBookmarksService.moveItem] in _reparentOrphans

Status: RESOLVED WORKSFORME

(Firefox :: Sync, defect)

Description

[Benjamin Smedberg]

I'm running three desktops and sometimes a mobile device, and for the past few days (weeks?) I've been getting sync errors on multiple machines. They are all up to date nightlies:

"Sync encountered an error while syncing: Unknown error. Sync will automatically retry this action."

The JS console shows the following errors:

Error: [Exception... "Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsINavBookmarksService.moveItem]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://services-sync/engines/bookmarks.js :: <TOP_LEVEL> :: line 422"  data: no]
Source File: resource://services-sync/engines/bookmarks.js
Line: 422
Error: [Exception... "'Error: NS_ERROR_ILLEGAL_VALUE' when calling method: [nsIStreamListener::onStopRequest]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "<unknown>"  data: no]
Error: [Exception... "Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsIGlobalHistory3.setPageTitle]"  nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)"  location: "JS frame :: resource://services-sync/engines/history.js :: HistStore_update :: line 430"  data: no]
Source File: resource://services-sync/engines/history.js
Line: 430
Error: [Exception... "'Error: NS_ERROR_NOT_AVAILABLE' when calling method: [nsIStreamListener::onStopRequest]"  nsresult: "0x8057001c (NS_ERROR_XPC_JS_THREW_JS_OBJECT)"  location: "<unknown>"  data: no]

I turned on sync logging and here's the tail that appears to be interesting:

2010-12-22 08:40:39	Service.Main         INFO	Loading Weave @weave_version@
2010-12-22 08:40:39	Engine.Bookmarks     DEBUG	Engine initialized
2010-12-22 08:40:39	Engine.Forms         DEBUG	Engine initialized
2010-12-22 08:40:39	Engine.History       DEBUG	Engine initialized
2010-12-22 08:40:39	Engine.Passwords     DEBUG	Engine initialized
2010-12-22 08:40:39	Engine.Prefs         DEBUG	Engine initialized
2010-12-22 08:40:39	Engine.Tabs          DEBUG	Engine initialized
2010-12-22 08:40:39	Engine.Tabs          DEBUG	Resetting tabs last sync time
2010-12-22 08:40:39	Service.Main         INFO	Mozilla/5.0 (Windows NT 6.1; WOW64; rv:2.0b9pre) Gecko/20101221 Firefox/4.0b9pre
2010-12-22 08:40:39	Service.Main         DEBUG	Caching URLs under storage user base: https://phx-sync125.services.mozilla.com/1.0/bsmedberg/
2010-12-22 08:42:01	Service.Main         INFO	Logging in user bsmedberg
2010-12-22 08:42:02	Net.Resource         DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/info/collections
2010-12-22 08:42:02	Service.Main         DEBUG	Fetching global metadata record
2010-12-22 08:42:02	Net.Resource         DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/meta/global
2010-12-22 08:42:02	Service.Main         DEBUG	Weave Version: @weave_version@ Local Storage: 5 Remote Storage: 5
2010-12-22 08:42:02	Service.Main         INFO	Sync key is up-to-date: no need to upgrade.
2010-12-22 08:42:02	Service.Main         DEBUG	Fetching and verifying -- or generating -- symmetric keys.
2010-12-22 08:42:02	Net.Resource         DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/info/collections
2010-12-22 08:42:02	Service.Main         INFO	Testing info/collections: {"clients":1292985097,"crypto":1292227330.8,"forms":1292985115.89,"history":1292346714.96,"keys":1291345851.74,"meta":1292228386.67,"bookmarks":1292863897.54,"prefs":1292956822.85,"passwords":1292985119.08,"tabs":1292985120.13}
2010-12-22 08:42:02	CollectionKeys       INFO	Testing for updateNeeded. Last modified: 0
2010-12-22 08:42:02	Service.Main         INFO	CollectionKeys reports that a key update is needed.
2010-12-22 08:42:02	Net.Resource         DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/crypto/keys
2010-12-22 08:42:02	CollectionKeys       INFO	Updating collection keys...
2010-12-22 08:42:02	CollectionKeys       INFO	Setting CollectionKeys contents. Our last modified: 0, input modified: 1292227330.8.
2010-12-22 08:42:02	BulkKeyBundle        INFO	BulkKeyBundle being created for [default]
2010-12-22 08:42:02	CollectionKeys       INFO	Processing downloaded per-collection keys.
2010-12-22 08:42:02	CollectionKeys       INFO	Clearing CollectionKeys...
2010-12-22 08:42:02	CollectionKeys       INFO	Saving downloaded keys.
2010-12-22 08:42:02	CollectionKeys       INFO	Bumping last modified to 1292227330.8
2010-12-22 08:42:02	CollectionKeys       INFO	Collection keys updated.
2010-12-22 08:42:02	Service.Main         DEBUG	Syncing as soon as we're idle.
2010-12-22 08:42:02	Service.Main         DEBUG	Idle timer created for sync, will sync after 5 seconds of inactivity.
2010-12-22 08:42:25	Service.Main         INFO	In sync().
2010-12-22 08:42:25	Net.Resource         DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/info/collections
2010-12-22 08:42:25	Service.Main         DEBUG	Fetching global metadata record
2010-12-22 08:42:25	Service.Main         DEBUG	Clearing cached meta record. metaModified is undefined, setting to 1292228386.67
2010-12-22 08:42:25	Net.Resource         DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/meta/global
2010-12-22 08:42:25	Service.Main         DEBUG	Weave Version: @weave_version@ Local Storage: 5 Remote Storage: 5
2010-12-22 08:42:25	Service.Main         INFO	Sync key is up-to-date: no need to upgrade.
2010-12-22 08:42:25	Service.Main         DEBUG	Fetching and verifying -- or generating -- symmetric keys.
2010-12-22 08:42:25	Service.Main         INFO	Testing info/collections: {"clients":1292985097,"crypto":1292227330.8,"forms":1292985115.89,"history":1292346714.96,"keys":1291345851.74,"meta":1292228386.67,"bookmarks":1292863897.54,"prefs":1292956822.85,"passwords":1292985119.08,"tabs":1292985120.13}
2010-12-22 08:42:25	CollectionKeys       INFO	Testing for updateNeeded. Last modified: 1292227330.8
2010-12-22 08:42:25	Engine.Clients       DEBUG	First sync, uploading all items
2010-12-22 08:42:25	Engine.Clients       INFO	1 outgoing items pre-reconciliation
2010-12-22 08:42:25	Collection           DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/clients?full=1
2010-12-22 08:42:25	Engine.Clients       INFO	Records: 2 applied, 0 reconciled.
2010-12-22 08:42:25	Engine.Clients       INFO	Uploading all of 1 records
2010-12-22 08:42:25	Collection           DEBUG	POST Length: 277
2010-12-22 08:42:26	Collection           DEBUG	POST success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/clients
2010-12-22 08:42:26	Engine.Clients       DEBUG	Total (ms): sync 286, processIncoming 158, uploadOutgoing 127, syncStartup 1, syncFinish 0, reconcile 0, createRecord 0, syncCleanup 0
2010-12-22 08:42:26	Service.Main         INFO	Updating enabled engines: 2 clients.
2010-12-22 08:42:26	Service.Engines      DEBUG	Could not get engine: clients
2010-12-22 08:42:26	Service.Engines      DEBUG	Engines are: ["bookmarks","forms","history","passwords","prefs","tabs"]
2010-12-22 08:42:26	Engine.Bookmarks     INFO	0 outgoing items pre-reconciliation
2010-12-22 08:42:26	Engine.Bookmarks     INFO	Records: 0 applied, 0 reconciled.
2010-12-22 08:42:26	Engine.Bookmarks     DEBUG	Total (ms): sync 12, processIncoming 0, uploadOutgoing 0, syncStartup 1, syncFinish 11, getChangedIDs 0, syncCleanup 0
2010-12-22 08:42:26	Engine.Forms         INFO	0 outgoing items pre-reconciliation
2010-12-22 08:42:26	Collection           DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/forms?newer=1292963902.28&full=1
2010-12-22 08:42:26	Engine.Forms         INFO	Records: 3 applied, 0 reconciled.
2010-12-22 08:42:26	Engine.Forms         DEBUG	Total (ms): sync 541, processIncoming 540, uploadOutgoing 0, syncStartup 1, syncFinish 0, findDupe 2, getChangedIDs 0, reconcile 4, syncCleanup 0
2010-12-22 08:42:26	Engine.History       DEBUG	First sync, uploading all items
2010-12-22 08:42:27	Engine.History       INFO	4018 outgoing items pre-reconciliation
2010-12-22 08:42:32	Engine.History       DEBUG	Total (ms): sync 6060, processIncoming 5183, syncStartup 872, findDupe 128, createRecord 700, isEqual 751, deleteId 6, handleDupe 52, reconcile 1177, syncCleanup 3
2010-12-22 08:42:32	Service.Main         DEBUG	history failed: NS_ERROR_NOT_AVAILABLE JS Stack trace: Res_get()@resource.js:376 < SyncEngine__processIncoming()@engines.js:511 < ()@engines.js:203 < SyncEngine__sync()@engines.js:768 < wrappedSync(null)@util.js:168 < batchedSync()@util.js:174 < ()@engines.js:203 < WrappedNotify()@util.js:147 < Engine_sync()@engines.js:213 < WeaveSvc__syncEngine([object Object])@service.js:1738 < ()@service.js:1624 < WrappedNotify()@util.js:147 < WrappedLock()@util.js:119 < WrappedCatch()@util.js:97 < sync(false)@service.js:1529 < ([object Object])@service.js:554 < notify([object XPCWrappedNative_NoHelper])@util.js:1126
2010-12-22 08:42:32	Engine.Passwords     INFO	0 outgoing items pre-reconciliation
2010-12-22 08:42:33	Collection           DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/passwords?newer=1292956822.04&full=1
2010-12-22 08:42:33	Engine.Passwords     INFO	Records: 0 applied, 1 reconciled.
2010-12-22 08:42:33	Engine.Passwords     DEBUG	Total (ms): sync 351, processIncoming 351, uploadOutgoing 0, syncStartup 0, syncFinish 0, getChangedIDs 0, createRecord 2, isEqual 2, reconcile 4, syncCleanup 0
2010-12-22 08:42:33	Engine.Prefs         INFO	0 outgoing items pre-reconciliation
2010-12-22 08:42:33	Engine.Prefs         INFO	Records: 0 applied, 0 reconciled.
2010-12-22 08:42:33	Engine.Prefs         DEBUG	Total (ms): sync 0, processIncoming 0, uploadOutgoing 0, syncStartup 0, syncFinish 0, getChangedIDs 0, syncCleanup 0
2010-12-22 08:42:33	Engine.Tabs          DEBUG	First sync, uploading all items
2010-12-22 08:42:33	Engine.Tabs          INFO	1 outgoing items pre-reconciliation
2010-12-22 08:42:33	Store.Tabs           DEBUG	Adding remote tabs from bsmedberg's Firefox on dupre
2010-12-22 08:42:34	Collection           DEBUG	GET success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/tabs?full=1
2010-12-22 08:42:34	Engine.Tabs          INFO	Records: 2 applied, 0 reconciled.
2010-12-22 08:42:34	Engine.Tabs          INFO	Uploading all of 1 records
2010-12-22 08:42:34	Collection           DEBUG	POST Length: 26753
2010-12-22 08:42:34	Collection           DEBUG	POST success 200 https://phx-sync125.services.mozilla.com/1.0/bsmedberg/storage/tabs
2010-12-22 08:42:34	Engine.Tabs          DEBUG	Total (ms): sync 1762, processIncoming 1065, uploadOutgoing 696, syncStartup 1, syncFinish 0, createRecord 189, findDupe 0, isEqual 93, reconcile 93, syncCleanup 0
2010-12-22 08:42:34	Service.Main         DEBUG	Exception: Some engines did not sync correctly No traceback available

"First sync, uploading all items" seems like a really odd thing to be seeing in this situation.

Comment 1

[Richard Newman [:rnewman]]

Looks like the sibling of Bug 620889... Res_get hides a multitude of sins. I am cogitating.

Comment 2

[Richard Newman [:rnewman]]

Another one with NOT_AVAILABLE:

http://pastebin.mozilla.org/896970

Comment 3

[Philipp von Weitershausen [:philikon]]

(In reply to comment #1)
> Looks like the sibling of Bug 620889... Res_get hides a multitude of sins. I am
> cogitating.

As explained in bug 621594, I believe Res_get() is a red herring for an actual problem in the engine.

Benjamin, can you reproduce this reliably? If so, can you please set the debug level for the history engine (services.sync.log.logger.engine.history) to Trace, restart, sync, and then paste the log again? Then we should see which record exactly it's failing on. I expect to see an oddball like the one in bug 621594.

(In reply to comment #2)
> Another one with NOT_AVAILABLE:
> 
> http://pastebin.mozilla.org/896970

This URL no longer points to anything... Please upload as attachment in the future. Thanks!

Comment 4

[Benjamin Smedberg]

Attachment: Sync log with history=Trace

Comment 5

[Philipp von Weitershausen [:philikon]]

Comment on attachment 500826 [details]
Sync log with history=Trace

>2011-01-03 11:34:35	Engine.History       TRACE	Incoming: { id: UxHTzYR1CZdX
>  index: 0
>  modified: 1292346714.96
>  payload: {"id":"UxHTzYR1CZdX","histUri":"http://code.google.com/webfonts/family?family=Puritan&subset=latin#description","title":null,"visits":[]}
>  collection: history }

Yup, as I suspected you're running into bug 621594. Should be fixed real soon now (when we merge again to m-c.)

Comment 6

[Philipp von Weitershausen [:philikon]]

So, coming back to the original error you were seeing in the error console: What's really odd is that your Sync log does not reveal an error for bookmark sync. I wonder why it's not doing that.

In any case, the error occurs in _reparentOrphans, so we should keep this open for further investigation.

Can you reproduce it by any chance?

Comment 7

[Benjamin Smedberg]

Not at this point. Is it possible that the bookmarks error is masking the other? I can check this again after bug 621594 hits mozilla-central. (BTW, it's really confusing to have FIXED bugs which aren't actually fixed yet.)

Comment 8

[Philipp von Weitershausen [:philikon]]

(In reply to comment #7)
> Not at this point. Is it possible that the bookmarks error is masking the
> other? I can check this again after bug 621594 hits mozilla-central. (BTW, it's
> really confusing to have FIXED bugs which aren't actually fixed yet.)

They are fixed, they just aren't merged yet. mozilla-central is not necessarily the arbiter of truth (and it will become increasingly so as we move to more project branches.)

Comment 9

[Mike Connor [:mconnor]]

Clearing nom for now, please re-nom if this is reproducible now that bug 621594 is fixed.

Comment 10

[Benjamin Smedberg]

WFM right now, I'll reopen if necessary.