Bug 622999 - Merge fx-sync to mozilla-central. a=blockers

services/sync/modules/engines/bookmarks.js

@@ -210,12 +210,15 @@ BookmarksEngine.prototype = {
   },
 
   _processIncoming: function _processIncoming() {
-    SyncEngine.prototype._processIncoming.call(this);
-    // Reorder children.
-    this._tracker.ignoreAll = true;
-    this._store._orderChildren();
-    this._tracker.ignoreAll = false;
-    delete this._store._childrenToOrder;
+    try {
+      SyncEngine.prototype._processIncoming.call(this);
+    } finally {
+      // Reorder children.
+      this._tracker.ignoreAll = true;
+      this._store._orderChildren();
+      this._tracker.ignoreAll = false;
+      delete this._store._childrenToOrder;
+    }
   },
 
   _syncFinish: function _syncFinish() {

services/sync/modules/engines/forms.js

@@ -46,8 +46,11 @@ Cu.import("resource://services-sync/stores.js");
 Cu.import("resource://services-sync/trackers.js");
 Cu.import("resource://services-sync/type_records/forms.js");
 Cu.import("resource://services-sync/util.js");
+Cu.import("resource://services-sync/log4moz.js");
 
 let FormWrapper = {
+  _log: Log4Moz.repository.getLogger('Engine.Forms'),
+    
   getAllEntries: function getAllEntries() {
     // Sort by (lastUsed - minLast) / (maxLast - minLast) * timesUsed / maxTimes
     let query = this.createStatement(
@@ -76,6 +79,16 @@ let FormWrapper = {
 
     // Give the guid if we found one
     let item = Utils.queryAsync(getQuery, "guid")[0];
+    
+    if (!item) {
+      // Shouldn't happen, but Bug 597400...
+      // Might as well just return.
+      this._log.warn("GUID query returned " + item + "; turn on Trace logging for details.");
+      this._log.trace("getGUID(" + JSON.stringify(name) + ", " +
+                      JSON.stringify(value) + ") => " + item);
+      return null;
+    }
+    
     if (item.guid != null)
       return item.guid;
 

services/sync/modules/resource.js

@@ -452,9 +452,24 @@ ChannelListener.prototype = {
     let siStream = Cc["@mozilla.org/scriptableinputstream;1"].
       createInstance(Ci.nsIScriptableInputStream);
     siStream.init(stream);
-
-    this._data += siStream.read(count);
-    this._onProgress();
+    try {
+      this._data += siStream.read(count);
+    } catch (ex) {
+      this._log.warn("Exception thrown reading " + count +
+                     " bytes from " + siStream + ".");
+      throw ex;
+    }
+    
+    try {
+      this._onProgress();
+    } catch (ex) {
+      this._log.warn("Got exception calling onProgress handler during fetch of "
+                     + req.URI.spec);
+      this._log.debug(Utils.stackTrace(ex));
+      this._log.trace("Rethrowing; expect a failure code from the HTTP channel.");
+      throw ex;
+    }
+    
     this.delayAbort();
   },
 

services/sync/modules/service.js

@@ -479,9 +479,14 @@ WeaveSvc.prototype = {
       verbose.append("verbose-log.txt");
       if (!verbose.exists())
         verbose.create(verbose.NORMAL_FILE_TYPE, PERMS_FILE);
-  
-      let maxSize = 65536; // 64 * 1024 (64KB)
-      this._debugApp = new Log4Moz.RotatingFileAppender(verbose, formatter, maxSize);
+
+      if (Svc.Prefs.get("log.appender.debugLog.rotate", true)) {
+        let maxSize = Svc.Prefs.get("log.appender.debugLog.maxSize");
+        this._debugApp = new Log4Moz.RotatingFileAppender(verbose, formatter,
+                                                          maxSize);
+      } else {
+        this._debugApp = new Log4Moz.FileAppender(verbose, formatter);
+      }
       this._debugApp.level = Log4Moz.Level[Svc.Prefs.get("log.appender.debugLog")];
       root.addAppender(this._debugApp);
     }

services/sync/services-sync.js

@@ -26,6 +26,8 @@ pref("services.sync.log.appender.console", "Warn");
 pref("services.sync.log.appender.dump", "Error");
 pref("services.sync.log.appender.debugLog", "Trace");
 pref("services.sync.log.appender.debugLog.enabled", false);
+pref("services.sync.log.appender.debugLog.rotate", true);
+pref("services.sync.log.appender.debugLog.maxSize", 1048576);
 pref("services.sync.log.rootLogger", "Debug");
 pref("services.sync.log.logger.service.main", "Debug");
 pref("services.sync.log.logger.authenticator", "Debug");

services/sync/tests/unit/test_bookmark_engine.js

@@ -0,0 +1,99 @@
+Cu.import("resource://services-sync/engines/bookmarks.js");
+Cu.import("resource://services-sync/type_records/bookmark.js");
+Cu.import("resource://services-sync/base_records/wbo.js");
+Cu.import("resource://services-sync/base_records/crypto.js");
+Cu.import("resource://services-sync/log4moz.js");
+Cu.import("resource://services-sync/util.js");
+
+function makeEngine() {
+  return new BookmarksEngine();
+}
+var syncTesting = new SyncTestingInfrastructure(makeEngine);
+
+function test_processIncoming_error_orderChildren() {
+  _("Ensure that _orderChildren() is called even when _processIncoming() throws an error.");
+
+  Svc.Prefs.set("clusterURL", "http://localhost:8080/");
+  Svc.Prefs.set("username", "foo");
+
+  let collection = new ServerCollection();
+  let engine = new BookmarksEngine();
+  let store = engine._store;
+  let global = new ServerWBO('global',
+                             {engines: {bookmarks: {version: engine.version,
+                                                    syncID: engine.syncID}}});
+  let server = httpd_setup({
+    "/1.0/foo/storage/meta/global": global.handler(),
+    "/1.0/foo/storage/bookmarks": collection.handler()
+  });
+
+
+  try {
+
+    let folder1_id = Svc.Bookmark.createFolder(
+      Svc.Bookmark.toolbarFolder, "Folder 1", 0);
+    let folder1_guid = store.GUIDForId(folder1_id);
+
+    let fxuri = Utils.makeURI("http://getfirefox.com/");
+    let tburi = Utils.makeURI("http://getthunderbird.com/");
+
+    let bmk1_id = Svc.Bookmark.insertBookmark(
+      folder1_id, fxuri, Svc.Bookmark.DEFAULT_INDEX, "Get Firefox!");
+    let bmk1_guid = store.GUIDForId(bmk1_id);
+    let bmk2_id = Svc.Bookmark.insertBookmark(
+      folder1_id, tburi, Svc.Bookmark.DEFAULT_INDEX, "Get Thunderbird!");
+    let bmk2_guid = store.GUIDForId(bmk2_id);
+
+    // Create a server record for folder1 where we flip the order of
+    // the children.
+    let folder1_payload = store.createRecord(folder1_guid).cleartext;
+    folder1_payload.children.reverse();
+    collection.wbos[folder1_guid] = new ServerWBO(
+      folder1_guid, encryptPayload(folder1_payload));
+
+    // Also create a bogus server record (no parent) to provoke an exception.
+    const BOGUS_GUID = "zzzzzzzzzzzz";
+    collection.wbos[BOGUS_GUID] = new ServerWBO(
+      BOGUS_GUID, encryptPayload({
+        id: BOGUS_GUID,
+        type: "folder",
+        title: "Bogus Folder",
+        parentid: null,
+        parentName: null,
+        children: []
+    }));
+
+    let error;
+    try {
+      engine.sync();
+    } catch(ex) {
+      error = ex;
+    }
+    do_check_true(!!error);
+
+    // Verify that the bookmark order has been applied.
+    let new_children = store.createRecord(folder1_guid).children;
+    do_check_eq(new_children.length, 2);
+    do_check_eq(new_children[0], folder1_payload.children[0]);
+    do_check_eq(new_children[1], folder1_payload.children[1]);
+
+    do_check_eq(Svc.Bookmark.getItemIndex(bmk1_id), 1);
+    do_check_eq(Svc.Bookmark.getItemIndex(bmk2_id), 0);
+
+  } finally {
+    store.wipe();
+    server.stop(do_test_finished);
+    Svc.Prefs.resetBranch("");
+    Records.clearCache();
+    syncTesting = new SyncTestingInfrastructure(makeEngine);
+  }
+}
+
+function run_test() {
+  initTestLogging("Trace");
+  Log4Moz.repository.getLogger("Engine.Bookmarks").level = Log4Moz.Level.Trace;
+
+  CollectionKeys.generateNewKeys();
+
+  test_processIncoming_error_orderChildren();
+}

services/sync/tests/unit/test_forms_tracker.js

@@ -1,10 +1,12 @@
 Cu.import("resource://services-sync/engines/forms.js");
 Cu.import("resource://services-sync/util.js");
+Cu.import("resource://services-sync/log4moz.js");
 
 function run_test() {
   _("Verify we've got an empty tracker to work with.");
   let tracker = new FormEngine()._tracker;
   do_check_eq([id for (id in tracker.changedIDs)].length, 0);
+  Log4Moz.repository.rootLogger.addAppender(new Log4Moz.DumpAppender());
 
   try {
     _("Create an entry. Won't show because we haven't started tracking yet");
@@ -32,6 +34,11 @@ function run_test() {
     Svc.Obs.notify("weave:engine:stop-tracking");
     Svc.Form.removeEntry("email", "john@doe.com");
     do_check_eq([id for (id in tracker.changedIDs)].length, 0);
+  
+    _("Test error detection.");
+    // This throws an exception without the fix for Bug 597400.
+    tracker.trackEntry("foo", "bar");
+    
   } finally {
     _("Clean up.");
     Svc.Form.removeAllEntries();

services/sync/tests/unit/test_resource.js

@@ -472,5 +472,51 @@ function run_test() {
   do_check_eq(content.status, 0);
   do_check_false(content.success);
 
+  _("Checking handling of errors in onProgress.");
+  let res18 = new Resource("http://localhost:8080/json");
+  let onProgress = function(rec) {
+    // Provoke an XPC exception without a Javascript wrapper.
+    Svc.IO.newURI("::::::::", null, null);
+  };
+  res18._onProgress = onProgress;
+  let oldWarn = res18._log.warn;
+  let warnings = [];
+  res18._log.warn = function(msg) { warnings.push(msg) };
+  error = undefined;
+  try {
+    content = res18.get();
+  } catch (ex) {
+    error = ex;
+  }
+
+  // It throws and logs.
+  do_check_eq(error, "Error: NS_ERROR_MALFORMED_URI");
+  do_check_eq(warnings.pop(),
+              "Got exception calling onProgress handler during fetch of " +
+              "http://localhost:8080/json");
+  
+  // And this is what happens if JS throws an exception.
+  res18 = new Resource("http://localhost:8080/json");
+  onProgress = function(rec) {
+    throw "BOO!";
+  };
+  res18._onProgress = onProgress;
+  oldWarn = res18._log.warn;
+  warnings = [];
+  res18._log.warn = function(msg) { warnings.push(msg) };
+  error = undefined;
+  try {
+    content = res18.get();
+  } catch (ex) {
+    error = ex;
+  }
+
+  // It throws and logs.
+  do_check_eq(error, "Error: NS_ERROR_XPC_JS_THREW_STRING");
+  do_check_eq(warnings.pop(),
+              "Got exception calling onProgress handler during fetch of " +
+              "http://localhost:8080/json");
+  
+  
   server.stop(do_test_finished);
 }

services/sync/tests/unit/test_resource_async.js

@@ -619,6 +619,49 @@ function run_test() {
       next();
     }));
 
+  }, function (next) {
+
+    _("Exception handling inside fetches.");
+    let res14 = new AsyncResource("http://localhost:8080/json");
+    res14._onProgress = function(rec) {
+      // Provoke an XPC exception without a Javascript wrapper.
+      Svc.IO.newURI("::::::::", null, null);
+    };
+    let warnings = [];
+    res14._log.warn = function(msg) { warnings.push(msg) };
+
+    res14.get(ensureThrows(function (error, content) {
+      do_check_eq(error, "Error: NS_ERROR_MALFORMED_URI");
+      do_check_eq(content, null);
+      do_check_eq(warnings.pop(),
+                  "Got exception calling onProgress handler during fetch of " +
+                  "http://localhost:8080/json");
+      
+      do_test_finished();
+      next();
+    }));
+
+  }, function (next) {
+
+    _("JS exception handling inside fetches.");
+    let res15 = new AsyncResource("http://localhost:8080/json");
+    res15._onProgress = function(rec) {
+      throw "BOO!";
+    };
+    warnings = [];
+    res15._log.warn = function(msg) { warnings.push(msg) };
+
+    res15.get(ensureThrows(function (error, content) {
+      do_check_eq(error, "Error: NS_ERROR_XPC_JS_THREW_STRING");
+      do_check_eq(content, null);
+      do_check_eq(warnings.pop(),
+                  "Got exception calling onProgress handler during fetch of " +
+                  "http://localhost:8080/json");
+      
+      do_test_finished();
+      next();
+    }));
+
   }, function (next) {
 
     // Don't quit test harness before server shuts down.