diff --git a/services/sync/modules/engines/bookmarks.js b/services/sync/modules/engines/bookmarks.js index f8a55f7dac0a..eb86b9ed3d2c 100644 --- a/services/sync/modules/engines/bookmarks.js +++ b/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() { diff --git a/services/sync/modules/engines/forms.js b/services/sync/modules/engines/forms.js index ed4029dd598c..ba3078028155 100644 --- a/services/sync/modules/engines/forms.js +++ b/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; diff --git a/services/sync/modules/resource.js b/services/sync/modules/resource.js index e326f3a44929..dd01bd4e0fdb 100644 --- a/services/sync/modules/resource.js +++ b/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(); }, diff --git a/services/sync/modules/service.js b/services/sync/modules/service.js index f6064bbe18be..c748a5dacb4d 100644 --- a/services/sync/modules/service.js +++ b/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); } diff --git a/services/sync/services-sync.js b/services/sync/services-sync.js index 4b221ba95f2f..a91540b10796 100644 --- a/services/sync/services-sync.js +++ b/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"); diff --git a/services/sync/tests/unit/test_bookmark_engine.js b/services/sync/tests/unit/test_bookmark_engine.js new file mode 100644 index 000000000000..36eb7b38276a --- /dev/null +++ b/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(); +} diff --git a/services/sync/tests/unit/test_forms_tracker.js b/services/sync/tests/unit/test_forms_tracker.js index 46ff13802be6..9a39816df8a4 100644 --- a/services/sync/tests/unit/test_forms_tracker.js +++ b/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(); diff --git a/services/sync/tests/unit/test_resource.js b/services/sync/tests/unit/test_resource.js index 264e81dbcc00..d3ccacd0613e 100644 --- a/services/sync/tests/unit/test_resource.js +++ b/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); } diff --git a/services/sync/tests/unit/test_resource_async.js b/services/sync/tests/unit/test_resource_async.js index 9376a54a0152..0f0d1dce02c7 100644 --- a/services/sync/tests/unit/test_resource_async.js +++ b/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.