Closed Bug 1150521 Opened 9 years ago Closed 9 years ago

Reading list sync fails, client out of sync with server

Categories

(Firefox Graveyard :: Reading List, defect, P1)

Product:
Firefox Graveyard
Component:
Reading List
Platform:
x86
macOS
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: sphilp, Unassigned)

References

(Blocks 1 open bug)

Details

On Firefox Dev Edition 38.0a2 (2015-03-30), OSX 10.10.2.

After several successful add/remove article syncs, I tried to remove the URL:

http://www.engadget.com/2015/03/31/macbook-pro-with-retina-display-review-13-inch-2015/

The URL bar '-' button and the 'x' in the sidebar do not remove the article, no UI feedback/errors are given, but the about:sync-log shows:

1427984757630	browserwindow.syncui.LogManager	DEBUG	Flushing file log
1427984757630	browserwindow.syncui	DEBUG	observed: readinglist:sync:error
1427984757630	browserwindow.syncui	DEBUG	onActivityStop with numActive: 1
1427984757630	browserwindow.syncui	DEBUG	onRLSyncError with readingList state: other error
1427984757630	browserwindow.syncui	DEBUG	isProlongedReadingListError has last successful sync at Thu Apr 02 2015 10:24:26 GMT-0400 (EDT), threshold is Thu Mar 19 2015 10:25:57 GMT-0400 (EDT), prolonged=false
1427984757630	browserwindow.syncui	DEBUG	onRLSyncError has a non-authentication, non-prolonged error, so not showing any error UI
1427984757630	browserwindow.syncui	DEBUG	observed: readinglist:sync:error
1427984757631	browserwindow.syncui	DEBUG	onActivityStop with numActive: 1
1427984757631	browserwindow.syncui	DEBUG	onRLSyncError with readingList state: other error
1427984757631	browserwindow.syncui	DEBUG	isProlongedReadingListError has last successful sync at Thu Apr 02 2015 10:24:26 GMT-0400 (EDT), threshold is Thu Mar 19 2015 10:25:57 GMT-0400 (EDT), prolonged=false
1427984757631	browserwindow.syncui	DEBUG	onRLSyncError has a non-authentication, non-prolonged error, so not showing any error UI
1427984757631	browserwindow.syncui	DEBUG	observed: readinglist:sync:error
1427984757631	browserwindow.syncui	DEBUG	onActivityStop with numActive: 1
1427984757631	browserwindow.syncui	DEBUG	onRLSyncError with readingList state: other error
1427984757631	browserwindow.syncui	DEBUG	isProlongedReadingListError has last successful sync at Thu Apr 02 2015 10:24:26 GMT-0400 (EDT), threshold is Thu Mar 19 2015 10:25:57 GMT-0400 (EDT), prolonged=false
1427984757631	browserwindow.syncui	DEBUG	onRLSyncError has a non-authentication, non-prolonged error, so not showing any error UI
1427984757631	browserwindow.syncui	DEBUG	observed: readinglist:sync:error
1427984757631	browserwindow.syncui	DEBUG	onRLSyncError with readingList state: other error
1427984757631	browserwindow.syncui	DEBUG	isProlongedReadingListError has last successful sync at Thu Apr 02 2015 10:24:26 GMT-0400 (EDT), threshold is Thu Mar 19 2015 10:25:57 GMT-0400 (EDT), prolonged=false
1427984757631	browserwindow.syncui	DEBUG	onRLSyncError has a non-authentication, non-prolonged error, so not showing any error UI
1427984757631	readinglist.scheduler	INFO	canSync=true
1427984757631	readinglist.scheduler	INFO	next scheduled sync is in 7200000ms (at Thu Apr 02 2015 12:25:57 GMT-0400 (EDT))
1427984757636	browserwindow.syncui.LogManager	DEBUG	Log cleanup threshold time: 1426256757636
1427984757682	browserwindow.syncui.LogManager	DEBUG	Done deleting files.
1427985071603	readinglist.scheduler	DEBUG	starting sync
1427985071604	browserwindow.syncui	DEBUG	observed: readinglist:sync:start
1427985071604	browserwindow.syncui	DEBUG	onActivityStart with numActive: 0
1427985071604	browserwindow.syncui	DEBUG	observed: readinglist:sync:start
1427985071604	browserwindow.syncui	DEBUG	onActivityStart with numActive: 0
1427985071604	browserwindow.syncui	DEBUG	observed: readinglist:sync:start
1427985071604	browserwindow.syncui	DEBUG	onActivityStart with numActive: 0
1427985071604	browserwindow.syncui	DEBUG	observed: readinglist:sync:start
1427985071605	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 < TaskImpl_run@Task.jsm:314:40 < TaskImpl@Task.jsm:275:3 < createAsyncFunction/asyncFunction@Task.jsm:249:14 < SyncImpl.prototype._uploadNewItems<@Sync.jsm:285:13 < TaskImpl_run@Task.jsm:314:40 < Handler.prototype.process@Promise-backend.js:867:23 < this.PromiseWalker.walkerLoop@Promise-backend.js:746:7 < this.PromiseWalker.scheduleWalkerLoop/<@Promise-backend.js:688:37
Mark, is there a way to see what calls are made to the server when this happens ?
Flags: needinfo?(mhammond)
Trapped the requests with charles proxy, here's what I get.

