1149105 - Various sync failures including "Failed to add a new item from server record: Error: The item must have a url"

Status: RESOLVED FIXED

(Firefox Graveyard :: Reading List, defect)

Description

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Attachment: log

Trying to track down bug 1149023 (which is almost certainly related to this), I found the same error Drew and I chatted about briefly in IRC. My STR are basically "click the '+/-' button in the URL bar as fast as you possibly can".

Highlights from this single log include:

> 1427712929379   readinglist.sync        WARN    Failed to add a new item from server record {"deleted":true,"last_modified":1427713238777,"id":"5a2f319a497f438c83e4ddecb628ec69"}: Error: The item must have a url (resource:///modules/readinglist/ReadingList.jsm:315) JS Stack trace: ReadingListImpl.prototype.addItem<@ReadingList.jsm:315:1

> 1427712929683   readinglist.sync        WARN    Failed to update an item from server record {"archived":false,"marked_read_on":null,"favorite":true,"title":"1149023 – unable to remove reading list item","url":"https://bugzilla.mozilla.org/show_bug.cgi?id=1149023","is_article":true,"stored_on":1427713239323,"excerpt":"","marked_read_by":null,"word_count":null,"read_position":0,"last_modified":1427713239326,"added_by":"skip's Nightly on eden","resolved_url":"https://bugzilla.mozilla.org/show_bug.cgi?id=1149023","id":"a2289718fa2c4384b78eb258fdc3c105","preview":"https://bugzilla.mozilla.org/extensions/OpenGraph/web/bugzilla.png","unread":true,"resolved_title":"1149023 – unable to remove reading list item","added_on":1427712928476}: Error: The item must belong to a reading list (resource:///modules/readinglist/ReadingList.jsm:884:12) JS Stack trace: [e-mail]:884:13 < [e-mail]:559:5 < ReadingListImpl.prototype.updateItem<@ReadingList.jsm:358:5

> 1427712929936   readinglist.sync        WARN    Failed to add a new item from server record {"archived":false,"marked_read_on":null,"favorite":true,"title":"1149023 – unable to remove reading list item","url":"https://bugzilla.mozilla.org/show_bug.cgi?id=1149023","is_article":true,"stored_on":1427713239323,"excerpt":"","marked_read_by":null,"word_count":null,"read_position":0,"last_modified":1427713239326,"added_by":"skip's Nightly on eden","resolved_url":"https://bugzilla.mozilla.org/show_bug.cgi?id=1149023","id":"a2289718fa2c4384b78eb258fdc3c105","preview":"https://bugzilla.mozilla.org/extensions/OpenGraph/web/bugzilla.png","unread":true,"resolved_title":"1149023 – unable to remove reading list item","added_on":1427712928476}: 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

Comment 1

[Marco Mucci [:MarcoM]]

Hi Drew, can you provide a point value.

Comment 2

[Drew Willcoxon :adw]

Attachment: patch

The 'Failed to add a new item from server record {"deleted":true' is due to downloading a deleted item, during the download-modified-items phase, that doesn't exist locally.  Sync should pretty clearly handle that possibility I think, regardless of how it happened, since the client doesn't control when the server truly deletes its (the server's) items.

The other two changes just allow the possibility of errors, as documented in their comments.  I'm kind of uneasy about this part of the patch, so I'm not asserting it's 100% right, and I'd like to hear your thoughts.

Comment 3

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Comment on attachment 8586355 [details] [diff] [review]
patch

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

I think this is in the right direction, but I'm not sure it's quite enough and may silence real errors.

::: browser/components/readinglist/Sync.jsm
@@ +380,5 @@
>          continue;
>        }
> +      if (serverRecord.deleted) {
> +        // There's no local item for this record, so there's nothing to do.
> +        continue;

I don't see a reason not to hoist the serverRecord.deleted check a few lines above, before we've even tried to get a local item, and _deleteItemForGUID should gracefully and silently handle an "already deleted" exception - ie, this is a good use-case for those better errors (and possibly why those errors should be done in this patch rather than the other.)

This also helps us move to a more atomic model - rather than a "check it exists then delete if it does", which is error prone, we just always try the delete without first checking.

(I think eventually we should do the same for, eg, ReadingList.hasItem*() - we should just force the browser code to *always* attempt to add the item, and a ReadingList.Errors.AlreadyExists() exception is gracefully handled.)  See also below.

@@ +390,5 @@
>        try {
>          yield this.list.addItem(localRecord);
>        } catch (ex) {
> +        log.debug("Failed to add a new item from server record ${serverRecord}: ${ex}",
> +                  {serverRecord, ex});

ditto here - in bug 1148980 I've changed this to log.error() which would cause an error log to be written.  I think "downgrading" this to a .debug is a step backwards without first checking if the error is exactly "item already exists" - ie, I was planning to write this as:

} catch (ex) {
  if (ex instanceof ReadingList.Errors.AlreadyExists) {
    log.debug("tried to apply a item from the server but it already existed - ignoring");
  } else {
    log.error(...);
  }
}

@@ +434,5 @@
>     */
>    _updateItemWithServerRecord: Task.async(function* (localItem, serverRecord) {
>      if (!localItem) {
> +      // The item may have been deleted from the local list between the time we
> +      // saw that it needed updating and now.

I think we should log.debug here with the URL and GUID of the offending item.  But even better would be to re-jig things so we don't need the local item to perform the update - eg, maybe updateItem could have a similar updateFromRecord() that "does the right thing" if it can.

IOW, I think ultimately we should be suspect of any code that does a 2-step "fetch local item, then update/delete it" and replace it with a single function we can pretend is atomic.

@@ +442,5 @@
>      try {
>        yield this.list.updateItem(localItem);
>      } catch (ex) {
> +      // The item may have been deleted from the local list after we fetched it.
> +      log.debug("Failed to update an item from server record ${serverRecord}: ${ex}",

or it could be an unrelated error?

Comment 4

[Drew Willcoxon :adw]

Attachment: patch v2 + error changes from other bug

This includes the error changes from bug 1149403.

(In reply to Mark Hammond [:markh] from comment #3)
> @@ +434,5 @@
> >     */
> >    _updateItemWithServerRecord: Task.async(function* (localItem, serverRecord) {
> >      if (!localItem) {
> > +      // The item may have been deleted from the local list between the time we
> > +      // saw that it needed updating and now.
> 
> I think we should log.debug here with the URL and GUID of the offending
> item.  But even better would be to re-jig things so we don't need the local
> item to perform the update - eg, maybe updateItem could have a similar
> updateFromRecord() that "does the right thing" if it can.

I like that idea, but one of the TODOs is to reconcile differences between local and server items before updating the local item, so we need to fetch the local item anyway.  Since that makes two of the three _updateItemWithServerRecord callers that either need or already have the local item, I left it as is (but did the logging you suggested).

Comment 5

[Mark Hammond (PTO; back Oct-3) [:markh] [:mhammond]]

Comment on attachment 8587054 [details] [diff] [review]
patch v2 + error changes from other bug

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

I think this is OK with the requested tweaks.

::: browser/components/readinglist/ReadingList.jsm
@@ +101,5 @@
>    unread
>  `.trim().split(/\s+/);
>  
> +function ReadingListError(message, fileName, lineNumber) {
> +  message = Array.isArray(message) ? message.join(": ") : message;

No one ever passes an array, so I don't think we need this.

@@ +106,5 @@
> +  this.message = message;
> +  this.fileName = fileName;
> +  this.lineNumber = lineNumber;
> +  this.name = this.constructor.name;
> +  this.stack = (new Error()).stack;

do we really need .fileName, .lineNumber and .stack?  We never pass the former 2 in and I can't see why the default .stack behaviour isn't fine for us (eg, I wonder if .stack will actually break future builtin stack enhancements that manage to unwrap promises). So I think we should remove them.

@@ +334,5 @@
>     */
>    addItem: Task.async(function* (record) {
>      record = normalizeRecord(record);
>      if (!record.url) {
> +      throw new ReadingListError("The item to be added must have a url");

TBH I'm not sure that this should be a ReadingListError - if JS had a "ValueError" I'd say to use that - but it doesn't :)  This error is due to a caller error rather than something specific to the readinglist, so I vaguely think a plain Error() is more suitable but I don't feel strongly.

@@ +350,5 @@
>      if (!("syncStatus" in record)) {
>        record.syncStatus = SYNC_STATUS_NEW;
>      }
>  
> +    log.debug("Adding item with guid: ${guid}, url: ${url}", record);

I think you will find this log is already there from my push of yesterday (ie, this will probably need trivial rebasing)

@@ +355,1 @@
>      yield this._store.addItem(record);

isn't this where we need to throw Error.Exists()?  Oh - see my comments in SQLiteStore.jsm - it does seem a little strange that this is the one place where we rely on the store to throw our ReadingListError for us.

@@ +376,5 @@
>     *         Error on error.
>     */
>    updateItem: Task.async(function* (item) {
> +    if (item._deleted) {
> +      throw new ReadingListDeletedError("The item to be updated has been deleted");

I don't see much value in specific strings for these errors - the stack should make it obvious - so passing no args and using the default seems better to me (similarly for all errors below)

@@ +859,5 @@
>     *
>     * @return Promise<null> Resolved when the list has been updated.
>     */
>    delete: Task.async(function* () {
>      this._ensureBelongsToList();

don't we want a ._deleted check here?  I suspect we'll still throw the "must belong to a list" error instead of Error.Deleted

(hrm - I see your test covers this, but I don't understand it. The deleted record should have no .list attribute, so it should immediately fail rather than getting to the this.list.deleteItem() call where .Deleted() is thrown?)

@@ +1031,5 @@
>      if (ITEM_DISREGARDED_PROPERTIES.indexOf(prop) >= 0) {
>        continue;
>      }
>      if (ITEM_RECORD_PROPERTIES.indexOf(prop) < 0) {
> +      throw new ReadingListError("Unrecognized item property: " + prop);

same comment here as above re a "plain" error

::: browser/components/readinglist/SQLiteStore.jsm
@@ +307,5 @@
> +function throwExistsError(err) {
> +  let match =
> +    /UNIQUE constraint failed: items\.([a-zA-Z0-9_]+)/.exec(err.message);
> +  if (match) {
> +    let newErr = new ReadingList.Error.Exists(

it seems a little wrong to me that this module is throwing readinglist errors, but do agree the logic for "parsing" the constraint failures *does* belong here.  It seems it would be cleaner to have this module throw a specific error and for ReadingList.jsm to catch that and re-throw it as a ReadingList error.  OTOH though, this is pragmatic and not too bad (the modules are already relatively tightly bound), so I guess I'm OK with it (but TBH got less OK with it the more files I looked at).  But if you feel strongly about keeping it this way I can live with it.

::: browser/components/readinglist/Sync.jsm
@@ +390,5 @@
> +        if (ex instanceof ReadingList.Error.Exists) {
> +          log.debug("Tried to add an item that already exists.");
> +        } else {
> +          log.error("Error adding an item from server record",
> +                    serverRecord, ex);

the log module doesn't support 2 additional args, only 1 - ie:

log.error("foo", bar); // appends the repr of bar
log.error("foo", bar, rab); // same as above - ignores rab

so what you want is something like:

log.error("Error adding an item from server record: item=${serverRecord}, error=${ex}", {serverRecord, ex});

@@ +450,5 @@
> +        log.debug("Tried to update an item that was deleted from server record",
> +                  serverRecord);
> +      } else {
> +        log.error("Error updating an item from server record",
> +                  serverRecord, ex);

ditto here (but note the 2 .debug lines above are fine - a single additional arg with no ${} insertions just appends that param)

@@ +471,5 @@
>        item._record.syncStatus = ReadingList.SyncStatus.NEW;
>        try {
>          yield this.list.deleteItem(item);
>        } catch (ex) {
> +        log.error("Failed delete local item with id", guid, ex);

and here

@@ +483,5 @@
>      log.debug("Item not present in list, deleting it by GUID instead");
>      try {
>        this.list._store.deleteItemByGUID(guid);
>      } catch (ex) {
> +      log.error("Failed to delete local item with id", guid, ex);

and here.

::: browser/components/readinglist/test/xpcshell/test_SQLiteStore.js
@@ +59,5 @@
>    catch (e) {
>      err = e;
>    }
> +  Assert.ok(err);
> +  Assert.ok(err instanceof ReadingList.Error.Exists);

same comment re the errors thrown in SQLiteStore - seems very unnatural for this test to need to import ReadingList.jsm and catch an error defined in that module when unittesting the store.

Comment 6

[Drew Willcoxon :adw]

(In reply to Mark Hammond [:markh] from comment #5)
> ::: browser/components/readinglist/ReadingList.jsm
> @@ +101,5 @@
> >    unread
> >  `.trim().split(/\s+/);
> >  
> > +function ReadingListError(message, fileName, lineNumber) {
> > +  message = Array.isArray(message) ? message.join(": ") : message;
> 
> No one ever passes an array, so I don't think we need this.

Oops, left over from a previous version.

> @@ +106,5 @@
> > +  this.message = message;
> > +  this.fileName = fileName;
> > +  this.lineNumber = lineNumber;
> > +  this.name = this.constructor.name;
> > +  this.stack = (new Error()).stack;
> 
> do we really need .fileName, .lineNumber and .stack?  We never pass the
> former 2 in and I can't see why the default .stack behaviour isn't fine for
> us (eg, I wonder if .stack will actually break future builtin stack
> enhancements that manage to unwrap promises). So I think we should remove
> them.

This is what you end up with if you just call Error.call(this, ...args) instead of setting all those properties:

>  0:01.79 LOG: Thread-1 ERROR Unexpected exception Error:  at resource:///modules/readinglist/ReadingList.jsm:115
> @resource:///modules/readinglist/ReadingList.jsm:115:30
> @/Users/adw/fx/obj-debug/_tests/xpcshell/browser/components/readinglist/test/xpcshell/test_ReadingList.js:8:1
> load_file@/Users/adw/fx/testing/xpcshell/head.js:593:7
> _load_files@/Users/adw/fx/testing/xpcshell/head.js:605:3
> _execute_test@/Users/adw/fx/testing/xpcshell/head.js:494:3
> @-e:1:1
> ReadingListImpl.prototype.addItem<@resource:///modules/readinglist/ReadingList.jsm:355:11
> constraints@/Users/adw/fx/obj-debug/_tests/xpcshell/browser/components/readinglist/test/xpcshell/test_ReadingList.js:86:11
> _run_next_test@/Users/adw/fx/testing/xpcshell/head.js:1377:9
> do_execute_soon/<.run@/Users/adw/fx/testing/xpcshell/head.js:646:9
> _do_main@/Users/adw/fx/testing/xpcshell/head.js:207:5
> _execute_test@/Users/adw/fx/testing/xpcshell/head.js:506:5
> @-e:1:1

* no message
* the line number is the line number of ReadingListError.prototype = new Error()
* wrong error name
* weird stack

> @@ +334,5 @@
> >     */
> >    addItem: Task.async(function* (record) {
> >      record = normalizeRecord(record);
> >      if (!record.url) {
> > +      throw new ReadingListError("The item to be added must have a url");
> 
> TBH I'm not sure that this should be a ReadingListError - if JS had a
> "ValueError" I'd say to use that - but it doesn't :)  This error is due to a
> caller error rather than something specific to the readinglist, so I vaguely
> think a plain Error() is more suitable but I don't feel strongly.

So I guess I'm not clear on what the definition of "reading list error" is in your mind.  To me it's any error expressly created and thrown by reading list.  If it's not that, then there's no need for a generic reading list error like you suggested originally.

> @@ +355,1 @@
> >      yield this._store.addItem(record);
> 
> isn't this where we need to throw Error.Exists()?  Oh - see my comments in
> SQLiteStore.jsm - it does seem a little strange that this is the one place
> where we rely on the store to throw our ReadingListError for us.

> @@ +376,5 @@
> >     *         Error on error.
> >     */
> >    updateItem: Task.async(function* (item) {
> > +    if (item._deleted) {
> > +      throw new ReadingListDeletedError("The item to be updated has been deleted");
> 
> I don't see much value in specific strings for these errors - the stack
> should make it obvious - so passing no args and using the default seems
> better to me (similarly for all errors below)

It gives more context.  Here it says we were trying to update an item.  So I'll leave it.

> @@ +859,5 @@
> >     *
> >     * @return Promise<null> Resolved when the list has been updated.
> >     */
> >    delete: Task.async(function* () {
> >      this._ensureBelongsToList();
> 
> don't we want a ._deleted check here?  I suspect we'll still throw the "must
> belong to a list" error instead of Error.Deleted

Covered over IRC, you're right.

> ::: browser/components/readinglist/SQLiteStore.jsm
> @@ +307,5 @@
> > +function throwExistsError(err) {
> > +  let match =
> > +    /UNIQUE constraint failed: items\.([a-zA-Z0-9_]+)/.exec(err.message);
> > +  if (match) {
> > +    let newErr = new ReadingList.Error.Exists(
> 
> it seems a little wrong to me that this module is throwing readinglist
> errors, but do agree the logic for "parsing" the constraint failures *does*
> belong here.  It seems it would be cleaner to have this module throw a
> specific error and for ReadingList.jsm to catch that and re-throw it as a
> ReadingList error.  OTOH though, this is pragmatic and not too bad (the
> modules are already relatively tightly bound), so I guess I'm OK with it
> (but TBH got less OK with it the more files I looked at).  But if you feel
> strongly about keeping it this way I can live with it.

It seems OK to me, but I understand you.  It's weird that you didn't mind mixing sync stuff in with ReadingList.jsm but this is a problem.  The store jsm is only in service of the reading list, and I think it's OK for that to be reflected in the names of the errors.

Comment 7

[Drew Willcoxon :adw]

(In reply to Drew Willcoxon :adw from comment #6)
> > @@ +106,5 @@
> > > +  this.message = message;
> > > +  this.fileName = fileName;
> > > +  this.lineNumber = lineNumber;
> > > +  this.name = this.constructor.name;
> > > +  this.stack = (new Error()).stack;
> > 
> > do we really need .fileName, .lineNumber and .stack?  We never pass the
> > former 2 in and I can't see why the default .stack behaviour isn't fine for
> > us (eg, I wonder if .stack will actually break future builtin stack
> > enhancements that manage to unwrap promises). So I think we should remove
> > them.
> 
> This is what you end up with if you just call Error.call(this, ...args)
> instead of setting all those properties:

But you're right that we never pass fileName or lineNumber, so I did remove those.

Comment 8

[Drew Willcoxon :adw]

https://hg.mozilla.org/integration/fx-team/rev/7126c724dfbb

Comment 9

[Drew Willcoxon :adw]

https://hg.mozilla.org/mozilla-central/rev/7bb3942888eb
https://hg.mozilla.org/releases/mozilla-aurora/rev/1e609e29b0d4
https://hg.mozilla.org/releases/mozilla-beta/rev/818e63fbfba2

Comment 10

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/7126c724dfbb