Thu, 22 Jan 2015 13:21:57 +0100
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 | }; |