tl;dr: internal server error, this might be in the server logs somewhere

There's 1 article in my reading list, the one that can't be deleted, in the this test it is:

http://www.engadget.com/2015/04/01/eve-valkyrie-vr-interview-preview/

Note that restarting firefox allowed me to delete the previous un-deletable article.

I add a new item to my reading list: 

http://www.engadget.com/2015/04/01/playstation-original-programming-powers/

First request goes out to get the current articles list:

https://readinglist.services.mozilla.com/v1/articles?_since=1427987128703

Response:

{
	"items": [{
		"archived": false,
		"marked_read_on": null,
		"favorite": true,
		"title": "The maker of 'Eve' is betting big on VR and it might pay off",
		"url": "http:\/\/www.engadget.com\/2015\/04\/01\/eve-valkyrie-vr-interview-preview\/",
		"is_article": true,
		"stored_on": 1427987129305,
		"excerpt": "It's been a very rough 18 months for the makers of Eve Online, CCP. The company has lost money, canceled the long-delayed World of Darkness MMO, laid off",
		"word_count": null,
		"read_position": 0,
		"marked_read_by": null,
		"added_on": 1427987128799,
		"last_modified": 1427987129308,
		"id": "98717224-6c26-481e-918b-0624f0392c9b",
		"preview": "http:\/\/o.aolcdn.com\/hss\/storage\/midas\/434684185702f7f5b78aa25a011673de\/201720184\/valkyriedemopeeps.jpg",
		"unread": true,
		"resolved_url": "http:\/\/www.engadget.com\/2015\/04\/01\/eve-valkyrie-vr-interview-preview\/",
		"resolved_title": "The maker of 'Eve' is betting big on VR and it might pay off",
		"added_by": "stuartphilp's Firefox Developer Edition on Stuarts-MBP"
	}]
}

Then a batch request is made to https://readinglist.services.mozilla.com/v1/batch:

{
	"defaults": {
		"method": "POST",
		"path": "/articles"
	},
	"requests": [{
		"body": {
			"url": "http://www.engadget.com/2015/04/01/eve-valkyrie-vr-interview-preview/",
			"title": "The maker of 'Eve' is betting big on VR and it might pay off",
			"resolved_url": "http://www.engadget.com/2015/04/01/eve-valkyrie-vr-interview-preview/",
			"resolved_title": null,
			"excerpt": "It's been a very rough 18 months for the makers of Eve Online, CCP. The company has lost money, canceled the long-delayed World of Darkness MMO, laid off",
			"favorite": null,
			"is_article": null,
			"word_count": null,
			"unread": null,
			"added_by": "stuartphilp's Firefox Developer Edition on Stuarts-MBP",
			"added_on": 1427987128799,
			"marked_read_by": null,
			"marked_read_on": null,
			"read_position": null,
			"preview": "http://o.aolcdn.com/hss/storage/midas/434684185702f7f5b78aa25a011673de/201720184/valkyriedemopeeps.jpg"
		}
	}, {
		"body": {
			"url": "http://www.engadget.com/2015/04/01/playstation-original-programming-powers/",
			"title": "PlayStation's original programming future depends on 'Powers'",
			"resolved_url": "http://www.engadget.com/2015/04/01/playstation-original-programming-powers/",
			"resolved_title": null,
			"excerpt": "Powers is the first series to come from Sony PlayStation's original programming push, a partnership with Sony Pictures Entertainment, and it's not rated",
			"favorite": null,
			"is_article": null,
			"word_count": null,
			"unread": null,
			"added_by": "stuartphilp's Firefox Developer Edition on Stuarts-MBP",
			"added_on": 1427987142241,
			"marked_read_by": null,
			"marked_read_on": null,
			"read_position": null,
			"preview": "http://o.aolcdn.com/hss/storage/midas/2c10ae042cc19467bab88cd84be18065/201769666/Powers_Gallery_9_fb.jpg"
		}
	}]
}

which responds with:

