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