michael@0: /* Any copyright is dedicated to the Public Domain.
michael@0:    http://creativecommons.org/publicdomain/zero/1.0/ */
michael@0: 
michael@0: _("Test that node reassignment responses are respected on all kinds of " +
michael@0:   "requests.");
michael@0: 
michael@0: Cu.import("resource://gre/modules/Log.jsm");
michael@0: Cu.import("resource://services-common/rest.js");
michael@0: Cu.import("resource://services-sync/constants.js");
michael@0: Cu.import("resource://services-sync/service.js");
michael@0: Cu.import("resource://services-sync/status.js");
michael@0: Cu.import("resource://services-sync/util.js");
michael@0: Cu.import("resource://testing-common/services/sync/rotaryengine.js");
michael@0: Cu.import("resource://testing-common/services/sync/utils.js");
michael@0: 
michael@0: Service.engineManager.clear();
michael@0: 
michael@0: function run_test() {
michael@0:   Log.repository.getLogger("Sync.AsyncResource").level = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.ErrorHandler").level  = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.Resource").level      = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.RESTRequest").level   = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.Service").level       = Log.Level.Trace;
michael@0:   Log.repository.getLogger("Sync.SyncScheduler").level = Log.Level.Trace;
michael@0:   initTestLogging();
michael@0: 
michael@0:   ensureLegacyIdentityManager();
michael@0: 
michael@0:   Service.engineManager.register(RotaryEngine);
michael@0: 
michael@0:   // None of the failures in this file should result in a UI error.
michael@0:   function onUIError() {
michael@0:     do_throw("Errors should not be presented in the UI.");
michael@0:   }
michael@0:   Svc.Obs.add("weave:ui:login:error", onUIError);
michael@0:   Svc.Obs.add("weave:ui:sync:error", onUIError);
michael@0: 
michael@0:   run_next_test();
michael@0: }
michael@0: 
michael@0: /**
michael@0:  * Emulate the following Zeus config:
michael@0:  * $draining = data.get($prefix . $host . " draining");
michael@0:  * if ($draining == "drain.") {
michael@0:  *   log.warn($log_host_db_status . " migrating=1 (node-reassignment)" .
michael@0:  *            $log_suffix);
michael@0:  *   http.sendResponse("401 Node reassignment", $content_type,
michael@0:  *                     '"server request: node reassignment"', "");
michael@0:  * }
michael@0:  */
michael@0: const reassignBody = "\"server request: node reassignment\"";
michael@0: 
michael@0: // API-compatible with SyncServer handler. Bind `handler` to something to use
michael@0: // as a ServerCollection handler.
michael@0: function handleReassign(handler, req, resp) {
michael@0:   resp.setStatusLine(req.httpVersion, 401, "Node reassignment");
michael@0:   resp.setHeader("Content-Type", "application/json");
michael@0:   resp.bodyOutputStream.write(reassignBody, reassignBody.length);
michael@0: }
michael@0: 
michael@0: /**
michael@0:  * A node assignment handler.
michael@0:  */
michael@0: function installNodeHandler(server, next) {
michael@0:   let newNodeBody = server.baseURI;
michael@0:   function handleNodeRequest(req, resp) {
michael@0:     _("Client made a request for a node reassignment.");
michael@0:     resp.setStatusLine(req.httpVersion, 200, "OK");
michael@0:     resp.setHeader("Content-Type", "text/plain");
michael@0:     resp.bodyOutputStream.write(newNodeBody, newNodeBody.length);
michael@0:     Utils.nextTick(next);
michael@0:   }
michael@0:   let nodePath = "/user/1.0/johndoe/node/weave";
michael@0:   server.server.registerPathHandler(nodePath, handleNodeRequest);
michael@0:   _("Registered node handler at " + nodePath);
michael@0: }
michael@0: 
michael@0: function prepareServer() {
michael@0:   let deferred = Promise.defer();
michael@0:   configureIdentity({username: "johndoe"}).then(() => {
michael@0:     let server = new SyncServer();
michael@0:     server.registerUser("johndoe");
michael@0:     server.start();
michael@0:     Service.serverURL = server.baseURI;
michael@0:     Service.clusterURL = server.baseURI;
michael@0:     do_check_eq(Service.userAPIURI, server.baseURI + "user/1.0/");
michael@0:     deferred.resolve(server);
michael@0:   });
michael@0:   return deferred.promise;
michael@0: }
michael@0: 
michael@0: function getReassigned() {
michael@0:   try {
michael@0:     return Services.prefs.getBoolPref("services.sync.lastSyncReassigned");
michael@0:   } catch (ex if (ex.result == Cr.NS_ERROR_UNEXPECTED)) {
michael@0:     return false;
michael@0:   } catch (ex) {
michael@0:     do_throw("Got exception retrieving lastSyncReassigned: " +
michael@0:              Utils.exceptionStr(ex));
michael@0:   }
michael@0: }
michael@0: 
michael@0: /**
michael@0:  * Make a test request to `url`, then watch the result of two syncs
michael@0:  * to ensure that a node request was made.
michael@0:  * Runs `between` between the two. This can be used to undo deliberate failure
michael@0:  * setup, detach observers, etc.
michael@0:  */
michael@0: function syncAndExpectNodeReassignment(server, firstNotification, between,
michael@0:                                        secondNotification, url) {
michael@0:   let deferred = Promise.defer();
michael@0:   function onwards() {
michael@0:     let nodeFetched = false;
michael@0:     function onFirstSync() {
michael@0:       _("First sync completed.");
michael@0:       Svc.Obs.remove(firstNotification, onFirstSync);
michael@0:       Svc.Obs.add(secondNotification, onSecondSync);
michael@0: 
michael@0:       do_check_eq(Service.clusterURL, "");
michael@0: 
michael@0:       // Track whether we fetched node/weave. We want to wait for the second
michael@0:       // sync to finish so that we're cleaned up for the next test, so don't
michael@0:       // run_next_test in the node handler.
michael@0:       nodeFetched = false;
michael@0: 
michael@0:       // Verify that the client requests a node reassignment.
michael@0:       // Install a node handler to watch for these requests.
michael@0:       installNodeHandler(server, function () {
michael@0:         nodeFetched = true;
michael@0:       });
michael@0: 
michael@0:       // Allow for tests to clean up error conditions.
michael@0:       between();
michael@0:     }
michael@0:     function onSecondSync() {
michael@0:       _("Second sync completed.");
michael@0:       Svc.Obs.remove(secondNotification, onSecondSync);
michael@0:       Service.scheduler.clearSyncTriggers();
michael@0: 
michael@0:       // Make absolutely sure that any event listeners are done with their work
michael@0:       // before we proceed.
michael@0:       waitForZeroTimer(function () {
michael@0:         _("Second sync nextTick.");
michael@0:         do_check_true(nodeFetched);
michael@0:         Service.startOver();
michael@0:         server.stop(deferred.resolve);
michael@0:       });
michael@0:     }
michael@0: 
michael@0:     Svc.Obs.add(firstNotification, onFirstSync);
michael@0:     Service.sync();
michael@0:   }
michael@0: 
michael@0:   // Make sure that it works!
michael@0:   let request = new RESTRequest(url);
michael@0:   request.get(function () {
michael@0:     do_check_eq(request.response.status, 401);
michael@0:     Utils.nextTick(onwards);
michael@0:   });
michael@0:   yield deferred.promise;
michael@0: }
michael@0: 
michael@0: add_task(function test_momentary_401_engine() {
michael@0:   _("Test a failure for engine URLs that's resolved by reassignment.");
michael@0:   let server = yield prepareServer();
michael@0:   let john   = server.user("johndoe");
michael@0: 
michael@0:   _("Enabling the Rotary engine.");
michael@0:   let engine = Service.engineManager.get("rotary");
michael@0:   engine.enabled = true;
michael@0: 
michael@0:   // We need the server to be correctly set up prior to experimenting. Do this
michael@0:   // through a sync.
michael@0:   let global = {syncID: Service.syncID,
michael@0:                 storageVersion: STORAGE_VERSION,
michael@0:                 rotary: {version: engine.version,
michael@0:                          syncID:  engine.syncID}}
michael@0:   john.createCollection("meta").insert("global", global);
michael@0: 
michael@0:   _("First sync to prepare server contents.");
michael@0:   Service.sync();
michael@0: 
michael@0:   _("Setting up Rotary collection to 401.");
michael@0:   let rotary = john.createCollection("rotary");
michael@0:   let oldHandler = rotary.collectionHandler;
michael@0:   rotary.collectionHandler = handleReassign.bind(this, undefined);
michael@0: 
michael@0:   // We want to verify that the clusterURL pref has been cleared after a 401
michael@0:   // inside a sync. Flag the Rotary engine to need syncing.
michael@0:   john.collection("rotary").timestamp += 1000;
michael@0: 
michael@0:   function between() {
michael@0:     _("Undoing test changes.");
michael@0:     rotary.collectionHandler = oldHandler;
michael@0: 
michael@0:     function onLoginStart() {
michael@0:       // lastSyncReassigned shouldn't be cleared until a sync has succeeded.
michael@0:       _("Ensuring that lastSyncReassigned is still set at next sync start.");
michael@0:       Svc.Obs.remove("weave:service:login:start", onLoginStart);
michael@0:       do_check_true(getReassigned());
michael@0:     }
michael@0: 
michael@0:     _("Adding observer that lastSyncReassigned is still set on login.");
michael@0:     Svc.Obs.add("weave:service:login:start", onLoginStart);
michael@0:   }
michael@0: 
michael@0:   yield syncAndExpectNodeReassignment(server,
michael@0:                                       "weave:service:sync:finish",
michael@0:                                       between,
michael@0:                                       "weave:service:sync:finish",
michael@0:                                       Service.storageURL + "rotary");
michael@0: });
michael@0: 
michael@0: // This test ends up being a failing fetch *after we're already logged in*.
michael@0: add_task(function test_momentary_401_info_collections() {
michael@0:   _("Test a failure for info/collections that's resolved by reassignment.");
michael@0:   let server = yield prepareServer();
michael@0: 
michael@0:   _("First sync to prepare server contents.");
michael@0:   Service.sync();
michael@0: 
michael@0:   // Return a 401 for info requests, particularly info/collections.
michael@0:   let oldHandler = server.toplevelHandlers.info;
michael@0:   server.toplevelHandlers.info = handleReassign;
michael@0: 
michael@0:   function undo() {
michael@0:     _("Undoing test changes.");
michael@0:     server.toplevelHandlers.info = oldHandler;
michael@0:   }
michael@0: 
michael@0:   yield syncAndExpectNodeReassignment(server,
michael@0:                                       "weave:service:sync:error",
michael@0:                                       undo,
michael@0:                                       "weave:service:sync:finish",
michael@0:                                       Service.infoURL);
michael@0: });
michael@0: 
michael@0: add_task(function test_momentary_401_storage_loggedin() {
michael@0:   _("Test a failure for any storage URL, not just engine parts. " +
michael@0:     "Resolved by reassignment.");
michael@0:   let server = yield prepareServer();
michael@0: 
michael@0:   _("Performing initial sync to ensure we are logged in.")
michael@0:   Service.sync();
michael@0: 
michael@0:   // Return a 401 for all storage requests.
michael@0:   let oldHandler = server.toplevelHandlers.storage;
michael@0:   server.toplevelHandlers.storage = handleReassign;
michael@0: 
michael@0:   function undo() {
michael@0:     _("Undoing test changes.");
michael@0:     server.toplevelHandlers.storage = oldHandler;
michael@0:   }
michael@0: 
michael@0:   do_check_true(Service.isLoggedIn, "already logged in");
michael@0:   yield syncAndExpectNodeReassignment(server,
michael@0:                                       "weave:service:sync:error",
michael@0:                                       undo,
michael@0:                                       "weave:service:sync:finish",
michael@0:                                       Service.storageURL + "meta/global");
michael@0: });
michael@0: 
michael@0: add_task(function test_momentary_401_storage_loggedout() {
michael@0:   _("Test a failure for any storage URL, not just engine parts. " +
michael@0:     "Resolved by reassignment.");
michael@0:   let server = yield prepareServer();
michael@0: 
michael@0:   // Return a 401 for all storage requests.
michael@0:   let oldHandler = server.toplevelHandlers.storage;
michael@0:   server.toplevelHandlers.storage = handleReassign;
michael@0: 
michael@0:   function undo() {
michael@0:     _("Undoing test changes.");
michael@0:     server.toplevelHandlers.storage = oldHandler;
michael@0:   }
michael@0: 
michael@0:   do_check_false(Service.isLoggedIn, "not already logged in");
michael@0:   yield syncAndExpectNodeReassignment(server,
michael@0:                                       "weave:service:login:error",
michael@0:                                       undo,
michael@0:                                       "weave:service:sync:finish",
michael@0:                                       Service.storageURL + "meta/global");
michael@0: });
michael@0: 
michael@0: add_task(function test_loop_avoidance_storage() {
michael@0:   _("Test that a repeated failure doesn't result in a sync loop " +
michael@0:     "if node reassignment cannot resolve the failure.");
michael@0: 
michael@0:   let server = yield prepareServer();
michael@0: 
michael@0:   // Return a 401 for all storage requests.
michael@0:   let oldHandler = server.toplevelHandlers.storage;
michael@0:   server.toplevelHandlers.storage = handleReassign;
michael@0: 
michael@0:   let firstNotification  = "weave:service:login:error";
michael@0:   let secondNotification = "weave:service:login:error";
michael@0:   let thirdNotification  = "weave:service:sync:finish";
michael@0: 
michael@0:   let nodeFetched = false;
michael@0:   let deferred = Promise.defer();
michael@0: 
michael@0:   // Track the time. We want to make sure the duration between the first and
michael@0:   // second sync is small, and then that the duration between second and third
michael@0:   // is set to be large.
michael@0:   let now;
michael@0: 
michael@0:   function onFirstSync() {
michael@0:     _("First sync completed.");
michael@0:     Svc.Obs.remove(firstNotification, onFirstSync);
michael@0:     Svc.Obs.add(secondNotification, onSecondSync);
michael@0: 
michael@0:     do_check_eq(Service.clusterURL, "");
michael@0: 
michael@0:     // We got a 401 mid-sync, and set the pref accordingly.
michael@0:     do_check_true(Services.prefs.getBoolPref("services.sync.lastSyncReassigned"));
michael@0: 
michael@0:     // Track whether we fetched node/weave. We want to wait for the second
michael@0:     // sync to finish so that we're cleaned up for the next test, so don't
michael@0:     // run_next_test in the node handler.
michael@0:     nodeFetched = false;
michael@0: 
michael@0:     // Verify that the client requests a node reassignment.
michael@0:     // Install a node handler to watch for these requests.
michael@0:     installNodeHandler(server, function () {
michael@0:       nodeFetched = true;
michael@0:     });
michael@0: 
michael@0:     // Update the timestamp.
michael@0:     now = Date.now();
michael@0:   }
michael@0: 
michael@0:   function onSecondSync() {
michael@0:     _("Second sync completed.");
michael@0:     Svc.Obs.remove(secondNotification, onSecondSync);
michael@0:     Svc.Obs.add(thirdNotification, onThirdSync);
michael@0: 
michael@0:     // This sync occurred within the backoff interval.
michael@0:     let elapsedTime = Date.now() - now;
michael@0:     do_check_true(elapsedTime < MINIMUM_BACKOFF_INTERVAL);
michael@0: 
michael@0:     // This pref will be true until a sync completes successfully.
michael@0:     do_check_true(getReassigned());
michael@0: 
michael@0:     // The timer will be set for some distant time.
michael@0:     // We store nextSync in prefs, which offers us only limited resolution.
michael@0:     // Include that logic here.
michael@0:     let expectedNextSync = 1000 * Math.floor((now + MINIMUM_BACKOFF_INTERVAL) / 1000);
michael@0:     _("Next sync scheduled for " + Service.scheduler.nextSync);
michael@0:     _("Expected to be slightly greater than " + expectedNextSync);
michael@0: 
michael@0:     do_check_true(Service.scheduler.nextSync >= expectedNextSync);
michael@0:     do_check_true(!!Service.scheduler.syncTimer);
michael@0: 
michael@0:     // Undo our evil scheme.
michael@0:     server.toplevelHandlers.storage = oldHandler;
michael@0: 
michael@0:     // Bring the timer forward to kick off a successful sync, so we can watch
michael@0:     // the pref get cleared.
michael@0:     Service.scheduler.scheduleNextSync(0);
michael@0:   }
michael@0:   function onThirdSync() {
michael@0:     Svc.Obs.remove(thirdNotification, onThirdSync);
michael@0: 
michael@0:     // That'll do for now; no more syncs.
michael@0:     Service.scheduler.clearSyncTriggers();
michael@0: 
michael@0:     // Make absolutely sure that any event listeners are done with their work
michael@0:     // before we proceed.
michael@0:     waitForZeroTimer(function () {
michael@0:       _("Third sync nextTick.");
michael@0:       do_check_false(getReassigned());
michael@0:       do_check_true(nodeFetched);
michael@0:       Service.startOver();
michael@0:       server.stop(deferred.resolve);
michael@0:     });
michael@0:   }
michael@0: 
michael@0:   Svc.Obs.add(firstNotification, onFirstSync);
michael@0: 
michael@0:   now = Date.now();
michael@0:   Service.sync();
michael@0:   yield deferred.promise;
michael@0: });
michael@0: 
michael@0: add_task(function test_loop_avoidance_engine() {
michael@0:   _("Test that a repeated 401 in an engine doesn't result in a sync loop " +
michael@0:     "if node reassignment cannot resolve the failure.");
michael@0:   let server = yield prepareServer();
michael@0:   let john   = server.user("johndoe");
michael@0: 
michael@0:   _("Enabling the Rotary engine.");
michael@0:   let engine = Service.engineManager.get("rotary");
michael@0:   engine.enabled = true;
michael@0:   let deferred = Promise.defer();
michael@0: 
michael@0:   // We need the server to be correctly set up prior to experimenting. Do this
michael@0:   // through a sync.
michael@0:   let global = {syncID: Service.syncID,
michael@0:                 storageVersion: STORAGE_VERSION,
michael@0:                 rotary: {version: engine.version,
michael@0:                          syncID:  engine.syncID}}
michael@0:   john.createCollection("meta").insert("global", global);
michael@0: 
michael@0:   _("First sync to prepare server contents.");
michael@0:   Service.sync();
michael@0: 
michael@0:   _("Setting up Rotary collection to 401.");
michael@0:   let rotary = john.createCollection("rotary");
michael@0:   let oldHandler = rotary.collectionHandler;
michael@0:   rotary.collectionHandler = handleReassign.bind(this, undefined);
michael@0: 
michael@0:   // Flag the Rotary engine to need syncing.
michael@0:   john.collection("rotary").timestamp += 1000;
michael@0: 
michael@0:   function onLoginStart() {
michael@0:     // lastSyncReassigned shouldn't be cleared until a sync has succeeded.
michael@0:     _("Ensuring that lastSyncReassigned is still set at next sync start.");
michael@0:     do_check_true(getReassigned());
michael@0:   }
michael@0: 
michael@0:   function beforeSuccessfulSync() {
michael@0:     _("Undoing test changes.");
michael@0:     rotary.collectionHandler = oldHandler;
michael@0:   }
michael@0: 
michael@0:   function afterSuccessfulSync() {
michael@0:     Svc.Obs.remove("weave:service:login:start", onLoginStart);
michael@0:     Service.startOver();
michael@0:     server.stop(deferred.resolve);
michael@0:   }
michael@0: 
michael@0:   let firstNotification  = "weave:service:sync:finish";
michael@0:   let secondNotification = "weave:service:sync:finish";
michael@0:   let thirdNotification  = "weave:service:sync:finish";
michael@0: 
michael@0:   let nodeFetched = false;
michael@0: 
michael@0:   // Track the time. We want to make sure the duration between the first and
michael@0:   // second sync is small, and then that the duration between second and third
michael@0:   // is set to be large.
michael@0:   let now;
michael@0: 
michael@0:   function onFirstSync() {
michael@0:     _("First sync completed.");
michael@0:     Svc.Obs.remove(firstNotification, onFirstSync);
michael@0:     Svc.Obs.add(secondNotification, onSecondSync);
michael@0: 
michael@0:     do_check_eq(Service.clusterURL, "");
michael@0: 
michael@0:     _("Adding observer that lastSyncReassigned is still set on login.");
michael@0:     Svc.Obs.add("weave:service:login:start", onLoginStart);
michael@0: 
michael@0:     // We got a 401 mid-sync, and set the pref accordingly.
michael@0:     do_check_true(Services.prefs.getBoolPref("services.sync.lastSyncReassigned"));
michael@0: 
michael@0:     // Track whether we fetched node/weave. We want to wait for the second
michael@0:     // sync to finish so that we're cleaned up for the next test, so don't
michael@0:     // run_next_test in the node handler.
michael@0:     nodeFetched = false;
michael@0: 
michael@0:     // Verify that the client requests a node reassignment.
michael@0:     // Install a node handler to watch for these requests.
michael@0:     installNodeHandler(server, function () {
michael@0:       nodeFetched = true;
michael@0:     });
michael@0: 
michael@0:     // Update the timestamp.
michael@0:     now = Date.now();
michael@0:   }
michael@0: 
michael@0:   function onSecondSync() {
michael@0:     _("Second sync completed.");
michael@0:     Svc.Obs.remove(secondNotification, onSecondSync);
michael@0:     Svc.Obs.add(thirdNotification, onThirdSync);
michael@0: 
michael@0:     // This sync occurred within the backoff interval.
michael@0:     let elapsedTime = Date.now() - now;
michael@0:     do_check_true(elapsedTime < MINIMUM_BACKOFF_INTERVAL);
michael@0: 
michael@0:     // This pref will be true until a sync completes successfully.
michael@0:     do_check_true(getReassigned());
michael@0: 
michael@0:     // The timer will be set for some distant time.
michael@0:     // We store nextSync in prefs, which offers us only limited resolution.
michael@0:     // Include that logic here.
michael@0:     let expectedNextSync = 1000 * Math.floor((now + MINIMUM_BACKOFF_INTERVAL) / 1000);
michael@0:     _("Next sync scheduled for " + Service.scheduler.nextSync);
michael@0:     _("Expected to be slightly greater than " + expectedNextSync);
michael@0: 
michael@0:     do_check_true(Service.scheduler.nextSync >= expectedNextSync);
michael@0:     do_check_true(!!Service.scheduler.syncTimer);
michael@0: 
michael@0:     // Undo our evil scheme.
michael@0:     beforeSuccessfulSync();
michael@0: 
michael@0:     // Bring the timer forward to kick off a successful sync, so we can watch
michael@0:     // the pref get cleared.
michael@0:     Service.scheduler.scheduleNextSync(0);
michael@0:   }
michael@0: 
michael@0:   function onThirdSync() {
michael@0:     Svc.Obs.remove(thirdNotification, onThirdSync);
michael@0: 
michael@0:     // That'll do for now; no more syncs.
michael@0:     Service.scheduler.clearSyncTriggers();
michael@0: 
michael@0:     // Make absolutely sure that any event listeners are done with their work
michael@0:     // before we proceed.
michael@0:     waitForZeroTimer(function () {
michael@0:       _("Third sync nextTick.");
michael@0:       do_check_false(getReassigned());
michael@0:       do_check_true(nodeFetched);
michael@0:       afterSuccessfulSync();
michael@0:     });
michael@0:   }
michael@0: 
michael@0:   Svc.Obs.add(firstNotification, onFirstSync);
michael@0: 
michael@0:   now = Date.now();
michael@0:   Service.sync();
michael@0:   yield deferred.promise;
michael@0: });