Bug 1265419 - Hook bookmark sync validator into the bookmark sync engine and add a telemetry probe for it f?markh draft
authorThom Chiovoloni <tchiovoloni@mozilla.com>
Mon, 25 Apr 2016 14:28:53 -0400
changeset 356158 0fe5de57c7fdd5816fe1f379d69a17729c25b324
parent 356157 7a43b64752a80cc246d3c5f792a4bc3d9a10834a
child 519354 0252b8e965c33b8e106974333341447af75b428f
push id16460
push userbmo:tchiovoloni@mozilla.com
push dateMon, 25 Apr 2016 21:02:48 +0000
bugs1265419
milestone48.0a1
Bug 1265419 - Hook bookmark sync validator into the bookmark sync engine and add a telemetry probe for it f?markh MozReview-Commit-ID: 6H32uH7ndMy
browser/app/profile/firefox.js
services/sync/modules/bookmark_validator.js
services/sync/modules/engines.js
services/sync/modules/engines/bookmarks.js
services/sync/modules/service.js
services/sync/services-sync.js
toolkit/components/telemetry/Histograms.json
--- 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",