unable to remove reading list item

VERIFIED FIXED in Firefox 40

Status

Firefox Graveyard
Reading List
VERIFIED FIXED
3 years ago
2 years ago

People

(Reporter: glob, Assigned: markh)

Tracking

unspecified
Firefox 40
Bug Flags:
qe-verify +

Details

Attachments

(2 attachments)

(Reporter)

Description

3 years ago
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.
(Reporter)

Comment 1

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

Comment 2

3 years ago
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<.handleCompletion@Sqlite.jsm:685:25

oddly enough when i click on the close button in the sidebar nothing is outputted to the log.
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?
Flags: needinfo?(glob)
(Reporter)

Comment 4

3 years ago
(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.
Flags: needinfo?(glob)

Comment 5

3 years ago
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

3 years ago
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.

Updated

3 years ago
Assignee: nobody → adw
Status: NEW → ASSIGNED
(Assignee)

Comment 7

3 years ago
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");
+    }
Flags: needinfo?(adw)
(Assignee)

Comment 8

3 years ago
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)
(Assignee)

Comment 9

3 years ago
Created attachment 8586019 [details] [diff] [review]
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.
Assignee: adw → mhammond
Flags: needinfo?(adw)
(Assignee)

Comment 10

3 years ago
Created attachment 8586024 [details] [diff] [review]
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.
Attachment #8586024 - Flags: review?(adw)

Comment 11

3 years ago
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
Attachment #8586024 - Flags: review?(adw) → review+

Comment 12

3 years ago
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?
(Assignee)

Comment 13

3 years ago
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
Points: --- → 3
status-firefox38: --- → fixed
status-firefox39: --- → fixed
status-firefox40: --- → affected
https://hg.mozilla.org/mozilla-central/rev/6b167d125ec9
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
status-firefox40: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 40
Flags: qe-verify+
QA Contact: andrei.vaida
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.
Status: RESOLVED → VERIFIED
status-firefox39: fixed → verified
status-firefox40: fixed → verified
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.
status-firefox38: fixed → verified
(Assignee)

Comment 17

3 years ago
(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)
Flags: needinfo?(andrei.vaida)
(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.
Flags: needinfo?(andrei.vaida)
Product: Firefox → Firefox Graveyard
You need to log in before you can comment on or make changes to this bug.