michael@0: /* This Source Code Form is subject to the terms of the Mozilla Public
michael@0:  * License, v. 2.0. If a copy of the MPL was not distributed with this
michael@0:  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
michael@0: 
michael@0: this.EXPORTED_SYMBOLS = [
michael@0:   "ErrorHandler",
michael@0:   "SyncScheduler",
michael@0: ];
michael@0: 
michael@0: const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
michael@0: 
michael@0: Cu.import("resource://gre/modules/Log.jsm");
michael@0: Cu.import("resource://services-sync/constants.js");
michael@0: Cu.import("resource://services-sync/engines.js");
michael@0: Cu.import("resource://services-sync/util.js");
michael@0: Cu.import("resource://gre/modules/FileUtils.jsm");
michael@0: Cu.import("resource://gre/modules/NetUtil.jsm");
michael@0: 
michael@0: XPCOMUtils.defineLazyModuleGetter(this, "Status",
michael@0:                                   "resource://services-sync/status.js");
michael@0: 
michael@0: this.SyncScheduler = function SyncScheduler(service) {
michael@0:   this.service = service;
michael@0:   this.init();
michael@0: }
michael@0: SyncScheduler.prototype = {
michael@0:   _log: Log.repository.getLogger("Sync.SyncScheduler"),
michael@0: 
michael@0:   _fatalLoginStatus: [LOGIN_FAILED_NO_USERNAME,
michael@0:                       LOGIN_FAILED_NO_PASSWORD,
michael@0:                       LOGIN_FAILED_NO_PASSPHRASE,
michael@0:                       LOGIN_FAILED_INVALID_PASSPHRASE,
michael@0:                       LOGIN_FAILED_LOGIN_REJECTED],
michael@0: 
michael@0:   /**
michael@0:    * The nsITimer object that schedules the next sync. See scheduleNextSync().
michael@0:    */
michael@0:   syncTimer: null,
michael@0: 
michael@0:   setDefaults: function setDefaults() {
michael@0:     this._log.trace("Setting SyncScheduler policy values to defaults.");
michael@0: 
michael@0:     let service = Cc["@mozilla.org/weave/service;1"]
michael@0:                     .getService(Ci.nsISupports)
michael@0:                     .wrappedJSObject;
michael@0: 
michael@0:     let part = service.fxAccountsEnabled ? "fxa" : "sync11";
michael@0:     let prefSDInterval = "scheduler." + part + ".singleDeviceInterval";
michael@0:     this.singleDeviceInterval = Svc.Prefs.get(prefSDInterval) * 1000;
michael@0: 
michael@0:     this.idleInterval         = Svc.Prefs.get("scheduler.idleInterval")         * 1000;
michael@0:     this.activeInterval       = Svc.Prefs.get("scheduler.activeInterval")       * 1000;
michael@0:     this.immediateInterval    = Svc.Prefs.get("scheduler.immediateInterval")    * 1000;
michael@0:     this.eolInterval          = Svc.Prefs.get("scheduler.eolInterval")          * 1000;
michael@0: 
michael@0:     // A user is non-idle on startup by default.
michael@0:     this.idle = false;
michael@0: 
michael@0:     this.hasIncomingItems = false;
michael@0: 
michael@0:     this.clearSyncTriggers();
michael@0:   },
michael@0: 
michael@0:   // nextSync is in milliseconds, but prefs can't hold that much
michael@0:   get nextSync() Svc.Prefs.get("nextSync", 0) * 1000,
michael@0:   set nextSync(value) Svc.Prefs.set("nextSync", Math.floor(value / 1000)),
michael@0: 
michael@0:   get syncInterval() Svc.Prefs.get("syncInterval", this.singleDeviceInterval),
michael@0:   set syncInterval(value) Svc.Prefs.set("syncInterval", value),
michael@0: 
michael@0:   get syncThreshold() Svc.Prefs.get("syncThreshold", SINGLE_USER_THRESHOLD),
michael@0:   set syncThreshold(value) Svc.Prefs.set("syncThreshold", value),
michael@0: 
michael@0:   get globalScore() Svc.Prefs.get("globalScore", 0),
michael@0:   set globalScore(value) Svc.Prefs.set("globalScore", value),
michael@0: 
michael@0:   get numClients() Svc.Prefs.get("numClients", 0),
michael@0:   set numClients(value) Svc.Prefs.set("numClients", value),
michael@0: 
michael@0:   init: function init() {
michael@0:     this._log.level = Log.Level[Svc.Prefs.get("log.logger.service.main")];
michael@0:     this.setDefaults();
michael@0:     Svc.Obs.add("weave:engine:score:updated", this);
michael@0:     Svc.Obs.add("network:offline-status-changed", this);
michael@0:     Svc.Obs.add("weave:service:sync:start", this);
michael@0:     Svc.Obs.add("weave:service:sync:finish", this);
michael@0:     Svc.Obs.add("weave:engine:sync:finish", this);
michael@0:     Svc.Obs.add("weave:engine:sync:error", this);
michael@0:     Svc.Obs.add("weave:service:login:error", this);
michael@0:     Svc.Obs.add("weave:service:logout:finish", this);
michael@0:     Svc.Obs.add("weave:service:sync:error", this);
michael@0:     Svc.Obs.add("weave:service:backoff:interval", this);
michael@0:     Svc.Obs.add("weave:service:ready", this);
michael@0:     Svc.Obs.add("weave:engine:sync:applied", this);
michael@0:     Svc.Obs.add("weave:service:setup-complete", this);
michael@0:     Svc.Obs.add("weave:service:start-over", this);
michael@0:     Svc.Obs.add("FxA:hawk:backoff:interval", this);
michael@0: 
michael@0:     if (Status.checkSetup() == STATUS_OK) {
michael@0:       Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   observe: function observe(subject, topic, data) {
michael@0:     this._log.trace("Handling " + topic);
michael@0:     switch(topic) {
michael@0:       case "weave:engine:score:updated":
michael@0:         if (Status.login == LOGIN_SUCCEEDED) {
michael@0:           Utils.namedTimer(this.calculateScore, SCORE_UPDATE_DELAY, this,
michael@0:                            "_scoreTimer");
michael@0:         }
michael@0:         break;
michael@0:       case "network:offline-status-changed":
michael@0:         // Whether online or offline, we'll reschedule syncs
michael@0:         this._log.trace("Network offline status change: " + data);
michael@0:         this.checkSyncStatus();
michael@0:         break;
michael@0:       case "weave:service:sync:start":
michael@0:         // Clear out any potentially pending syncs now that we're syncing
michael@0:         this.clearSyncTriggers();
michael@0: 
michael@0:         // reset backoff info, if the server tells us to continue backing off,
michael@0:         // we'll handle that later
michael@0:         Status.resetBackoff();
michael@0: 
michael@0:         this.globalScore = 0;
michael@0:         break;
michael@0:       case "weave:service:sync:finish":
michael@0:         this.nextSync = 0;
michael@0:         this.adjustSyncInterval();
michael@0: 
michael@0:         if (Status.service == SYNC_FAILED_PARTIAL && this.requiresBackoff) {
michael@0:           this.requiresBackoff = false;
michael@0:           this.handleSyncError();
michael@0:           return;
michael@0:         }
michael@0: 
michael@0:         let sync_interval;
michael@0:         this._syncErrors = 0;
michael@0:         if (Status.sync == NO_SYNC_NODE_FOUND) {
michael@0:           this._log.trace("Scheduling a sync at interval NO_SYNC_NODE_FOUND.");
michael@0:           sync_interval = NO_SYNC_NODE_INTERVAL;
michael@0:         }
michael@0:         this.scheduleNextSync(sync_interval);
michael@0:         break;
michael@0:       case "weave:engine:sync:finish":
michael@0:         if (data == "clients") {
michael@0:           // Update the client mode because it might change what we sync.
michael@0:           this.updateClientMode();
michael@0:         }
michael@0:         break;
michael@0:       case "weave:engine:sync:error":
michael@0:         // `subject` is the exception thrown by an engine's sync() method.
michael@0:         let exception = subject;
michael@0:         if (exception.status >= 500 && exception.status <= 504) {
michael@0:           this.requiresBackoff = true;
michael@0:         }
michael@0:         break;
michael@0:       case "weave:service:login:error":
michael@0:         this.clearSyncTriggers();
michael@0: 
michael@0:         if (Status.login == MASTER_PASSWORD_LOCKED) {
michael@0:           // Try again later, just as if we threw an error... only without the
michael@0:           // error count.
michael@0:           this._log.debug("Couldn't log in: master password is locked.");
michael@0:           this._log.trace("Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL");
michael@0:           this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
michael@0:         } else if (this._fatalLoginStatus.indexOf(Status.login) == -1) {
michael@0:           // Not a fatal login error, just an intermittent network or server
michael@0:           // issue. Keep on syncin'.
michael@0:           this.checkSyncStatus();
michael@0:         }
michael@0:         break;
michael@0:       case "weave:service:logout:finish":
michael@0:         // Start or cancel the sync timer depending on if
michael@0:         // logged in or logged out
michael@0:         this.checkSyncStatus();
michael@0:         break;
michael@0:       case "weave:service:sync:error":
michael@0:         // There may be multiple clients but if the sync fails, client mode
michael@0:         // should still be updated so that the next sync has a correct interval.
michael@0:         this.updateClientMode();
michael@0:         this.adjustSyncInterval();
michael@0:         this.nextSync = 0;
michael@0:         this.handleSyncError();
michael@0:         break;
michael@0:       case "FxA:hawk:backoff:interval":
michael@0:       case "weave:service:backoff:interval":
michael@0:         let requested_interval = subject * 1000;
michael@0:         this._log.debug("Got backoff notification: " + requested_interval + "ms");
michael@0:         // Leave up to 25% more time for the back off.
michael@0:         let interval = requested_interval * (1 + Math.random() * 0.25);
michael@0:         Status.backoffInterval = interval;
michael@0:         Status.minimumNextSync = Date.now() + requested_interval;
michael@0:         this._log.debug("Fuzzed minimum next sync: " + Status.minimumNextSync);
michael@0:         break;
michael@0:       case "weave:service:ready":
michael@0:         // Applications can specify this preference if they want autoconnect
michael@0:         // to happen after a fixed delay.
michael@0:         let delay = Svc.Prefs.get("autoconnectDelay");
michael@0:         if (delay) {
michael@0:           this.delayedAutoConnect(delay);
michael@0:         }
michael@0:         break;
michael@0:       case "weave:engine:sync:applied":
michael@0:         let numItems = subject.succeeded;
michael@0:         this._log.trace("Engine " + data + " successfully applied " + numItems +
michael@0:                         " items.");
michael@0:         if (numItems) {
michael@0:           this.hasIncomingItems = true;
michael@0:         }
michael@0:         break;
michael@0:       case "weave:service:setup-complete":
michael@0:          Services.prefs.savePrefFile(null);
michael@0:          Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
michael@0:          break;
michael@0:       case "weave:service:start-over":
michael@0:          this.setDefaults();
michael@0:          try {
michael@0:            Svc.Idle.removeIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
michael@0:          } catch (ex if (ex.result == Cr.NS_ERROR_FAILURE)) {
michael@0:            // In all likelihood we didn't have an idle observer registered yet.
michael@0:            // It's all good.
michael@0:          }
michael@0:          break;
michael@0:       case "idle":
michael@0:         this._log.trace("We're idle.");
michael@0:         this.idle = true;
michael@0:         // Adjust the interval for future syncs. This won't actually have any
michael@0:         // effect until the next pending sync (which will happen soon since we
michael@0:         // were just active.)
michael@0:         this.adjustSyncInterval();
michael@0:         break;
michael@0:       case "active":
michael@0:         this._log.trace("Received notification that we're back from idle.");
michael@0:         this.idle = false;
michael@0:         Utils.namedTimer(function onBack() {
michael@0:           if (this.idle) {
michael@0:             this._log.trace("... and we're idle again. " +
michael@0:                             "Ignoring spurious back notification.");
michael@0:             return;
michael@0:           }
michael@0: 
michael@0:           this._log.trace("Genuine return from idle. Syncing.");
michael@0:           // Trigger a sync if we have multiple clients.
michael@0:           if (this.numClients > 1) {
michael@0:             this.scheduleNextSync(0);
michael@0:           }
michael@0:         }, IDLE_OBSERVER_BACK_DELAY, this, "idleDebouncerTimer");
michael@0:         break;
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   adjustSyncInterval: function adjustSyncInterval() {
michael@0:     if (Status.eol) {
michael@0:       this._log.debug("Server status is EOL; using eolInterval.");
michael@0:       this.syncInterval = this.eolInterval;
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     if (this.numClients <= 1) {
michael@0:       this._log.trace("Adjusting syncInterval to singleDeviceInterval.");
michael@0:       this.syncInterval = this.singleDeviceInterval;
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     // Only MULTI_DEVICE clients will enter this if statement
michael@0:     // since SINGLE_USER clients will be handled above.
michael@0:     if (this.idle) {
michael@0:       this._log.trace("Adjusting syncInterval to idleInterval.");
michael@0:       this.syncInterval = this.idleInterval;
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     if (this.hasIncomingItems) {
michael@0:       this._log.trace("Adjusting syncInterval to immediateInterval.");
michael@0:       this.hasIncomingItems = false;
michael@0:       this.syncInterval = this.immediateInterval;
michael@0:     } else {
michael@0:       this._log.trace("Adjusting syncInterval to activeInterval.");
michael@0:       this.syncInterval = this.activeInterval;
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   calculateScore: function calculateScore() {
michael@0:     let engines = [this.service.clientsEngine].concat(this.service.engineManager.getEnabled());
michael@0:     for (let i = 0;i < engines.length;i++) {
michael@0:       this._log.trace(engines[i].name + ": score: " + engines[i].score);
michael@0:       this.globalScore += engines[i].score;
michael@0:       engines[i]._tracker.resetScore();
michael@0:     }
michael@0: 
michael@0:     this._log.trace("Global score updated: " + this.globalScore);
michael@0:     this.checkSyncStatus();
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Process the locally stored clients list to figure out what mode to be in
michael@0:    */
michael@0:   updateClientMode: function updateClientMode() {
michael@0:     // Nothing to do if it's the same amount
michael@0:     let numClients = this.service.clientsEngine.stats.numClients;
michael@0:     if (this.numClients == numClients)
michael@0:       return;
michael@0: 
michael@0:     this._log.debug("Client count: " + this.numClients + " -> " + numClients);
michael@0:     this.numClients = numClients;
michael@0: 
michael@0:     if (numClients <= 1) {
michael@0:       this._log.trace("Adjusting syncThreshold to SINGLE_USER_THRESHOLD");
michael@0:       this.syncThreshold = SINGLE_USER_THRESHOLD;
michael@0:     } else {
michael@0:       this._log.trace("Adjusting syncThreshold to MULTI_DEVICE_THRESHOLD");
michael@0:       this.syncThreshold = MULTI_DEVICE_THRESHOLD;
michael@0:     }
michael@0:     this.adjustSyncInterval();
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Check if we should be syncing and schedule the next sync, if it's not scheduled
michael@0:    */
michael@0:   checkSyncStatus: function checkSyncStatus() {
michael@0:     // Should we be syncing now, if not, cancel any sync timers and return
michael@0:     // if we're in backoff, we'll schedule the next sync.
michael@0:     let ignore = [kSyncBackoffNotMet, kSyncMasterPasswordLocked];
michael@0:     let skip = this.service._checkSync(ignore);
michael@0:     this._log.trace("_checkSync returned \"" + skip + "\".");
michael@0:     if (skip) {
michael@0:       this.clearSyncTriggers();
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     // Only set the wait time to 0 if we need to sync right away
michael@0:     let wait;
michael@0:     if (this.globalScore > this.syncThreshold) {
michael@0:       this._log.debug("Global Score threshold hit, triggering sync.");
michael@0:       wait = 0;
michael@0:     }
michael@0:     this.scheduleNextSync(wait);
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Call sync() if Master Password is not locked.
michael@0:    *
michael@0:    * Otherwise, reschedule a sync for later.
michael@0:    */
michael@0:   syncIfMPUnlocked: function syncIfMPUnlocked() {
michael@0:     // No point if we got kicked out by the master password dialog.
michael@0:     if (Status.login == MASTER_PASSWORD_LOCKED &&
michael@0:         Utils.mpLocked()) {
michael@0:       this._log.debug("Not initiating sync: Login status is " + Status.login);
michael@0: 
michael@0:       // If we're not syncing now, we need to schedule the next one.
michael@0:       this._log.trace("Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL");
michael@0:       this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     Utils.nextTick(this.service.sync, this.service);
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Set a timer for the next sync
michael@0:    */
michael@0:   scheduleNextSync: function scheduleNextSync(interval) {
michael@0:     // If no interval was specified, use the current sync interval.
michael@0:     if (interval == null) {
michael@0:       interval = this.syncInterval;
michael@0:     }
michael@0: 
michael@0:     // Ensure the interval is set to no less than the backoff.
michael@0:     if (Status.backoffInterval && interval < Status.backoffInterval) {
michael@0:       this._log.trace("Requested interval " + interval +
michael@0:                       " ms is smaller than the backoff interval. " +
michael@0:                       "Using backoff interval " +
michael@0:                       Status.backoffInterval + " ms instead.");
michael@0:       interval = Status.backoffInterval;
michael@0:     }
michael@0: 
michael@0:     if (this.nextSync != 0) {
michael@0:       // There's already a sync scheduled. Don't reschedule if there's already
michael@0:       // a timer scheduled for sooner than requested.
michael@0:       let currentInterval = this.nextSync - Date.now();
michael@0:       this._log.trace("There's already a sync scheduled in " +
michael@0:                       currentInterval + " ms.");
michael@0:       if (currentInterval < interval && this.syncTimer) {
michael@0:         this._log.trace("Ignoring scheduling request for next sync in " +
michael@0:                         interval + " ms.");
michael@0:         return;
michael@0:       }
michael@0:     }
michael@0: 
michael@0:     // Start the sync right away if we're already late.
michael@0:     if (interval <= 0) {
michael@0:       this._log.trace("Requested sync should happen right away.");
michael@0:       this.syncIfMPUnlocked();
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     this._log.debug("Next sync in " + interval + " ms.");
michael@0:     Utils.namedTimer(this.syncIfMPUnlocked, interval, this, "syncTimer");
michael@0: 
michael@0:     // Save the next sync time in-case sync is disabled (logout/offline/etc.)
michael@0:     this.nextSync = Date.now() + interval;
michael@0:   },
michael@0: 
michael@0: 
michael@0:   /**
michael@0:    * Incorporates the backoff/retry logic used in error handling and elective
michael@0:    * non-syncing.
michael@0:    */
michael@0:   scheduleAtInterval: function scheduleAtInterval(minimumInterval) {
michael@0:     let interval = Utils.calculateBackoff(this._syncErrors,
michael@0:                                           MINIMUM_BACKOFF_INTERVAL,
michael@0:                                           Status.backoffInterval);
michael@0:     if (minimumInterval) {
michael@0:       interval = Math.max(minimumInterval, interval);
michael@0:     }
michael@0: 
michael@0:     this._log.debug("Starting client-initiated backoff. Next sync in " +
michael@0:                     interval + " ms.");
michael@0:     this.scheduleNextSync(interval);
michael@0:   },
michael@0: 
michael@0:  /**
michael@0:   * Automatically start syncing after the given delay (in seconds).
michael@0:   *
michael@0:   * Applications can define the `services.sync.autoconnectDelay` preference
michael@0:   * to have this called automatically during start-up with the pref value as
michael@0:   * the argument. Alternatively, they can call it themselves to control when
michael@0:   * Sync should first start to sync.
michael@0:   */
michael@0:   delayedAutoConnect: function delayedAutoConnect(delay) {
michael@0:     if (this.service._checkSetup() == STATUS_OK) {
michael@0:       Utils.namedTimer(this.autoConnect, delay * 1000, this, "_autoTimer");
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   autoConnect: function autoConnect() {
michael@0:     if (this.service._checkSetup() == STATUS_OK && !this.service._checkSync()) {
michael@0:       // Schedule a sync based on when a previous sync was scheduled.
michael@0:       // scheduleNextSync() will do the right thing if that time lies in
michael@0:       // the past.
michael@0:       this.scheduleNextSync(this.nextSync - Date.now());
michael@0:     }
michael@0: 
michael@0:     // Once autoConnect is called we no longer need _autoTimer.
michael@0:     if (this._autoTimer) {
michael@0:       this._autoTimer.clear();
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   _syncErrors: 0,
michael@0:   /**
michael@0:    * Deal with sync errors appropriately
michael@0:    */
michael@0:   handleSyncError: function handleSyncError() {
michael@0:     this._log.trace("In handleSyncError. Error count: " + this._syncErrors);
michael@0:     this._syncErrors++;
michael@0: 
michael@0:     // Do nothing on the first couple of failures, if we're not in
michael@0:     // backoff due to 5xx errors.
michael@0:     if (!Status.enforceBackoff) {
michael@0:       if (this._syncErrors < MAX_ERROR_COUNT_BEFORE_BACKOFF) {
michael@0:         this.scheduleNextSync();
michael@0:         return;
michael@0:       }
michael@0:       this._log.debug("Sync error count has exceeded " +
michael@0:                       MAX_ERROR_COUNT_BEFORE_BACKOFF + "; enforcing backoff.");
michael@0:       Status.enforceBackoff = true;
michael@0:     }
michael@0: 
michael@0:     this.scheduleAtInterval();
michael@0:   },
michael@0: 
michael@0: 
michael@0:   /**
michael@0:    * Remove any timers/observers that might trigger a sync
michael@0:    */
michael@0:   clearSyncTriggers: function clearSyncTriggers() {
michael@0:     this._log.debug("Clearing sync triggers and the global score.");
michael@0:     this.globalScore = this.nextSync = 0;
michael@0: 
michael@0:     // Clear out any scheduled syncs
michael@0:     if (this.syncTimer)
michael@0:       this.syncTimer.clear();
michael@0:   },
michael@0: };
michael@0: 
michael@0: const LOG_PREFIX_SUCCESS = "success-";
michael@0: const LOG_PREFIX_ERROR   = "error-";
michael@0: 
michael@0: this.ErrorHandler = function ErrorHandler(service) {
michael@0:   this.service = service;
michael@0:   this.init();
michael@0: }
michael@0: ErrorHandler.prototype = {
michael@0:   MINIMUM_ALERT_INTERVAL_MSEC: 604800000,   // One week.
michael@0: 
michael@0:   /**
michael@0:    * Flag that turns on error reporting for all errors, incl. network errors.
michael@0:    */
michael@0:   dontIgnoreErrors: false,
michael@0: 
michael@0:   /**
michael@0:    * Flag that indicates if we have already reported a prolonged failure.
michael@0:    * Once set, we don't report it again, meaning this error is only reported
michael@0:    * one per run.
michael@0:    */
michael@0:   didReportProlongedError: false,
michael@0: 
michael@0:   init: function init() {
michael@0:     Svc.Obs.add("weave:engine:sync:applied", this);
michael@0:     Svc.Obs.add("weave:engine:sync:error", this);
michael@0:     Svc.Obs.add("weave:service:login:error", this);
michael@0:     Svc.Obs.add("weave:service:sync:error", this);
michael@0:     Svc.Obs.add("weave:service:sync:finish", this);
michael@0: 
michael@0:     this.initLogs();
michael@0:   },
michael@0: 
michael@0:   initLogs: function initLogs() {
michael@0:     this._log = Log.repository.getLogger("Sync.ErrorHandler");
michael@0:     this._log.level = Log.Level[Svc.Prefs.get("log.logger.service.main")];
michael@0:     this._cleaningUpFileLogs = false;
michael@0: 
michael@0:     let root = Log.repository.getLogger("Sync");
michael@0:     root.level = Log.Level[Svc.Prefs.get("log.rootLogger")];
michael@0: 
michael@0:     let formatter = new Log.BasicFormatter();
michael@0:     let capp = new Log.ConsoleAppender(formatter);
michael@0:     capp.level = Log.Level[Svc.Prefs.get("log.appender.console")];
michael@0:     root.addAppender(capp);
michael@0: 
michael@0:     let dapp = new Log.DumpAppender(formatter);
michael@0:     dapp.level = Log.Level[Svc.Prefs.get("log.appender.dump")];
michael@0:     root.addAppender(dapp);
michael@0: 
michael@0:     let fapp = this._logAppender = new Log.StorageStreamAppender(formatter);
michael@0:     fapp.level = Log.Level[Svc.Prefs.get("log.appender.file.level")];
michael@0:     root.addAppender(fapp);
michael@0: 
michael@0:     // Arrange for the FxA logs to also go to our file.
michael@0:     Log.repository.getLogger("FirefoxAccounts").addAppender(fapp);
michael@0:   },
michael@0: 
michael@0:   observe: function observe(subject, topic, data) {
michael@0:     this._log.trace("Handling " + topic);
michael@0:     switch(topic) {
michael@0:       case "weave:engine:sync:applied":
michael@0:         if (subject.newFailed) {
michael@0:           // An engine isn't able to apply one or more incoming records.
michael@0:           // We don't fail hard on this, but it usually indicates a bug,
michael@0:           // so for now treat it as sync error (c.f. Service._syncEngine())
michael@0:           Status.engines = [data, ENGINE_APPLY_FAIL];
michael@0:           this._log.debug(data + " failed to apply some records.");
michael@0:         }
michael@0:         break;
michael@0:       case "weave:engine:sync:error":
michael@0:         let exception = subject;  // exception thrown by engine's sync() method
michael@0:         let engine_name = data;   // engine name that threw the exception
michael@0: 
michael@0:         this.checkServerError(exception);
michael@0: 
michael@0:         Status.engines = [engine_name, exception.failureCode || ENGINE_UNKNOWN_FAIL];
michael@0:         this._log.debug(engine_name + " failed: " + Utils.exceptionStr(exception));
michael@0:         break;
michael@0:       case "weave:service:login:error":
michael@0:         this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
michael@0:                           LOG_PREFIX_ERROR);
michael@0: 
michael@0:         if (this.shouldReportError()) {
michael@0:           this.notifyOnNextTick("weave:ui:login:error");
michael@0:         } else {
michael@0:           this.notifyOnNextTick("weave:ui:clear-error");
michael@0:         }
michael@0: 
michael@0:         this.dontIgnoreErrors = false;
michael@0:         break;
michael@0:       case "weave:service:sync:error":
michael@0:         if (Status.sync == CREDENTIALS_CHANGED) {
michael@0:           this.service.logout();
michael@0:         }
michael@0: 
michael@0:         this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
michael@0:                           LOG_PREFIX_ERROR);
michael@0: 
michael@0:         if (this.shouldReportError()) {
michael@0:           this.notifyOnNextTick("weave:ui:sync:error");
michael@0:         } else {
michael@0:           this.notifyOnNextTick("weave:ui:sync:finish");
michael@0:         }
michael@0: 
michael@0:         this.dontIgnoreErrors = false;
michael@0:         break;
michael@0:       case "weave:service:sync:finish":
michael@0:         this._log.trace("Status.service is " + Status.service);
michael@0: 
michael@0:         // Check both of these status codes: in the event of a failure in one
michael@0:         // engine, Status.service will be SYNC_FAILED_PARTIAL despite
michael@0:         // Status.sync being SYNC_SUCCEEDED.
michael@0:         // *facepalm*
michael@0:         if (Status.sync    == SYNC_SUCCEEDED &&
michael@0:             Status.service == STATUS_OK) {
michael@0:           // Great. Let's clear our mid-sync 401 note.
michael@0:           this._log.trace("Clearing lastSyncReassigned.");
michael@0:           Svc.Prefs.reset("lastSyncReassigned");
michael@0:         }
michael@0: 
michael@0:         if (Status.service == SYNC_FAILED_PARTIAL) {
michael@0:           this._log.debug("Some engines did not sync correctly.");
michael@0:           this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
michael@0:                             LOG_PREFIX_ERROR);
michael@0: 
michael@0:           if (this.shouldReportError()) {
michael@0:             this.dontIgnoreErrors = false;
michael@0:             this.notifyOnNextTick("weave:ui:sync:error");
michael@0:             break;
michael@0:           }
michael@0:         } else {
michael@0:           this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnSuccess"),
michael@0:                             LOG_PREFIX_SUCCESS);
michael@0:         }
michael@0:         this.dontIgnoreErrors = false;
michael@0:         this.notifyOnNextTick("weave:ui:sync:finish");
michael@0:         break;
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   notifyOnNextTick: function notifyOnNextTick(topic) {
michael@0:     Utils.nextTick(function() {
michael@0:       this._log.trace("Notifying " + topic +
michael@0:                       ". Status.login is " + Status.login +
michael@0:                       ". Status.sync is " + Status.sync);
michael@0:       Svc.Obs.notify(topic);
michael@0:     }, this);
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Trigger a sync and don't muffle any errors, particularly network errors.
michael@0:    */
michael@0:   syncAndReportErrors: function syncAndReportErrors() {
michael@0:     this._log.debug("Beginning user-triggered sync.");
michael@0: 
michael@0:     this.dontIgnoreErrors = true;
michael@0:     Utils.nextTick(this.service.sync, this.service);
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Finds all logs older than maxErrorAge and deletes them without tying up I/O.
michael@0:    */
michael@0:   cleanupLogs: function cleanupLogs() {
michael@0:     let direntries = FileUtils.getDir("ProfD", ["weave", "logs"]).directoryEntries;
michael@0:     let oldLogs = [];
michael@0:     let index = 0;
michael@0:     let threshold = Date.now() - 1000 * Svc.Prefs.get("log.appender.file.maxErrorAge");
michael@0: 
michael@0:     this._log.debug("Log cleanup threshold time: " + threshold);
michael@0:     while (direntries.hasMoreElements()) {
michael@0:       let logFile = direntries.getNext().QueryInterface(Ci.nsIFile);
michael@0:       if (logFile.lastModifiedTime < threshold) {
michael@0:         this._log.trace(" > Noting " + logFile.leafName +
michael@0:                         " for cleanup (" + logFile.lastModifiedTime + ")");
michael@0:         oldLogs.push(logFile);
michael@0:       }
michael@0:     }
michael@0: 
michael@0:     // Deletes a file from oldLogs each tick until there are none left.
michael@0:     let errorHandler = this;
michael@0:     function deleteFile() {
michael@0:       if (index >= oldLogs.length) {
michael@0:         errorHandler._log.debug("Done deleting files.");
michael@0:         errorHandler._cleaningUpFileLogs = false;
michael@0:         Svc.Obs.notify("weave:service:cleanup-logs");
michael@0:         return;
michael@0:       }
michael@0:       try {
michael@0:         let file = oldLogs[index];
michael@0:         file.remove(false);
michael@0:         errorHandler._log.trace("Deleted " + file.leafName + ".");
michael@0:       } catch (ex) {
michael@0:         errorHandler._log._debug("Encountered error trying to clean up old log file '"
michael@0:                                  + oldLogs[index].leafName + "':"
michael@0:                                  + Utils.exceptionStr(ex));
michael@0:       }
michael@0:       index++;
michael@0:       Utils.nextTick(deleteFile);
michael@0:     }
michael@0: 
michael@0:     if (oldLogs.length > 0) {
michael@0:       this._cleaningUpFileLogs = true;
michael@0:       Utils.nextTick(deleteFile);
michael@0:     } else {
michael@0:       this._log.debug("No logs to clean up.");
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Generate a log file for the sync that just completed
michael@0:    * and refresh the input & output streams.
michael@0:    *
michael@0:    * @param flushToFile
michael@0:    *        the log file to be flushed/reset
michael@0:    *
michael@0:    * @param filenamePrefix
michael@0:    *        a value of either LOG_PREFIX_SUCCESS or LOG_PREFIX_ERROR
michael@0:    *        to be used as the log filename prefix
michael@0:    */
michael@0:   resetFileLog: function resetFileLog(flushToFile, filenamePrefix) {
michael@0:     let inStream = this._logAppender.getInputStream();
michael@0:     this._logAppender.reset();
michael@0:     if (flushToFile && inStream) {
michael@0:       this._log.debug("Flushing file log.");
michael@0:       try {
michael@0:         let filename = filenamePrefix + Date.now() + ".txt";
michael@0:         let file = FileUtils.getFile("ProfD", ["weave", "logs", filename]);
michael@0:         let outStream = FileUtils.openFileOutputStream(file);
michael@0: 
michael@0:         this._log.trace("Beginning stream copy to " + file.leafName + ": " +
michael@0:                         Date.now());
michael@0:         NetUtil.asyncCopy(inStream, outStream, function onCopyComplete() {
michael@0:           this._log.trace("onCopyComplete: " + Date.now());
michael@0:           this._log.trace("Output file timestamp: " + file.lastModifiedTime);
michael@0:           Svc.Obs.notify("weave:service:reset-file-log");
michael@0:           this._log.trace("Notified: " + Date.now());
michael@0:           if (filenamePrefix == LOG_PREFIX_ERROR &&
michael@0:               !this._cleaningUpFileLogs) {
michael@0:             this._log.trace("Scheduling cleanup.");
michael@0:             Utils.nextTick(this.cleanupLogs, this);
michael@0:           }
michael@0:         }.bind(this));
michael@0:       } catch (ex) {
michael@0:         Svc.Obs.notify("weave:service:reset-file-log");
michael@0:       }
michael@0:     } else {
michael@0:       Svc.Obs.notify("weave:service:reset-file-log");
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Translates server error codes to meaningful strings.
michael@0:    *
michael@0:    * @param code
michael@0:    *        server error code as an integer
michael@0:    */
michael@0:   errorStr: function errorStr(code) {
michael@0:     switch (code.toString()) {
michael@0:     case "1":
michael@0:       return "illegal-method";
michael@0:     case "2":
michael@0:       return "invalid-captcha";
michael@0:     case "3":
michael@0:       return "invalid-username";
michael@0:     case "4":
michael@0:       return "cannot-overwrite-resource";
michael@0:     case "5":
michael@0:       return "userid-mismatch";
michael@0:     case "6":
michael@0:       return "json-parse-failure";
michael@0:     case "7":
michael@0:       return "invalid-password";
michael@0:     case "8":
michael@0:       return "invalid-record";
michael@0:     case "9":
michael@0:       return "weak-password";
michael@0:     default:
michael@0:       return "generic-server-error";
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   shouldReportError: function shouldReportError() {
michael@0:     if (Status.login == MASTER_PASSWORD_LOCKED) {
michael@0:       this._log.trace("shouldReportError: false (master password locked).");
michael@0:       return false;
michael@0:     }
michael@0: 
michael@0:     if (this.dontIgnoreErrors) {
michael@0:       return true;
michael@0:     }
michael@0: 
michael@0:     let lastSync = Svc.Prefs.get("lastSync");
michael@0:     if (lastSync && ((Date.now() - Date.parse(lastSync)) >
michael@0:         Svc.Prefs.get("errorhandler.networkFailureReportTimeout") * 1000)) {
michael@0:       Status.sync = PROLONGED_SYNC_FAILURE;
michael@0:       if (this.didReportProlongedError) {
michael@0:         this._log.trace("shouldReportError: false (prolonged sync failure, but" +
michael@0:                         " we've already reported it).");
michael@0:         return false;
michael@0:       }
michael@0:       this._log.trace("shouldReportError: true (first prolonged sync failure).");
michael@0:       this.didReportProlongedError = true;
michael@0:       return true;
michael@0:     }
michael@0: 
michael@0:     // We got a 401 mid-sync. Wait for the next sync before actually handling
michael@0:     // an error. This assumes that we'll get a 401 again on a login fetch in
michael@0:     // order to report the error.
michael@0:     if (!this.service.clusterURL) {
michael@0:       this._log.trace("shouldReportError: false (no cluster URL; " +
michael@0:                       "possible node reassignment).");
michael@0:       return false;
michael@0:     }
michael@0: 
michael@0:     return ([Status.login, Status.sync].indexOf(SERVER_MAINTENANCE) == -1 &&
michael@0:             [Status.login, Status.sync].indexOf(LOGIN_FAILED_NETWORK_ERROR) == -1);
michael@0:   },
michael@0: 
michael@0:   get currentAlertMode() {
michael@0:     return Svc.Prefs.get("errorhandler.alert.mode");
michael@0:   },
michael@0: 
michael@0:   set currentAlertMode(str) {
michael@0:     return Svc.Prefs.set("errorhandler.alert.mode", str);
michael@0:   },
michael@0: 
michael@0:   get earliestNextAlert() {
michael@0:     return Svc.Prefs.get("errorhandler.alert.earliestNext", 0) * 1000;
michael@0:   },
michael@0: 
michael@0:   set earliestNextAlert(msec) {
michael@0:     return Svc.Prefs.set("errorhandler.alert.earliestNext", msec / 1000);
michael@0:   },
michael@0: 
michael@0:   clearServerAlerts: function () {
michael@0:     // If we have any outstanding alerts, apparently they're no longer relevant.
michael@0:     Svc.Prefs.resetBranch("errorhandler.alert");
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * X-Weave-Alert headers can include a JSON object:
michael@0:    *
michael@0:    *   {
michael@0:    *    "code":    // One of "hard-eol", "soft-eol".
michael@0:    *    "url":     // For "Learn more" link.
michael@0:    *    "message": // Logged in Sync logs.
michael@0:    *   }
michael@0:    */
michael@0:   handleServerAlert: function (xwa) {
michael@0:     if (!xwa.code) {
michael@0:       this._log.warn("Got structured X-Weave-Alert, but no alert code.");
michael@0:       return;
michael@0:     }
michael@0: 
michael@0:     switch (xwa.code) {
michael@0:       // Gently and occasionally notify the user that this service will be
michael@0:       // shutting down.
michael@0:       case "soft-eol":
michael@0:         // Fall through.
michael@0: 
michael@0:       // Tell the user that this service has shut down, and drop our syncing
michael@0:       // frequency dramatically.
michael@0:       case "hard-eol":
michael@0:         // Note that both of these alerts should be subservient to future "sign
michael@0:         // in with your Firefox Account" storage alerts.
michael@0:         if ((this.currentAlertMode != xwa.code) ||
michael@0:             (this.earliestNextAlert < Date.now())) {
michael@0:           Utils.nextTick(function() {
michael@0:             Svc.Obs.notify("weave:eol", xwa);
michael@0:           }, this);
michael@0:           this._log.error("X-Weave-Alert: " + xwa.code + ": " + xwa.message);
michael@0:           this.earliestNextAlert = Date.now() + this.MINIMUM_ALERT_INTERVAL_MSEC;
michael@0:           this.currentAlertMode = xwa.code;
michael@0:         }
michael@0:         break;
michael@0:       default:
michael@0:         this._log.debug("Got unexpected X-Weave-Alert code: " + xwa.code);
michael@0:     }
michael@0:   },
michael@0: 
michael@0:   /**
michael@0:    * Handle HTTP response results or exceptions and set the appropriate
michael@0:    * Status.* bits.
michael@0:    *
michael@0:    * This method also looks for "side-channel" warnings.
michael@0:    */
michael@0:   checkServerError: function (resp) {
michael@0:     switch (resp.status) {
michael@0:       case 200:
michael@0:       case 404:
michael@0:       case 513:
michael@0:         let xwa = resp.headers['x-weave-alert'];
michael@0: 
michael@0:         // Only process machine-readable alerts.
michael@0:         if (!xwa || !xwa.startsWith("{")) {
michael@0:           this.clearServerAlerts();
michael@0:           return;
michael@0:         }
michael@0: 
michael@0:         try {
michael@0:           xwa = JSON.parse(xwa);
michael@0:         } catch (ex) {
michael@0:           this._log.warn("Malformed X-Weave-Alert from server: " + xwa);
michael@0:           return;
michael@0:         }
michael@0: 
michael@0:         this.handleServerAlert(xwa);
michael@0:         break;
michael@0: 
michael@0:       case 400:
michael@0:         if (resp == RESPONSE_OVER_QUOTA) {
michael@0:           Status.sync = OVER_QUOTA;
michael@0:         }
michael@0:         break;
michael@0: 
michael@0:       case 401:
michael@0:         this.service.logout();
michael@0:         this._log.info("Got 401 response; resetting clusterURL.");
michael@0:         Svc.Prefs.reset("clusterURL");
michael@0: 
michael@0:         let delay = 0;
michael@0:         if (Svc.Prefs.get("lastSyncReassigned")) {
michael@0:           // We got a 401 in the middle of the previous sync, and we just got
michael@0:           // another. Login must have succeeded in order for us to get here, so
michael@0:           // the password should be correct.
michael@0:           // This is likely to be an intermittent server issue, so back off and
michael@0:           // give it time to recover.
michael@0:           this._log.warn("Last sync also failed for 401. Delaying next sync.");
michael@0:           delay = MINIMUM_BACKOFF_INTERVAL;
michael@0:         } else {
michael@0:           this._log.debug("New mid-sync 401 failure. Making a note.");
michael@0:           Svc.Prefs.set("lastSyncReassigned", true);
michael@0:         }
michael@0:         this._log.info("Attempting to schedule another sync.");
michael@0:         this.service.scheduler.scheduleNextSync(delay);
michael@0:         break;
michael@0: 
michael@0:       case 500:
michael@0:       case 502:
michael@0:       case 503:
michael@0:       case 504:
michael@0:         Status.enforceBackoff = true;
michael@0:         if (resp.status == 503 && resp.headers["retry-after"]) {
michael@0:           let retryAfter = resp.headers["retry-after"];
michael@0:           this._log.debug("Got Retry-After: " + retryAfter);
michael@0:           if (this.service.isLoggedIn) {
michael@0:             Status.sync = SERVER_MAINTENANCE;
michael@0:           } else {
michael@0:             Status.login = SERVER_MAINTENANCE;
michael@0:           }
michael@0:           Svc.Obs.notify("weave:service:backoff:interval",
michael@0:                          parseInt(retryAfter, 10));
michael@0:         }
michael@0:         break;
michael@0:     }
michael@0: 
michael@0:     switch (resp.result) {
michael@0:       case Cr.NS_ERROR_UNKNOWN_HOST:
michael@0:       case Cr.NS_ERROR_CONNECTION_REFUSED:
michael@0:       case Cr.NS_ERROR_NET_TIMEOUT:
michael@0:       case Cr.NS_ERROR_NET_RESET:
michael@0:       case Cr.NS_ERROR_NET_INTERRUPT:
michael@0:       case Cr.NS_ERROR_PROXY_CONNECTION_REFUSED:
michael@0:         // The constant says it's about login, but in fact it just
michael@0:         // indicates general network error.
michael@0:         if (this.service.isLoggedIn) {
michael@0:           Status.sync = LOGIN_FAILED_NETWORK_ERROR;
michael@0:         } else {
michael@0:           Status.login = LOGIN_FAILED_NETWORK_ERROR;
michael@0:         }
michael@0:         break;
michael@0:     }
michael@0:   },
michael@0: };