1149023 - unable to remove reading list item

Status: VERIFIED FIXED

(Firefox Graveyard :: Reading List, defect)

Description

[:glob ✱]

after accidentally adding a page to my reading list (see bug 1149022) i'm now unable to remove it.

clicking on the x in the reading list sidebar does nothing.
clicking on the - in the address bar does nothing.
clicking on the item loads the page.

about 8 seconds after trying the close the item from the sidebar i get the following in the browser console:

14:01:20.534 A promise chain failed to handle a rejection. Did you forget to '.catch', or did you forget to 'return'?
See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise

Date: Mon Mar 30 2015 14:01:12 GMT+0800 (AWST)
Full Message: Error: The item must belong to a reading list
Full Stack: _ensureBelongsToList@resource:///modules/readinglist/ReadingList.jsm:884:13
_ensureItemBelongsToList@resource:///modules/readinglist/ReadingList.jsm:559:5
ReadingListImpl.prototype.deleteItem<@resource:///modules/readinglist/ReadingList.jsm:375:5
TaskImpl_run@resource://gre/modules/Task.jsm:314:40
TaskImpl@resource://gre/modules/Task.jsm:275:3
createAsyncFunction/asyncFunction@resource://gre/modules/Task.jsm:249:14
onListClick@chrome://browser/content/readinglist/sidebar.js:382:1
init/<@chrome://browser/content/readinglist/sidebar.js:60:50
1 ReadingList.jsm:884:0

the address bar's - icon doesn't appear to generate an errors.

Comment 1

[:glob ✱]

this is using devedition - 38.0a2 (2015-03-29).
appears to work find on nightly (although that's a clean profile).

Comment 2

[:glob ✱]

after setting readinglist.log.appender.dump to "Debug" i see the following in my logs:

1427704765716	readinglist.sync	WARN	Failed to add a new item from server record {"archived":false,"marked_read_on":null,"favorite":true,"title":"1078653 - notification count incorrect","url":"https://bugzilla.mozilla.org/show_bug.cgi?id=1078653","is_article":true,"stored_on":1427704764949,"excerpt":"","word_count":null,"read_position":0,"marked_read_by":null,"added_on":1427704764347,"last_modified":1427704764953,"id":"7ce30906-4c1d-4f8d-aabe-6d313ae14792","preview":"https://bugzilla.mozilla.org/extensions/OpenGraph/web/bugzilla.png","unread":true,"resolved_url":"https://bugzilla.mozilla.org/show_bug.cgi?id=1078653","resolved_title":"1078653 - notification count incorrect","added_by":"byron's Firefox Developer Edition on mac"}: Error: Error(s) encountered during statement execution: UNIQUE constraint failed: items.resolvedURL (resource://gre/modules/Sqlite.jsm:685:24) JS Stack trace: ConnectionData.prototype<._executeStatement/pending<[e-mail]:685:25

oddly enough when i click on the close button in the sidebar nothing is outputted to the log.

Comment 3

[Andrei Vaida [:avaida]]

I was unable to reproduce this bug on Aurora 38.0a2 (2015-03-29) and Aurora 38.0a2 (2015-03-30), using Ubuntu 14.04 (x64). The item removal button from the sidebar works fine on my end.

Byron, could you please let me know the OS on which you noticed this bug? Also, have you tried replicating it on the 2015-03-30 aurora?

Comment 4

[:glob ✱]

(In reply to Andrei Vaida, QA [:avaida] from comment #3)
> Byron, could you please let me know the OS on which you noticed this bug?

osx.  nigelb in #fx-team could also replicate this issue with devedition on linux.

> Also, have you tried replicating it on the 2015-03-30 aurora?

just updated, still happens.
sometimes i have to click the +/- button multiple times before it gets stuck.

Comment 5

[David Smith]

I'm getting the same thing on Windows 7, Aurora channel, 2015-03-30 build.

1) Hit the + on the address bar and the page gets added to the Reading List sidebar.
1a) Once this has been done, the icon changes to -, and will be that way permanently, regardless of adding or removing the page from the Reading List.
2) Hitting the - on the address bar will remove the item from the Reading List.
3) Further hits of the - button will toggle the item's presence in the Reading List.
4) Removing the item from the Reading List via the x in the sidebar works the first time it's tried.
5) After removing the item using the x, and re-adding it using the -, it's now impossible to remove using either the - or the x.
6) Restarting the browser will return the address bar button back to a +, and allow removal of the sidebar item.

Comment 6

[David Smith]

