Bug 1188170 - log the url string when the Sync bookmarks engine fails to get a URI. r=rnewman

services/sync/modules/engines/bookmarks.js

@@ -240,6 +240,32 @@ BookmarksEngine.prototype = {
     }
   },
 
+  // A diagnostic helper to get the string value for a bookmark's URL given
+  // its ID. Always returns a string - on error will return a string in the
+  // form of "<description of error>" as this is purely for, eg, logging.
+  // (This means hitting the DB directly and we don't bother using a cached
+  // statement - we should rarely hit this.)
+  _getStringUrlForId(id) {
+    let url;
+    try {
+      let stmt = this._store._getStmt(`
+            SELECT h.url
+            FROM moz_places h
+            JOIN moz_bookmarks b ON h.id = b.fk
+            WHERE b.id = :id`);
+      stmt.params.id = id;
+      let rows = Async.querySpinningly(stmt, ["url"]);
+      url = rows.length == 0 ? "<not found>" : rows[0].url;
+    } catch (ex) {
+      if (ex instanceof Ci.mozIStorageError) {
+        url = `<failed: Storage error: ${ex.message} (${ex.result})>`;
+      } else {
+        url = `<failed: ${ex.toString()}>`;
+      }
+    }
+    return url;
+  },
+
   _guidMapFailed: false,
   _buildGUIDMap: function _buildGUIDMap() {
     let guidMap = {};
@@ -277,7 +303,9 @@ BookmarksEngine.prototype = {
               uri = PlacesUtils.bookmarks.getBookmarkURI(id);
             } catch (ex) {
               // Bug 1182366 - NS_ERROR_MALFORMED_URI here stops bookmarks sync.
-              this._log.warn("Deleting bookmark with invalid URI. id: " + id);
+              // Try and get the string value of the URL for diagnostic purposes.
+              let url = this._getStringUrlForId(id);
+              this._log.warn(`Deleting bookmark with invalid URI. url="${url}", id=${id}`);
               try {
                 PlacesUtils.bookmarks.removeItem(id);
               } catch (ex) {

services/sync/tests/unit/test_bookmark_invalid.js

@@ -0,0 +1,111 @@
+Cu.import("resource://gre/modules/PlacesUtils.jsm");
+Cu.import("resource://gre/modules/Log.jsm");
+Cu.import("resource://gre/modules/Task.jsm");
+Cu.import("resource://services-sync/engines.js");
+Cu.import("resource://services-sync/engines/bookmarks.js");
+Cu.import("resource://services-sync/service.js");
+Cu.import("resource://services-sync/util.js");
+
+Service.engineManager.register(BookmarksEngine);
+
+let engine = Service.engineManager.get("bookmarks");
+let store = engine._store;
+let tracker = engine._tracker;
+
+// Return a promise resolved when the specified message is written to the
+// bookmarks engine log.
+function promiseLogMessage(messagePortion) {
+  return new Promise(resolve => {
+    let appender;
+    let log = Log.repository.getLogger("Sync.Engine.Bookmarks");
+
+    function TestAppender() {
+      Log.Appender.call(this);
+    }
+    TestAppender.prototype = Object.create(Log.Appender.prototype);
+    TestAppender.prototype.doAppend = function(message) {
+      if (message.indexOf(messagePortion) >= 0) {
+        log.removeAppender(appender);
+        resolve();
+      }
+    };
+    TestAppender.prototype.level = Log.Level.Debug;
+    appender = new TestAppender();
+    log.addAppender(appender);
+  });
+}
+
+// Returns a promise that resolves if the specified ID does *not* exist and
+// rejects if it does.
+function promiseNoItem(itemId) {
+  return new Promise((resolve, reject) => {
+    try {
+      PlacesUtils.bookmarks.getFolderIdForItem(itemId);
+      reject("fetching the item didn't fail");
+    } catch (ex) {
+      if (ex.result == Cr.NS_ERROR_ILLEGAL_VALUE) {
+        resolve("item doesn't exist");
+      } else {
+        reject("unexpected exception: " + ex);
+      }
+    }
+  });
+}
+
+add_task(function* test_ignore_invalid_uri() {
+  _("Ensure that we don't die with invalid bookmarks.");
+
+  // First create a valid bookmark.
+  let bmid = PlacesUtils.bookmarks.insertBookmark(PlacesUtils.unfiledBookmarksFolderId,
+                                                  Services.io.newURI("http://example.com/", null, null),
+                                                  PlacesUtils.bookmarks.DEFAULT_INDEX,
+                                                  "the title");
+
+  // Now update moz_places with an invalid url.
+  yield PlacesUtils.withConnectionWrapper("test_ignore_invalid_uri", Task.async(function* (db) {
+    yield db.execute(
+      `UPDATE moz_places SET url = :url
+       WHERE id = (SELECT b.fk FROM moz_bookmarks b
+       WHERE b.id = :id LIMIT 1)`,
+      { id: bmid, url: "<invalid url>" });
+  }));
+
+  // DB is now "corrupt" - setup a log appender to capture what we log.
+  let promiseMessage = promiseLogMessage('Deleting bookmark with invalid URI. url="<invalid url>"');
+  // This should work and log our invalid id.
+  engine._buildGUIDMap();
+  yield promiseMessage;
+  // And we should have deleted the item.
+  yield promiseNoItem(bmid);
+});
+
+add_task(function* test_ignore_missing_uri() {
+  _("Ensure that we don't die with a bookmark referencing an invalid bookmark id.");
+
+  // First create a valid bookmark.
+  let bmid = PlacesUtils.bookmarks.insertBookmark(PlacesUtils.unfiledBookmarksFolderId,
+                                                  Services.io.newURI("http://example.com/", null, null),
+                                                  PlacesUtils.bookmarks.DEFAULT_INDEX,
+                                                  "the title");
+
+  // Now update moz_bookmarks to reference a non-existing places ID
+  yield PlacesUtils.withConnectionWrapper("test_ignore_missing_uri", Task.async(function* (db) {
+    yield db.execute(
+      `UPDATE moz_bookmarks SET fk = 999999
+       WHERE id = :id`
+      , { id: bmid });
+  }));
+
+  // DB is now "corrupt" - bookmarks will fail to locate a string url to log
+  // and use "<not found>" as a placeholder.
+  let promiseMessage = promiseLogMessage('Deleting bookmark with invalid URI. url="<not found>"');
+  engine._buildGUIDMap();
+  yield promiseMessage;
+  // And we should have deleted the item.
+  yield promiseNoItem(bmid);
+});
+
+function run_test() {
+  initTestLogging('Trace');
+  run_next_test();
+}

services/sync/tests/unit/xpcshell.ini

@@ -136,6 +136,7 @@ run-sequentially = Hardcoded port in static files.
 [test_addons_tracker.js]
 [test_bookmark_batch_fail.js]
 [test_bookmark_engine.js]
+[test_bookmark_invalid.js]
 [test_bookmark_legacy_microsummaries_support.js]
 [test_bookmark_livemarks.js]
 [test_bookmark_order.js]