Bug 1265419 - Hook bookmark sync validator into the bookmark sync engine and add a telemetry probe for it f?markh
MozReview-Commit-ID: 6H32uH7ndMy
--- a/browser/app/profile/firefox.js
+++ b/browser/app/profile/firefox.js
@@ -1496,8 +1496,13 @@ pref("media.webspeech.synth.enabled", tr
pref("browser.esedbreader.loglevel", "Error");
pref("browser.laterrun.enabled", false);
// Enable browser frames for use on desktop. Only exposed to chrome callers.
pref("dom.mozBrowserFramesEnabled", true);
pref("extensions.pocket.enabled", true);
+
+#ifdef NIGHTLY_BUILD
+// Enable the (fairly costly) client/server validation on nightly only.
+pref("services.sync.validationEnabled", true);
+#endif
--- a/services/sync/modules/bookmark_validator.js
+++ b/services/sync/modules/bookmark_validator.js
@@ -1,25 +1,33 @@
/* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this file,
* You can obtain one at http://mozilla.org/MPL/2.0/. */
"use strict";
const Cu = Components.utils;
+Cu.import("resource://gre/modules/Log.jsm");
Cu.import("resource://gre/modules/PlacesUtils.jsm");
+Cu.import("resource://gre/modules/Task.jsm");
Cu.import("resource://services-sync/util.js");
Cu.import("resource://services-sync/bookmark_utils.js");
this.EXPORTED_SYMBOLS = ["BookmarkValidator"];
class BookmarkValidator {
+ constructor() {
+ this._log = Log.repository.getLogger("Sync.Validator.Bookmarks");
+ let level = Svc.Prefs.get("log.logger.engine.bookmarks", "Debug");
+ this._log.level = Log.Level[level];
+ }
+
createClientRecordsFromTree(clientTree) {
// Iterate over the treeNode, converting it to something more similar to what
// the server stores.
let records = [];
function traverse(treeNode) {
let guid = BookmarkSpecialIds.specialGUIDForId(treeNode.id) || treeNode.guid;
let itemType = 'item';
treeNode.id = guid;
@@ -451,12 +459,62 @@ class BookmarkValidator {
}
if (differences.length) {
problemData.differences.push({id, differences});
}
}
return problemData;
}
+
+ _getServerState(engine) {
+ let collection = engine.itemSource();
+ let collectionKey = engine.service.collectionKeys.keyForCollection(engine.name);
+ collection.full = true;
+ let items = [];
+ collection.recordHandler = function(item) {
+ item.decrypt(collectionKey);
+ items.push(item.cleartext);
+ };
+ collection.get();
+ return items;
+ }
+
+ validate(engine) {
+ let self = this;
+ return Task.spawn(function*() {
+ self._log.trace('Beginning bookmark validation');
+ let start = Date.now();
+ let clientTree = yield PlacesUtils.promiseBookmarksTree("", {
+ includeItemIds: true
+ });
+ let serverState = self._getServerState(engine);
+ let result = self.compareServerWithClient(serverState, clientTree);
+
+ let end = Date.now();
+ let duration = end-start;
+
+ self._log.debug(`Completed bookmark validation in ${duration}ms. Summary:`);
+ self._log.debug(` Missing from client: ${result.clientMissing.length}`);
+ self._log.debug(` Missing from server: ${result.serverMissing.length}`);
+ self._log.debug(` Client/Server differences: ${result.differences.length}`);
+ self._log.debug(` Missing IDs: ${result.missingIDs}`);
+ self._log.debug(` Duplicated IDs: ${result.duplicates.length}`);
+ self._log.debug(` Parent/Child mismatches: ${result.parentChildMismatches.length}`);
+ self._log.debug(` Cycles: ${result.cycles.length}`);
+ self._log.debug(` Orphans: ${result.orphans.length}`);
+ self._log.debug(` Missing Children: ${result.missingChildren.length}`);
+ self._log.debug(` Children with multiple parents: ${result.multipleParents.length}`);
+ self._log.debug(` Children with deleted parents: ${result.deletedParents.length}`);
+ self._log.debug(` Children on non-folders: ${result.childrenOnNonFolder.length}`);
+ self._log.debug(` Duplicate children: ${result.duplicateChildren.length}`);
+ self._log.debug(` Parents that are non-folders: ${result.parentNotFolder.length}`);
+ self._log.debug(` Children with incorrect parent names: ${result.wrongParentName.length}`);
+
+ Services.telemetry.getHistogramById('WEAVE_BOOKMARK_VALIDATION_DURATION').add(duration);
+ return result;
+ });
+ }
+
};
--- a/services/sync/modules/engines.js
+++ b/services/sync/modules/engines.js
@@ -687,16 +687,24 @@ Engine.prototype = {
this._tracker.ignoreAll = true;
this._store.wipe();
this._tracker.ignoreAll = false;
this._tracker.clearChangedIDs();
},
wipeClient: function () {
this._notify("wipe-client", this.name, this._wipeClient)();
+ },
+
+ /**
+ * If one exists, initialize and return a validator for this engine (which
+ * must have a `validate(engine)` method). Otherwise return null.
+ */
+ getValidator: function () {
+ return null;
}
};
this.SyncEngine = function SyncEngine(name, service) {
Engine.call(this, name || "SyncEngine", service);
this.loadToFetch();
this.loadPreviousFailed();
@@ -942,34 +950,34 @@ SyncEngine.prototype = {
// Keep track of what to delete at the end of sync
this._delete = {};
},
/**
* A tiny abstraction to make it easier to test incoming record
* application.
*/
- _itemSource: function () {
+ itemSource: function () {
return new Collection(this.engineURL, this._recordObj, this.service);
},
/**
* Process incoming records.
* In the most awful and untestable way possible.
* This now accepts something that makes testing vaguely less impossible.
*/
_processIncoming: function (newitems) {
this._log.trace("Downloading & applying server changes");
// Figure out how many total items to fetch this sync; do less on mobile.
let batchSize = this.downloadLimit || Infinity;
let isMobile = (Svc.Prefs.get("client.type") == "mobile");
if (!newitems) {
- newitems = this._itemSource();
+ newitems = this.itemSource();
}
if (this._defaultSort) {
newitems.sort = this._defaultSort;
}
if (isMobile) {
batchSize = MOBILE_BATCH_SIZE;
--- a/services/sync/modules/engines/bookmarks.js
+++ b/services/sync/modules/engines/bookmarks.js
@@ -13,16 +13,17 @@ var Cu = Components.utils;
Cu.import("resource://gre/modules/PlacesUtils.jsm");
Cu.import("resource://gre/modules/XPCOMUtils.jsm");
Cu.import("resource://services-common/async.js");
Cu.import("resource://services-sync/constants.js");
Cu.import("resource://services-sync/engines.js");
Cu.import("resource://services-sync/record.js");
Cu.import("resource://services-sync/util.js");
Cu.import("resource://services-sync/bookmark_utils.js");
+Cu.import("resource://services-sync/bookmark_validator.js");
Cu.import("resource://gre/modules/Task.jsm");
Cu.import("resource://gre/modules/PlacesBackups.jsm");
const ANNOS_TO_TRACK = [BookmarkAnnos.DESCRIPTION_ANNO, BookmarkAnnos.SIDEBAR_ANNO,
PlacesUtils.LMANNO_FEEDURI, PlacesUtils.LMANNO_SITEURI];
const SERVICE_NOT_SUPPORTED = "Service not supported on this platform";
const FOLDER_SORTINDEX = 1000000;
@@ -418,16 +419,20 @@ BookmarksEngine.prototype = {
// Don't bother finding a dupe if the incoming item has duplicates.
if (item.hasDupe) {
this._log.trace(item.id + " already a dupe: not finding one.");
return;
}
let mapped = this._mapDupe(item);
this._log.debug(item.id + " mapped to " + mapped);
return mapped;
+ },
+
+ getValidator() {
+ return new BookmarkValidator(this._log.debug.bind(this._log));
}
};
function BookmarksStore(name, engine) {
Store.call(this, name, engine);
// Explicitly nullify our references to our cached services so we don't leak
Svc.Obs.add("places-shutdown", function() {
--- a/services/sync/modules/service.js
+++ b/services/sync/modules/service.js
@@ -1240,16 +1240,53 @@ Sync11Service.prototype = {
}
else {
this._log.trace("In sync: no need to login.");
}
return this._lockedSync(engineNamesToSync);
})();
},
+ _runValidation: function _runValidation() {
+ let enabledEngines = this.engineManager.getEnabled();
+ let results = [];
+ for (let engine of enabledEngines) {
+ let validator = engine.getValidator();
+ if (validator) {
+ try {
+ results.push(validator.validate(engine));
+ } catch(ex) {
+ if (Async.isShutdownException(ex)) {
+ throw ex;
+ }
+ this._log.error('Failed to validate '+engine.name, ex);
+ }
+ }
+ }
+ return Promise.all(results);
+ },
+
+ /**
+ * Decides whether or not to call _runValidation, based on how long it has
+ * been since the last validation
+ */
+ _validate: function _validate() {
+ if (Svc.Prefs.get("validationEnabled")) {
+ let lastValidation = Svc.Prefs.get("lastValidation", 0);
+ let validationInterval = Svc.Prefs.get("validationInterval", 60*60*24);
+ if (Date.now()/1000-lastValidation > validationInterval) {
+ Svc.Prefs.set("lastValidation", Date.now()/1000)
+ this._runValidation().catch(error => {
+ // Validation failed, reset to previous lastValidation time.
+ Svc.Prefs.set('lastValidation', lastValidation);
+ });
+ }
+ }
+ },
+
/**
* Sync up engines with the server.
*/
_lockedSync: function _lockedSync(engineNamesToSync) {
return this._lock("service.js: sync",
this._notify("sync", "", function onNotify() {
let histogram = Services.telemetry.getHistogramById("WEAVE_START_COUNT");
@@ -1262,16 +1299,20 @@ Sync11Service.prototype = {
synchronizer.sync(engineNamesToSync);
// wait() throws if the first argument is truthy, which is exactly what
// we want.
let result = cb.wait();
histogram = Services.telemetry.getHistogramById("WEAVE_COMPLETE_SUCCESS_COUNT");
histogram.add(1);
+ // Check and see if we should run validation, but wait until we've
+ // released the lock.
+ Utils.nextTick(this._validate.bind(this));
+
// We successfully synchronized.
// Check if the identity wants to pre-fetch a migration sentinel from
// the server.
// If we have no clusterURL, we are probably doing a node reassignment
// so don't attempt to get it in that case.
if (this.clusterURL) {
this.identity.prefetchMigrationSentinel(this);
}
@@ -1286,16 +1327,17 @@ Sync11Service.prototype = {
let declinedEngines = new DeclinedEngines(this);
let didChange = declinedEngines.updateDeclined(meta, this.engineManager);
if (!didChange) {
this._log.info("No change to declined engines. Not reuploading meta/global.");
return;
}
this.uploadMetaGlobal(meta);
+
}))();
},
/**
* Upload meta/global, throwing the response on failure.
*/
uploadMetaGlobal: function (meta) {
this._log.debug("Uploading meta/global: " + JSON.stringify(meta));
--- a/services/sync/services-sync.js
+++ b/services/sync/services-sync.js
@@ -73,8 +73,10 @@ pref("services.sync.log.logger.engine.ta
pref("services.sync.log.logger.engine.addons", "Debug");
pref("services.sync.log.logger.engine.apps", "Debug");
pref("services.sync.log.logger.identity", "Debug");
pref("services.sync.log.logger.userapi", "Debug");
pref("services.sync.log.cryptoDebug", false);
pref("services.sync.fxa.termsURL", "https://accounts.firefox.com/legal/terms");
pref("services.sync.fxa.privacyURL", "https://accounts.firefox.com/legal/privacy");
+
+pref("services.sync.validationInterval", 86400);
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -10098,16 +10098,25 @@
"alert_emails": ["fx-team@mozilla.com"],
"bug_numbers": [1236383],
"expires_in_version": "never",
"kind": "count",
"keyed": true,
"releaseChannelCollection": "opt-out",
"description": "Exceptions thrown by a Sync engine. Keyed on the engine name."
},
+ "WEAVE_BOOKMARK_VALIDATION_DURATION": {
+ "alert_emails": ["fx-team@mozilla.com"],
+ "bug_numbers": [1265419, 1263835],
+ "expires_in_version": "60",
+ "kind": "exponential",
+ "n_buckets": 50,
+ "high": 600000,
+ "description": "Duration of the Sync Bookmark engine's validation process. (ms)"
+ },
"CONTENT_DOCUMENTS_DESTROYED": {
"expires_in_version": "never",
"kind": "count",
"description": "Number of content documents destroyed; used in conjunction with use counter histograms"
},
"TOP_LEVEL_CONTENT_DOCUMENTS_DESTROYED": {
"expires_in_version": "never",
"kind": "count",