diff --git a/services/sync/modules/policies.js b/services/sync/modules/policies.js index 0195459eef9d..653420121bf0 100644 --- a/services/sync/modules/policies.js +++ b/services/sync/modules/policies.js @@ -72,16 +72,26 @@ let SyncScheduler = { this.idle = false; this.hasIncomingItems = false; - this.numClients = 0; - this.nextSync = 0, - this.syncInterval = this.singleDeviceInterval; - this.syncThreshold = SINGLE_USER_THRESHOLD; + this.clearSyncTriggers(); }, + // nextSync is in milliseconds, but prefs can't hold that much + get nextSync() Svc.Prefs.get("nextSync", 0) * 1000, + set nextSync(value) Svc.Prefs.set("nextSync", Math.floor(value / 1000)), + + get syncInterval() Svc.Prefs.get("syncInterval", this.singleDeviceInterval), + set syncInterval(value) Svc.Prefs.set("syncInterval", value), + + get syncThreshold() Svc.Prefs.get("syncThreshold", SINGLE_USER_THRESHOLD), + set syncThreshold(value) Svc.Prefs.set("syncThreshold", value), + get globalScore() Svc.Prefs.get("globalScore", 0), set globalScore(value) Svc.Prefs.set("globalScore", value), + get numClients() Svc.Prefs.get("numClients", 0), + set numClients(value) Svc.Prefs.set("numClients", value), + init: function init() { this._log.level = Log4Moz.Level[Svc.Prefs.get("log.logger.service.main")]; this.setDefaults(); @@ -103,7 +113,6 @@ let SyncScheduler = { if (Status.checkSetup() == STATUS_OK) { Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime")); } - }, observe: function observe(subject, topic, data) { @@ -357,25 +366,34 @@ let SyncScheduler = { // Ensure the interval is set to no less than the backoff. if (Status.backoffInterval && interval < Status.backoffInterval) { + this._log.trace("Requested interval " + interval + + " ms is smaller than the backoff interval. " + + "Using backoff interval " + + Status.backoffInterval + " ms instead."); interval = Status.backoffInterval; } if (this.nextSync != 0) { - // There's already a sync scheduled. Don't reschedule if that's already - // going to happen sooner than requested. + // There's already a sync scheduled. Don't reschedule if there's already + // a timer scheduled for sooner than requested. let currentInterval = this.nextSync - Date.now(); - if (currentInterval < interval) { + this._log.trace("There's already a sync scheduled in " + + currentInterval + " ms."); + if (currentInterval < interval && this.syncTimer) { + this._log.trace("Ignoring scheduling request for next sync in " + + interval + " ms."); return; } } - // Start the sync right away if we're already late + // Start the sync right away if we're already late. if (interval <= 0) { + this._log.trace("Requested sync should happen right away."); this.syncIfMPUnlocked(); return; } - this._log.trace("Next sync in " + Math.ceil(interval / 1000) + " sec."); + this._log.debug("Next sync in " + interval + " ms."); Utils.namedTimer(this.syncIfMPUnlocked, interval, this, "syncTimer"); // Save the next sync time in-case sync is disabled (logout/offline/etc.) @@ -389,12 +407,12 @@ let SyncScheduler = { */ scheduleAtInterval: function scheduleAtInterval(minimumInterval) { let interval = Utils.calculateBackoff(this._syncErrors, MINIMUM_BACKOFF_INTERVAL); - if (minimumInterval) + if (minimumInterval) { interval = Math.max(minimumInterval, interval); + } - let d = new Date(Date.now() + interval); - this._log.config("Starting backoff, next sync at:" + d.toString()); - + this._log.debug("Starting client-initiated backoff. Next sync in " + + interval + " ms."); this.scheduleNextSync(interval); }, @@ -414,7 +432,10 @@ let SyncScheduler = { autoConnect: function autoConnect() { if (Weave.Service._checkSetup() == STATUS_OK && !Weave.Service._checkSync()) { - Utils.nextTick(Weave.Service.sync, Weave.Service); + // Schedule a sync based on when a previous sync was scheduled. + // scheduleNextSync() will do the right thing if that time lies in + // the past. + this.scheduleNextSync(this.nextSync - Date.now()); } // Once autoConnect is called we no longer need _autoTimer. diff --git a/services/sync/tests/unit/test_errorhandler_filelog.js b/services/sync/tests/unit/test_errorhandler_filelog.js index 57836211f276..305cce76798e 100644 --- a/services/sync/tests/unit/test_errorhandler_filelog.js +++ b/services/sync/tests/unit/test_errorhandler_filelog.js @@ -2,6 +2,7 @@ http://creativecommons.org/publicdomain/zero/1.0/ */ Cu.import("resource://services-sync/service.js"); +Cu.import("resource://services-sync/policies.js"); Cu.import("resource://services-sync/util.js"); Cu.import("resource://services-sync/log4moz.js"); @@ -15,15 +16,23 @@ const PROLONGED_ERROR_DURATION = (Svc.Prefs.get('errorhandler.networkFailureReportTimeout') * 2) * 1000; function setLastSync(lastSyncValue) { - Svc.Prefs.set("lastSync", (new Date(Date.now() - - lastSyncValue)).toString()); + Svc.Prefs.set("lastSync", (new Date(Date.now() - lastSyncValue)).toString()); } function run_test() { + initTestLogging("Trace"); + + Log4Moz.repository.getLogger("Sync.Service").level = Log4Moz.Level.Trace; + Log4Moz.repository.getLogger("Sync.SyncScheduler").level = Log4Moz.Level.Trace; + Log4Moz.repository.getLogger("Sync.ErrorHandler").level = Log4Moz.Level.Trace; + run_next_test(); } add_test(function test_noOutput() { + // Ensure that the log appender won't print anything. + ErrorHandler._logAppender.level = Log4Moz.Level.Fatal + 1; + // Clear log output from startup. Svc.Prefs.set("log.appender.file.logOnSuccess", false); Svc.Obs.notify("weave:service:sync:finish"); @@ -34,6 +43,7 @@ add_test(function test_noOutput() { Svc.Obs.add("weave:service:reset-file-log", function onResetFileLog() { Svc.Obs.remove("weave:service:reset-file-log", onResetFileLog); + ErrorHandler._logAppender.level = Log4Moz.Level.Trace; Svc.Prefs.resetBranch(""); run_next_test(); }); diff --git a/services/sync/tests/unit/test_syncscheduler.js b/services/sync/tests/unit/test_syncscheduler.js index e1a975842a9b..ec5b93824226 100644 --- a/services/sync/tests/unit/test_syncscheduler.js +++ b/services/sync/tests/unit/test_syncscheduler.js @@ -60,6 +60,34 @@ function setUp() { return serverKeys.upload(Service.cryptoKeysURL).success; } +function cleanUpAndGo(server) { + Utils.nextTick(function () { + Service.startOver(); + if (server) { + server.stop(run_next_test); + } else { + run_next_test(); + } + }); +} + +let timer; +function waitForZeroTimer(callback) { + // First wait >100ms (nsITimers can take up to that much time to fire, so + // we can account for the timer in delayedAutoconnect) and then two event + // loop ticks (to account for the Utils.nextTick() in autoConnect). + let ticks = 2; + function wait() { + if (ticks) { + ticks -= 1; + Utils.nextTick(wait); + return; + } + callback(); + } + timer = Utils.namedTimer(wait, 150, {}, "timer"); +} + function run_test() { initTestLogging("Trace"); @@ -77,6 +105,26 @@ add_test(function test_prefAttributes() { const SCORE = 2718; const TIMESTAMP1 = 1275493471649; + _("The 'nextSync' attribute stores a millisecond timestamp rounded down to the nearest second."); + do_check_eq(SyncScheduler.nextSync, 0); + SyncScheduler.nextSync = TIMESTAMP1; + do_check_eq(SyncScheduler.nextSync, Math.floor(TIMESTAMP1 / 1000) * 1000); + + _("'syncInterval' defaults to singleDeviceInterval."); + do_check_eq(Svc.Prefs.get('syncInterval'), undefined); + do_check_eq(SyncScheduler.syncInterval, SyncScheduler.singleDeviceInterval); + + _("'syncInterval' corresponds to a preference setting."); + SyncScheduler.syncInterval = INTERVAL; + do_check_eq(SyncScheduler.syncInterval, INTERVAL); + do_check_eq(Svc.Prefs.get('syncInterval'), INTERVAL); + + _("'syncThreshold' corresponds to preference, defaults to SINGLE_USER_THRESHOLD"); + do_check_eq(Svc.Prefs.get('syncThreshold'), undefined); + do_check_eq(SyncScheduler.syncThreshold, SINGLE_USER_THRESHOLD); + SyncScheduler.syncThreshold = THRESHOLD; + do_check_eq(SyncScheduler.syncThreshold, THRESHOLD); + _("'globalScore' corresponds to preference, defaults to zero."); do_check_eq(Svc.Prefs.get('globalScore'), undefined); do_check_eq(SyncScheduler.globalScore, 0); @@ -137,10 +185,7 @@ add_test(function test_updateClientMode() { do_check_false(SyncScheduler.numClients > 1); do_check_false(SyncScheduler.idle); - Svc.Prefs.resetBranch(""); - SyncScheduler.setDefaults(); - Clients.resetClient(); - run_next_test(); + cleanUpAndGo(); }); add_test(function test_masterpassword_locked_retry_interval() { @@ -176,8 +221,7 @@ add_test(function test_masterpassword_locked_retry_interval() { Service.verifyLogin = Service._verifyLogin; SyncScheduler.scheduleAtInterval = SyncScheduler._scheduleAtInterval; - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); add_test(function test_calculateBackoff() { @@ -197,14 +241,23 @@ add_test(function test_calculateBackoff() { do_check_eq(backoffInterval, MAXIMUM_BACKOFF_INTERVAL + 10); - Status.backoffInterval = 0; - Svc.Prefs.resetBranch(""); - SyncScheduler.setDefaults(); - Clients.resetClient(); - run_next_test(); + cleanUpAndGo(); }); -add_test(function test_scheduleNextSync_noBackoff() { +add_test(function test_scheduleNextSync_nowOrPast() { + Svc.Obs.add("weave:service:sync:finish", function onSyncFinish() { + Svc.Obs.remove("weave:service:sync:finish", onSyncFinish); + cleanUpAndGo(server); + }); + + let server = sync_httpd_setup(); + setUp(); + + // We're late for a sync... + SyncScheduler.scheduleNextSync(-1); +}); + +add_test(function test_scheduleNextSync_future_noBackoff() { _("scheduleNextSync() uses the current syncInterval if no interval is provided."); // Test backoffInterval is 0 as expected. do_check_eq(Status.backoffInterval, 0); @@ -250,12 +303,10 @@ add_test(function test_scheduleNextSync_noBackoff() { do_check_true(SyncScheduler.nextSync <= Date.now() + 1); do_check_eq(SyncScheduler.syncTimer.delay, 1); - SyncScheduler.syncTimer.clear(); - Service.startOver(); - run_next_test(); + cleanUpAndGo(); }); -add_test(function test_scheduleNextSync_backoff() { +add_test(function test_scheduleNextSync_future_backoff() { _("scheduleNextSync() will honour backoff in all scheduling requests."); // Let's take a backoff interval that's bigger than the default sync interval. const BACKOFF = 7337; @@ -297,14 +348,12 @@ add_test(function test_scheduleNextSync_backoff() { do_check_true(SyncScheduler.nextSync <= Date.now() + requestedInterval); do_check_eq(SyncScheduler.syncTimer.delay, requestedInterval); - // Request a sync at the smallest possible number. + // Request a sync at the smallest possible interval (0 triggers now). SyncScheduler.scheduleNextSync(1); do_check_true(SyncScheduler.nextSync <= Date.now() + Status.backoffInterval); do_check_eq(SyncScheduler.syncTimer.delay, Status.backoffInterval); - SyncScheduler.syncTimer.clear(); - Service.startOver(); - run_next_test(); + cleanUpAndGo(); }); add_test(function test_handleSyncError() { @@ -362,8 +411,7 @@ add_test(function test_handleSyncError() { do_check_true(Status.enforceBackoff); SyncScheduler.syncTimer.clear(); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); add_test(function test_client_sync_finish_updateClientMode() { @@ -397,16 +445,15 @@ add_test(function test_client_sync_finish_updateClientMode() { do_check_false(SyncScheduler.numClients > 1); do_check_false(SyncScheduler.idle); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); -add_test(function test_autoconnect() { +add_test(function test_autoconnect_nextSync_past() { + // nextSync will be 0 by default, so it's way in the past. + Svc.Obs.add("weave:service:sync:finish", function onSyncFinish() { Svc.Obs.remove("weave:service:sync:finish", onSyncFinish); - - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); let server = sync_httpd_setup(); @@ -415,6 +462,33 @@ add_test(function test_autoconnect() { SyncScheduler.delayedAutoConnect(0); }); +add_test(function test_autoconnect_nextSync_future() { + let previousSync = Date.now() + SyncScheduler.syncInterval / 2; + SyncScheduler.nextSync = previousSync; + // nextSync rounds to the nearest second. + let expectedSync = SyncScheduler.nextSync; + let expectedInterval = expectedSync - Date.now() - 1000; + + // Ensure we don't actually try to sync (or log in for that matter). + function onLoginStart() { + do_throw("Should not get here!"); + } + Svc.Obs.add("weave:service:login:start", onLoginStart); + + waitForZeroTimer(function () { + do_check_eq(SyncScheduler.nextSync, expectedSync); + do_check_true(SyncScheduler.syncTimer.delay >= expectedInterval); + + Svc.Obs.remove("weave:service:login:start", onLoginStart); + cleanUpAndGo(); + }); + + Service.username = "johndoe"; + Service.password = "ilovejane"; + Service.passphrase = "abcdeabcdeabcdeabcdeabcdea"; + SyncScheduler.delayedAutoConnect(0); +}); + add_test(function test_autoconnect_mp_locked() { let server = sync_httpd_setup(); setUp(); @@ -426,6 +500,7 @@ add_test(function test_autoconnect_mp_locked() { let origPP = Service.__lookupGetter__("passphrase"); delete Service.passphrase; Service.__defineGetter__("passphrase", function() { + _("Faking Master Password entry cancelation."); throw "User canceled Master Password entry"; }); @@ -440,15 +515,13 @@ add_test(function test_autoconnect_mp_locked() { delete Service.passphrase; Service.__defineGetter__("passphrase", origPP); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); }); SyncScheduler.delayedAutoConnect(0); }); -let timer; add_test(function test_no_autoconnect_during_wizard() { let server = sync_httpd_setup(); setUp(); @@ -462,22 +535,10 @@ add_test(function test_no_autoconnect_during_wizard() { } Svc.Obs.add("weave:service:login:start", onLoginStart); - // First wait >100ms (nsITimers can take up to that much time to fire, so - // we can account for the timer in delayedAutoconnect) and then two event - // loop ticks (to account for the Utils.nextTick() in autoConnect). - let ticks = 2; - function wait() { - if (ticks) { - ticks -= 1; - Utils.nextTick(wait); - return; - } + waitForZeroTimer(function () { Svc.Obs.remove("weave:service:login:start", onLoginStart); - - Service.startOver(); - server.stop(run_next_test); - } - timer = Utils.namedTimer(wait, 150, {}, "timer"); + cleanUpAndGo(server); + }); SyncScheduler.delayedAutoConnect(0); }); @@ -491,25 +552,14 @@ add_test(function test_no_autoconnect_status_not_ok() { } Svc.Obs.add("weave:service:login:start", onLoginStart); - // First wait >100ms (nsITimers can take up to that much time to fire, so - // we can account for the timer in delayedAutoconnect) and then two event - // loop ticks (to account for the Utils.nextTick() in autoConnect). - let ticks = 2; - function wait() { - if (ticks) { - ticks -= 1; - Utils.nextTick(wait); - return; - } + waitForZeroTimer(function () { Svc.Obs.remove("weave:service:login:start", onLoginStart); do_check_eq(Status.service, CLIENT_NOT_CONFIGURED); do_check_eq(Status.login, LOGIN_FAILED_NO_USERNAME); - - Service.startOver(); - server.stop(run_next_test); - } - timer = Utils.namedTimer(wait, 150, {}, "timer"); + + cleanUpAndGo(server); + }); SyncScheduler.delayedAutoConnect(0); }); @@ -517,9 +567,7 @@ add_test(function test_no_autoconnect_status_not_ok() { add_test(function test_autoconnectDelay_pref() { Svc.Obs.add("weave:service:sync:finish", function onSyncFinish() { Svc.Obs.remove("weave:service:sync:finish", onSyncFinish); - - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); Svc.Prefs.set("autoconnectDelay", 1); @@ -551,8 +599,7 @@ add_test(function test_idle_adjustSyncInterval() { do_check_eq(SyncScheduler.idle, true); do_check_eq(SyncScheduler.syncInterval, SyncScheduler.idleInterval); - SyncScheduler.setDefaults(); - run_next_test(); + cleanUpAndGo(); }); add_test(function test_back_triggersSync() { @@ -569,9 +616,7 @@ add_test(function test_back_triggersSync() { // succeed. We just want to ensure that it was attempted. Svc.Obs.add("weave:service:login:error", function onLoginError() { Svc.Obs.remove("weave:service:login:error", onLoginError); - SyncScheduler.syncTimer.clear(); - SyncScheduler.setDefaults(); - run_next_test(); + cleanUpAndGo(); }); // Send a 'back' event to trigger sync soonish. @@ -600,9 +645,7 @@ add_test(function test_back_triggersSync_observesBackoff() { do_check_true(SyncScheduler.nextSync <= Date.now() + Status.backoffInterval); do_check_eq(SyncScheduler.syncTimer.delay, Status.backoffInterval); - SyncScheduler.syncTimer.clear(); - SyncScheduler.setDefaults(); - run_next_test(); + cleanUpAndGo(); }, IDLE_OBSERVER_BACK_DELAY * 1.5, {}, "timer"); // Send a 'back' event to try to trigger sync soonish. @@ -631,8 +674,7 @@ add_test(function test_back_debouncing() { timer = Utils.namedTimer(function () { Svc.Obs.remove("weave:service:login:start", onLoginStart); - SyncScheduler.setDefaults(); - run_next_test(); + cleanUpAndGo(); }, IDLE_OBSERVER_BACK_DELAY * 1.5, {}, "timer"); }); @@ -648,10 +690,7 @@ add_test(function test_no_sync_node() { do_check_eq(Status.sync, NO_SYNC_NODE_FOUND); do_check_eq(SyncScheduler.syncTimer.delay, NO_SYNC_NODE_INTERVAL); - // Clean up. - Service.startOver(); - Status.resetSync(); - server.stop(run_next_test); + cleanUpAndGo(server); }); add_test(function test_sync_failed_partial_500s() { @@ -678,9 +717,7 @@ add_test(function test_sync_failed_partial_500s() { do_check_true(SyncScheduler.nextSync <= (Date.now() + maxInterval)); do_check_true(SyncScheduler.syncTimer.delay <= maxInterval); - Status.resetSync(); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); add_test(function test_sync_failed_partial_400s() { @@ -710,9 +747,7 @@ add_test(function test_sync_failed_partial_400s() { do_check_true(SyncScheduler.nextSync <= (Date.now() + SyncScheduler.activeInterval)); do_check_true(SyncScheduler.syncTimer.delay <= SyncScheduler.activeInterval); - Status.resetSync(); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); add_test(function test_sync_X_Weave_Backoff() { @@ -767,8 +802,7 @@ add_test(function test_sync_X_Weave_Backoff() { do_check_true(SyncScheduler.nextSync >= Date.now() + minimumExpectedDelay); do_check_true(SyncScheduler.syncTimer.delay >= minimumExpectedDelay); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); }); add_test(function test_sync_503_Retry_After() { @@ -827,6 +861,5 @@ add_test(function test_sync_503_Retry_After() { do_check_true(SyncScheduler.nextSync >= Date.now() + minimumExpectedDelay); do_check_true(SyncScheduler.syncTimer.delay >= minimumExpectedDelay); - Service.startOver(); - server.stop(run_next_test); + cleanUpAndGo(server); });