Correction on #6, above: Restarting the browser and going back to the same page leaves the address bar button as a -, but it will return to a + after removing the page in question.

Comment 7

[Mark Hammond [:markh] [:mhammond]]

There is something very strange going on which I can see but can't explain - ReadingList.itemForURL() is returning a deleted item.

To demonstrate:
* apply the patch below.
* wait for sync to start.
* repeatedly add and remove the same item

Eventually '********** got a deleted item!' will appear.  Somehow, itemForURL() is returning a deleted item - so the front-end code attempts to re-delete it.  IIUC, it should be impossible for this to happen, even with the fun of sync trying to keep up.

Drew, flagging needinfo just so you see this - I think we need to sort this out before we dig too deep into making sure Sync keeps up (ie, this is *without* any changes to Sync to have it gracefully handle these races)

index a872825..59048a4 100644
--- a/browser/base/content/browser-readinglist.js
+++ b/browser/base/content/browser-readinglist.js
@@ -312,7 +312,11 @@ let ReadingListUI = {
     if (!uri)
       return;

+    dump("Looking for item " + uri.spec + "\n");
     let item = yield ReadingList.itemForURL(uri);
+    if (item && !item.list) {
+      dump("\n********** got a deleted item!\n");
+    }

Comment 8

[Mark Hammond [:markh] [:mhammond]]

Part of the problem seems to be forEachSyncedDeletedItem(), which winds up calling _itemFromRecord() with a record with a null URL (as we have explicitly nuked the URL when writing it as deleted). The map operations in that function (a) rely on a URL and (b) explicitly add items to the _itemsByNormalizedURL() - so we are ending up with deleted items in that map.

The following patch seems to fix that, but *does not* solve the problem:

index 032c314..4d25446 100644
--- a/browser/components/readinglist/ReadingList.jsm
+++ b/browser/components/readinglist/ReadingList.jsm
@@ -224,7 +224,8 @@ ReadingListImpl.prototype = {
    *         an Error on error.
    */
   forEachItem: Task.async(function* (callback, ...optsList) {
-    yield this._forEachItem(callback, optsList, STORE_OPTIONS_IGNORE_DELETED);
+    let thisCallback = record => callback(this._itemFromRecord(record));
+    yield this._forEachItem(thisCallback, optsList, STORE_OPTIONS_IGNORE_DELETED);
   }),

   /**
@@ -248,7 +249,7 @@ ReadingListImpl.prototype = {
     yield this._store.forEachItem(record => {
       promiseChain = promiseChain.then(() => {
         return new Promise((resolve, reject) => {
-          let promise = callback(this._itemFromRecord(record));
+          let promise = callback(record);

Also, if I add:

-    this._itemsByNormalizedURL.delete(item.url);
+    if (!this._itemsByNormalizedURL.delete(item.url)) {
+      log.error("logic error - failed to remove item from the map", item);
+    }

I see that log appear, which I strongly suspect is also related.

I think it might also be worth adding:

@@ -507,12 +512,17 @@ ReadingListImpl.prototype = {
    * @return The ReadingListItem.
    */
   _itemFromRecord(record) {
+    if (!record.url) {
+      throw new Error("record must have a URL");
+    }

(which is how I found the "deleted items" problem)

Comment 9

[Mark Hammond [:markh] [:mhammond]]

Attachment: t.patch

I think I've nailed this - here is a test patch that demonstrates the 2 problems.  Next up a patch to fix it and to remove the hacks from this test.

Comment 10

[Mark Hammond [:markh] [:mhammond]]

Attachment: 0008-Bug-1149023-fix-errors-deleting-an-already-synced-re.patch

The 2 problems were:
* the _itemFromRecord problem I mentioned above.
* when deleting a synced item, we nuked all the fields and updated |item| to those nuked fields - this made item.url null so we tried to remove null as the key, leaving the now deleted item in the map.

Comment 11

[Drew Willcoxon :adw]

Comment on attachment 8586024 [details] [diff] [review]
0008-Bug-1149023-fix-errors-deleting-an-already-synced-re.patch

Review of attachment 8586024 [details] [diff] [review]:
-----------------------------------------------------------------

Yes!  Man, that's a big fail on my part.  Could you please also s/Item/Record/ for forEachSyncedDeletedItem and _forEachItem, and update their comments to say that the callback is passed a record, not a ReadingListItem?  (forEachSyncedDeletedItem has test_ReadingList.js and Sync.jsm callers that would need to be updated of course.)

::: browser/components/readinglist/test/xpcshell/test_ReadingList.js
@@ +657,5 @@
>    gList.removeListener(listener);
>    Assert.equal((yield gList.count()), gItems.length);
>  });
>  
> +// This test deletes items so it should probably run last of the 'gItem' tests...

gItem -> gItems

Comment 12

[Drew Willcoxon :adw]

I'm testing with this patch plus one of my own, and I'm seeing the _itemsByNormalizedURL.delete() fail when rapidly clicking the +/- button.  As far as I can tell, deleteItem is getting called twice in a row for the same item by ReaderParent: http://mxr.mozilla.org/mozilla-central/source/browser/modules/ReaderParent.jsm#100

It's weird because the first deleteItem call should null out item.list, so the second one should throw, right?  So I think what must be happening is that the second call passes the _ensureItemBelongsToList test while the first call is still waiting on the store update to finish.

So deleteItem should probably null out list (and set item._deleted) before updating the store.  But then, the front-end's second call would throw an error because it doesn't wait for the first call to be resolved.  I'm not sure it should have to wait.  So should deleteItem just do nothing if the item has already been deleted?

Comment 13

[Mark Hammond [:markh] [:mhammond]]

I updated the patch to address the review comments, and also copied a couple of the log messages from my other patch - all DB operations cause a log.debug before they start and a log.trace after they finish, which should make it easier to track down other races while the DB operation is in progress (although note we'll need a pref tweak to see .trace() calls)

(In reply to Drew Willcoxon :adw from comment #12)
> So I think what must be happening is
> that the second call passes the _ensureItemBelongsToList test while the
> first call is still waiting on the store update to finish.

I can't reproduce that after lots of trying, but I think you are correct that it *could* happen.  It's probably related to your Sync patch - I could imagine that might cause concurrent delete requests once the obvious failures we currently see are fixed.

However, I didn't make any changes for this as I think we need to think them through a little more - eg, removing from the map etc before the DB operation may still leave us with a tiny window where the item is "resurrected" due to a concurrent getItem() completing after we've nuked it and before the DB operation is complete. Similarly, invalidating the iterators before the operation seems to run the risk that an iterator running at the same time will similarly resurrect it.

So I'm wondering if as you imply, we should just handle this error, and instead of the .remove() logging an error, just return at that point (ie, not call the onItemDeleted() handler and not send the message as we must have already done it.)

So I think we need to think on that part a little more...

> So deleteItem should probably null out list (and set item._deleted) before
> updating the store.

Note that the ._deleted stuff is *not* part of this patch - it was part of the "better errors" patch (bug 1149403) - but I think that's fine for now as ._deleted was just to throw a sane exception - all such exceptions should still happen, it's just that they'll currently be the cryptic "The item is not a ReadingListItem" error.

https://hg.mozilla.org/integration/fx-team/rev/6b167d125ec9
https://hg.mozilla.org/releases/mozilla-aurora/rev/1b042c16d6f1
https://hg.mozilla.org/releases/mozilla-beta/rev/4e05802f6eb4

Comment 14

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/6b167d125ec9

Comment 15

[Andrei Vaida [:avaida]]

Verified fixed on Nightly 40.0a1 (2015-04-02) and Aurora 39.0a2 (2015-04-02), using Windows 7 (x64), Ubuntu 14.04 (x64) and Mac OS X 10.9.5.

I'll follow up on this with results for the 38 branch as soon as Beta 2 lands.

Comment 16

[Andrei Vaida [:avaida]]

Verified fixed on Beta 38.0b2-build1 (20150406174117) as well, using Windows 7 (x64), Ubuntu 14.04 (x64) and Mac OS X 10.9.5. 

Please note that Bug 1149869 is still affecting the 38 branch.

Comment 17

[Mark Hammond [:markh] [:mhammond]]

(In reply to Andrei Vaida, QA [:avaida] from comment #16)
> Please note that Bug 1149869 is still affecting the 38 branch.

That bug is currently marked "unaffected" for 38, so we need to dig a little deeper into this (ie, if it is true, I guess we need a new bug)

Comment 18

[Andrei Vaida [:avaida]]

(In reply to Mark Hammond [:markh] from comment #17)
> (In reply to Andrei Vaida, QA [:avaida] from comment #16)
> > Please note that Bug 1149869 is still affecting the 38 branch.
> 
> That bug is currently marked "unaffected" for 38, so we need to dig a little
> deeper into this (ie, if it is true, I guess we need a new bug)

I see, well I managed to replicate it across platforms on the 38 branch, here's a screenshot for clarity: http://i.imgur.com/eqt0sZW.png. I'll file a separate bug for it.