Bug 1122443 - Decrease FxA email status polling frequency. r=markh
authorEdouard Oger <eoger@fastmail.com>
Wed, 19 Jul 2017 16:05:34 -0400
changeset 421797 30b65b87bd9a7fb1b4e4f36dbe45e872f2f6f2e2
parent 421796 c008db4b7874f353bc66a727d402127d3d2cef9b
child 421798 767224f031ac7ad09261957ebbbaa2d8f178a54c
push id1517
push userjlorenzo@mozilla.com
push dateThu, 14 Sep 2017 16:50:54 +0000
treeherdermozilla-release@3b41fd564418 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmarkh
bugs1122443
milestone56.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1122443 - Decrease FxA email status polling frequency. r=markh MozReview-Commit-ID: L8QQwgWqsyH
services/fxaccounts/FxAccounts.jsm
services/fxaccounts/tests/xpcshell/head.js
services/fxaccounts/tests/xpcshell/test_accounts.js
--- a/services/fxaccounts/FxAccounts.jsm
+++ b/services/fxaccounts/FxAccounts.jsm
@@ -364,20 +364,25 @@ function FxAccountsInternal() {
   // All significant initialization should be done in the initialize() method
   // below as it helps with testing.
 }
 
 /**
  * The internal API's prototype.
  */
 FxAccountsInternal.prototype = {
-  // The timeout (in ms) we use to poll for a verified mail for the first 2 mins.
-  VERIFICATION_POLL_TIMEOUT_INITIAL: 15000, // 15 seconds
-  // And how often we poll after the first 2 mins.
-  VERIFICATION_POLL_TIMEOUT_SUBSEQUENT: 30000, // 30 seconds.
+  // The timeout (in ms) we use to poll for a verified mail for the first
+  // VERIFICATION_POLL_START_SLOWDOWN_THRESHOLD minutes if the user has
+  // logged-in in this session.
+  VERIFICATION_POLL_TIMEOUT_INITIAL: 60000, // 1 minute.
+  // All the other cases (> 5 min, on restart etc).
+  VERIFICATION_POLL_TIMEOUT_SUBSEQUENT: 5 * 60000, // 5 minutes.
+  // After X minutes, the polling will slow down to _SUBSEQUENT if we have
+  // logged-in in this session.
+  VERIFICATION_POLL_START_SLOWDOWN_THRESHOLD: 5,
   // The current version of the device registration, we use this to re-register
   // devices after we update what we send on device registration.
   DEVICE_REGISTRATION_VERSION: 2,
 
   _fxAccountsClient: null,
 
   // All significant initialization should be done in this initialize() method,
   // as it's called after this object has been mocked for tests.
@@ -693,17 +698,17 @@ FxAccountsInternal.prototype = {
       // If the caller is asking for verification to be re-sent, and there is
       // no signed-in user to begin with, this is probably best regarded as an
       // error.
       if (data) {
         if (!data.sessionToken) {
           return Promise.reject(new Error(
             "resendVerificationEmail called without a session token"));
         }
-        this.pollEmailStatus(currentState, data.sessionToken, "start");
+        this.startPollEmailStatus(currentState, data.sessionToken, "start");
         return this.fxAccountsClient.resendVerificationEmail(
           data.sessionToken).catch(err => this._handleTokenError(err));
       }
       throw new Error("Cannot resend verification email; no signed-in user");
     });
   },
 
   /*
@@ -741,17 +746,17 @@ FxAccountsInternal.prototype = {
         log.trace("checkVerificationStatus - no user data");
         return null;
       }
 
       // Always check the verification status, even if the local state indicates
       // we're already verified. If the user changed their password, the check
       // will fail, and we'll enter the reauth state.
       log.trace("checkVerificationStatus - forcing verification status check");
-      return this.pollEmailStatus(currentState, data.sessionToken, "push");
+      return this.startPollEmailStatus(currentState, data.sessionToken, "push");
     });
   },
 
   _destroyOAuthToken(tokenData) {
     let client = new FxAccountsOAuthGrantClient({
       serverURL: tokenData.server,
       client_id: FX_OAUTH_CLIENT_ID
     });
@@ -1106,17 +1111,17 @@ FxAccountsInternal.prototype = {
    */
   loadAndPoll() {
     let currentState = this.currentAccountState;
     return currentState.getUserAccountData()
       .then(data => {
         if (data) {
           Services.telemetry.getHistogramById("FXA_CONFIGURED").add(1);
           if (!this.isUserEmailVerified(data)) {
-            this.pollEmailStatus(currentState, data.sessionToken, "start");
+            this.startPollEmailStatus(currentState, data.sessionToken, "browser-startup");
           }
         }
         return data;
       });
   },
 
   startVerifiedCheck(data) {
     log.debug("startVerifiedCheck", data && data.verified);
@@ -1143,122 +1148,129 @@ FxAccountsInternal.prototype = {
   whenVerified(data) {
     let currentState = this.currentAccountState;
     if (data.verified) {
       log.debug("already verified");
       return currentState.resolve(data);
     }
     if (!currentState.whenVerifiedDeferred) {
       log.debug("whenVerified promise starts polling for verified email");
-      this.pollEmailStatus(currentState, data.sessionToken, "start");
+      this.startPollEmailStatus(currentState, data.sessionToken, "start");
     }
     return currentState.whenVerifiedDeferred.promise.then(
       result => currentState.resolve(result)
     );
   },
 
   notifyObservers(topic, data) {
     log.debug("Notifying observers of " + topic);
     Services.obs.notifyObservers(null, topic, data);
   },
 
-  // XXX - pollEmailStatus should maybe be on the AccountState object?
-  pollEmailStatus: function pollEmailStatus(currentState, sessionToken, why) {
-    log.debug("entering pollEmailStatus: " + why);
-    if (why == "start" || why == "push") {
-      if (this.currentTimer) {
-        log.debug("pollEmailStatus starting while existing timer is running");
-        clearTimeout(this.currentTimer);
-        this.currentTimer = null;
-      }
-
-      // If we were already polling, stop and start again.  This could happen
-      // if the user requested the verification email to be resent while we
-      // were already polling for receipt of an earlier email.
-      this.pollStartDate = Date.now();
-      if (!currentState.whenVerifiedDeferred) {
-        currentState.whenVerifiedDeferred = PromiseUtils.defer();
-        // This deferred might not end up with any handlers (eg, if sync
-        // is yet to start up.)  This might cause "A promise chain failed to
-        // handle a rejection" messages, so add an error handler directly
-        // on the promise to log the error.
-        currentState.whenVerifiedDeferred.promise.catch(err => {
-          log.info("the wait for user verification was stopped: " + err);
-        });
-      }
+  startPollEmailStatus(currentState, sessionToken, why) {
+    log.debug("entering startPollEmailStatus: " + why);
+    // If we were already polling, stop and start again.  This could happen
+    // if the user requested the verification email to be resent while we
+    // were already polling for receipt of an earlier email.
+    if (this.currentTimer) {
+      log.debug("startPollEmailStatus starting while existing timer is running");
+      clearTimeout(this.currentTimer);
+      this.currentTimer = null;
     }
 
-    // We return a promise for testing only. Other callers can ignore this,
-    // since verification polling continues in the background.
-    return this.checkEmailStatus(sessionToken, { reason: why })
-      .then((response) => {
-        log.debug("checkEmailStatus -> " + JSON.stringify(response));
-        if (response && response.verified) {
-          currentState.updateUserAccountData({ verified: true })
-            .then(() => {
-              return currentState.getUserAccountData();
-            })
-            .then(data => {
-              // Now that the user is verified, we can proceed to fetch keys
-              if (currentState.whenVerifiedDeferred) {
-                currentState.whenVerifiedDeferred.resolve(data);
-                delete currentState.whenVerifiedDeferred;
-              }
-              // Tell FxAccountsManager to clear its cache
-              this.notifyObservers(ON_FXA_UPDATE_NOTIFICATION, ONVERIFIED_NOTIFICATION);
-              // Record how we determined the account was verified
-              Services.telemetry.scalarSet("services.sync.fxa_verification_method",
-                                           why == "push" ? "push" : "poll");
-            });
-        } else {
-          // Poll email status again after a short delay.
-          this.pollEmailStatusAgain(currentState, sessionToken);
-        }
-      }, error => {
-        let timeoutMs = undefined;
-        if (error && error.retryAfter) {
-          // If the server told us to back off, back off the requested amount.
-          timeoutMs = (error.retryAfter + 3) * 1000;
-        }
-        // The server will return 401 if a request parameter is erroneous or
-        // if the session token expired. Let's continue polling otherwise.
-        if (!error || !error.code || error.code != 401) {
-          this.pollEmailStatusAgain(currentState, sessionToken, timeoutMs);
-        } else {
-          let error = new Error("Verification status check failed");
-          this._rejectWhenVerified(currentState, error);
-        }
+    this.pollStartDate = Date.now();
+    if (!currentState.whenVerifiedDeferred) {
+      currentState.whenVerifiedDeferred = PromiseUtils.defer();
+      // This deferred might not end up with any handlers (eg, if sync
+      // is yet to start up.)  This might cause "A promise chain failed to
+      // handle a rejection" messages, so add an error handler directly
+      // on the promise to log the error.
+      currentState.whenVerifiedDeferred.promise.catch(err => {
+        log.info("the wait for user verification was stopped: " + err);
       });
+    }
+    return this.pollEmailStatus(currentState, sessionToken, why);
   },
 
-  _rejectWhenVerified(currentState, error) {
-    currentState.whenVerifiedDeferred.reject(error);
-    delete currentState.whenVerifiedDeferred;
-  },
-
-  // Poll email status using truncated exponential back-off.
-  pollEmailStatusAgain(currentState, sessionToken, timeoutMs) {
-    let ageMs = Date.now() - this.pollStartDate;
-    if (ageMs >= this.POLL_SESSION) {
+  // We return a promise for testing only. Other callers can ignore this,
+  // since verification polling continues in the background.
+  async pollEmailStatus(currentState, sessionToken, why) {
+    log.debug("entering pollEmailStatus: " + why);
+    let nextPollMs;
+    try {
+      const response = await this.checkEmailStatus(sessionToken, { reason: why });
+      log.debug("checkEmailStatus -> " + JSON.stringify(response));
+      if (response && response.verified) {
+        await this.onPollEmailSuccess(currentState, why);
+        return;
+      }
+    } catch (error) {
+      if (error && error.code && error.code == 401) {
+        let error = new Error("Verification status check failed");
+        this._rejectWhenVerified(currentState, error);
+        return;
+      }
+      if (error && error.retryAfter) {
+        // If the server told us to back off, back off the requested amount.
+        nextPollMs = (error.retryAfter + 3) * 1000;
+      }
+    }
+    if (why == "push") {
+      return;
+    }
+    let pollDuration = Date.now() - this.pollStartDate;
+    // Polling session expired.
+    if (pollDuration >= this.POLL_SESSION) {
       if (currentState.whenVerifiedDeferred) {
         let error = new Error("User email verification timed out.");
         this._rejectWhenVerified(currentState, error);
       }
       log.debug("polling session exceeded, giving up");
       return;
     }
-    if (timeoutMs === undefined) {
-      let currentMinute = Math.ceil(ageMs / 60000);
-      timeoutMs = currentMinute <= 2 ? this.VERIFICATION_POLL_TIMEOUT_INITIAL
-                                     : this.VERIFICATION_POLL_TIMEOUT_SUBSEQUENT;
+    // Poll email status again after a short delay.
+    if (nextPollMs === undefined) {
+      let currentMinute = Math.ceil(pollDuration / 60000);
+      nextPollMs = (why == "start" && currentMinute < this.VERIFICATION_POLL_START_SLOWDOWN_THRESHOLD) ?
+                   this.VERIFICATION_POLL_TIMEOUT_INITIAL :
+                   this.VERIFICATION_POLL_TIMEOUT_SUBSEQUENT;
     }
-    log.debug("polling with timeout = " + timeoutMs);
+    this._scheduleNextPollEmailStatus(currentState, sessionToken, nextPollMs, why);
+  },
+
+  // Easy-to-mock testable method
+  _scheduleNextPollEmailStatus(currentState, sessionToken, nextPollMs, why) {
+    log.debug("polling with timeout = " + nextPollMs);
     this.currentTimer = setTimeout(() => {
-      this.pollEmailStatus(currentState, sessionToken, "timer");
-    }, timeoutMs);
+      this.pollEmailStatus(currentState, sessionToken, why);
+    }, nextPollMs);
+  },
+
+  async onPollEmailSuccess(currentState, why) {
+    try {
+      await currentState.updateUserAccountData({ verified: true })
+      const accountData = await currentState.getUserAccountData();
+      // Now that the user is verified, we can proceed to fetch keys
+      if (currentState.whenVerifiedDeferred) {
+        currentState.whenVerifiedDeferred.resolve(accountData);
+        delete currentState.whenVerifiedDeferred;
+      }
+      // Tell FxAccountsManager to clear its cache
+      this.notifyObservers(ON_FXA_UPDATE_NOTIFICATION, ONVERIFIED_NOTIFICATION);
+      // Record how we determined the account was verified
+      Services.telemetry.scalarSet("services.sync.fxa_verification_method",
+                                   why == "push" ? "push" : "poll");
+    } catch (e) {
+      log.error(e);
+    }
+  },
+
+  _rejectWhenVerified(currentState, error) {
+    currentState.whenVerifiedDeferred.reject(error);
+    delete currentState.whenVerifiedDeferred;
   },
 
   requiresHttps() {
     let allowHttp = Services.prefs.getBoolPref("identity.fxaccounts.allowHttp", false);
     return allowHttp !== true;
   },
 
   promiseAccountsSignUpURI() {
--- a/services/fxaccounts/tests/xpcshell/head.js
+++ b/services/fxaccounts/tests/xpcshell/head.js
@@ -14,8 +14,28 @@ Cu.import("resource://gre/modules/XPCOMU
 (function initFxAccountsTestingInfrastructure() {
   do_get_profile();
 
   let ns = {};
   Cu.import("resource://testing-common/services/common/logging.js", ns);
 
   ns.initTestLogging("Trace");
 }).call(this);
+
+// ================================================
+// Load mocking/stubbing library, sinon
+// docs: http://sinonjs.org/releases/v2.3.2/
+Cu.import("resource://gre/modules/Timer.jsm");
+var {Loader} = Cu.import("resource://gre/modules/commonjs/toolkit/loader.js", {});
+var loader = new Loader.Loader({
+  paths: {
+    "": "resource://testing-common/",
+  },
+  globals: {
+    setTimeout,
+    setInterval,
+    clearTimeout,
+    clearInterval,
+  },
+});
+var require = Loader.Require(loader, {id: ""});
+var sinon = require("sinon-2.3.2");
+// ================================================
--- a/services/fxaccounts/tests/xpcshell/test_accounts.js
+++ b/services/fxaccounts/tests/xpcshell/test_accounts.js
@@ -530,16 +530,120 @@ add_test(function test_polling_timeout()
       (fail) => {
         removeObserver();
         fxa.signOut().then(run_next_test);
       }
     );
   });
 });
 
+add_test(function test_pollEmailStatus_start_verified() {
+  let fxa = new MockFxAccounts();
+  let test_user = getTestUser("carol");
+
+  fxa.internal.POLL_SESSION = 20 * 60000;
+  fxa.internal.VERIFICATION_POLL_TIMEOUT_INITIAL = 50000;
+
+  fxa.setSignedInUser(test_user).then(() => {
+    fxa.internal.getUserAccountData().then(user => {
+      fxa.internal.fxAccountsClient._email = test_user.email;
+      fxa.internal.fxAccountsClient._verified = true;
+      const mock = sinon.mock(fxa.internal)
+      mock.expects("_scheduleNextPollEmailStatus").never();
+      fxa.internal.startPollEmailStatus(fxa.internal.currentAccountState, user.sessionToken, "start").then(() => {
+        mock.verify();
+        mock.restore();
+        run_next_test();
+      });
+    });
+  });
+});
+
+add_test(function test_pollEmailStatus_start() {
+  let fxa = new MockFxAccounts();
+  let test_user = getTestUser("carol");
+
+  fxa.internal.POLL_SESSION = 20 * 60000;
+  fxa.internal.VERIFICATION_POLL_TIMEOUT_INITIAL = 123456;
+
+  fxa.setSignedInUser(test_user).then(() => {
+    fxa.internal.getUserAccountData().then(user => {
+      const mock = sinon.mock(fxa.internal)
+      mock.expects("_scheduleNextPollEmailStatus").once()
+          .withArgs(fxa.internal.currentAccountState, user.sessionToken, 123456, "start");
+      fxa.internal.startPollEmailStatus(fxa.internal.currentAccountState, user.sessionToken, "start").then(() => {
+        mock.verify();
+        mock.restore();
+        run_next_test();
+      });
+    });
+  });
+});
+
+add_test(function test_pollEmailStatus_start_subsequent() {
+  let fxa = new MockFxAccounts();
+  let test_user = getTestUser("carol");
+
+  fxa.internal.POLL_SESSION = 20 * 60000;
+  fxa.internal.VERIFICATION_POLL_TIMEOUT_INITIAL = 123456;
+  fxa.internal.VERIFICATION_POLL_TIMEOUT_SUBSEQUENT = 654321;
+  fxa.internal.VERIFICATION_POLL_START_SLOWDOWN_THRESHOLD = -1;
+
+  fxa.setSignedInUser(test_user).then(() => {
+    fxa.internal.getUserAccountData().then(user => {
+      const mock = sinon.mock(fxa.internal)
+      mock.expects("_scheduleNextPollEmailStatus").once()
+          .withArgs(fxa.internal.currentAccountState, user.sessionToken, 654321, "start");
+      fxa.internal.startPollEmailStatus(fxa.internal.currentAccountState, user.sessionToken, "start").then(() => {
+        mock.verify();
+        mock.restore();
+        run_next_test();
+      });
+    });
+  });
+});
+
+add_test(function test_pollEmailStatus_browser_startup() {
+  let fxa = new MockFxAccounts();
+  let test_user = getTestUser("carol");
+
+  fxa.internal.POLL_SESSION = 20 * 60000;
+  fxa.internal.VERIFICATION_POLL_TIMEOUT_SUBSEQUENT = 654321;
+
+  fxa.setSignedInUser(test_user).then(() => {
+    fxa.internal.getUserAccountData().then(user => {
+      const mock = sinon.mock(fxa.internal)
+      mock.expects("_scheduleNextPollEmailStatus").once()
+          .withArgs(fxa.internal.currentAccountState, user.sessionToken, 654321, "browser-startup");
+      fxa.internal.startPollEmailStatus(fxa.internal.currentAccountState, user.sessionToken, "browser-startup").then(() => {
+        mock.verify();
+        mock.restore();
+        run_next_test();
+      });
+    });
+  });
+});
+
+add_test(function test_pollEmailStatus_push() {
+  let fxa = new MockFxAccounts();
+  let test_user = getTestUser("carol");
+
+  fxa.setSignedInUser(test_user).then(() => {
+    fxa.internal.getUserAccountData().then(user => {
+      const mock = sinon.mock(fxa.internal)
+      mock.expects("_scheduleNextPollEmailStatus").never();
+      fxa.internal.startPollEmailStatus(fxa.internal.currentAccountState, user.sessionToken, "push").then(() => {
+        mock.verify();
+        mock.restore();
+        run_next_test();
+      });
+    });
+  });
+});
+
 add_test(function test_getKeys() {
   let fxa = new MockFxAccounts();
   let user = getTestUser("eusebius");
 
   // Once email has been verified, we will be able to get keys
   user.verified = true;
 
   fxa.setSignedInUser(user).then(() => {