Bug 1552621 - Record bookmark validation telemetry for the buffered engine. r=tcsc

Differential Revision: https://phabricator.services.mozilla.com/D33410

--HG--
extra : moz-landing-system : lando

services/sync/modules/doctor.js

@@ -178,7 +178,13 @@ var Doctor = {
         // if we don't end up repairing?
         log.info(`Running validator for ${engine.name}`);
         let result = await validator.validate(engine);
-        Observers.notify("weave:engine:validate:finish", result, engine.name);
+        let { problems, version, duration, recordCount } = result;
+        Observers.notify("weave:engine:validate:finish", {
+          version,
+          checked: recordCount,
+          took: duration,
+          problems: problems ? problems.getSummary(true) : null,
+        }, engine.name);
         // And see if we should repair.
         await this._maybeCure(engine, result, flowID);
       } catch (ex) {

services/sync/modules/engines/bookmarks.js

@@ -18,6 +18,7 @@ const {Svc, Utils} = ChromeUtils.import("resource://services-sync/util.js");
 XPCOMUtils.defineLazyModuleGetters(this, {
   BookmarkValidator: "resource://services-sync/bookmark_validator.js",
   LiveBookmarkMigrator: "resource:///modules/LiveBookmarkMigrator.jsm",
+  Observers: "resource://services-common/observers.js",
   OS: "resource://gre/modules/osfile.jsm",
   PlacesBackups: "resource://gre/modules/PlacesBackups.jsm",
   PlacesDBUtils: "resource://gre/modules/PlacesDBUtils.jsm",
@@ -62,6 +63,12 @@ XPCOMUtils.defineLazyGetter(this, "IGNORED_SOURCES", () => [
   PlacesUtils.bookmarks.SOURCES.SYNC_REPARENT_REMOVED_FOLDER_CHILDREN,
 ]);
 
+// The validation telemetry version for the buffered engine. Version 1 is
+// collected by `bookmark_validator.js`, and checks value as well as structure
+// differences. Version 2 is collected by the buffered engine as part of
+// building the remote tree, and checks structure differences only.
+const BUFFERED_BOOKMARK_VALIDATOR_VERSION = 2;
+
 function isSyncedRootNode(node) {
   return node.root == "bookmarksMenuFolder" ||
          node.root == "unfiledBookmarksFolder" ||
@@ -476,10 +483,6 @@ BaseBookmarksEngine.prototype = {
     return FORBIDDEN_INCOMING_IDS.includes(incomingItem.id) ||
            FORBIDDEN_INCOMING_PARENT_IDS.includes(incomingItem.parentid);
   },
-
-  getValidator() {
-    return new BookmarkValidator();
-  },
 };
 
 /**
@@ -750,6 +753,10 @@ BookmarksEngine.prototype = {
     this._log.debug("Recording children of " + localRecord.id, order);
     this._store._childrenToOrder[localRecord.id] = order;
   },
+
+  getValidator() {
+    return new BookmarkValidator();
+  },
 };
 
 /**
@@ -1220,7 +1227,14 @@ BufferedBookmarksStore.prototype = {
                                                  extra);
       },
       recordStepTelemetry() {},
-      recordValidationTelemetry() {},
+      recordValidationTelemetry: (took, checked, problems) => {
+        Observers.notify("weave:engine:validate:finish", {
+          version: BUFFERED_BOOKMARK_VALIDATOR_VERSION,
+          took,
+          checked,
+          problems,
+        }, this.name);
+      },
     });
   },
 

services/sync/modules/telemetry.js

@@ -211,15 +211,15 @@ class EngineRecord {
       log.error(`Multiple validations occurred for engine ${this.name}!`);
       return;
     }
-    let { problems, version, duration, recordCount } = validationResult;
+    let { problems, version, took, checked } = validationResult;
     let validation = {
       version: version || 0,
-      checked: recordCount || 0,
+      checked: checked || 0,
     };
-    if (duration > 0) {
-      validation.took = Math.round(duration);
+    if (took > 0) {
+      validation.took = Math.round(took);
     }
-    let summarized = problems.getSummary(true).filter(({count}) => count > 0);
+    let summarized = problems.filter(({count}) => count > 0);
     if (summarized.length) {
       validation.problems = summarized;
     }

services/sync/tests/unit/test_bookmark_engine.js

@@ -160,6 +160,8 @@ add_bookmark_test(async function test_maintenance_after_failure(engine) {
 add_bookmark_test(async function test_delete_invalid_roots_from_server(engine) {
   _("Ensure that we delete the Places and Reading List roots from the server.");
 
+  enableValidationPrefs();
+
   let store   = engine._store;
   let server = await serverForFoo(engine);
   await SyncTestingInfrastructure(server);
@@ -186,6 +188,9 @@ add_bookmark_test(async function test_delete_invalid_roots_from_server(engine) {
     readingList.parentid = "places";
     collection.insert("readinglist", encryptPayload(readingList.cleartext));
 
+    // Note that we don't insert a record for the toolbar, so the buffered
+    // engine will report a parent-child disagreement, since Firefox's
+    // `parentid` is `toolbar`.
     let newBmk = new Bookmark("bookmarks", Utils.makeGUID());
     newBmk.bmkUri = "http://getfirefox.com";
     newBmk.title = "Get Firefox!";
@@ -196,7 +201,26 @@ add_bookmark_test(async function test_delete_invalid_roots_from_server(engine) {
     deepEqual(collection.keys().sort(), ["places", "readinglist", listBmk.id, newBmk.id].sort(),
       "Should store Places root, reading list items, and new bookmark on server");
 
-    await sync_engine_and_validate_telem(engine, false);
+    if (engine instanceof BufferedBookmarksEngine) {
+      let ping = await sync_engine_and_validate_telem(engine, true);
+      if (engine instanceof BufferedBookmarksEngine) {
+        // In a real sync, the buffered engine is named `bookmarks-buffered`.
+        // However, `sync_engine_and_validate_telem` simulates a sync, where
+        // the engine isn't registered with the engine manager, so the recorder
+        // doesn't see its `overrideTelemetryName`.
+        let engineData = ping.engines.find(e => e.name == "bookmarks");
+        ok(engineData.validation, "Buffered engine should always run validation");
+        equal(engineData.validation.checked, 6, "Buffered engine should validate all items");
+        deepEqual(engineData.validation.problems, [{
+          name: "parentChildDisagreements",
+          count: 1,
+        }], "Buffered engine should report parent-child disagreement");
+      }
+    } else {
+      // The legacy engine doesn't report validation failures for this case,
+      // so we disallow error pings.
+      await sync_engine_and_validate_telem(engine, false);
+    }
 
     await Assert.rejects(PlacesUtils.promiseItemId("readinglist"),
       /no item found for the given GUID/, "Should not apply Reading List root");
@@ -769,6 +793,14 @@ add_bookmark_test(async function test_sync_dateAdded(engine) {
   let oneYearMS = 365 * 24 * 60 * 60 * 1000;
 
   try {
+    let toolbar = new BookmarkFolder("bookmarks", "toolbar");
+    toolbar.title = "toolbar";
+    toolbar.parentName = "";
+    toolbar.parentid = "places";
+    toolbar.children = ["abcdefabcdef", "aaaaaaaaaaaa", "bbbbbbbbbbbb",
+                        "cccccccccccc", "dddddddddddd", "eeeeeeeeeeee"];
+    collection.insert("toolbar", encryptPayload(toolbar.cleartext));
+
     let item1GUID = "abcdefabcdef";
     let item1 = new Bookmark("bookmarks", item1GUID);
     item1.bmkUri = "https://example.com";

services/sync/tests/unit/test_bookmark_repair.js

@@ -6,7 +6,7 @@
 const {BookmarkRepairRequestor} = ChromeUtils.import("resource://services-sync/bookmark_repair.js");
 const {Service} = ChromeUtils.import("resource://services-sync/service.js");
 const {ClientEngine} = ChromeUtils.import("resource://services-sync/engines/clients.js");
-const {BufferedBookmarksEngine} = ChromeUtils.import("resource://services-sync/engines/bookmarks.js");
+const {BookmarksEngine} = ChromeUtils.import("resource://services-sync/engines/bookmarks.js");
 
 const BOOKMARK_REPAIR_STATE_PREFS = [
   "client.GUID",
@@ -22,7 +22,7 @@ var recordedEvents = [];
 
 add_task(async function setup() {
   await Service.engineManager.unregister("bookmarks");
-  await Service.engineManager.register(BufferedBookmarksEngine);
+  await Service.engineManager.register(BookmarksEngine);
 
   clientsEngine = Service.clientsEngine;
   clientsEngine.ignoreLastModifiedOnProcessCommands = true;
@@ -36,9 +36,7 @@ add_task(async function setup() {
 });
 
 function checkRecordedEvents(expected, message) {
-  // Ignore event telemetry from the merger.
-  let repairEvents = recordedEvents.filter(event => event.object != "mirror");
-  deepEqual(repairEvents, expected, message);
+  deepEqual(recordedEvents, expected, message);
   // and clear the list so future checks are easier to write.
   recordedEvents = [];
 }
@@ -63,7 +61,7 @@ async function promiseValidationDone(expected) {
   let obs = promiseOneObserver("weave:engine:validate:finish");
   let { subject: validationResult } = await obs;
   // check the results - anything non-zero is checked against |expected|
-  let summary = validationResult.problems.getSummary();
+  let summary = validationResult.problems;
   let actual = summary.filter(({name, count}) => count);
   actual.sort((a, b) => String(a.name).localeCompare(b.name));
   expected.sort((a, b) => String(a.name).localeCompare(b.name));
@@ -125,16 +123,7 @@ add_task(async function test_bookmark_repair_integration() {
     checkRecordedEvents([], "Should not start repair after first sync");
 
     _("Back up last sync timestamps for remote client");
-    let buf = await bookmarksEngine._store.ensureOpenMirror();
-    let metaRows = await buf.db.execute(`
-      SELECT key, value FROM meta`);
-    let metaInfos = [];
-    for (let row of metaRows) {
-      metaInfos.push({
-        key: row.getResultByName("key"),
-        value: row.getResultByName("value"),
-      });
-    }
+    let lastSync = await PlacesSyncUtils.bookmarks.getLastSync();
 
     _(`Delete ${bookmarkInfo.guid} locally and on server`);
     // Now we will reach into the server and hard-delete the bookmark
@@ -147,30 +136,11 @@ add_task(async function test_bookmark_repair_integration() {
     deepEqual((await PlacesSyncUtils.bookmarks.pullChanges()), {},
       `Should not upload tombstone for ${bookmarkInfo.guid}`);
 
-    // Remove the bookmark from the mirror, too.
-    let itemRows = await buf.db.execute(`
-      SELECT guid, kind, title, urlId
-      FROM items
-      WHERE guid = :guid`,
-      { guid: bookmarkInfo.guid });
-    equal(itemRows.length, 1, `Bookmark ${
-      bookmarkInfo.guid} should exist in mirror`);
-    let bufInfos = [];
-    for (let row of itemRows) {
-      bufInfos.push({
-        guid: row.getResultByName("guid"),
-        kind: row.getResultByName("kind"),
-        title: row.getResultByName("title"),
-        urlId: row.getResultByName("urlId"),
-      });
-    }
-    await buf.db.execute(`DELETE FROM items WHERE guid = :guid`,
-                         { guid: bookmarkInfo.guid });
-
     // sync again - we should have a few problems...
     _("Sync again to trigger repair");
     validationPromise = promiseValidationDone([
       {"name": "missingChildren", "count": 1},
+      {"name": "sdiff:childGUIDs", "count": 1},
       {"name": "structuralDifferences", "count": 1},
     ]);
     await Service.sync();
@@ -215,6 +185,7 @@ add_task(async function test_bookmark_repair_integration() {
 
     _("Back up repair state to restore later");
     let restoreInitialRepairState = backupPrefs(BOOKMARK_REPAIR_STATE_PREFS);
+    let initialLastSync = await PlacesSyncUtils.bookmarks.getLastSync();
 
     // so now let's take over the role of that other client!
     _("Create new clients engine pretending to be remote client");
@@ -228,14 +199,7 @@ add_task(async function test_bookmark_repair_integration() {
     // repair instead of the sync.
     bookmarkInfo.source = PlacesUtils.bookmarks.SOURCE_SYNC;
     await PlacesUtils.bookmarks.insert(bookmarkInfo);
-    await buf.db.execute(`
-      INSERT INTO items(guid, urlId, kind, title)
-      VALUES(:guid, :urlId, :kind, :title)`,
-      bufInfos);
-    await buf.db.execute(`
-      REPLACE INTO meta(key, value)
-      VALUES(:key, :value)`,
-      metaInfos);
+    await PlacesSyncUtils.bookmarks.setLastSync(lastSync);
 
     _("Sync as remote client");
     await Service.sync();
@@ -294,13 +258,8 @@ add_task(async function test_bookmark_repair_integration() {
     await PlacesUtils.bookmarks.remove(bookmarkInfo.guid, {
       source: PlacesUtils.bookmarks.SOURCE_SYNC,
     });
-    await buf.db.execute(`DELETE FROM items WHERE guid = :guid`,
-                         { guid: bookmarkInfo.guid });
-    await buf.db.execute(`
-      REPLACE INTO meta(key, value)
-      VALUES(:key, :value)`,
-      metaInfos);
     restoreInitialRepairState();
+    await PlacesSyncUtils.bookmarks.setLastSync(initialLastSync);
     ok(Services.prefs.prefHasUserValue("services.sync.repairs.bookmarks.state"),
       "Initial client should still be repairing");
 
@@ -387,10 +346,6 @@ add_task(async function test_repair_client_missing() {
     await PlacesUtils.bookmarks.remove(bookmarkInfo.guid, {
       source: PlacesUtils.bookmarks.SOURCE_SYNC,
     });
-    // Delete the bookmark from the mirror, too.
-    let buf = await bookmarksEngine._store.ensureOpenMirror();
-    await buf.db.execute(`DELETE FROM items WHERE guid = :guid`,
-                         { guid: bookmarkInfo.guid });
 
     // Ensure we won't upload a tombstone for the removed bookmark.
     Assert.deepEqual((await PlacesSyncUtils.bookmarks.pullChanges()), {});
@@ -401,6 +356,7 @@ add_task(async function test_repair_client_missing() {
     _("Syncing again.");
     validationPromise = promiseValidationDone([
       {"name": "clientMissing", "count": 1},
+      {"name": "sdiff:childGUIDs", "count": 1},
       {"name": "structuralDifferences", "count": 1},
     ]);
     await Service.sync();

services/sync/tests/unit/test_bookmark_validator.js

@@ -390,10 +390,10 @@ async function validationPing(server, client, duration) {
   let {problemData} = await validator.compareServerWithClient(server, client);
   let data = {
     // We fake duration and version just so that we can verify they"re passed through.
-    duration,
+    took: duration,
     version: validator.version,
-    recordCount: server.length,
-    problems: problemData,
+    checked: server.length,
+    problems: problemData.getSummary(true),
   };
   Svc.Obs.notify("weave:engine:validate:finish", data, "bookmarks");
   Svc.Obs.notify("weave:service:sync:finish");

services/sync/tests/unit/test_engine_changes_during_sync.js

@@ -476,8 +476,12 @@ add_task(async function test_bookmark_change_during_sync() {
                                               "bookmarks";
       return p.syncs[0].engines.find(e => e.name == name);
     });
-    ok(!engineData[0].validation, "Should not validate after first sync");
-    ok(engineData[1].validation, "Should validate after second sync");
+    if (bufferedBookmarksEnabled()) {
+      ok(engineData[0].validation, "Buffered engine should validate after first sync");
+    } else {
+      ok(!engineData[0].validation, "Legacy engine should not validate after first sync");
+    }
+    ok(engineData[1].validation, "Buffered and legacy engines should validate after second sync");
   } finally {
     engine._uploadOutgoing = uploadOutgoing;
     await cleanup(engine, server);