services/sync/modules/policies.js

Thu, 22 Jan 2015 13:21:57 +0100

author
Michael Schloh von Bennewitz <michael@schloh.com>
date
Thu, 22 Jan 2015 13:21:57 +0100
branch
TOR_BUG_9701
changeset 15
b8a032363ba2
permissions
-rw-r--r--

Incorporate requested changes from Mozilla in review:
https://bugzilla.mozilla.org/show_bug.cgi?id=1123480#c6

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

mercurial