1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/services/sync/modules/policies.js Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,963 @@
1.4 +/* This Source Code Form is subject to the terms of the Mozilla Public
1.5 + * License, v. 2.0. If a copy of the MPL was not distributed with this
1.6 + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
1.7 +
1.8 +this.EXPORTED_SYMBOLS = [
1.9 + "ErrorHandler",
1.10 + "SyncScheduler",
1.11 +];
1.12 +
1.13 +const {classes: Cc, interfaces: Ci, utils: Cu, results: Cr} = Components;
1.14 +
1.15 +Cu.import("resource://gre/modules/Log.jsm");
1.16 +Cu.import("resource://services-sync/constants.js");
1.17 +Cu.import("resource://services-sync/engines.js");
1.18 +Cu.import("resource://services-sync/util.js");
1.19 +Cu.import("resource://gre/modules/FileUtils.jsm");
1.20 +Cu.import("resource://gre/modules/NetUtil.jsm");
1.21 +
1.22 +XPCOMUtils.defineLazyModuleGetter(this, "Status",
1.23 + "resource://services-sync/status.js");
1.24 +
1.25 +this.SyncScheduler = function SyncScheduler(service) {
1.26 + this.service = service;
1.27 + this.init();
1.28 +}
1.29 +SyncScheduler.prototype = {
1.30 + _log: Log.repository.getLogger("Sync.SyncScheduler"),
1.31 +
1.32 + _fatalLoginStatus: [LOGIN_FAILED_NO_USERNAME,
1.33 + LOGIN_FAILED_NO_PASSWORD,
1.34 + LOGIN_FAILED_NO_PASSPHRASE,
1.35 + LOGIN_FAILED_INVALID_PASSPHRASE,
1.36 + LOGIN_FAILED_LOGIN_REJECTED],
1.37 +
1.38 + /**
1.39 + * The nsITimer object that schedules the next sync. See scheduleNextSync().
1.40 + */
1.41 + syncTimer: null,
1.42 +
1.43 + setDefaults: function setDefaults() {
1.44 + this._log.trace("Setting SyncScheduler policy values to defaults.");
1.45 +
1.46 + let service = Cc["@mozilla.org/weave/service;1"]
1.47 + .getService(Ci.nsISupports)
1.48 + .wrappedJSObject;
1.49 +
1.50 + let part = service.fxAccountsEnabled ? "fxa" : "sync11";
1.51 + let prefSDInterval = "scheduler." + part + ".singleDeviceInterval";
1.52 + this.singleDeviceInterval = Svc.Prefs.get(prefSDInterval) * 1000;
1.53 +
1.54 + this.idleInterval = Svc.Prefs.get("scheduler.idleInterval") * 1000;
1.55 + this.activeInterval = Svc.Prefs.get("scheduler.activeInterval") * 1000;
1.56 + this.immediateInterval = Svc.Prefs.get("scheduler.immediateInterval") * 1000;
1.57 + this.eolInterval = Svc.Prefs.get("scheduler.eolInterval") * 1000;
1.58 +
1.59 + // A user is non-idle on startup by default.
1.60 + this.idle = false;
1.61 +
1.62 + this.hasIncomingItems = false;
1.63 +
1.64 + this.clearSyncTriggers();
1.65 + },
1.66 +
1.67 + // nextSync is in milliseconds, but prefs can't hold that much
1.68 + get nextSync() Svc.Prefs.get("nextSync", 0) * 1000,
1.69 + set nextSync(value) Svc.Prefs.set("nextSync", Math.floor(value / 1000)),
1.70 +
1.71 + get syncInterval() Svc.Prefs.get("syncInterval", this.singleDeviceInterval),
1.72 + set syncInterval(value) Svc.Prefs.set("syncInterval", value),
1.73 +
1.74 + get syncThreshold() Svc.Prefs.get("syncThreshold", SINGLE_USER_THRESHOLD),
1.75 + set syncThreshold(value) Svc.Prefs.set("syncThreshold", value),
1.76 +
1.77 + get globalScore() Svc.Prefs.get("globalScore", 0),
1.78 + set globalScore(value) Svc.Prefs.set("globalScore", value),
1.79 +
1.80 + get numClients() Svc.Prefs.get("numClients", 0),
1.81 + set numClients(value) Svc.Prefs.set("numClients", value),
1.82 +
1.83 + init: function init() {
1.84 + this._log.level = Log.Level[Svc.Prefs.get("log.logger.service.main")];
1.85 + this.setDefaults();
1.86 + Svc.Obs.add("weave:engine:score:updated", this);
1.87 + Svc.Obs.add("network:offline-status-changed", this);
1.88 + Svc.Obs.add("weave:service:sync:start", this);
1.89 + Svc.Obs.add("weave:service:sync:finish", this);
1.90 + Svc.Obs.add("weave:engine:sync:finish", this);
1.91 + Svc.Obs.add("weave:engine:sync:error", this);
1.92 + Svc.Obs.add("weave:service:login:error", this);
1.93 + Svc.Obs.add("weave:service:logout:finish", this);
1.94 + Svc.Obs.add("weave:service:sync:error", this);
1.95 + Svc.Obs.add("weave:service:backoff:interval", this);
1.96 + Svc.Obs.add("weave:service:ready", this);
1.97 + Svc.Obs.add("weave:engine:sync:applied", this);
1.98 + Svc.Obs.add("weave:service:setup-complete", this);
1.99 + Svc.Obs.add("weave:service:start-over", this);
1.100 + Svc.Obs.add("FxA:hawk:backoff:interval", this);
1.101 +
1.102 + if (Status.checkSetup() == STATUS_OK) {
1.103 + Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
1.104 + }
1.105 + },
1.106 +
1.107 + observe: function observe(subject, topic, data) {
1.108 + this._log.trace("Handling " + topic);
1.109 + switch(topic) {
1.110 + case "weave:engine:score:updated":
1.111 + if (Status.login == LOGIN_SUCCEEDED) {
1.112 + Utils.namedTimer(this.calculateScore, SCORE_UPDATE_DELAY, this,
1.113 + "_scoreTimer");
1.114 + }
1.115 + break;
1.116 + case "network:offline-status-changed":
1.117 + // Whether online or offline, we'll reschedule syncs
1.118 + this._log.trace("Network offline status change: " + data);
1.119 + this.checkSyncStatus();
1.120 + break;
1.121 + case "weave:service:sync:start":
1.122 + // Clear out any potentially pending syncs now that we're syncing
1.123 + this.clearSyncTriggers();
1.124 +
1.125 + // reset backoff info, if the server tells us to continue backing off,
1.126 + // we'll handle that later
1.127 + Status.resetBackoff();
1.128 +
1.129 + this.globalScore = 0;
1.130 + break;
1.131 + case "weave:service:sync:finish":
1.132 + this.nextSync = 0;
1.133 + this.adjustSyncInterval();
1.134 +
1.135 + if (Status.service == SYNC_FAILED_PARTIAL && this.requiresBackoff) {
1.136 + this.requiresBackoff = false;
1.137 + this.handleSyncError();
1.138 + return;
1.139 + }
1.140 +
1.141 + let sync_interval;
1.142 + this._syncErrors = 0;
1.143 + if (Status.sync == NO_SYNC_NODE_FOUND) {
1.144 + this._log.trace("Scheduling a sync at interval NO_SYNC_NODE_FOUND.");
1.145 + sync_interval = NO_SYNC_NODE_INTERVAL;
1.146 + }
1.147 + this.scheduleNextSync(sync_interval);
1.148 + break;
1.149 + case "weave:engine:sync:finish":
1.150 + if (data == "clients") {
1.151 + // Update the client mode because it might change what we sync.
1.152 + this.updateClientMode();
1.153 + }
1.154 + break;
1.155 + case "weave:engine:sync:error":
1.156 + // `subject` is the exception thrown by an engine's sync() method.
1.157 + let exception = subject;
1.158 + if (exception.status >= 500 && exception.status <= 504) {
1.159 + this.requiresBackoff = true;
1.160 + }
1.161 + break;
1.162 + case "weave:service:login:error":
1.163 + this.clearSyncTriggers();
1.164 +
1.165 + if (Status.login == MASTER_PASSWORD_LOCKED) {
1.166 + // Try again later, just as if we threw an error... only without the
1.167 + // error count.
1.168 + this._log.debug("Couldn't log in: master password is locked.");
1.169 + this._log.trace("Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL");
1.170 + this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
1.171 + } else if (this._fatalLoginStatus.indexOf(Status.login) == -1) {
1.172 + // Not a fatal login error, just an intermittent network or server
1.173 + // issue. Keep on syncin'.
1.174 + this.checkSyncStatus();
1.175 + }
1.176 + break;
1.177 + case "weave:service:logout:finish":
1.178 + // Start or cancel the sync timer depending on if
1.179 + // logged in or logged out
1.180 + this.checkSyncStatus();
1.181 + break;
1.182 + case "weave:service:sync:error":
1.183 + // There may be multiple clients but if the sync fails, client mode
1.184 + // should still be updated so that the next sync has a correct interval.
1.185 + this.updateClientMode();
1.186 + this.adjustSyncInterval();
1.187 + this.nextSync = 0;
1.188 + this.handleSyncError();
1.189 + break;
1.190 + case "FxA:hawk:backoff:interval":
1.191 + case "weave:service:backoff:interval":
1.192 + let requested_interval = subject * 1000;
1.193 + this._log.debug("Got backoff notification: " + requested_interval + "ms");
1.194 + // Leave up to 25% more time for the back off.
1.195 + let interval = requested_interval * (1 + Math.random() * 0.25);
1.196 + Status.backoffInterval = interval;
1.197 + Status.minimumNextSync = Date.now() + requested_interval;
1.198 + this._log.debug("Fuzzed minimum next sync: " + Status.minimumNextSync);
1.199 + break;
1.200 + case "weave:service:ready":
1.201 + // Applications can specify this preference if they want autoconnect
1.202 + // to happen after a fixed delay.
1.203 + let delay = Svc.Prefs.get("autoconnectDelay");
1.204 + if (delay) {
1.205 + this.delayedAutoConnect(delay);
1.206 + }
1.207 + break;
1.208 + case "weave:engine:sync:applied":
1.209 + let numItems = subject.succeeded;
1.210 + this._log.trace("Engine " + data + " successfully applied " + numItems +
1.211 + " items.");
1.212 + if (numItems) {
1.213 + this.hasIncomingItems = true;
1.214 + }
1.215 + break;
1.216 + case "weave:service:setup-complete":
1.217 + Services.prefs.savePrefFile(null);
1.218 + Svc.Idle.addIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
1.219 + break;
1.220 + case "weave:service:start-over":
1.221 + this.setDefaults();
1.222 + try {
1.223 + Svc.Idle.removeIdleObserver(this, Svc.Prefs.get("scheduler.idleTime"));
1.224 + } catch (ex if (ex.result == Cr.NS_ERROR_FAILURE)) {
1.225 + // In all likelihood we didn't have an idle observer registered yet.
1.226 + // It's all good.
1.227 + }
1.228 + break;
1.229 + case "idle":
1.230 + this._log.trace("We're idle.");
1.231 + this.idle = true;
1.232 + // Adjust the interval for future syncs. This won't actually have any
1.233 + // effect until the next pending sync (which will happen soon since we
1.234 + // were just active.)
1.235 + this.adjustSyncInterval();
1.236 + break;
1.237 + case "active":
1.238 + this._log.trace("Received notification that we're back from idle.");
1.239 + this.idle = false;
1.240 + Utils.namedTimer(function onBack() {
1.241 + if (this.idle) {
1.242 + this._log.trace("... and we're idle again. " +
1.243 + "Ignoring spurious back notification.");
1.244 + return;
1.245 + }
1.246 +
1.247 + this._log.trace("Genuine return from idle. Syncing.");
1.248 + // Trigger a sync if we have multiple clients.
1.249 + if (this.numClients > 1) {
1.250 + this.scheduleNextSync(0);
1.251 + }
1.252 + }, IDLE_OBSERVER_BACK_DELAY, this, "idleDebouncerTimer");
1.253 + break;
1.254 + }
1.255 + },
1.256 +
1.257 + adjustSyncInterval: function adjustSyncInterval() {
1.258 + if (Status.eol) {
1.259 + this._log.debug("Server status is EOL; using eolInterval.");
1.260 + this.syncInterval = this.eolInterval;
1.261 + return;
1.262 + }
1.263 +
1.264 + if (this.numClients <= 1) {
1.265 + this._log.trace("Adjusting syncInterval to singleDeviceInterval.");
1.266 + this.syncInterval = this.singleDeviceInterval;
1.267 + return;
1.268 + }
1.269 +
1.270 + // Only MULTI_DEVICE clients will enter this if statement
1.271 + // since SINGLE_USER clients will be handled above.
1.272 + if (this.idle) {
1.273 + this._log.trace("Adjusting syncInterval to idleInterval.");
1.274 + this.syncInterval = this.idleInterval;
1.275 + return;
1.276 + }
1.277 +
1.278 + if (this.hasIncomingItems) {
1.279 + this._log.trace("Adjusting syncInterval to immediateInterval.");
1.280 + this.hasIncomingItems = false;
1.281 + this.syncInterval = this.immediateInterval;
1.282 + } else {
1.283 + this._log.trace("Adjusting syncInterval to activeInterval.");
1.284 + this.syncInterval = this.activeInterval;
1.285 + }
1.286 + },
1.287 +
1.288 + calculateScore: function calculateScore() {
1.289 + let engines = [this.service.clientsEngine].concat(this.service.engineManager.getEnabled());
1.290 + for (let i = 0;i < engines.length;i++) {
1.291 + this._log.trace(engines[i].name + ": score: " + engines[i].score);
1.292 + this.globalScore += engines[i].score;
1.293 + engines[i]._tracker.resetScore();
1.294 + }
1.295 +
1.296 + this._log.trace("Global score updated: " + this.globalScore);
1.297 + this.checkSyncStatus();
1.298 + },
1.299 +
1.300 + /**
1.301 + * Process the locally stored clients list to figure out what mode to be in
1.302 + */
1.303 + updateClientMode: function updateClientMode() {
1.304 + // Nothing to do if it's the same amount
1.305 + let numClients = this.service.clientsEngine.stats.numClients;
1.306 + if (this.numClients == numClients)
1.307 + return;
1.308 +
1.309 + this._log.debug("Client count: " + this.numClients + " -> " + numClients);
1.310 + this.numClients = numClients;
1.311 +
1.312 + if (numClients <= 1) {
1.313 + this._log.trace("Adjusting syncThreshold to SINGLE_USER_THRESHOLD");
1.314 + this.syncThreshold = SINGLE_USER_THRESHOLD;
1.315 + } else {
1.316 + this._log.trace("Adjusting syncThreshold to MULTI_DEVICE_THRESHOLD");
1.317 + this.syncThreshold = MULTI_DEVICE_THRESHOLD;
1.318 + }
1.319 + this.adjustSyncInterval();
1.320 + },
1.321 +
1.322 + /**
1.323 + * Check if we should be syncing and schedule the next sync, if it's not scheduled
1.324 + */
1.325 + checkSyncStatus: function checkSyncStatus() {
1.326 + // Should we be syncing now, if not, cancel any sync timers and return
1.327 + // if we're in backoff, we'll schedule the next sync.
1.328 + let ignore = [kSyncBackoffNotMet, kSyncMasterPasswordLocked];
1.329 + let skip = this.service._checkSync(ignore);
1.330 + this._log.trace("_checkSync returned \"" + skip + "\".");
1.331 + if (skip) {
1.332 + this.clearSyncTriggers();
1.333 + return;
1.334 + }
1.335 +
1.336 + // Only set the wait time to 0 if we need to sync right away
1.337 + let wait;
1.338 + if (this.globalScore > this.syncThreshold) {
1.339 + this._log.debug("Global Score threshold hit, triggering sync.");
1.340 + wait = 0;
1.341 + }
1.342 + this.scheduleNextSync(wait);
1.343 + },
1.344 +
1.345 + /**
1.346 + * Call sync() if Master Password is not locked.
1.347 + *
1.348 + * Otherwise, reschedule a sync for later.
1.349 + */
1.350 + syncIfMPUnlocked: function syncIfMPUnlocked() {
1.351 + // No point if we got kicked out by the master password dialog.
1.352 + if (Status.login == MASTER_PASSWORD_LOCKED &&
1.353 + Utils.mpLocked()) {
1.354 + this._log.debug("Not initiating sync: Login status is " + Status.login);
1.355 +
1.356 + // If we're not syncing now, we need to schedule the next one.
1.357 + this._log.trace("Scheduling a sync at MASTER_PASSWORD_LOCKED_RETRY_INTERVAL");
1.358 + this.scheduleAtInterval(MASTER_PASSWORD_LOCKED_RETRY_INTERVAL);
1.359 + return;
1.360 + }
1.361 +
1.362 + Utils.nextTick(this.service.sync, this.service);
1.363 + },
1.364 +
1.365 + /**
1.366 + * Set a timer for the next sync
1.367 + */
1.368 + scheduleNextSync: function scheduleNextSync(interval) {
1.369 + // If no interval was specified, use the current sync interval.
1.370 + if (interval == null) {
1.371 + interval = this.syncInterval;
1.372 + }
1.373 +
1.374 + // Ensure the interval is set to no less than the backoff.
1.375 + if (Status.backoffInterval && interval < Status.backoffInterval) {
1.376 + this._log.trace("Requested interval " + interval +
1.377 + " ms is smaller than the backoff interval. " +
1.378 + "Using backoff interval " +
1.379 + Status.backoffInterval + " ms instead.");
1.380 + interval = Status.backoffInterval;
1.381 + }
1.382 +
1.383 + if (this.nextSync != 0) {
1.384 + // There's already a sync scheduled. Don't reschedule if there's already
1.385 + // a timer scheduled for sooner than requested.
1.386 + let currentInterval = this.nextSync - Date.now();
1.387 + this._log.trace("There's already a sync scheduled in " +
1.388 + currentInterval + " ms.");
1.389 + if (currentInterval < interval && this.syncTimer) {
1.390 + this._log.trace("Ignoring scheduling request for next sync in " +
1.391 + interval + " ms.");
1.392 + return;
1.393 + }
1.394 + }
1.395 +
1.396 + // Start the sync right away if we're already late.
1.397 + if (interval <= 0) {
1.398 + this._log.trace("Requested sync should happen right away.");
1.399 + this.syncIfMPUnlocked();
1.400 + return;
1.401 + }
1.402 +
1.403 + this._log.debug("Next sync in " + interval + " ms.");
1.404 + Utils.namedTimer(this.syncIfMPUnlocked, interval, this, "syncTimer");
1.405 +
1.406 + // Save the next sync time in-case sync is disabled (logout/offline/etc.)
1.407 + this.nextSync = Date.now() + interval;
1.408 + },
1.409 +
1.410 +
1.411 + /**
1.412 + * Incorporates the backoff/retry logic used in error handling and elective
1.413 + * non-syncing.
1.414 + */
1.415 + scheduleAtInterval: function scheduleAtInterval(minimumInterval) {
1.416 + let interval = Utils.calculateBackoff(this._syncErrors,
1.417 + MINIMUM_BACKOFF_INTERVAL,
1.418 + Status.backoffInterval);
1.419 + if (minimumInterval) {
1.420 + interval = Math.max(minimumInterval, interval);
1.421 + }
1.422 +
1.423 + this._log.debug("Starting client-initiated backoff. Next sync in " +
1.424 + interval + " ms.");
1.425 + this.scheduleNextSync(interval);
1.426 + },
1.427 +
1.428 + /**
1.429 + * Automatically start syncing after the given delay (in seconds).
1.430 + *
1.431 + * Applications can define the `services.sync.autoconnectDelay` preference
1.432 + * to have this called automatically during start-up with the pref value as
1.433 + * the argument. Alternatively, they can call it themselves to control when
1.434 + * Sync should first start to sync.
1.435 + */
1.436 + delayedAutoConnect: function delayedAutoConnect(delay) {
1.437 + if (this.service._checkSetup() == STATUS_OK) {
1.438 + Utils.namedTimer(this.autoConnect, delay * 1000, this, "_autoTimer");
1.439 + }
1.440 + },
1.441 +
1.442 + autoConnect: function autoConnect() {
1.443 + if (this.service._checkSetup() == STATUS_OK && !this.service._checkSync()) {
1.444 + // Schedule a sync based on when a previous sync was scheduled.
1.445 + // scheduleNextSync() will do the right thing if that time lies in
1.446 + // the past.
1.447 + this.scheduleNextSync(this.nextSync - Date.now());
1.448 + }
1.449 +
1.450 + // Once autoConnect is called we no longer need _autoTimer.
1.451 + if (this._autoTimer) {
1.452 + this._autoTimer.clear();
1.453 + }
1.454 + },
1.455 +
1.456 + _syncErrors: 0,
1.457 + /**
1.458 + * Deal with sync errors appropriately
1.459 + */
1.460 + handleSyncError: function handleSyncError() {
1.461 + this._log.trace("In handleSyncError. Error count: " + this._syncErrors);
1.462 + this._syncErrors++;
1.463 +
1.464 + // Do nothing on the first couple of failures, if we're not in
1.465 + // backoff due to 5xx errors.
1.466 + if (!Status.enforceBackoff) {
1.467 + if (this._syncErrors < MAX_ERROR_COUNT_BEFORE_BACKOFF) {
1.468 + this.scheduleNextSync();
1.469 + return;
1.470 + }
1.471 + this._log.debug("Sync error count has exceeded " +
1.472 + MAX_ERROR_COUNT_BEFORE_BACKOFF + "; enforcing backoff.");
1.473 + Status.enforceBackoff = true;
1.474 + }
1.475 +
1.476 + this.scheduleAtInterval();
1.477 + },
1.478 +
1.479 +
1.480 + /**
1.481 + * Remove any timers/observers that might trigger a sync
1.482 + */
1.483 + clearSyncTriggers: function clearSyncTriggers() {
1.484 + this._log.debug("Clearing sync triggers and the global score.");
1.485 + this.globalScore = this.nextSync = 0;
1.486 +
1.487 + // Clear out any scheduled syncs
1.488 + if (this.syncTimer)
1.489 + this.syncTimer.clear();
1.490 + },
1.491 +};
1.492 +
1.493 +const LOG_PREFIX_SUCCESS = "success-";
1.494 +const LOG_PREFIX_ERROR = "error-";
1.495 +
1.496 +this.ErrorHandler = function ErrorHandler(service) {
1.497 + this.service = service;
1.498 + this.init();
1.499 +}
1.500 +ErrorHandler.prototype = {
1.501 + MINIMUM_ALERT_INTERVAL_MSEC: 604800000, // One week.
1.502 +
1.503 + /**
1.504 + * Flag that turns on error reporting for all errors, incl. network errors.
1.505 + */
1.506 + dontIgnoreErrors: false,
1.507 +
1.508 + /**
1.509 + * Flag that indicates if we have already reported a prolonged failure.
1.510 + * Once set, we don't report it again, meaning this error is only reported
1.511 + * one per run.
1.512 + */
1.513 + didReportProlongedError: false,
1.514 +
1.515 + init: function init() {
1.516 + Svc.Obs.add("weave:engine:sync:applied", this);
1.517 + Svc.Obs.add("weave:engine:sync:error", this);
1.518 + Svc.Obs.add("weave:service:login:error", this);
1.519 + Svc.Obs.add("weave:service:sync:error", this);
1.520 + Svc.Obs.add("weave:service:sync:finish", this);
1.521 +
1.522 + this.initLogs();
1.523 + },
1.524 +
1.525 + initLogs: function initLogs() {
1.526 + this._log = Log.repository.getLogger("Sync.ErrorHandler");
1.527 + this._log.level = Log.Level[Svc.Prefs.get("log.logger.service.main")];
1.528 + this._cleaningUpFileLogs = false;
1.529 +
1.530 + let root = Log.repository.getLogger("Sync");
1.531 + root.level = Log.Level[Svc.Prefs.get("log.rootLogger")];
1.532 +
1.533 + let formatter = new Log.BasicFormatter();
1.534 + let capp = new Log.ConsoleAppender(formatter);
1.535 + capp.level = Log.Level[Svc.Prefs.get("log.appender.console")];
1.536 + root.addAppender(capp);
1.537 +
1.538 + let dapp = new Log.DumpAppender(formatter);
1.539 + dapp.level = Log.Level[Svc.Prefs.get("log.appender.dump")];
1.540 + root.addAppender(dapp);
1.541 +
1.542 + let fapp = this._logAppender = new Log.StorageStreamAppender(formatter);
1.543 + fapp.level = Log.Level[Svc.Prefs.get("log.appender.file.level")];
1.544 + root.addAppender(fapp);
1.545 +
1.546 + // Arrange for the FxA logs to also go to our file.
1.547 + Log.repository.getLogger("FirefoxAccounts").addAppender(fapp);
1.548 + },
1.549 +
1.550 + observe: function observe(subject, topic, data) {
1.551 + this._log.trace("Handling " + topic);
1.552 + switch(topic) {
1.553 + case "weave:engine:sync:applied":
1.554 + if (subject.newFailed) {
1.555 + // An engine isn't able to apply one or more incoming records.
1.556 + // We don't fail hard on this, but it usually indicates a bug,
1.557 + // so for now treat it as sync error (c.f. Service._syncEngine())
1.558 + Status.engines = [data, ENGINE_APPLY_FAIL];
1.559 + this._log.debug(data + " failed to apply some records.");
1.560 + }
1.561 + break;
1.562 + case "weave:engine:sync:error":
1.563 + let exception = subject; // exception thrown by engine's sync() method
1.564 + let engine_name = data; // engine name that threw the exception
1.565 +
1.566 + this.checkServerError(exception);
1.567 +
1.568 + Status.engines = [engine_name, exception.failureCode || ENGINE_UNKNOWN_FAIL];
1.569 + this._log.debug(engine_name + " failed: " + Utils.exceptionStr(exception));
1.570 + break;
1.571 + case "weave:service:login:error":
1.572 + this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
1.573 + LOG_PREFIX_ERROR);
1.574 +
1.575 + if (this.shouldReportError()) {
1.576 + this.notifyOnNextTick("weave:ui:login:error");
1.577 + } else {
1.578 + this.notifyOnNextTick("weave:ui:clear-error");
1.579 + }
1.580 +
1.581 + this.dontIgnoreErrors = false;
1.582 + break;
1.583 + case "weave:service:sync:error":
1.584 + if (Status.sync == CREDENTIALS_CHANGED) {
1.585 + this.service.logout();
1.586 + }
1.587 +
1.588 + this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
1.589 + LOG_PREFIX_ERROR);
1.590 +
1.591 + if (this.shouldReportError()) {
1.592 + this.notifyOnNextTick("weave:ui:sync:error");
1.593 + } else {
1.594 + this.notifyOnNextTick("weave:ui:sync:finish");
1.595 + }
1.596 +
1.597 + this.dontIgnoreErrors = false;
1.598 + break;
1.599 + case "weave:service:sync:finish":
1.600 + this._log.trace("Status.service is " + Status.service);
1.601 +
1.602 + // Check both of these status codes: in the event of a failure in one
1.603 + // engine, Status.service will be SYNC_FAILED_PARTIAL despite
1.604 + // Status.sync being SYNC_SUCCEEDED.
1.605 + // *facepalm*
1.606 + if (Status.sync == SYNC_SUCCEEDED &&
1.607 + Status.service == STATUS_OK) {
1.608 + // Great. Let's clear our mid-sync 401 note.
1.609 + this._log.trace("Clearing lastSyncReassigned.");
1.610 + Svc.Prefs.reset("lastSyncReassigned");
1.611 + }
1.612 +
1.613 + if (Status.service == SYNC_FAILED_PARTIAL) {
1.614 + this._log.debug("Some engines did not sync correctly.");
1.615 + this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnError"),
1.616 + LOG_PREFIX_ERROR);
1.617 +
1.618 + if (this.shouldReportError()) {
1.619 + this.dontIgnoreErrors = false;
1.620 + this.notifyOnNextTick("weave:ui:sync:error");
1.621 + break;
1.622 + }
1.623 + } else {
1.624 + this.resetFileLog(Svc.Prefs.get("log.appender.file.logOnSuccess"),
1.625 + LOG_PREFIX_SUCCESS);
1.626 + }
1.627 + this.dontIgnoreErrors = false;
1.628 + this.notifyOnNextTick("weave:ui:sync:finish");
1.629 + break;
1.630 + }
1.631 + },
1.632 +
1.633 + notifyOnNextTick: function notifyOnNextTick(topic) {
1.634 + Utils.nextTick(function() {
1.635 + this._log.trace("Notifying " + topic +
1.636 + ". Status.login is " + Status.login +
1.637 + ". Status.sync is " + Status.sync);
1.638 + Svc.Obs.notify(topic);
1.639 + }, this);
1.640 + },
1.641 +
1.642 + /**
1.643 + * Trigger a sync and don't muffle any errors, particularly network errors.
1.644 + */
1.645 + syncAndReportErrors: function syncAndReportErrors() {
1.646 + this._log.debug("Beginning user-triggered sync.");
1.647 +
1.648 + this.dontIgnoreErrors = true;
1.649 + Utils.nextTick(this.service.sync, this.service);
1.650 + },
1.651 +
1.652 + /**
1.653 + * Finds all logs older than maxErrorAge and deletes them without tying up I/O.
1.654 + */
1.655 + cleanupLogs: function cleanupLogs() {
1.656 + let direntries = FileUtils.getDir("ProfD", ["weave", "logs"]).directoryEntries;
1.657 + let oldLogs = [];
1.658 + let index = 0;
1.659 + let threshold = Date.now() - 1000 * Svc.Prefs.get("log.appender.file.maxErrorAge");
1.660 +
1.661 + this._log.debug("Log cleanup threshold time: " + threshold);
1.662 + while (direntries.hasMoreElements()) {
1.663 + let logFile = direntries.getNext().QueryInterface(Ci.nsIFile);
1.664 + if (logFile.lastModifiedTime < threshold) {
1.665 + this._log.trace(" > Noting " + logFile.leafName +
1.666 + " for cleanup (" + logFile.lastModifiedTime + ")");
1.667 + oldLogs.push(logFile);
1.668 + }
1.669 + }
1.670 +
1.671 + // Deletes a file from oldLogs each tick until there are none left.
1.672 + let errorHandler = this;
1.673 + function deleteFile() {
1.674 + if (index >= oldLogs.length) {
1.675 + errorHandler._log.debug("Done deleting files.");
1.676 + errorHandler._cleaningUpFileLogs = false;
1.677 + Svc.Obs.notify("weave:service:cleanup-logs");
1.678 + return;
1.679 + }
1.680 + try {
1.681 + let file = oldLogs[index];
1.682 + file.remove(false);
1.683 + errorHandler._log.trace("Deleted " + file.leafName + ".");
1.684 + } catch (ex) {
1.685 + errorHandler._log._debug("Encountered error trying to clean up old log file '"
1.686 + + oldLogs[index].leafName + "':"
1.687 + + Utils.exceptionStr(ex));
1.688 + }
1.689 + index++;
1.690 + Utils.nextTick(deleteFile);
1.691 + }
1.692 +
1.693 + if (oldLogs.length > 0) {
1.694 + this._cleaningUpFileLogs = true;
1.695 + Utils.nextTick(deleteFile);
1.696 + } else {
1.697 + this._log.debug("No logs to clean up.");
1.698 + }
1.699 + },
1.700 +
1.701 + /**
1.702 + * Generate a log file for the sync that just completed
1.703 + * and refresh the input & output streams.
1.704 + *
1.705 + * @param flushToFile
1.706 + * the log file to be flushed/reset
1.707 + *
1.708 + * @param filenamePrefix
1.709 + * a value of either LOG_PREFIX_SUCCESS or LOG_PREFIX_ERROR
1.710 + * to be used as the log filename prefix
1.711 + */
1.712 + resetFileLog: function resetFileLog(flushToFile, filenamePrefix) {
1.713 + let inStream = this._logAppender.getInputStream();
1.714 + this._logAppender.reset();
1.715 + if (flushToFile && inStream) {
1.716 + this._log.debug("Flushing file log.");
1.717 + try {
1.718 + let filename = filenamePrefix + Date.now() + ".txt";
1.719 + let file = FileUtils.getFile("ProfD", ["weave", "logs", filename]);
1.720 + let outStream = FileUtils.openFileOutputStream(file);
1.721 +
1.722 + this._log.trace("Beginning stream copy to " + file.leafName + ": " +
1.723 + Date.now());
1.724 + NetUtil.asyncCopy(inStream, outStream, function onCopyComplete() {
1.725 + this._log.trace("onCopyComplete: " + Date.now());
1.726 + this._log.trace("Output file timestamp: " + file.lastModifiedTime);
1.727 + Svc.Obs.notify("weave:service:reset-file-log");
1.728 + this._log.trace("Notified: " + Date.now());
1.729 + if (filenamePrefix == LOG_PREFIX_ERROR &&
1.730 + !this._cleaningUpFileLogs) {
1.731 + this._log.trace("Scheduling cleanup.");
1.732 + Utils.nextTick(this.cleanupLogs, this);
1.733 + }
1.734 + }.bind(this));
1.735 + } catch (ex) {
1.736 + Svc.Obs.notify("weave:service:reset-file-log");
1.737 + }
1.738 + } else {
1.739 + Svc.Obs.notify("weave:service:reset-file-log");
1.740 + }
1.741 + },
1.742 +
1.743 + /**
1.744 + * Translates server error codes to meaningful strings.
1.745 + *
1.746 + * @param code
1.747 + * server error code as an integer
1.748 + */
1.749 + errorStr: function errorStr(code) {
1.750 + switch (code.toString()) {
1.751 + case "1":
1.752 + return "illegal-method";
1.753 + case "2":
1.754 + return "invalid-captcha";
1.755 + case "3":
1.756 + return "invalid-username";
1.757 + case "4":
1.758 + return "cannot-overwrite-resource";
1.759 + case "5":
1.760 + return "userid-mismatch";
1.761 + case "6":
1.762 + return "json-parse-failure";
1.763 + case "7":
1.764 + return "invalid-password";
1.765 + case "8":
1.766 + return "invalid-record";
1.767 + case "9":
1.768 + return "weak-password";
1.769 + default:
1.770 + return "generic-server-error";
1.771 + }
1.772 + },
1.773 +
1.774 + shouldReportError: function shouldReportError() {
1.775 + if (Status.login == MASTER_PASSWORD_LOCKED) {
1.776 + this._log.trace("shouldReportError: false (master password locked).");
1.777 + return false;
1.778 + }
1.779 +
1.780 + if (this.dontIgnoreErrors) {
1.781 + return true;
1.782 + }
1.783 +
1.784 + let lastSync = Svc.Prefs.get("lastSync");
1.785 + if (lastSync && ((Date.now() - Date.parse(lastSync)) >
1.786 + Svc.Prefs.get("errorhandler.networkFailureReportTimeout") * 1000)) {
1.787 + Status.sync = PROLONGED_SYNC_FAILURE;
1.788 + if (this.didReportProlongedError) {
1.789 + this._log.trace("shouldReportError: false (prolonged sync failure, but" +
1.790 + " we've already reported it).");
1.791 + return false;
1.792 + }
1.793 + this._log.trace("shouldReportError: true (first prolonged sync failure).");
1.794 + this.didReportProlongedError = true;
1.795 + return true;
1.796 + }
1.797 +
1.798 + // We got a 401 mid-sync. Wait for the next sync before actually handling
1.799 + // an error. This assumes that we'll get a 401 again on a login fetch in
1.800 + // order to report the error.
1.801 + if (!this.service.clusterURL) {
1.802 + this._log.trace("shouldReportError: false (no cluster URL; " +
1.803 + "possible node reassignment).");
1.804 + return false;
1.805 + }
1.806 +
1.807 + return ([Status.login, Status.sync].indexOf(SERVER_MAINTENANCE) == -1 &&
1.808 + [Status.login, Status.sync].indexOf(LOGIN_FAILED_NETWORK_ERROR) == -1);
1.809 + },
1.810 +
1.811 + get currentAlertMode() {
1.812 + return Svc.Prefs.get("errorhandler.alert.mode");
1.813 + },
1.814 +
1.815 + set currentAlertMode(str) {
1.816 + return Svc.Prefs.set("errorhandler.alert.mode", str);
1.817 + },
1.818 +
1.819 + get earliestNextAlert() {
1.820 + return Svc.Prefs.get("errorhandler.alert.earliestNext", 0) * 1000;
1.821 + },
1.822 +
1.823 + set earliestNextAlert(msec) {
1.824 + return Svc.Prefs.set("errorhandler.alert.earliestNext", msec / 1000);
1.825 + },
1.826 +
1.827 + clearServerAlerts: function () {
1.828 + // If we have any outstanding alerts, apparently they're no longer relevant.
1.829 + Svc.Prefs.resetBranch("errorhandler.alert");
1.830 + },
1.831 +
1.832 + /**
1.833 + * X-Weave-Alert headers can include a JSON object:
1.834 + *
1.835 + * {
1.836 + * "code": // One of "hard-eol", "soft-eol".
1.837 + * "url": // For "Learn more" link.
1.838 + * "message": // Logged in Sync logs.
1.839 + * }
1.840 + */
1.841 + handleServerAlert: function (xwa) {
1.842 + if (!xwa.code) {
1.843 + this._log.warn("Got structured X-Weave-Alert, but no alert code.");
1.844 + return;
1.845 + }
1.846 +
1.847 + switch (xwa.code) {
1.848 + // Gently and occasionally notify the user that this service will be
1.849 + // shutting down.
1.850 + case "soft-eol":
1.851 + // Fall through.
1.852 +
1.853 + // Tell the user that this service has shut down, and drop our syncing
1.854 + // frequency dramatically.
1.855 + case "hard-eol":
1.856 + // Note that both of these alerts should be subservient to future "sign
1.857 + // in with your Firefox Account" storage alerts.
1.858 + if ((this.currentAlertMode != xwa.code) ||
1.859 + (this.earliestNextAlert < Date.now())) {
1.860 + Utils.nextTick(function() {
1.861 + Svc.Obs.notify("weave:eol", xwa);
1.862 + }, this);
1.863 + this._log.error("X-Weave-Alert: " + xwa.code + ": " + xwa.message);
1.864 + this.earliestNextAlert = Date.now() + this.MINIMUM_ALERT_INTERVAL_MSEC;
1.865 + this.currentAlertMode = xwa.code;
1.866 + }
1.867 + break;
1.868 + default:
1.869 + this._log.debug("Got unexpected X-Weave-Alert code: " + xwa.code);
1.870 + }
1.871 + },
1.872 +
1.873 + /**
1.874 + * Handle HTTP response results or exceptions and set the appropriate
1.875 + * Status.* bits.
1.876 + *
1.877 + * This method also looks for "side-channel" warnings.
1.878 + */
1.879 + checkServerError: function (resp) {
1.880 + switch (resp.status) {
1.881 + case 200:
1.882 + case 404:
1.883 + case 513:
1.884 + let xwa = resp.headers['x-weave-alert'];
1.885 +
1.886 + // Only process machine-readable alerts.
1.887 + if (!xwa || !xwa.startsWith("{")) {
1.888 + this.clearServerAlerts();
1.889 + return;
1.890 + }
1.891 +
1.892 + try {
1.893 + xwa = JSON.parse(xwa);
1.894 + } catch (ex) {
1.895 + this._log.warn("Malformed X-Weave-Alert from server: " + xwa);
1.896 + return;
1.897 + }
1.898 +
1.899 + this.handleServerAlert(xwa);
1.900 + break;
1.901 +
1.902 + case 400:
1.903 + if (resp == RESPONSE_OVER_QUOTA) {
1.904 + Status.sync = OVER_QUOTA;
1.905 + }
1.906 + break;
1.907 +
1.908 + case 401:
1.909 + this.service.logout();
1.910 + this._log.info("Got 401 response; resetting clusterURL.");
1.911 + Svc.Prefs.reset("clusterURL");
1.912 +
1.913 + let delay = 0;
1.914 + if (Svc.Prefs.get("lastSyncReassigned")) {
1.915 + // We got a 401 in the middle of the previous sync, and we just got
1.916 + // another. Login must have succeeded in order for us to get here, so
1.917 + // the password should be correct.
1.918 + // This is likely to be an intermittent server issue, so back off and
1.919 + // give it time to recover.
1.920 + this._log.warn("Last sync also failed for 401. Delaying next sync.");
1.921 + delay = MINIMUM_BACKOFF_INTERVAL;
1.922 + } else {
1.923 + this._log.debug("New mid-sync 401 failure. Making a note.");
1.924 + Svc.Prefs.set("lastSyncReassigned", true);
1.925 + }
1.926 + this._log.info("Attempting to schedule another sync.");
1.927 + this.service.scheduler.scheduleNextSync(delay);
1.928 + break;
1.929 +
1.930 + case 500:
1.931 + case 502:
1.932 + case 503:
1.933 + case 504:
1.934 + Status.enforceBackoff = true;
1.935 + if (resp.status == 503 && resp.headers["retry-after"]) {
1.936 + let retryAfter = resp.headers["retry-after"];
1.937 + this._log.debug("Got Retry-After: " + retryAfter);
1.938 + if (this.service.isLoggedIn) {
1.939 + Status.sync = SERVER_MAINTENANCE;
1.940 + } else {
1.941 + Status.login = SERVER_MAINTENANCE;
1.942 + }
1.943 + Svc.Obs.notify("weave:service:backoff:interval",
1.944 + parseInt(retryAfter, 10));
1.945 + }
1.946 + break;
1.947 + }
1.948 +
1.949 + switch (resp.result) {
1.950 + case Cr.NS_ERROR_UNKNOWN_HOST:
1.951 + case Cr.NS_ERROR_CONNECTION_REFUSED:
1.952 + case Cr.NS_ERROR_NET_TIMEOUT:
1.953 + case Cr.NS_ERROR_NET_RESET:
1.954 + case Cr.NS_ERROR_NET_INTERRUPT:
1.955 + case Cr.NS_ERROR_PROXY_CONNECTION_REFUSED:
1.956 + // The constant says it's about login, but in fact it just
1.957 + // indicates general network error.
1.958 + if (this.service.isLoggedIn) {
1.959 + Status.sync = LOGIN_FAILED_NETWORK_ERROR;
1.960 + } else {
1.961 + Status.login = LOGIN_FAILED_NETWORK_ERROR;
1.962 + }
1.963 + break;
1.964 + }
1.965 + },
1.966 +};
