/services/sync/modules/policies.js

  1/* ***** BEGIN LICENSE BLOCK *****
  2 * Version: MPL 1.1/GPL 2.0/LGPL 2.1
  3 *
  4 * The contents of this file are subject to the Mozilla Public License Version
  5 * 1.1 (the "License"); you may not use this file except in compliance with
  6 * the License. You may obtain a copy of the License at
  7 * http://www.mozilla.org/MPL/
  8 *
  9 * Software distributed under the License is distributed on an "AS IS" basis,
 10 * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
 11 * for the specific language governing rights and limitations under the
 12 * License.
 13 *
 14 * The Original Code is Firefox Sync.
 15 *
 16 * The Initial Developer of the Original Code is
 17 * the Mozilla Foundation.
 18 * Portions created by the Initial Developer are Copyright (C) 2011
 19 * the Initial Developer. All Rights Reserved.
 20 *
 21 * Contributor(s):
 22 *  Marina Samuel <msamuel@mozilla.com>
 23 *  Philipp von Weitershausen <philipp@weitershausen.de>
 24 *  Chenxia Liu <liuche@mozilla.com>
 25 *  Richard Newman <rnewman@mozilla.com>
 26 *
 27 * Alternatively, the contents of this file may be used under the terms of
 28 * either the GNU General Public License Version 2 or later (the "GPL"), or
 29 * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
 30 * in which case the provisions of the GPL or the LGPL are applicable instead
 31 * of those above. If you wish to allow use of your version of this file only
 32 * under the terms of either the GPL or the LGPL, and not to allow others to
 33 * use your version of this file under the terms of the MPL, indicate your
 34 * decision by deleting the provisions above and replace them with the notice
 35 * and other provisions required by the GPL or the LGPL. If you do not delete
 36 * the provisions above, a recipient may use your version of this file under
 37 * the terms of any one of the MPL, the GPL or the LGPL.
 38 *
 39 * ***** END LICENSE BLOCK ***** */
 40
 41const EXPORTED_SYMBOLS = ["SyncScheduler",
 42                          "ErrorHandler",
 43                          "SendCredentialsController"];
 44
 45const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
 46
 47Cu.import("resource://services-sync/constants.js");
 48Cu.import("resource://services-sync/log4moz.js");
 49Cu.import("resource://services-sync/util.js");
 50Cu.import("resource://services-sync/engines.js");
 51Cu.import("resource://services-sync/engines/clients.js");
 52Cu.import("resource://services-sync/status.js");
 53
 54Cu.import("resource://services-sync/main.js");    // So we can get to Service for callbacks.
 55
 56let SyncScheduler = {
 57  _log: Log4Moz.repository.getLogger("Sync.SyncScheduler"),
 58
 59  _fatalLoginStatus: [LOGIN_FAILED_NO_USERNAME,
 60                      LOGIN_FAILED_NO_PASSWORD,
 61                      LOGIN_FAILED_NO_PASSPHRASE,
 62                      LOGIN_FAILED_INVALID_PASSPHRASE,
 63                      LOGIN_FAILED_LOGIN_REJECTED],
 64
 65  /**
 66   * The nsITimer object that schedules the next sync. See scheduleNextSync().
 67   */
 68  syncTimer: null,
 69
 70  setDefaults: function setDefaults() {
 71    this._log.trace("Setting SyncScheduler policy values to defaults.");
 72
 73    this.singleDeviceInterval = Svc.Prefs.get("scheduler.singleDeviceInterval") * 1000;
 74    this.idleInterval         = Svc.Prefs.get("scheduler.idleInterval")         * 1000;
 75    this.activeInterval       = Svc.Prefs.get("scheduler.activeInterval")       * 1000;
 76    this.immediateInterval    = Svc.Prefs.get("scheduler.immediateInterval")    * 1000;
 77
 78    // A user is non-idle on startup by default.
 79    this.idle = false;
 80
 81    this.hasIncomingItems = false;
 82
 83    this.clearSyncTriggers();
 84  },
 85
 86  // nextSync is in milliseconds, but prefs can't hold that much
 87  get nextSync() Svc.Prefs.get("nextSync", 0) * 1000,
 88  set nextSync(value) Svc.Prefs.set("nextSync", Math.floor(value / 1000)),
 89
 90  get syncInterval() Svc.Prefs.get("syncInterval", this.singleDeviceInterval),
 91  set syncInterval(value) Svc.Prefs.set("syncInterval", value),
 92
 93  get syncThreshold() Svc.Prefs.get("syncThreshold", SINGLE_USER_THRESHOLD),
 94  set syncThreshold(value) Svc.Prefs.set("syncThreshold", value),
 95
 96  get globalScore() Svc.Prefs.get("globalScore", 0),
 97  set globalScore(value) Svc.Prefs.set("globalScore", value),
 98
 99  get numClients() Svc.Prefs.get("numClients", 0),
100  set numClients(value) Svc.Prefs.set("numClients", value),
101
102  init: function init() {
103    this._log.level = Log4Moz.Level[Svc.Prefs.get("log.logger.service.main")];
104    this.setDefaults();
105    Svc.Obs.add("weave:engine:score:updated", this);
106    Svc.Obs.add("network:offline-status-changed", this);
107    Svc.Obs.add("weave:service:sync:start", this);
108    Svc.Obs.add("weave:service:sync:finish", this);
109    Svc.Obs.add("weave:engine:sync:finish", this);
110    Svc.Obs.add("weave:engine:sync:error", this);
111    Svc.Obs.add("weave:service:login:error", this);
112    Svc.Obs.add("weave:service:logout:finish", this);
113    Svc.Obs.add("weave:service:sync:error", this);
114    Svc.Obs.add("weave:service:backoff:interval", this);
115    Svc.Obs.add("weave:service:ready", this);
116    Svc.Obs.add("weave:engine:sync:applied", this);
117    Svc.Obs.add("weave:service:setup-complete", this);
118    Svc.Obs.add("weave:service:start-over", this);
119
120    if (Status.checkSetup() == STATUS_OK) {
121      Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
122    }
123  },
124
125  observe: function observe(subject, topic, data) {
126    this._log.trace("Handling " + topic);
127    switch(topic) {
128      case "weave:engine:score:updated":
129        if (Status.login == LOGIN_SUCCEEDED) {
130          Utils.namedTimer(this.calculateScore, SCORE_UPDATE_DELAY, this,
131                           "_scoreTimer");
132        }
133        break;
134      case "network:offline-status-changed":
135        // Whether online or offline, we'll reschedule syncs
136        this._log.trace("Network offline status change: " + data);
137        this.checkSyncStatus();
138        break;
139      case "weave:service:sync:start":
140        // Clear out any potentially pending syncs now that we're syncing
141        this.clearSyncTriggers();
142
143        // reset backoff info, if the server tells us to continue backing off,
144        // we'll handle that later
145        Status.resetBackoff();
146
147        this.globalScore = 0;
148        break;
149      case "weave:service:sync:finish":
150        this.nextSync = 0;
151        this.adjustSyncInterval();
152
153        if (Status.service == SYNC_FAILED_PARTIAL && this.requiresBackoff) {
154          this.requiresBackoff = false;
155          this.handleSyncError();
156          return;
157        }
158
159        let sync_interval;
160        this._syncErrors = 0;
161        if (Status.sync == NO_SYNC_NODE_FOUND) {
162          this._log.trace("Scheduling a sync at interval NO_SYNC_NODE_FOUND.");
163          sync_interval = NO_SYNC_NODE_INTERVAL;
164        }
165        this.scheduleNextSync(sync_interval);
166        break;
167      case "weave:engine:sync:finish":
168        if (data == "clients") {
169          // Update the client mode because it might change what we sync.
170          this.updateClientMode();
171        }
172        break;
173      case "weave:engine:sync:error":
174        // `subject` is the exception thrown by an engine's sync() method.
175        let exception = subject;
176        if (exception.status >= 500 && exception.status <= 504) {
177          this.requiresBackoff = true;
178        }
179        break;
180      case "weave:service:login:error":
181        this.clearSyncTriggers();
182
183        if (Status.login == MASTER_PASSWORD_LOCKED) {
184          // Try again later, just as if we threw an error... only without the
185          // error count.
186          this._log.debug("Couldn't log in: master password is locked.");
187          this._log.trace("Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL");
188          this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
189        } else if (this._fatalLoginStatus.indexOf(Status.login) == -1) {
190          // Not a fatal login error, just an intermittent network or server
191          // issue. Keep on syncin'.
192          this.checkSyncStatus();
193        }
194        break;
195      case "weave:service:logout:finish":
196        // Start or cancel the sync timer depending on if
197        // logged in or logged out
198        this.checkSyncStatus();
199        break;
200      case "weave:service:sync:error":
201        // There may be multiple clients but if the sync fails, client mode
202        // should still be updated so that the next sync has a correct interval.
203        this.updateClientMode();
204        this.adjustSyncInterval();
205        this.nextSync = 0;
206        this.handleSyncError();
207        break;
208      case "weave:service:backoff:interval":
209        let requested_interval = subject * 1000;
210        // Leave up to 25% more time for the back off.
211        let interval = requested_interval * (1 + Math.random() * 0.25);
212        Status.backoffInterval = interval;
213        Status.minimumNextSync = Date.now() + requested_interval;
214        break;
215      case "weave:service:ready":
216        // Applications can specify this preference if they want autoconnect
217        // to happen after a fixed delay.
218        let delay = Svc.Prefs.get("autoconnectDelay");
219        if (delay) {
220          this.delayedAutoConnect(delay);
221        }
222        break;
223      case "weave:engine:sync:applied":
224        let numItems = subject.applied;
225        this._log.trace("Engine " + data + " applied " + numItems + " items.");
226        if (numItems)
227          this.hasIncomingItems = true;
228        break;
229      case "weave:service:setup-complete":
230         Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
231         break;
232      case "weave:service:start-over":
233         SyncScheduler.setDefaults();
234         try {
235           Svc.Idle.removeIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
236         } catch (ex if (ex.result == Cr.NS_ERROR_FAILURE)) {
237           // In all likelihood we didn't have an idle observer registered yet.
238           // It's all good.
239         }
240         break;
241      case "idle":
242        this._log.trace("We're idle.");
243        this.idle = true;
244        // Adjust the interval for future syncs. This won't actually have any
245        // effect until the next pending sync (which will happen soon since we
246        // were just active.)
247        this.adjustSyncInterval();
248        break;
249      case "back":
250        this._log.trace("Received notification that we're back from idle.");
251        this.idle = false;
252        Utils.namedTimer(function onBack() {
253          if (this.idle) {
254            this._log.trace("... and we're idle again. " +
255                            "Ignoring spurious back notification.");
256            return;
257          }
258
259          this._log.trace("Genuine return from idle. Syncing.");
260          // Trigger a sync if we have multiple clients.
261          if (this.numClients > 1) {
262            this.scheduleNextSync(0);
263          }
264        }, IDLE_OBSERVER_BACK_DELAY, this, "idleDebouncerTimer");
265        break;
266    }
267  },
268
269  adjustSyncInterval: function adjustSyncInterval() {
270    if (this.numClients <= 1) {
271      this._log.trace("Adjusting syncInterval to singleDeviceInterval.");
272      this.syncInterval = this.singleDeviceInterval;
273      return;
274    }
275    // Only MULTI_DEVICE clients will enter this if statement
276    // since SINGLE_USER clients will be handled above.
277    if (this.idle) {
278      this._log.trace("Adjusting syncInterval to idleInterval.");
279      this.syncInterval = this.idleInterval;
280      return;
281    }
282
283    if (this.hasIncomingItems) {
284      this._log.trace("Adjusting syncInterval to immediateInterval.");
285      this.hasIncomingItems = false;
286      this.syncInterval = this.immediateInterval;
287    } else {
288      this._log.trace("Adjusting syncInterval to activeInterval.");
289      this.syncInterval = this.activeInterval;
290    }
291  },
292
293  calculateScore: function calculateScore() {
294    let engines = [Clients].concat(Engines.getEnabled());
295    for (let i = 0;i < engines.length;i++) {
296      this._log.trace(engines[i].name + ": score: " + engines[i].score);
297      this.globalScore += engines[i].score;
298      engines[i]._tracker.resetScore();
299    }
300
301    this._log.trace("Global score updated: " + this.globalScore);
302    this.checkSyncStatus();
303  },
304
305  /**
306   * Process the locally stored clients list to figure out what mode to be in
307   */
308  updateClientMode: function updateClientMode() {
309    // Nothing to do if it's the same amount
310    let numClients = Clients.stats.numClients;
311    if (this.numClients == numClients)
312      return;
313
314    this._log.debug("Client count: " + this.numClients + " -> " + numClients);
315    this.numClients = numClients;
316
317    if (numClients <= 1) {
318      this._log.trace("Adjusting syncThreshold to SINGLE_USER_THRESHOLD");
319      this.syncThreshold = SINGLE_USER_THRESHOLD;
320    } else {
321      this._log.trace("Adjusting syncThreshold to MULTI_DEVICE_THRESHOLD");
322      this.syncThreshold = MULTI_DEVICE_THRESHOLD;
323    }
324    this.adjustSyncInterval();
325  },
326
327  /**
328   * Check if we should be syncing and schedule the next sync, if it's not scheduled
329   */
330  checkSyncStatus: function checkSyncStatus() {
331    // Should we be syncing now, if not, cancel any sync timers and return
332    // if we're in backoff, we'll schedule the next sync.
333    let ignore = [kSyncBackoffNotMet, kSyncMasterPasswordLocked];
334    let skip = Weave.Service._checkSync(ignore);
335    this._log.trace("_checkSync returned \"" + skip + "\".");
336    if (skip) {
337      this.clearSyncTriggers();
338      return;
339    }
340
341    // Only set the wait time to 0 if we need to sync right away
342    let wait;
343    if (this.globalScore > this.syncThreshold) {
344      this._log.debug("Global Score threshold hit, triggering sync.");
345      wait = 0;
346    }
347    this.scheduleNextSync(wait);
348  },
349
350  /**
351   * Call sync() if Master Password is not locked.
352   *
353   * Otherwise, reschedule a sync for later.
354   */
355  syncIfMPUnlocked: function syncIfMPUnlocked() {
356    // No point if we got kicked out by the master password dialog.
357    if (Status.login == MASTER_PASSWORD_LOCKED &&
358        Utils.mpLocked()) {
359      this._log.debug("Not initiating sync: Login status is " + Status.login);
360
361      // If we're not syncing now, we need to schedule the next one.
362      this._log.trace("Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL");
363      this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
364      return;
365    }
366
367    Utils.nextTick(Weave.Service.sync, Weave.Service);
368  },
369
370  /**
371   * Set a timer for the next sync
372   */
373  scheduleNextSync: function scheduleNextSync(interval) {
374    // If no interval was specified, use the current sync interval.
375    if (interval == null) {
376      interval = this.syncInterval;
377    }
378
379    // Ensure the interval is set to no less than the backoff.
380    if (Status.backoffInterval && interval < Status.backoffInterval) {
381      this._log.trace("Requested interval " + interval +
382                      " ms is smaller than the backoff interval. " + 
383                      "Using backoff interval " +
384                      Status.backoffInterval + " ms instead.");
385      interval = Status.backoffInterval;
386    }
387
388    if (this.nextSync != 0) {
389      // There's already a sync scheduled. Don't reschedule if there's already
390      // a timer scheduled for sooner than requested.
391      let currentInterval = this.nextSync - Date.now();
392      this._log.trace("There's already a sync scheduled in " +
393                      currentInterval + " ms.");
394      if (currentInterval < interval && this.syncTimer) {
395        this._log.trace("Ignoring scheduling request for next sync in " +
396                        interval + " ms.");
397        return;
398      }
399    }
400
401    // Start the sync right away if we're already late.
402    if (interval <= 0) {
403      this._log.trace("Requested sync should happen right away.");
404      this.syncIfMPUnlocked();
405      return;
406    }
407
408    this._log.debug("Next sync in " + interval + " ms.");
409    Utils.namedTimer(this.syncIfMPUnlocked, interval, this, "syncTimer");
410
411    // Save the next sync time in-case sync is disabled (logout/offline/etc.)
412    this.nextSync = Date.now() + interval;
413  },
414
415
416  /**
417   * Incorporates the backoff/retry logic used in error handling and elective
418   * non-syncing.
419   */
420  scheduleAtInterval: function scheduleAtInterval(minimumInterval) {
421    let interval = Utils.calculateBackoff(this._syncErrors, MINIMUM_BACKOFF_INTERVAL);
422    if (minimumInterval) {
423      interval = Math.max(minimumInterval, interval);
424    }
425
426    this._log.debug("Starting client-initiated backoff. Next sync in " +
427                    interval + " ms.");
428    this.scheduleNextSync(interval);
429  },
430
431 /**
432  * Automatically start syncing after the given delay (in seconds).
433  *
434  * Applications can define the `services.sync.autoconnectDelay` preference
435  * to have this called automatically during start-up with the pref value as
436  * the argument. Alternatively, they can call it themselves to control when
437  * Sync should first start to sync.
438  */
439  delayedAutoConnect: function delayedAutoConnect(delay) {
440    if (Weave.Service._checkSetup() == STATUS_OK) {
441      Utils.namedTimer(this.autoConnect, delay * 1000, this, "_autoTimer");
442    }
443  },
444
445  autoConnect: function autoConnect() {
446    if (Weave.Service._checkSetup() == STATUS_OK && !Weave.Service._checkSync()) {
447      // Schedule a sync based on when a previous sync was scheduled.
448      // scheduleNextSync() will do the right thing if that time lies in
449      // the past.
450      this.scheduleNextSync(this.nextSync - Date.now());
451    }
452
453    // Once autoConnect is called we no longer need _autoTimer.
454    if (this._autoTimer) {
455      this._autoTimer.clear();
456    }
457  },
458
459  _syncErrors: 0,
460  /**
461   * Deal with sync errors appropriately
462   */
463  handleSyncError: function handleSyncError() {
464    this._log.trace("In handleSyncError. Error count: " + this._syncErrors);
465    this._syncErrors++;
466
467    // Do nothing on the first couple of failures, if we're not in
468    // backoff due to 5xx errors.
469    if (!Status.enforceBackoff) {
470      if (this._syncErrors < MAX_ERROR_COUNT_BEFORE_BACKOFF) {
471        this.scheduleNextSync();
472        return;
473      }
474      this._log.debug("Sync error count has exceeded " +
475                      MAX_ERROR_COUNT_BEFORE_BACKOFF + "; enforcing backoff.");
476      Status.enforceBackoff = true;
477    }
478
479    this.scheduleAtInterval();
480  },
481
482
483  /**
484   * Remove any timers/observers that might trigger a sync
485   */
486  clearSyncTriggers: function clearSyncTriggers() {
487    this._log.debug("Clearing sync triggers and the global score.");
488    this.globalScore = this.nextSync = 0;
489
490    // Clear out any scheduled syncs
491    if (this.syncTimer)
492      this.syncTimer.clear();
493  }
494
495};
496
497const LOG_PREFIX_SUCCESS = "success-";
498const LOG_PREFIX_ERROR   = "error-";
499
500let ErrorHandler = {
501
502  /**
503   * Flag that turns on error reporting for all errors, incl. network errors.
504   */
505  dontIgnoreErrors: false,
506
507  init: function init() {
508    Svc.Obs.add("weave:engine:sync:applied", this);
509    Svc.Obs.add("weave:engine:sync:error", this);
510    Svc.Obs.add("weave:service:login:error", this);
511    Svc.Obs.add("weave:service:sync:error", this);
512    Svc.Obs.add("weave:service:sync:finish", this);
513
514    this.initLogs();
515  },
516
517  initLogs: function initLogs() {
518    this._log = Log4Moz.repository.getLogger("Sync.ErrorHandler");
519    this._log.level = Log4Moz.Level[Svc.Prefs.get("log.logger.service.main")];
520    this._cleaningUpFileLogs = false;
521
522    let root = Log4Moz.repository.getLogger("Sync");
523    root.level = Log4Moz.Level[Svc.Prefs.get("log.rootLogger")];
524
525    let formatter = new Log4Moz.BasicFormatter();
526    let capp = new Log4Moz.ConsoleAppender(formatter);
527    capp.level = Log4Moz.Level[Svc.Prefs.get("log.appender.console")];
528    root.addAppender(capp);
529
530    let dapp = new Log4Moz.DumpAppender(formatter);
531    dapp.level = Log4Moz.Level[Svc.Prefs.get("log.appender.dump")];
532    root.addAppender(dapp);
533
534    let fapp = this._logAppender = new Log4Moz.StorageStreamAppender(formatter);
535    fapp.level = Log4Moz.Level[Svc.Prefs.get("log.appender.file.level")];
536    root.addAppender(fapp);
537  },
538
539  observe: function observe(subject, topic, data) {
540    this._log.trace("Handling " + topic);
541    switch(topic) {
542      case "weave:engine:sync:applied":
543        if (subject.newFailed) {
544          // An engine isn't able to apply one or more incoming records.
545          // We don't fail hard on this, but it usually indicates a bug,
546          // so for now treat it as sync error (c.f. Service._syncEngine())
547          Status.engines = [data, ENGINE_APPLY_FAIL];
548          this._log.debug(data + " failed to apply some records.");
549        }
550        break;
551      case "weave:engine:sync:error":
552        let exception = subject;  // exception thrown by engine's sync() method
553        let engine_name = data;   // engine name that threw the exception
554
555        this.checkServerError(exception);
556
557        Status.engines = [engine_name, exception.failureCode || ENGINE_UNKNOWN_FAIL];
558        this._log.debug(engine_name + " failed: " + Utils.exceptionStr(exception));
559        break;
560      case "weave:service:login:error":
561        this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
562                          LOG_PREFIX_ERROR);
563
564        if (this.shouldReportError()) {
565          this.notifyOnNextTick("weave:ui:login:error");
566        } else {
567          this.notifyOnNextTick("weave:ui:clear-error");
568        }
569
570        this.dontIgnoreErrors = false;
571        break;
572      case "weave:service:sync:error":
573        if (Status.sync == CREDENTIALS_CHANGED) {
574          Weave.Service.logout();
575        }
576
577        this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
578                          LOG_PREFIX_ERROR);
579
580        if (this.shouldReportError()) {
581          this.notifyOnNextTick("weave:ui:sync:error");
582        } else {
583          this.notifyOnNextTick("weave:ui:sync:finish");
584        }
585
586        this.dontIgnoreErrors = false;
587        break;
588      case "weave:service:sync:finish":
589        this._log.trace("Status.service is " + Status.service);
590
591        // Check both of these status codes: in the event of a failure in one
592        // engine, Status.service will be SYNC_FAILED_PARTIAL despite
593        // Status.sync being SYNC_SUCCEEDED.
594        // *facepalm*
595        if (Status.sync    == SYNC_SUCCEEDED &&
596            Status.service == STATUS_OK) {
597          // Great. Let's clear our mid-sync 401 note.
598          this._log.trace("Clearing lastSyncReassigned.");
599          Svc.Prefs.reset("lastSyncReassigned");
600        }
601
602        if (Status.service == SYNC_FAILED_PARTIAL) {
603          this._log.debug("Some engines did not sync correctly.");
604          this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
605                            LOG_PREFIX_ERROR);
606
607          if (this.shouldReportError()) {
608            this.dontIgnoreErrors = false;
609            this.notifyOnNextTick("weave:ui:sync:error");
610            break;
611          }
612        } else {
613          this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnSuccess"),
614                            LOG_PREFIX_SUCCESS);
615        }
616        this.dontIgnoreErrors = false;
617        this.notifyOnNextTick("weave:ui:sync:finish");
618        break;
619    }
620  },
621
622  notifyOnNextTick: function notifyOnNextTick(topic) {
623    Utils.nextTick(function() {
624      this._log.trace("Notifying " + topic +
625                      ". Status.login is " + Status.login +
626                      ". Status.sync is " + Status.sync);
627      Svc.Obs.notify(topic);
628    }, this);
629  },
630
631  /**
632   * Trigger a sync and don't muffle any errors, particularly network errors.
633   */
634  syncAndReportErrors: function syncAndReportErrors() {
635    this._log.debug("Beginning user-triggered sync.");
636
637    this.dontIgnoreErrors = true;
638    Utils.nextTick(Weave.Service.sync, Weave.Service);
639  },
640
641  /**
642   * Finds all logs older than maxErrorAge and deletes them without tying up I/O.
643   */
644  cleanupLogs: function cleanupLogs() {
645    let direntries = FileUtils.getDir("ProfD", ["weave", "logs"]).directoryEntries;
646    let oldLogs = [];
647    let index = 0;
648    let threshold = Date.now() - 1000 * Svc.Prefs.get("log.appender.file.maxErrorAge");
649
650    while (direntries.hasMoreElements()) {
651      let logFile = direntries.getNext().QueryInterface(Ci.nsIFile);
652      if (logFile.lastModifiedTime < threshold) {
653        oldLogs.push(logFile);
654      }
655    }
656
657    // Deletes a file from oldLogs each tick until there are none left.
658    function deleteFile() {
659      if (index >= oldLogs.length) {
660        ErrorHandler._cleaningUpFileLogs = false;
661        Svc.Obs.notify("weave:service:cleanup-logs");
662        return;
663      }
664      try {
665        oldLogs[index].remove(false);
666      } catch (ex) {
667        ErrorHandler._log._debug("Encountered error trying to clean up old log file '"
668                                 + oldLogs[index].leafName + "':"
669                                 + Utils.exceptionStr(ex));
670      }
671      index++;
672      Utils.nextTick(deleteFile);
673    }
674
675    if (oldLogs.length > 0) {
676      ErrorHandler._cleaningUpFileLogs = true;
677      Utils.nextTick(deleteFile);
678    }
679  },
680
681  /**
682   * Generate a log file for the sync that just completed
683   * and refresh the input & output streams.
684   *
685   * @param flushToFile
686   *        the log file to be flushed/reset
687   *
688   * @param filenamePrefix
689   *        a value of either LOG_PREFIX_SUCCESS or LOG_PREFIX_ERROR
690   *        to be used as the log filename prefix
691   */
692  resetFileLog: function resetFileLog(flushToFile, filenamePrefix) {
693    let inStream = this._logAppender.getInputStream();
694    this._logAppender.reset();
695    if (flushToFile && inStream) {
696      try {
697        let filename = filenamePrefix + Date.now() + ".txt";
698        let file = FileUtils.getFile("ProfD", ["weave", "logs", filename]);
699        let outStream = FileUtils.openFileOutputStream(file);
700        NetUtil.asyncCopy(inStream, outStream, function () {
701          Svc.Obs.notify("weave:service:reset-file-log");
702          if (filenamePrefix == LOG_PREFIX_ERROR
703              && !ErrorHandler._cleaningUpFileLogs) {
704            Utils.nextTick(ErrorHandler.cleanupLogs, ErrorHandler);
705          }
706        });
707      } catch (ex) {
708        Svc.Obs.notify("weave:service:reset-file-log");
709      }
710    } else {
711      Svc.Obs.notify("weave:service:reset-file-log");
712    }
713  },
714
715  /**
716   * Translates server error codes to meaningful strings.
717   *
718   * @param code
719   *        server error code as an integer
720   */
721  errorStr: function errorStr(code) {
722    switch (code.toString()) {
723    case "1":
724      return "illegal-method";
725    case "2":
726      return "invalid-captcha";
727    case "3":
728      return "invalid-username";
729    case "4":
730      return "cannot-overwrite-resource";
731    case "5":
732      return "userid-mismatch";
733    case "6":
734      return "json-parse-failure";
735    case "7":
736      return "invalid-password";
737    case "8":
738      return "invalid-record";
739    case "9":
740      return "weak-password";
741    default:
742      return "generic-server-error";
743    }
744  },
745
746  shouldReportError: function shouldReportError() {
747    if (Status.login == MASTER_PASSWORD_LOCKED) {
748      this._log.trace("shouldReportError: false (master password locked).");
749      return false;
750    }
751
752    if (this.dontIgnoreErrors) {
753      return true;
754    }
755
756    let lastSync = Svc.Prefs.get("lastSync");
757    if (lastSync && ((Date.now() - Date.parse(lastSync)) >
758        Svc.Prefs.get("errorhandler.networkFailureReportTimeout") * 1000)) {
759      Status.sync = PROLONGED_SYNC_FAILURE;
760      this._log.trace("shouldReportError: true (prolonged sync failure).");
761      return true;
762    }
763 
764    // We got a 401 mid-sync. Wait for the next sync before actually handling
765    // an error. This assumes that we'll get a 401 again on a login fetch in
766    // order to report the error.
767    if (!Weave.Service.clusterURL) {
768      this._log.trace("shouldReportError: false (no cluster URL; " +
769                      "possible node reassignment).");
770      return false;
771    }
772
773    return ([Status.login, Status.sync].indexOf(SERVER_MAINTENANCE) == -1 &&
774            [Status.login, Status.sync].indexOf(LOGIN_FAILED_NETWORK_ERROR) == -1);
775  },
776
777  /**
778   * Handle HTTP response results or exceptions and set the appropriate
779   * Status.* bits.
780   */
781  checkServerError: function checkServerError(resp) {
782    switch (resp.status) {
783      case 400:
784        if (resp == RESPONSE_OVER_QUOTA) {
785          Status.sync = OVER_QUOTA;
786        }
787        break;
788
789      case 401:
790        Weave.Service.logout();
791        this._log.info("Got 401 response; resetting clusterURL.");
792        Svc.Prefs.reset("clusterURL");
793
794        let delay = 0;
795        if (Svc.Prefs.get("lastSyncReassigned")) {
796          // We got a 401 in the middle of the previous sync, and we just got
797          // another. Login must have succeeded in order for us to get here, so
798          // the password should be correct.
799          // This is likely to be an intermittent server issue, so back off and
800          // give it time to recover.
801          this._log.warn("Last sync also failed for 401. Delaying next sync.");
802          delay = MINIMUM_BACKOFF_INTERVAL;
803        } else {
804          this._log.debug("New mid-sync 401 failure. Making a note.");
805          Svc.Prefs.set("lastSyncReassigned", true);
806        }
807        this._log.info("Attempting to schedule another sync.");
808        SyncScheduler.scheduleNextSync(delay);
809        break;
810
811      case 500:
812      case 502:
813      case 503:
814      case 504:
815        Status.enforceBackoff = true;
816        if (resp.status == 503 && resp.headers["retry-after"]) {
817          if (Weave.Service.isLoggedIn) {
818            Status.sync = SERVER_MAINTENANCE;
819          } else {
820            Status.login = SERVER_MAINTENANCE;
821          }
822          Svc.Obs.notify("weave:service:backoff:interval",
823                         parseInt(resp.headers["retry-after"], 10));
824        }
825        break;
826    }
827
828    switch (resp.result) {
829      case Cr.NS_ERROR_UNKNOWN_HOST:
830      case Cr.NS_ERROR_CONNECTION_REFUSED:
831      case Cr.NS_ERROR_NET_TIMEOUT:
832      case Cr.NS_ERROR_NET_RESET:
833      case Cr.NS_ERROR_NET_INTERRUPT:
834      case Cr.NS_ERROR_PROXY_CONNECTION_REFUSED:
835        // The constant says it's about login, but in fact it just
836        // indicates general network error.
837        if (Weave.Service.isLoggedIn) {
838          Status.sync = LOGIN_FAILED_NETWORK_ERROR;
839        } else {
840          Status.login = LOGIN_FAILED_NETWORK_ERROR;
841        }
842        break;
843    }
844  },
845};
846
847
848/**
849 * Send credentials over an active J-PAKE channel.
850 * 
851 * This object is designed to take over as the JPAKEClient controller,
852 * presumably replacing one that is UI-based which would either cause
853 * DOM objects to leak or the JPAKEClient to be GC'ed when the DOM
854 * context disappears. This object stays alive for the duration of the
855 * transfer by being strong-ref'ed as an nsIObserver.
856 * 
857 * Credentials are sent after the first sync has been completed
858 * (successfully or not.)
859 * 
860 * Usage:
861 * 
862 *   jpakeclient.controller = new SendCredentialsController(jpakeclient);
863 * 
864 */
865function SendCredentialsController(jpakeclient) {
866  this._log = Log4Moz.repository.getLogger("Sync.SendCredentialsController");
867  this._log.level = Log4Moz.Level[Svc.Prefs.get("log.logger.service.main")];
868
869  this._log.trace("Loading.");
870  this.jpakeclient = jpakeclient;
871
872  // Register ourselves as observers the first Sync finishing (either
873  // successfully or unsuccessfully, we don't care) or for removing
874  // this device's sync configuration, in case that happens while we
875  // haven't finished the first sync yet.
876  Services.obs.addObserver(this, "weave:service:sync:finish", false);
877  Services.obs.addObserver(this, "weave:service:sync:error",  false);
878  Services.obs.addObserver(this, "weave:service:start-over",  false);
879}
880SendCredentialsController.prototype = {
881
882  unload: function unload() {
883    this._log.trace("Unloading.");
884    try {
885      Services.obs.removeObserver(this, "weave:service:sync:finish");
886      Services.obs.removeObserver(this, "weave:service:sync:error");
887      Services.obs.removeObserver(this, "weave:service:start-over");
888    } catch (ex) {
889      // Ignore.
890    }
891  },
892
893  observe: function observe(subject, topic, data) {
894    switch (topic) {
895      case "weave:service:sync:finish":
896      case "weave:service:sync:error":
897        Utils.nextTick(this.sendCredentials, this);
898        break;
899      case "weave:service:start-over":
900        // This will call onAbort which will call unload().
901        this.jpakeclient.abort();
902        break;
903    }
904  },
905
906  sendCredentials: function sendCredentials() {
907    this._log.trace("Sending credentials.");
908    let credentials = {account:   Weave.Service.account,
909                       password:  Weave.Service.password,
910                       synckey:   Weave.Service.passphrase,
911                       serverURL: Weave.Service.serverURL};
912    this.jpakeclient.sendAndComplete(credentials);
913  },
914
915  // JPAKEClient controller API
916
917  onComplete: function onComplete() {
918    this._log.debug("Exchange was completed successfully!");
919    this.unload();
920
921    // Schedule a Sync for soonish to fetch the data uploaded by the
922    // device with which we just paired.
923    SyncScheduler.scheduleNextSync(SyncScheduler.activeInterval);
924  },
925
926  onAbort: function onAbort(error) {
927    // It doesn't really matter why we aborted, but the channel is closed
928    // for sure, so we won't be able to do anything with it.
929    this._log.debug("Exchange was aborted with error: " + error);
930    this.unload();
931  },
932
933  // Irrelevant methods for this controller:
934  displayPIN: function displayPIN() {},
935  onPairingStart: function onPairingStart() {},
936  onPaired: function onPaired() {}
937};