{
	"responses": [{
		"status": 500,
		"path": "\/v1\/articles",
		"body": {
			"errno": 999,
			"code": 500,
			"error": "Internal Server Error"
		},
		"headers": {
			"Content-Length": "56",
			"Content-Type": "application\/json; charset=UTF-8"
		}
	}, {
		"status": 201,
		"path": "\/v1\/articles",
		"body": {
			"archived": false,
			"marked_read_on": null,
			"favorite": true,
			"title": "PlayStation's original programming future depends on 'Powers'",
			"url": "http:\/\/www.engadget.com\/2015\/04\/01\/playstation-original-programming-powers\/",
			"is_article": true,
			"stored_on": 1427987142650,
			"excerpt": "Powers is the first series to come from Sony PlayStation's original programming push, a partnership with Sony Pictures Entertainment, and it's not rated",
			"marked_read_by": null,
			"word_count": null,
			"read_position": 0,
			"last_modified": 1427987142653,
			"added_by": "stuartphilp's Firefox Developer Edition on Stuarts-MBP",
			"resolved_url": "http:\/\/www.engadget.com\/2015\/04\/01\/playstation-original-programming-powers\/",
			"id": "2334c3e5-ed52-4ef7-a9eb-1a326c90077c",
			"preview": "http:\/\/o.aolcdn.com\/hss\/storage\/midas\/2c10ae042cc19467bab88cd84be18065\/201769666\/Powers_Gallery_9_fb.jpg",
			"unread": true,
			"resolved_title": "PlayStation's original programming future depends on 'Powers'",
			"added_on": 1427987142241
		},
		"headers": {
			"Content-Length": "973",
			"Backoff": "None",
			"Content-Type": "application\/json; charset=UTF-8",
			"Access-Control-Expose-Headers": "Backoff, Retry-After, Alert"
		}
	}]
}
Blocks: desktop-readinglist
I can't work out why all the logging info isn't there, but this is almost certainly bug 1149105
Flags: needinfo?(mhammond)
Priority: -- → P1
Blocks: 1132074
Flags: qe-verify?
Flags: firefox-backlog+
Stuart, can you please re-test now that bug 1149105 has landed? The error in the pasted log above no longer exists.
Flags: needinfo?(sphilp)
Thanks Mark, I can't seem to reproduce this now so I'll marked resolved/duplicate
Status: NEW → RESOLVED
Closed: 9 years ago
Flags: needinfo?(sphilp)
Resolution: --- → DUPLICATE
Actually Mark, we could possibly reopen this or link it to the duplicate articles bug 1151704. 

Repeatedly and rapidly tapping the +/- button will eventually start duplicating the article being added in the sidebar, with the older copies of the article unable to be deleted (exhibiting the same logs as above). Normal add remove seems to work fine, but this specific case of rapidly adding/removing may be something else to look at.
Flags: needinfo?(mhammond)
(In reply to Stuart Philp :sphilp from comment #6)
> Actually Mark, we could possibly reopen this or link it to the duplicate
> articles bug 1151704. 

Sure! I haven't seen this recently, so please upload new logs - see also https://id.etherpad.mozilla.org/readinglist-testing
Status: RESOLVED → REOPENED
Flags: needinfo?(mhammond)
Resolution: DUPLICATE → ---
(In reply to Stuart Philp :sphilp from comment #6)
> (exhibiting the same logs as above).

To be clear, if the logs include "Sync failed, now in state 'other error': Error: Item should exist" then I'll suggest the build being tested doesn't have the fix for bug 1151704. But if they are *similar* but not with that exact error, it's probably not a dupe.
Looking into it a bit... 

Firefox 38, beta channel, does not seem to have this issue.

Firefox 39.0a2, dev edition, does have this issue. The logs here are not actually showing the same as before, and it looks like the server is responding with the correct thing (no items in an articles get request) but the UI is not reflecting that, it's showing things that shouldn't be there. I'm guessing there's a patch or two that aren't in 39 yet?
Moving to Firefox, since it sounds like this has been / possibly-still-is a client issue.

We can reverify that comment 9 is now fixed as thought likely.

Probably would have been best to file a new bug, if needed, around comment 6 since this is no longer about the originally-filed issue?
Assignee: tarek → nobody
Component: Server: ReadingList → Reading List
Flags: needinfo?(sphilp)
Product: Mozilla Services → Firefox
Yup, I'll file it separately and link back here for tracking
Flags: needinfo?(sphilp)
bug 1153436 for the duplication issue
Status: REOPENED → RESOLVED
Closed: 9 years ago → 9 years ago
Resolution: --- → FIXED
Product: Firefox → Firefox Graveyard
You need to log in before you can comment on or make changes to this bug.