1150369 - Intermittently, syncing Reading List items fails with an error thrown by Sync.jsm:431

Status: RESOLVED DUPLICATE of bug 1149105

(Firefox Graveyard :: Reading List, defect)

Description

[Andrei Vaida [:avaida]]

Attachment: full log file

Reproducible on:
Beta 38.0b1-build1 (20150330154247)

Affected platforms:
Windows 7 (x64)

Preconditions:
* a Firefox Account with Reading List items

Steps to reproduce:
1. Launch Firefox with a clean profile.
2. Login with your Firefox Account.

Expected result:
* A sync is initiated automatically and all items associated to that Firefox account are synced down to the profile.
* The Reading List items associated to that Firefox Account are successfully displayed in the new profile's sidebar.

Actual result:
* Almost everything is synced down to the new profile (e.g. bookmarks, history, etc.), except for the Reading List items.
* The following error is available in about:sync-log:
> 1427877868975   readinglist.scheduler   ERROR    Sync failed, now in state 'other error': 
> Error: Item should exist (resource:///modules/readinglist/Sync.jsm:431) JS Stack trace: 
> SyncImpl.prototype._updateItemWithServerRecord<@Sync.jsm:431:1 < [e-mail]:314:40 < 
> [e-mail]:275:3 < createAsyncFunction/[e-mail]:249:14 < 
> SyncImpl.prototype._uploadNewItems<@Sync.jsm:285:13 < [e-mail]:314:40 < 
> [e-mail]:867:23 < [e-mail]:746:7 < 
> this.PromiseWalker.scheduleWalkerLoop/<@Promise-backend.js:688:37

Notes:
* This is an intermittent issue, I didn't yet manage to replicate it on m-c or m-a branches.
* I've also attached the full log file.

Comment 1

[Bogdan Maris, Desktop Test Engineering]

Also encountered this issue as well on Ubuntu 14.04 64-bit using Firefox 38 beta 1. History, themes, bookmarks are synced but not reading list items, about:sync-log is empty.

Terminal output:

> 1427958571597	readinglist.scheduler	DEBUG	observed readinglist:user-sync
> 1427958571598	readinglist.scheduler	DEBUG	starting sync
> 1427958571598	readinglist.sync	INFO	Starting sync
> 1427958571599	readinglist.sync	DEBUG	Phase 1 part 1: Uploading status changes
> 1427958571601	readinglist.scheduler	INFO	canSync=true
> 1427958571601	readinglist.scheduler	INFO	checkStatus - currently syncing
> 1427958571602	readinglist.sync	DEBUG	No local changes to upload
> 1427958571603	readinglist.sync	DEBUG	Phase 1 part 2: Uploading new items
> 1427958571607	readinglist.sync	DEBUG	No new local items to upload
> 1427958571608	readinglist.sync	DEBUG	Phase 1 part 3: Uploading deleted items
> 1427958571609	readinglist.sync	DEBUG	No local deleted synced items to upload
> 1427958571609	readinglist.sync	DEBUG	Phase 2: Downloading modified items
> 1427958571609	readinglist.sync	DEBUG	Sending request: {"method":"GET","path":"/articles?_since=1427958097602"}
> 1427958572421	readinglist.serverclient	DEBUG	dispatching request to: https://readinglist.services.mozilla.com/v1/articles?_since=1427958097602
> 1427958573740	readinglist.serverclient	DEBUG	received response status: 200 OK
> 1427958573740	readinglist.serverclient	DEBUG	initial request got status 200
> 1427958573741	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Thu, 02 Apr 2015 07:09:33 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427958573475","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}
> 1427958573742	readinglist.sync	DEBUG	Phase 3: Uploading material changes
> 1427958573745	readinglist.sync	DEBUG	No local changes to upload
> 1427958573745	readinglist.sync	INFO	Sync done
> 1427958573745	readinglist.scheduler	INFO	Sync completed successfully
> 1427958573746	readinglist.scheduler	INFO	canSync=true

Browser console output:

> 1427958618901	readinglist.scheduler	DEBUG	observed readinglist:user-sync
> 1427958618902	readinglist.scheduler	DEBUG	starting sync
> 1427958618903	readinglist.sync	INFO	Starting sync
> 1427958618904	readinglist.sync	DEBUG	Phase 1 part 1: Uploading status changes
> 1427958618907	readinglist.scheduler	INFO	canSync=true
> 1427958618907	readinglist.scheduler	INFO	checkStatus - currently syncing
> 1427958618909	readinglist.sync	DEBUG	No local changes to upload
> 1427958618909	readinglist.sync	DEBUG	Phase 1 part 2: Uploading new items
> 1427958618916	readinglist.sync	DEBUG	No new local items to upload
> 1427958618916	readinglist.sync	DEBUG	Phase 1 part 3: Uploading deleted items
> 1427958618939	readinglist.sync	DEBUG	No local deleted synced items to upload
> 1427958618940	readinglist.sync	DEBUG	Phase 2: Downloading modified items
> 1427958618940	readinglist.sync	DEBUG	Sending request: {"method":"GET","path":"/articles?_since=1427958573475"}
> 1427958619231	readinglist.serverclient	DEBUG	dispatching request to: https://readinglist.services.mozilla.com/v1/articles?_since=1427958573475
> 1427958619546	readinglist.serverclient	DEBUG	received response status: 200 OK
> 1427958619547	readinglist.serverclient	DEBUG	initial request got status 200
> 1427958619548	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Thu, 02 Apr 2015 07:10:19 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427958619277","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}
> 1427958619549	readinglist.sync	DEBUG	Phase 3: Uploading material changes
> 1427958619557	readinglist.sync	DEBUG	No local changes to upload
> 1427958619557	readinglist.sync	INFO	Sync done
> 1427958619557	readinglist.scheduler	INFO	Sync completed successfully
> 1427958619558	readinglist.scheduler	INFO	canSync=true
> 1427958619558	readinglist.scheduler	INFO	next scheduled sync is in 7200000ms (at Thu Apr 02 2015 12:10:19 GMT+0300 (EEST))
> mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create async.js:199:4