services/sync/modules/policies.sys.mjs

   1 /* This Source Code Form is subject to the terms of the Mozilla Public
   2  * License, v. 2.0. If a copy of the MPL was not distributed with this
   3  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
   4
   5 import { XPCOMUtils } from "resource://gre/modules/XPCOMUtils.sys.mjs";
   6
   7 import { Log } from "resource://gre/modules/Log.sys.mjs";
   8
   9 import {
  10   CREDENTIALS_CHANGED,
  11   ENGINE_APPLY_FAIL,
  12   ENGINE_UNKNOWN_FAIL,
  13   IDLE_OBSERVER_BACK_DELAY,
  14   LOGIN_FAILED_INVALID_PASSPHRASE,
  15   LOGIN_FAILED_LOGIN_REJECTED,
  16   LOGIN_FAILED_NETWORK_ERROR,
  17   LOGIN_FAILED_NO_PASSPHRASE,
  18   LOGIN_SUCCEEDED,
  19   MASTER_PASSWORD_LOCKED,
  20   MASTER_PASSWORD_LOCKED_RETRY_INTERVAL,
  21   MAX_ERROR_COUNT_BEFORE_BACKOFF,
  22   MINIMUM_BACKOFF_INTERVAL,
  23   MULTI_DEVICE_THRESHOLD,
  24   NO_SYNC_NODE_FOUND,
  25   NO_SYNC_NODE_INTERVAL,
  26   OVER_QUOTA,
  27   RESPONSE_OVER_QUOTA,
  28   SCORE_UPDATE_DELAY,
  29   SERVER_MAINTENANCE,
  30   SINGLE_USER_THRESHOLD,
  31   STATUS_OK,
  32   SYNC_FAILED_PARTIAL,
  33   SYNC_SUCCEEDED,
  34   kSyncBackoffNotMet,
  35   kSyncMasterPasswordLocked,
  36 } from "resource://services-sync/constants.sys.mjs";
  37
  38 import { Svc, Utils } from "resource://services-sync/util.sys.mjs";
  39
  40 import { logManager } from "resource://gre/modules/FxAccountsCommon.sys.mjs";
  41 import { Async } from "resource://services-common/async.sys.mjs";
  42 import { CommonUtils } from "resource://services-common/utils.sys.mjs";
  43
  44 const lazy = {};
  45
  46 ChromeUtils.defineESModuleGetters(lazy, {
  47   AddonManager: "resource://gre/modules/AddonManager.sys.mjs",
  48   Status: "resource://services-sync/status.sys.mjs",
  49 });
  50 ChromeUtils.defineLazyGetter(lazy, "fxAccounts", () => {
  51   return ChromeUtils.importESModule(
  52     "resource://gre/modules/FxAccounts.sys.mjs"
  53   ).getFxAccountsSingleton();
  54 });
  55 XPCOMUtils.defineLazyServiceGetter(
  56   lazy,
  57   "IdleService",
  58   "@mozilla.org/widget/useridleservice;1",
  59   "nsIUserIdleService"
  60 );
  61 XPCOMUtils.defineLazyServiceGetter(
  62   lazy,
  63   "CaptivePortalService",
  64   "@mozilla.org/network/captive-portal-service;1",
  65   "nsICaptivePortalService"
  66 );
  67
  68 // Get the value for an interval that's stored in preferences. To save users
  69 // from themselves (and us from them!) the minimum time they can specify
  70 // is 60s.
  71 function getThrottledIntervalPreference(prefName) {
  72   return Math.max(Svc.PrefBranch.getIntPref(prefName), 60) * 1000;
  73 }
  74
  75 export function SyncScheduler(service) {
  76   this.service = service;
  77   this.init();
  78 }
  79
  80 SyncScheduler.prototype = {
  81   _log: Log.repository.getLogger("Sync.SyncScheduler"),
  82
  83   _fatalLoginStatus: [
  84     LOGIN_FAILED_NO_PASSPHRASE,
  85     LOGIN_FAILED_INVALID_PASSPHRASE,
  86     LOGIN_FAILED_LOGIN_REJECTED,
  87   ],
  88
  89   /**
  90    * The nsITimer object that schedules the next sync. See scheduleNextSync().
  91    */
  92   syncTimer: null,
  93
  94   setDefaults: function setDefaults() {
  95     this._log.trace("Setting SyncScheduler policy values to defaults.");
  96
  97     this.singleDeviceInterval = getThrottledIntervalPreference(
  98       "scheduler.fxa.singleDeviceInterval"
  99     );
 100     this.idleInterval = getThrottledIntervalPreference(
 101       "scheduler.idleInterval"
 102     );
 103     this.activeInterval = getThrottledIntervalPreference(
 104       "scheduler.activeInterval"
 105     );
 106     this.immediateInterval = getThrottledIntervalPreference(
 107       "scheduler.immediateInterval"
 108     );
 109
 110     // A user is non-idle on startup by default.
 111     this.idle = false;
 112
 113     this.hasIncomingItems = false;
 114     // This is the last number of clients we saw when previously updating the
 115     // client mode. If this != currentNumClients (obtained from prefs written
 116     // by the clients engine) then we need to transition to and from
 117     // single and multi-device mode.
 118     this.numClientsLastSync = 0;
 119
 120     this._resyncs = 0;
 121
 122     this.clearSyncTriggers();
 123   },
 124
 125   // nextSync is in milliseconds, but prefs can't hold that much
 126   get nextSync() {
 127     return Svc.PrefBranch.getIntPref("nextSync", 0) * 1000;
 128   },
 129   set nextSync(value) {
 130     Svc.PrefBranch.setIntPref("nextSync", Math.floor(value / 1000));
 131   },
 132
 133   get missedFxACommandsFetchInterval() {
 134     return Services.prefs.getIntPref(
 135       "identity.fxaccounts.commands.missed.fetch_interval"
 136     );
 137   },
 138
 139   get missedFxACommandsLastFetch() {
 140     return Services.prefs.getIntPref(
 141       "identity.fxaccounts.commands.missed.last_fetch",
 142       0
 143     );
 144   },
 145
 146   set missedFxACommandsLastFetch(val) {
 147     Services.prefs.setIntPref(
 148       "identity.fxaccounts.commands.missed.last_fetch",
 149       val
 150     );
 151   },
 152
 153   get syncInterval() {
 154     return this._syncInterval;
 155   },
 156   set syncInterval(value) {
 157     if (value != this._syncInterval) {
 158       Services.prefs.setIntPref("services.sync.syncInterval", value);
 159     }
 160   },
 161
 162   get syncThreshold() {
 163     return this._syncThreshold;
 164   },
 165   set syncThreshold(value) {
 166     if (value != this._syncThreshold) {
 167       Services.prefs.setIntPref("services.sync.syncThreshold", value);
 168     }
 169   },
 170
 171   get globalScore() {
 172     return this._globalScore;
 173   },
 174   set globalScore(value) {
 175     if (this._globalScore != value) {
 176       Services.prefs.setIntPref("services.sync.globalScore", value);
 177     }
 178   },
 179
 180   // Managed by the clients engine (by way of prefs)
 181   get numClients() {
 182     return this.numDesktopClients + this.numMobileClients;
 183   },
 184   set numClients(value) {
 185     throw new Error("Don't set numClients - the clients engine manages it.");
 186   },
 187
 188   get offline() {
 189     // Services.io.offline has slowly become fairly useless over the years - it
 190     // no longer attempts to track the actual network state by default, but one
 191     // thing stays true: if it says we're offline then we are definitely not online.
 192     //
 193     // We also ask the captive portal service if we are behind a locked captive
 194     // portal.
 195     //
 196     // We don't check on the NetworkLinkService however, because it gave us
 197     // false positives in the past in a vm environment.
 198     try {
 199       if (
 200         Services.io.offline ||
 201         lazy.CaptivePortalService.state ==
 202           lazy.CaptivePortalService.LOCKED_PORTAL
 203       ) {
 204         return true;
 205       }
 206     } catch (ex) {
 207       this._log.warn("Could not determine network status.", ex);
 208     }
 209     return false;
 210   },
 211
 212   _initPrefGetters() {
 213     XPCOMUtils.defineLazyPreferenceGetter(
 214       this,
 215       "idleTime",
 216       "services.sync.scheduler.idleTime"
 217     );
 218     XPCOMUtils.defineLazyPreferenceGetter(
 219       this,
 220       "maxResyncs",
 221       "services.sync.maxResyncs",
 222       0
 223     );
 224
 225     // The number of clients we have is maintained in preferences via the
 226     // clients engine, and only updated after a successsful sync.
 227     XPCOMUtils.defineLazyPreferenceGetter(
 228       this,
 229       "numDesktopClients",
 230       "services.sync.clients.devices.desktop",
 231       0
 232     );
 233     XPCOMUtils.defineLazyPreferenceGetter(
 234       this,
 235       "numMobileClients",
 236       "services.sync.clients.devices.mobile",
 237       0
 238     );
 239
 240     // Scheduler state that seems to be read more often than it's written.
 241     // We also check if the value has changed before writing in the setters.
 242     XPCOMUtils.defineLazyPreferenceGetter(
 243       this,
 244       "_syncThreshold",
 245       "services.sync.syncThreshold",
 246       SINGLE_USER_THRESHOLD
 247     );
 248     XPCOMUtils.defineLazyPreferenceGetter(
 249       this,
 250       "_syncInterval",
 251       "services.sync.syncInterval",
 252       this.singleDeviceInterval
 253     );
 254     XPCOMUtils.defineLazyPreferenceGetter(
 255       this,
 256       "_globalScore",
 257       "services.sync.globalScore",
 258       0
 259     );
 260   },
 261
 262   init: function init() {
 263     this._log.manageLevelFromPref("services.sync.log.logger.service.main");
 264     this.setDefaults();
 265     this._initPrefGetters();
 266     Svc.Obs.add("weave:engine:score:updated", this);
 267     Svc.Obs.add("network:offline-status-changed", this);
 268     Svc.Obs.add("network:link-status-changed", this);
 269     Svc.Obs.add("captive-portal-detected", this);
 270     Svc.Obs.add("weave:service:sync:start", this);
 271     Svc.Obs.add("weave:service:sync:finish", this);
 272     Svc.Obs.add("weave:engine:sync:finish", this);
 273     Svc.Obs.add("weave:engine:sync:error", this);
 274     Svc.Obs.add("weave:service:login:error", this);
 275     Svc.Obs.add("weave:service:logout:finish", this);
 276     Svc.Obs.add("weave:service:sync:error", this);
 277     Svc.Obs.add("weave:service:backoff:interval", this);
 278     Svc.Obs.add("weave:engine:sync:applied", this);
 279     Svc.Obs.add("weave:service:setup-complete", this);
 280     Svc.Obs.add("weave:service:start-over", this);
 281     Svc.Obs.add("FxA:hawk:backoff:interval", this);
 282
 283     if (lazy.Status.checkSetup() == STATUS_OK) {
 284       Svc.Obs.add("wake_notification", this);
 285       Svc.Obs.add("captive-portal-login-success", this);
 286       Svc.Obs.add("sleep_notification", this);
 287       lazy.IdleService.addIdleObserver(this, this.idleTime);
 288     }
 289   },
 290
 291   // eslint-disable-next-line complexity
 292   observe: function observe(subject, topic, data) {
 293     this._log.trace("Handling " + topic);
 294     switch (topic) {
 295       case "weave:engine:score:updated":
 296         if (lazy.Status.login == LOGIN_SUCCEEDED) {
 297           CommonUtils.namedTimer(
 298             this.calculateScore,
 299             SCORE_UPDATE_DELAY,
 300             this,
 301             "_scoreTimer"
 302           );
 303         }
 304         break;
 305       case "network:link-status-changed":
 306         // Note: NetworkLinkService is unreliable, we get false negatives for it
 307         // in cases such as VMs (bug 1420802), so we don't want to use it in
 308         // `get offline`, but we assume that it's probably reliable if we're
 309         // getting status changed events. (We might be wrong about this, but
 310         // if that's true, then the only downside is that we won't sync as
 311         // promptly).
 312         let isOffline = this.offline;
 313         this._log.debug(
 314           `Network link status changed to "${data}". Offline?`,
 315           isOffline
 316         );
 317         // Data may be one of `up`, `down`, `change`, or `unknown`. We only want
 318         // to sync if it's "up".
 319         if (data == "up" && !isOffline) {
 320           this._log.debug("Network link looks up. Syncing.");
 321           this.scheduleNextSync(0, { why: topic });
 322         } else if (data == "down") {
 323           // Unschedule pending syncs if we know we're going down. We don't do
 324           // this via `checkSyncStatus`, since link status isn't reflected in
 325           // `this.offline`.
 326           this.clearSyncTriggers();
 327         }
 328         break;
 329       case "network:offline-status-changed":
 330       case "captive-portal-detected":
 331         // Whether online or offline, we'll reschedule syncs
 332         this._log.trace("Network offline status change: " + data);
 333         this.checkSyncStatus();
 334         break;
 335       case "weave:service:sync:start":
 336         // Clear out any potentially pending syncs now that we're syncing
 337         this.clearSyncTriggers();
 338
 339         // reset backoff info, if the server tells us to continue backing off,
 340         // we'll handle that later
 341         lazy.Status.resetBackoff();
 342
 343         this.globalScore = 0;
 344         break;
 345       case "weave:service:sync:finish":
 346         this.nextSync = 0;
 347         this.adjustSyncInterval();
 348
 349         if (
 350           lazy.Status.service == SYNC_FAILED_PARTIAL &&
 351           this.requiresBackoff
 352         ) {
 353           this.requiresBackoff = false;
 354           this.handleSyncError();
 355           return;
 356         }
 357
 358         let sync_interval;
 359         let nextSyncReason = "schedule";
 360         this.updateGlobalScore();
 361         if (
 362           this.globalScore > this.syncThreshold &&
 363           lazy.Status.service == STATUS_OK
 364         ) {
 365           // The global score should be 0 after a sync. If it's not, either
 366           // items were changed during the last sync (and we should schedule an
 367           // immediate follow-up sync), or an engine skipped
 368           this._resyncs++;
 369           if (this._resyncs <= this.maxResyncs) {
 370             sync_interval = 0;
 371             nextSyncReason = "resync";
 372           } else {
 373             this._log.warn(
 374               `Resync attempt ${this._resyncs} exceeded ` +
 375                 `maximum ${this.maxResyncs}`
 376             );
 377             Svc.Obs.notify("weave:service:resyncs-finished");
 378           }
 379         } else {
 380           this._resyncs = 0;
 381           Svc.Obs.notify("weave:service:resyncs-finished");
 382         }
 383
 384         this._syncErrors = 0;
 385         if (lazy.Status.sync == NO_SYNC_NODE_FOUND) {
 386           // If we don't have a Sync node, override the interval, even if we've
 387           // scheduled a follow-up sync.
 388           this._log.trace("Scheduling a sync at interval NO_SYNC_NODE_FOUND.");
 389           sync_interval = NO_SYNC_NODE_INTERVAL;
 390         }
 391         this.scheduleNextSync(sync_interval, { why: nextSyncReason });
 392         break;
 393       case "weave:engine:sync:finish":
 394         if (data == "clients") {
 395           // Update the client mode because it might change what we sync.
 396           this.updateClientMode();
 397         }
 398         break;
 399       case "weave:engine:sync:error":
 400         // `subject` is the exception thrown by an engine's sync() method.
 401         let exception = subject;
 402         if (exception.status >= 500 && exception.status <= 504) {
 403           this.requiresBackoff = true;
 404         }
 405         break;
 406       case "weave:service:login:error":
 407         this.clearSyncTriggers();
 408
 409         if (lazy.Status.login == MASTER_PASSWORD_LOCKED) {
 410           // Try again later, just as if we threw an error... only without the
 411           // error count.
 412           this._log.debug("Couldn't log in: master password is locked.");
 413           this._log.trace(
 414             "Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL"
 415           );
 416           this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
 417         } else if (!this._fatalLoginStatus.includes(lazy.Status.login)) {
 418           // Not a fatal login error, just an intermittent network or server
 419           // issue. Keep on syncin'.
 420           this.checkSyncStatus();
 421         }
 422         break;
 423       case "weave:service:logout:finish":
 424         // Start or cancel the sync timer depending on if
 425         // logged in or logged out
 426         this.checkSyncStatus();
 427         break;
 428       case "weave:service:sync:error":
 429         // There may be multiple clients but if the sync fails, client mode
 430         // should still be updated so that the next sync has a correct interval.
 431         this.updateClientMode();
 432         this.adjustSyncInterval();
 433         this.nextSync = 0;
 434         this.handleSyncError();
 435         break;
 436       case "FxA:hawk:backoff:interval":
 437       case "weave:service:backoff:interval":
 438         let requested_interval = subject * 1000;
 439         this._log.debug(
 440           "Got backoff notification: " + requested_interval + "ms"
 441         );
 442         // Leave up to 25% more time for the back off.
 443         let interval = requested_interval * (1 + Math.random() * 0.25);
 444         lazy.Status.backoffInterval = interval;
 445         lazy.Status.minimumNextSync = Date.now() + requested_interval;
 446         this._log.debug(
 447           "Fuzzed minimum next sync: " + lazy.Status.minimumNextSync
 448         );
 449         break;
 450       case "weave:engine:sync:applied":
 451         let numItems = subject.succeeded;
 452         this._log.trace(
 453           "Engine " + data + " successfully applied " + numItems + " items."
 454         );
 455         // Bug 1800186 - the tabs engine always reports incoming items, so we don't
 456         // want special scheduling in this scenario.
 457         // (However, even when we fix the underlying cause of that, we probably still can
 458         // ignore tabs here - new incoming tabs don't need to trigger the extra syncs we do
 459         // based on this flag.)
 460         if (data != "tabs" && numItems) {
 461           this.hasIncomingItems = true;
 462         }
 463         if (subject.newFailed) {
 464           this._log.error(
 465             `Engine ${data} found ${subject.newFailed} new records that failed to apply`
 466           );
 467         }
 468         break;
 469       case "weave:service:setup-complete":
 470         Services.prefs.savePrefFile(null);
 471         lazy.IdleService.addIdleObserver(this, this.idleTime);
 472         Svc.Obs.add("wake_notification", this);
 473         Svc.Obs.add("captive-portal-login-success", this);
 474         Svc.Obs.add("sleep_notification", this);
 475         break;
 476       case "weave:service:start-over":
 477         this.setDefaults();
 478         try {
 479           lazy.IdleService.removeIdleObserver(this, this.idleTime);
 480         } catch (ex) {
 481           if (ex.result != Cr.NS_ERROR_FAILURE) {
 482             throw ex;
 483           }
 484           // In all likelihood we didn't have an idle observer registered yet.
 485           // It's all good.
 486         }
 487         break;
 488       case "idle":
 489         this._log.trace("We're idle.");
 490         this.idle = true;
 491         // Adjust the interval for future syncs. This won't actually have any
 492         // effect until the next pending sync (which will happen soon since we
 493         // were just active.)
 494         this.adjustSyncInterval();
 495         break;
 496       case "active":
 497         this._log.trace("Received notification that we're back from idle.");
 498         this.idle = false;
 499         CommonUtils.namedTimer(
 500           function onBack() {
 501             if (this.idle) {
 502               this._log.trace(
 503                 "... and we're idle again. " +
 504                   "Ignoring spurious back notification."
 505               );
 506               return;
 507             }
 508
 509             this._log.trace("Genuine return from idle. Syncing.");
 510             // Trigger a sync if we have multiple clients.
 511             if (this.numClients > 1) {
 512               this.scheduleNextSync(0, { why: topic });
 513             }
 514           },
 515           IDLE_OBSERVER_BACK_DELAY,
 516           this,
 517           "idleDebouncerTimer"
 518         );
 519         break;
 520       case "wake_notification":
 521         this._log.debug("Woke from sleep.");
 522         CommonUtils.nextTick(() => {
 523           // Trigger a sync if we have multiple clients. We give it 2 seconds
 524           // so the browser can recover from the wake and do more important
 525           // operations first (timers etc).
 526           if (this.numClients > 1) {
 527             if (!this.offline) {
 528               this._log.debug("Online, will sync in 2s.");
 529               this.scheduleNextSync(2000, { why: topic });
 530             }
 531           }
 532         });
 533         break;
 534       case "captive-portal-login-success":
 535         this._log.debug("Captive portal login success. Scheduling a sync.");
 536         CommonUtils.nextTick(() => {
 537           this.scheduleNextSync(3000, { why: topic });
 538         });
 539         break;
 540       case "sleep_notification":
 541         if (this.service.engineManager.get("tabs")._tracker.modified) {
 542           this._log.debug("Going to sleep, doing a quick sync.");
 543           this.scheduleNextSync(0, { engines: ["tabs"], why: "sleep" });
 544         }
 545         break;
 546     }
 547   },
 548
 549   adjustSyncInterval: function adjustSyncInterval() {
 550     if (this.numClients <= 1) {
 551       this._log.trace("Adjusting syncInterval to singleDeviceInterval.");
 552       this.syncInterval = this.singleDeviceInterval;
 553       return;
 554     }
 555
 556     // Only MULTI_DEVICE clients will enter this if statement
 557     // since SINGLE_USER clients will be handled above.
 558     if (this.idle) {
 559       this._log.trace("Adjusting syncInterval to idleInterval.");
 560       this.syncInterval = this.idleInterval;
 561       return;
 562     }
 563
 564     if (this.hasIncomingItems) {
 565       this._log.trace("Adjusting syncInterval to immediateInterval.");
 566       this.hasIncomingItems = false;
 567       this.syncInterval = this.immediateInterval;
 568     } else {
 569       this._log.trace("Adjusting syncInterval to activeInterval.");
 570       this.syncInterval = this.activeInterval;
 571     }
 572   },
 573
 574   updateGlobalScore() {
 575     let engines = [this.service.clientsEngine].concat(
 576       this.service.engineManager.getEnabled()
 577     );
 578     let globalScore = this.globalScore;
 579     for (let i = 0; i < engines.length; i++) {
 580       this._log.trace(engines[i].name + ": score: " + engines[i].score);
 581       globalScore += engines[i].score;
 582       engines[i]._tracker.resetScore();
 583     }
 584     this.globalScore = globalScore;
 585     this._log.trace("Global score updated: " + globalScore);
 586   },
 587
 588   calculateScore() {
 589     this.updateGlobalScore();
 590     this.checkSyncStatus();
 591   },
 592
 593   /**
 594    * Query the number of known clients to figure out what mode to be in
 595    */
 596   updateClientMode: function updateClientMode() {
 597     // Nothing to do if it's the same amount
 598     let numClients = this.numClients;
 599     if (numClients == this.numClientsLastSync) {
 600       return;
 601     }
 602
 603     this._log.debug(
 604       `Client count: ${this.numClientsLastSync} -> ${numClients}`
 605     );
 606     this.numClientsLastSync = numClients;
 607
 608     if (numClients <= 1) {
 609       this._log.trace("Adjusting syncThreshold to SINGLE_USER_THRESHOLD");
 610       this.syncThreshold = SINGLE_USER_THRESHOLD;
 611     } else {
 612       this._log.trace("Adjusting syncThreshold to MULTI_DEVICE_THRESHOLD");
 613       this.syncThreshold = MULTI_DEVICE_THRESHOLD;
 614     }
 615     this.adjustSyncInterval();
 616   },
 617
 618   /**
 619    * Check if we should be syncing and schedule the next sync, if it's not scheduled
 620    */
 621   checkSyncStatus: function checkSyncStatus() {
 622     // Should we be syncing now, if not, cancel any sync timers and return
 623     // if we're in backoff, we'll schedule the next sync.
 624     let ignore = [kSyncBackoffNotMet, kSyncMasterPasswordLocked];
 625     let skip = this.service._checkSync(ignore);
 626     this._log.trace('_checkSync returned "' + skip + '".');
 627     if (skip) {
 628       this.clearSyncTriggers();
 629       return;
 630     }
 631
 632     let why = "schedule";
 633     // Only set the wait time to 0 if we need to sync right away
 634     let wait;
 635     if (this.globalScore > this.syncThreshold) {
 636       this._log.debug("Global Score threshold hit, triggering sync.");
 637       wait = 0;
 638       why = "score";
 639     }
 640     this.scheduleNextSync(wait, { why });
 641   },
 642
 643   /**
 644    * Call sync() if Master Password is not locked.
 645    *
 646    * Otherwise, reschedule a sync for later.
 647    */
 648   syncIfMPUnlocked(engines, why) {
 649     // No point if we got kicked out by the master password dialog.
 650     if (lazy.Status.login == MASTER_PASSWORD_LOCKED && Utils.mpLocked()) {
 651       this._log.debug(
 652         "Not initiating sync: Login status is " + lazy.Status.login
 653       );
 654
 655       // If we're not syncing now, we need to schedule the next one.
 656       this._log.trace(
 657         "Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL"
 658       );
 659       this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
 660       return;
 661     }
 662
 663     if (!Async.isAppReady()) {
 664       this._log.debug("Not initiating sync: app is shutting down");
 665       return;
 666     }
 667     Services.tm.dispatchToMainThread(() => {
 668       this.service.sync({ engines, why });
 669       const now = Math.round(new Date().getTime() / 1000);
 670       // Only fetch missed messages in a "scheduled" sync so we don't race against
 671       // the Push service reconnecting on a network link change for example.
 672       if (
 673         why == "schedule" &&
 674         now >=
 675           this.missedFxACommandsLastFetch + this.missedFxACommandsFetchInterval
 676       ) {
 677         lazy.fxAccounts.commands
 678           .pollDeviceCommands()
 679           .then(() => {
 680             this.missedFxACommandsLastFetch = now;
 681           })
 682           .catch(e => {
 683             this._log.error("Fetching missed remote commands failed.", e);
 684           });
 685       }
 686     });
 687   },
 688
 689   /**
 690    * Set a timer for the next sync
 691    */
 692   scheduleNextSync(interval, { engines = null, why = null } = {}) {
 693     // If no interval was specified, use the current sync interval.
 694     if (interval == null) {
 695       interval = this.syncInterval;
 696     }
 697
 698     // Ensure the interval is set to no less than the backoff.
 699     if (lazy.Status.backoffInterval && interval < lazy.Status.backoffInterval) {
 700       this._log.trace(
 701         "Requested interval " +
 702           interval +
 703           " ms is smaller than the backoff interval. " +
 704           "Using backoff interval " +
 705           lazy.Status.backoffInterval +
 706           " ms instead."
 707       );
 708       interval = lazy.Status.backoffInterval;
 709     }
 710     let nextSync = this.nextSync;
 711     if (nextSync != 0) {
 712       // There's already a sync scheduled. Don't reschedule if there's already
 713       // a timer scheduled for sooner than requested.
 714       let currentInterval = nextSync - Date.now();
 715       this._log.trace(
 716         "There's already a sync scheduled in " + currentInterval + " ms."
 717       );
 718       if (currentInterval < interval && this.syncTimer) {
 719         this._log.trace(
 720           "Ignoring scheduling request for next sync in " + interval + " ms."
 721         );
 722         return;
 723       }
 724     }
 725
 726     // Start the sync right away if we're already late.
 727     if (interval <= 0) {
 728       this._log.trace(`Requested sync should happen right away. (why=${why})`);
 729       this.syncIfMPUnlocked(engines, why);
 730       return;
 731     }
 732
 733     this._log.debug(`Next sync in ${interval} ms. (why=${why})`);
 734     CommonUtils.namedTimer(
 735       () => {
 736         this.syncIfMPUnlocked(engines, why);
 737       },
 738       interval,
 739       this,
 740       "syncTimer"
 741     );
 742
 743     // Save the next sync time in-case sync is disabled (logout/offline/etc.)
 744     this.nextSync = Date.now() + interval;
 745   },
 746
 747   /**
 748    * Incorporates the backoff/retry logic used in error handling and elective
 749    * non-syncing.
 750    */
 751   scheduleAtInterval: function scheduleAtInterval(minimumInterval) {
 752     let interval = Utils.calculateBackoff(
 753       this._syncErrors,
 754       MINIMUM_BACKOFF_INTERVAL,
 755       lazy.Status.backoffInterval
 756     );
 757     if (minimumInterval) {
 758       interval = Math.max(minimumInterval, interval);
 759     }
 760
 761     this._log.debug(
 762       "Starting client-initiated backoff. Next sync in " + interval + " ms."
 763     );
 764     this.scheduleNextSync(interval, { why: "client-backoff-schedule" });
 765   },
 766
 767   autoConnect: function autoConnect() {
 768     if (this.service._checkSetup() == STATUS_OK && !this.service._checkSync()) {
 769       // Schedule a sync based on when a previous sync was scheduled.
 770       // scheduleNextSync() will do the right thing if that time lies in
 771       // the past.
 772       this.scheduleNextSync(this.nextSync - Date.now(), { why: "startup" });
 773     }
 774   },
 775
 776   _syncErrors: 0,
 777   /**
 778    * Deal with sync errors appropriately
 779    */
 780   handleSyncError: function handleSyncError() {
 781     this._log.trace("In handleSyncError. Error count: " + this._syncErrors);
 782     this._syncErrors++;
 783
 784     // Do nothing on the first couple of failures, if we're not in
 785     // backoff due to 5xx errors.
 786     if (!lazy.Status.enforceBackoff) {
 787       if (this._syncErrors < MAX_ERROR_COUNT_BEFORE_BACKOFF) {
 788         this.scheduleNextSync(null, { why: "reschedule" });
 789         return;
 790       }
 791       this._log.debug(
 792         "Sync error count has exceeded " +
 793           MAX_ERROR_COUNT_BEFORE_BACKOFF +
 794           "; enforcing backoff."
 795       );
 796       lazy.Status.enforceBackoff = true;
 797     }
 798
 799     this.scheduleAtInterval();
 800   },
 801
 802   /**
 803    * Remove any timers/observers that might trigger a sync
 804    */
 805   clearSyncTriggers: function clearSyncTriggers() {
 806     this._log.debug("Clearing sync triggers and the global score.");
 807     this.globalScore = this.nextSync = 0;
 808
 809     // Clear out any scheduled syncs
 810     if (this.syncTimer) {
 811       this.syncTimer.clear();
 812     }
 813   },
 814 };
 815
 816 export function ErrorHandler(service) {
 817   this.service = service;
 818   this.init();
 819 }
 820
 821 ErrorHandler.prototype = {
 822   init() {
 823     Svc.Obs.add("weave:engine:sync:applied", this);
 824     Svc.Obs.add("weave:engine:sync:error", this);
 825     Svc.Obs.add("weave:service:login:error", this);
 826     Svc.Obs.add("weave:service:sync:error", this);
 827     Svc.Obs.add("weave:service:sync:finish", this);
 828     Svc.Obs.add("weave:service:start-over:finish", this);
 829
 830     this.initLogs();
 831   },
 832
 833   initLogs: function initLogs() {
 834     // Set the root Sync logger level based on a pref. All other logs will
 835     // inherit this level unless they specifically override it.
 836     Log.repository
 837       .getLogger("Sync")
 838       .manageLevelFromPref(`services.sync.log.logger`);
 839     // And allow our specific log to have a custom level via a pref.
 840     this._log = Log.repository.getLogger("Sync.ErrorHandler");
 841     this._log.manageLevelFromPref("services.sync.log.logger.service.main");
 842   },
 843
 844   observe(subject, topic, data) {
 845     this._log.trace("Handling " + topic);
 846     switch (topic) {
 847       case "weave:engine:sync:applied":
 848         if (subject.newFailed) {
 849           // An engine isn't able to apply one or more incoming records.
 850           // We don't fail hard on this, but it usually indicates a bug,
 851           // so for now treat it as sync error (c.f. Service._syncEngine())
 852           lazy.Status.engines = [data, ENGINE_APPLY_FAIL];
 853           this._log.debug(data + " failed to apply some records.");
 854         }
 855         break;
 856       case "weave:engine:sync:error": {
 857         let exception = subject; // exception thrown by engine's sync() method
 858         let engine_name = data; // engine name that threw the exception
 859
 860         this.checkServerError(exception);
 861
 862         lazy.Status.engines = [
 863           engine_name,
 864           exception.failureCode || ENGINE_UNKNOWN_FAIL,
 865         ];
 866         if (Async.isShutdownException(exception)) {
 867           this._log.debug(
 868             engine_name +
 869               " was interrupted due to the application shutting down"
 870           );
 871         } else {
 872           this._log.debug(engine_name + " failed", exception);
 873         }
 874         break;
 875       }
 876       case "weave:service:login:error":
 877         this._log.error("Sync encountered a login error");
 878         this.resetFileLog();
 879         break;
 880       case "weave:service:sync:error": {
 881         if (lazy.Status.sync == CREDENTIALS_CHANGED) {
 882           this.service.logout();
 883         }
 884
 885         let exception = subject;
 886         if (Async.isShutdownException(exception)) {
 887           // If we are shutting down we just log the fact, attempt to flush
 888           // the log file and get out of here!
 889           this._log.error(
 890             "Sync was interrupted due to the application shutting down"
 891           );
 892           this.resetFileLog();
 893           break;
 894         }
 895
 896         // Not a shutdown related exception...
 897         this._log.error("Sync encountered an error", exception);
 898         this.resetFileLog();
 899         break;
 900       }
 901       case "weave:service:sync:finish":
 902         this._log.trace("Status.service is " + lazy.Status.service);
 903
 904         // Check both of these status codes: in the event of a failure in one
 905         // engine, Status.service will be SYNC_FAILED_PARTIAL despite
 906         // Status.sync being SYNC_SUCCEEDED.
 907         // *facepalm*
 908         if (
 909           lazy.Status.sync == SYNC_SUCCEEDED &&
 910           lazy.Status.service == STATUS_OK
 911         ) {
 912           // Great. Let's clear our mid-sync 401 note.
 913           this._log.trace("Clearing lastSyncReassigned.");
 914           Svc.PrefBranch.clearUserPref("lastSyncReassigned");
 915         }
 916
 917         if (lazy.Status.service == SYNC_FAILED_PARTIAL) {
 918           this._log.error("Some engines did not sync correctly.");
 919         }
 920         this.resetFileLog();
 921         break;
 922       case "weave:service:start-over:finish":
 923         // ensure we capture any logs between the last sync and the reset completing.
 924         this.resetFileLog()
 925           .then(() => {
 926             // although for privacy reasons we also delete all logs (but we allow
 927             // a preference to avoid this to help with debugging.)
 928             if (!Svc.PrefBranch.getBoolPref("log.keepLogsOnReset", false)) {
 929               return logManager.removeAllLogs().then(() => {
 930                 Svc.Obs.notify("weave:service:remove-file-log");
 931               });
 932             }
 933             return null;
 934           })
 935           .catch(err => {
 936             // So we failed to delete the logs - take the ironic option of
 937             // writing this error to the logs we failed to delete!
 938             this._log.error("Failed to delete logs on reset", err);
 939           });
 940         break;
 941     }
 942   },
 943
 944   async _dumpAddons() {
 945     // Just dump the items that sync may be concerned with. Specifically,
 946     // active extensions that are not hidden.
 947     let addons = [];
 948     try {
 949       addons = await lazy.AddonManager.getAddonsByTypes(["extension"]);
 950     } catch (e) {
 951       this._log.warn("Failed to dump addons", e);
 952     }
 953
 954     let relevantAddons = addons.filter(x => x.isActive && !x.hidden);
 955     this._log.trace("Addons installed", relevantAddons.length);
 956     for (let addon of relevantAddons) {
 957       this._log.trace(" - ${name}, version ${version}, id ${id}", addon);
 958     }
 959   },
 960
 961   /**
 962    * Generate a log file for the sync that just completed
 963    * and refresh the input & output streams.
 964    */
 965   async resetFileLog() {
 966     // If we're writing an error log, dump extensions that may be causing problems.
 967     if (logManager.sawError) {
 968       await this._dumpAddons();
 969     }
 970     const logType = await logManager.resetFileLog();
 971     if (logType == logManager.ERROR_LOG_WRITTEN) {
 972       console.error(
 973         "Sync encountered an error - see about:sync-log for the log file."
 974       );
 975     }
 976     Svc.Obs.notify("weave:service:reset-file-log");
 977   },
 978
 979   /**
 980    * Handle HTTP response results or exceptions and set the appropriate
 981    * Status.* bits.
 982    *
 983    * This method also looks for "side-channel" warnings.
 984    */
 985   checkServerError(resp) {
 986     // In this case we were passed a resolved value of Resource#_doRequest.
 987     switch (resp.status) {
 988       case 400:
 989         if (resp == RESPONSE_OVER_QUOTA) {
 990           lazy.Status.sync = OVER_QUOTA;
 991         }
 992         break;
 993
 994       case 401:
 995         this.service.logout();
 996         this._log.info("Got 401 response; resetting clusterURL.");
 997         this.service.clusterURL = null;
 998
 999         let delay = 0;
1000         if (Svc.PrefBranch.getBoolPref("lastSyncReassigned", false)) {
1001           // We got a 401 in the middle of the previous sync, and we just got
1002           // another. Login must have succeeded in order for us to get here, so
1003           // the password should be correct.
1004           // This is likely to be an intermittent server issue, so back off and
1005           // give it time to recover.
1006           this._log.warn("Last sync also failed for 401. Delaying next sync.");
1007           delay = MINIMUM_BACKOFF_INTERVAL;
1008         } else {
1009           this._log.debug("New mid-sync 401 failure. Making a note.");
1010           Svc.PrefBranch.setBoolPref("lastSyncReassigned", true);
1011         }
1012         this._log.info("Attempting to schedule another sync.");
1013         this.service.scheduler.scheduleNextSync(delay, { why: "reschedule" });
1014         break;
1015
1016       case 500:
1017       case 502:
1018       case 503:
1019       case 504:
1020         lazy.Status.enforceBackoff = true;
1021         if (resp.status == 503 && resp.headers["retry-after"]) {
1022           let retryAfter = resp.headers["retry-after"];
1023           this._log.debug("Got Retry-After: " + retryAfter);
1024           if (this.service.isLoggedIn) {
1025             lazy.Status.sync = SERVER_MAINTENANCE;
1026           } else {
1027             lazy.Status.login = SERVER_MAINTENANCE;
1028           }
1029           Svc.Obs.notify(
1030             "weave:service:backoff:interval",
1031             parseInt(retryAfter, 10)
1032           );
1033         }
1034         break;
1035     }
1036
1037     // In this other case we were passed a rejection value.
1038     switch (resp.result) {
1039       case Cr.NS_ERROR_UNKNOWN_HOST:
1040       case Cr.NS_ERROR_CONNECTION_REFUSED:
1041       case Cr.NS_ERROR_NET_TIMEOUT:
1042       case Cr.NS_ERROR_NET_RESET:
1043       case Cr.NS_ERROR_NET_INTERRUPT:
1044       case Cr.NS_ERROR_PROXY_CONNECTION_REFUSED:
1045         // The constant says it's about login, but in fact it just
1046         // indicates general network error.
1047         if (this.service.isLoggedIn) {
1048           lazy.Status.sync = LOGIN_FAILED_NETWORK_ERROR;
1049         } else {
1050           lazy.Status.login = LOGIN_FAILED_NETWORK_ERROR;
1051         }
1052         break;
1053     }
1054   },
1055 };