Bug 1149105 - Fix various desktop reading list sync failures, add more logging. r=markh

This commit is contained in:
Drew Willcoxon 2015-03-31 16:41:13 +11:00
parent e759de6df5
commit b4729bbf46
5 changed files with 189 additions and 75 deletions

View File

@ -26,16 +26,6 @@ XPCOMUtils.defineLazyGetter(this, "SyncUtils", function() {
return Utils;
});
{ // Prevent the parent log setup from leaking into the global scope.
let parentLog = Log.repository.getLogger("readinglist");
parentLog.level = Preferences.get("browser.readinglist.logLevel", Log.Level.Warn);
Preferences.observe("browser.readinglist.logLevel", value => {
parentLog.level = value;
});
let formatter = new Log.BasicFormatter();
parentLog.addAppender(new Log.ConsoleAppender(formatter));
parentLog.addAppender(new Log.DumpAppender(formatter));
}
let log = Log.repository.getLogger("readinglist.api");
@ -100,6 +90,30 @@ const SYNC_STATUS_PROPERTIES_STATUS = `
unread
`.trim().split(/\s+/);
function ReadingListError(message) {
this.message = message;
this.name = this.constructor.name;
this.stack = (new Error()).stack;
// Consumers can set this to an Error that this ReadingListError wraps.
this.originalError = null;
}
ReadingListError.prototype = new Error();
ReadingListError.prototype.constructor = ReadingListError;
function ReadingListExistsError(message) {
message = message || "The item already exists";
ReadingListError.call(this, message);
}
ReadingListExistsError.prototype = new ReadingListError();
ReadingListExistsError.prototype.constructor = ReadingListExistsError;
function ReadingListDeletedError(message) {
message = message || "The item has been deleted";
ReadingListError.call(this, message);
}
ReadingListDeletedError.prototype = new ReadingListError();
ReadingListDeletedError.prototype.constructor = ReadingListDeletedError;
/**
* A reading list contains ReadingListItems.
@ -161,6 +175,12 @@ function ReadingListImpl(store) {
ReadingListImpl.prototype = {
Error: {
Error: ReadingListError,
Exists: ReadingListExistsError,
Deleted: ReadingListDeletedError,
},
ItemRecordProperties: ITEM_RECORD_PROPERTIES,
SyncStatus: {
@ -303,7 +323,7 @@ ReadingListImpl.prototype = {
addItem: Task.async(function* (record) {
record = normalizeRecord(record);
if (!record.url) {
throw new Error("The item must have a url");
throw new ReadingListError("The item to be added must have a url");
}
if (!("addedOn" in record)) {
record.addedOn = Date.now();
@ -319,9 +339,9 @@ ReadingListImpl.prototype = {
record.syncStatus = SYNC_STATUS_NEW;
}
log.debug("addingItem with guid: ${guid}, url: ${url}", record);
log.debug("Adding item with guid: ${guid}, url: ${url}", record);
yield this._store.addItem(record);
log.trace("added item with guid: ${guid}, url: ${url}", record);
log.trace("Added item with guid: ${guid}, url: ${url}", record);
this._invalidateIterators();
let item = this._itemFromRecord(record);
this._callListeners("onItemAdded", item);
@ -345,13 +365,16 @@ ReadingListImpl.prototype = {
* Error on error.
*/
updateItem: Task.async(function* (item) {
if (item._deleted) {
throw new ReadingListDeletedError("The item to be updated has been deleted");
}
if (!item._record.url) {
throw new Error("The item must have a url");
throw new ReadingListError("The item to be updated must have a url");
}
this._ensureItemBelongsToList(item);
log.debug("updatingItem with guid: ${guid}, url: ${url}", item._record);
log.debug("Updating item with guid: ${guid}, url: ${url}", item._record);
yield this._store.updateItem(item._record);
log.trace("finished update of item guid: ${guid}, url: ${url}", item._record);
log.trace("Finished updating item with guid: ${guid}, url: ${url}", item._record);
this._invalidateIterators();
this._callListeners("onItemUpdated", item);
}),
@ -367,16 +390,23 @@ ReadingListImpl.prototype = {
* Error on error.
*/
deleteItem: Task.async(function* (item) {
if (item._deleted) {
throw new ReadingListDeletedError("The item has already been deleted");
}
this._ensureItemBelongsToList(item);
log.debug("Deleting item with guid: ${guid}, url: ${url}");
// If the item is new and therefore hasn't been synced yet, delete it from
// the store. Otherwise mark it as deleted but don't actually delete it so
// that its status can be synced.
if (item._record.syncStatus == SYNC_STATUS_NEW) {
log.debug("deleteItem guid: ${guid}, url: ${url} - item is local so really deleting it", item._record);
log.debug("Item is new, truly deleting it", item._record);
yield this._store.deleteItemByURL(item.url);
}
else {
log.debug("Item has been synced, only marking it as deleted",
item._record);
// To prevent data leakage, only keep the record fields needed to sync
// the deleted status: guid and syncStatus.
let newRecord = {};
@ -385,12 +415,12 @@ ReadingListImpl.prototype = {
}
newRecord.guid = item._record.guid;
newRecord.syncStatus = SYNC_STATUS_DELETED;
log.debug("deleteItem guid: ${guid}, url: ${url} - item has been synced so updating to deleted state", item._record);
yield this._store.updateItemByGUID(newRecord);
}
log.trace("finished db operation deleting item with guid: ${guid}, url: ${url}", item._record);
log.trace("Finished deleting item with guid: ${guid}, url: ${url}", item._record);
item.list = null;
item._deleted = true;
// failing to remove the item from the map points at something bad!
if (!this._itemsByNormalizedURL.delete(item.url)) {
log.error("Failed to remove item from the map", item);
@ -576,7 +606,7 @@ ReadingListImpl.prototype = {
_ensureItemBelongsToList(item) {
if (!item || !item._ensureBelongsToList) {
throw new Error("The item is not a ReadingListItem");
throw new ReadingListError("The item is not a ReadingListItem");
}
item._ensureBelongsToList();
},
@ -596,6 +626,7 @@ let _unserializable = () => {}; // See comments in the ReadingListItem ctor.
*/
function ReadingListItem(record={}) {
this._record = record;
this._deleted = false;
// |this._unserializable| works around a problem when sending one of these
// items via a message manager. If |this.list| is set, the item can't be
@ -844,9 +875,11 @@ ReadingListItem.prototype = {
* @return Promise<null> Resolved when the list has been updated.
*/
delete: Task.async(function* () {
if (this._deleted) {
throw new ReadingListDeletedError("The item has already been deleted");
}
this._ensureBelongsToList();
yield this.list.deleteItem(this);
this.delete = () => Promise.reject("The item has already been deleted");
}),
toJSON() {
@ -903,7 +936,7 @@ ReadingListItem.prototype = {
_ensureBelongsToList() {
if (!this.list) {
throw new Error("The item must belong to a reading list");
throw new ReadingListError("The item must belong to a list");
}
},
};
@ -996,7 +1029,7 @@ ReadingListItemIterator.prototype = {
_ensureValid() {
if (this.invalid) {
throw new Error("The iterator has been invalidated");
throw new ReadingListError("The iterator has been invalidated");
}
},
};
@ -1014,7 +1047,7 @@ function normalizeRecord(nonNormalizedRecord) {
let record = {};
for (let prop in nonNormalizedRecord) {
if (ITEM_RECORD_PROPERTIES.indexOf(prop) < 0) {
throw new Error("Unrecognized item property: " + prop);
throw new ReadingListError("Unrecognized item property: " + prop);
}
switch (prop) {
case "url":

View File

@ -90,9 +90,14 @@ this.SQLiteStore.prototype = {
paramNames.push(`:${propName}`);
}
let conn = yield this._connectionPromise;
yield conn.executeCached(`
INSERT INTO items (${colNames}) VALUES (${paramNames});
`, item);
try {
yield conn.executeCached(`
INSERT INTO items (${colNames}) VALUES (${paramNames});
`, item);
}
catch (err) {
throwExistsError(err);
}
}),
/**
@ -207,11 +212,16 @@ this.SQLiteStore.prototype = {
}
let conn = yield this._connectionPromise;
if (!item[keyProp]) {
throw new Error("Item must have " + keyProp);
throw new ReadingList.Error.Error("Item must have " + keyProp);
}
try {
yield conn.executeCached(`
UPDATE items SET ${assignments} WHERE ${keyProp} = :${keyProp};
`, item);
}
catch (err) {
throwExistsError(err);
}
yield conn.executeCached(`
UPDATE items SET ${assignments} WHERE ${keyProp} = :${keyProp};
`, item);
}),
// The current schema version.
@ -288,6 +298,26 @@ function itemFromRow(row) {
return item;
}
/**
* If the given Error indicates that a unique constraint failed, then wraps that
* error in a ReadingList.Error.Exists and throws it. Otherwise throws the
* given error.
*
* @param err An Error object.
*/
function throwExistsError(err) {
let match =
/UNIQUE constraint failed: items\.([a-zA-Z0-9_]+)/.exec(err.message);
if (match) {
let newErr = new ReadingList.Error.Exists(
"An item with the following property already exists: " + match[1]
);
newErr.originalError = err;
err = newErr;
}
throw err;
}
/**
* Returns the back part of a SELECT statement generated from the given list of
* options.

View File

@ -360,6 +360,11 @@ SyncImpl.prototype = {
// Update local items based on the response.
for (let serverRecord of response.body.items) {
if (serverRecord.deleted) {
// _deleteItemForGUID is a no-op if no item exists with the GUID.
yield this._deleteItemForGUID(serverRecord.id);
continue;
}
let localItem = yield this._itemForGUID(serverRecord.id);
if (localItem) {
if (localItem.serverLastModified == serverRecord.last_modified) {
@ -372,20 +377,22 @@ SyncImpl.prototype = {
// the material-changes phase.
// TODO
if (serverRecord.deleted) {
yield this._deleteItemForGUID(serverRecord.id);
continue;
}
yield this._updateItemWithServerRecord(localItem, serverRecord);
continue;
}
// new item
// A potentially new item. addItem() will fail here when an item was
// added to the local list between the time we uploaded new items and
// now.
let localRecord = localRecordFromServerRecord(serverRecord);
try {
yield this.list.addItem(localRecord);
} catch (ex) {
log.warn("Failed to add a new item from server record ${serverRecord}: ${ex}",
{serverRecord, ex});
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}",
{ serverRecord, ex });
}
}
}
@ -428,14 +435,24 @@ SyncImpl.prototype = {
*/
_updateItemWithServerRecord: Task.async(function* (localItem, serverRecord) {
if (!localItem) {
throw new Error("Item should exist");
// The item may have been deleted from the local list between the time we
// saw that it needed updating and now.
log.debug("Tried to update a null local item from server record",
serverRecord);
return;
}
localItem._record = localRecordFromServerRecord(serverRecord);
try {
yield this.list.updateItem(localItem);
} catch (ex) {
log.warn("Failed to update an item from server record ${serverRecord}: ${ex}",
{serverRecord, ex});
// The item may have been deleted from the local list after we fetched it.
if (ex instanceof ReadingList.Error.Deleted) {
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}",
{ serverRecord, ex });
}
}
}),
@ -455,8 +472,8 @@ SyncImpl.prototype = {
try {
yield this.list.deleteItem(item);
} catch (ex) {
log.warn("Failed delete local item with id ${guid}: ${ex}",
{guid, ex});
log.error("Failed delete local item with id ${guid} ${ex}",
{ guid, ex });
}
return;
}
@ -468,8 +485,8 @@ SyncImpl.prototype = {
try {
this.list._store.deleteItemByGUID(guid);
} catch (ex) {
log.warn("Failed to delete local item with id ${guid}: ${ex}",
{guid, ex});
log.error("Failed to delete local item with id ${guid} ${ex}",
{ guid, ex });
}
}),
@ -488,7 +505,7 @@ SyncImpl.prototype = {
}),
_handleUnexpectedResponse(contextMsgFragment, response) {
log.warn(`Unexpected response ${contextMsgFragment}`, response);
log.error(`Unexpected response ${contextMsgFragment}`, response);
},
// TODO: Wipe this pref when user logs out.

View File

@ -92,7 +92,8 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err);
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
// add a new item with an existing guid
let item = kindOfClone(gItems[0]);
@ -104,7 +105,8 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err);
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
// add a new item with an existing url
item = kindOfClone(gItems[0]);
@ -116,7 +118,8 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err);
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
// add a new item with an existing resolvedURL
item = kindOfClone(gItems[0]);
@ -128,7 +131,8 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err);
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
// add a new item with no url
item = kindOfClone(gItems[0]);
@ -141,8 +145,9 @@ add_task(function* constraints() {
err = e;
}
Assert.ok(err);
Assert.ok(err instanceof Cu.getGlobalForObject(ReadingList).Error, err);
Assert.equal(err.message, "The item must have a url");
Assert.ok(err instanceof ReadingList.Error.Error);
Assert.ok(!(err instanceof ReadingList.Error.Exists));
Assert.ok(!(err instanceof ReadingList.Error.Deleted));
// update an item with no url
item = (yield gList.item({ guid: gItems[0].guid }));
@ -158,8 +163,9 @@ add_task(function* constraints() {
}
item._record.url = oldURL;
Assert.ok(err);
Assert.ok(err instanceof Cu.getGlobalForObject(ReadingList).Error, err);
Assert.equal(err.message, "The item must have a url");
Assert.ok(err instanceof ReadingList.Error.Error);
Assert.ok(!(err instanceof ReadingList.Error.Exists));
Assert.ok(!(err instanceof ReadingList.Error.Deleted));
// add an item with a bogus property
item = kindOfClone(gItems[0]);
@ -172,8 +178,9 @@ add_task(function* constraints() {
err = e;
}
Assert.ok(err);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("Unrecognized item property:") >= 0);
Assert.ok(err instanceof ReadingList.Error.Error);
Assert.ok(!(err instanceof ReadingList.Error.Exists));
Assert.ok(!(err instanceof ReadingList.Error.Deleted));
// add a new item with no guid, which is allowed
item = kindOfClone(gItems[0]);
@ -666,7 +673,21 @@ add_task(function* deleteItem() {
});
let item = (yield iter.items(1))[0];
Assert.ok(item);
item.delete();
let {url, guid} = item;
Assert.ok((yield gList.itemForURL(url)), "should be able to get the item by URL before deletion");
Assert.ok((yield gList.item({guid})), "should be able to get the item by GUID before deletion");
yield item.delete();
try {
yield item.delete();
Assert.ok(false, "should not successfully delete the item a second time")
} catch(ex) {
Assert.ok(ex instanceof ReadingList.Error.Deleted);
}
Assert.ok(!(yield gList.itemForURL(url)), "should fail to get a deleted item by URL");
Assert.ok(!(yield gList.item({guid})), "should fail to get a deleted item by GUID");
gItems[0].list = null;
Assert.equal((yield gList.count()), gItems.length - 1);
let items = [];
@ -677,6 +698,12 @@ add_task(function* deleteItem() {
// delete second item with list.deleteItem()
yield gList.deleteItem(items[0]);
try {
yield gList.deleteItem(items[0]);
Assert.ok(false, "should not successfully delete the item a second time")
} catch(ex) {
Assert.ok(ex instanceof ReadingList.Error.Deleted);
}
gItems[1].list = null;
Assert.equal((yield gList.count()), gItems.length - 2);
items = [];
@ -728,11 +755,6 @@ function checkItems(actualItems, expectedItems) {
}
}
function checkError(err) {
Assert.ok(err);
Assert.ok(err instanceof Cu.getGlobalForObject(Sqlite).Error, err);
}
function kindOfClone(item) {
let newItem = {};
for (let prop in item) {

View File

@ -3,6 +3,7 @@
"use strict";
Cu.import("resource:///modules/readinglist/ReadingList.jsm");
Cu.import("resource:///modules/readinglist/SQLiteStore.jsm");
Cu.import("resource://gre/modules/Sqlite.jsm");
@ -58,7 +59,10 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err, "UNIQUE constraint failed");
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("An item with the following property already exists:") >= 0);
// add a new item with an existing guid
function kindOfClone(item) {
@ -80,7 +84,10 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err, "UNIQUE constraint failed: items.guid");
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("An item with the following property already exists: guid") >= 0);
// add a new item with an existing url
item = kindOfClone(gItems[0]);
@ -92,7 +99,10 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err, "UNIQUE constraint failed: items.url");
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("An item with the following property already exists: url") >= 0);
// update an item with an existing url
item.guid = gItems[1].guid;
@ -106,7 +116,10 @@ add_task(function* constraints() {
// The failure actually happens on items.guid, not items.url, because the item
// is first looked up by url, and then its other properties are updated on the
// resulting row.
checkError(err, "UNIQUE constraint failed: items.guid");
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("An item with the following property already exists: guid") >= 0);
// add a new item with an existing resolvedURL
item = kindOfClone(gItems[0]);
@ -118,7 +131,10 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err, "UNIQUE constraint failed: items.resolvedURL");
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("An item with the following property already exists: resolvedURL") >= 0);
// update an item with an existing resolvedURL
item.url = gItems[1].url;
@ -129,7 +145,10 @@ add_task(function* constraints() {
catch (e) {
err = e;
}
checkError(err, "UNIQUE constraint failed: items.resolvedURL");
Assert.ok(err);
Assert.ok(err instanceof ReadingList.Error.Exists);
Assert.ok(err.message);
Assert.ok(err.message.indexOf("An item with the following property already exists: resolvedURL") >= 0);
// add a new item with no guid, which is allowed
item = kindOfClone(gItems[0]);
@ -312,10 +331,3 @@ function checkItems(actualItems, expectedItems) {
}
}
}
function checkError(err, expectedMsgSubstring) {
Assert.ok(err);
Assert.ok(err instanceof Cu.getGlobalForObject(Sqlite).Error);
Assert.ok(err.message);
Assert.ok(err.message.indexOf(expectedMsgSubstring) >= 0, err.message);
}