Bug 1416320 - (DO NOT REVIEW - CURRENTLY IN AUTOLAND - #1304898) Include why in sync ping. draft
authorEdouard Oger <eoger@fastmail.com>
Wed, 15 Nov 2017 17:10:45 -0500
changeset 699235 ff77e460c4aace4769682206966b8be66289551d
parent 699096 a3f183201f7f183c263d554bfb15fbf0b0ed2ea4
child 699236 5f91af3250a80640c70be2d9f7ab32ac8a2ab57f
push id89506
push userbmo:eoger@fastmail.com
push dateThu, 16 Nov 2017 21:20:40 +0000
bugs1416320, 1304898
milestone59.0a1
Bug 1416320 - (DO NOT REVIEW - CURRENTLY IN AUTOLAND - #1304898) Include why in sync ping. MozReview-Commit-ID: G9WnHhuWD7Z
browser/base/content/browser-pageActions.js
services/sync/modules/SyncedTabs.jsm
services/sync/modules/service.js
services/sync/modules/telemetry.js
services/sync/tests/unit/sync_ping_schema.json
services/sync/tests/unit/test_engine_changes_during_sync.js
services/sync/tests/unit/test_service_sync_specified.js
services/sync/tests/unit/test_telemetry.js
--- a/browser/base/content/browser-pageActions.js
+++ b/browser/base/content/browser-pageActions.js
@@ -1003,17 +1003,17 @@ BrowserPageActions.sendToDevice = {
 
     bodyNode.removeAttribute("state");
     // In the first ~10 sec after startup, Sync may not be loaded and the list
     // of devices will be empty.
     if (gSync.syncConfiguredAndLoading) {
       bodyNode.setAttribute("state", "notready");
       // Force a background Sync
       Services.tm.dispatchToMainThread(async () => {
-        await Weave.Service.sync([]); // [] = clients engine only
+        await Weave.Service.sync({why: "pageactions", engines: []}); // [] = clients engine only
         // There's no way Sync is still syncing at this point, but we check
         // anyway to avoid infinite looping.
         if (!window.closed && !gSync.syncConfiguredAndLoading) {
           this.onShowingSubview(panelViewNode);
         }
       });
     }
   },
--- a/services/sync/modules/SyncedTabs.jsm
+++ b/services/sync/modules/SyncedTabs.jsm
@@ -156,17 +156,17 @@ let SyncedTabsInternal = {
     // of a login failure.
     if (Weave.Status.checkSetup() == Weave.CLIENT_NOT_CONFIGURED) {
       log.info("Sync client is not configured, so not attempting a tab sync");
       return false;
     }
     // Ask Sync to just do the tabs engine if it can.
     try {
       log.info("Doing a tab sync.");
-      await Weave.Service.sync(["tabs"]);
+      await Weave.Service.sync({why: "tabs", engines: ["tabs"]});
       return true;
     } catch (ex) {
       log.error("Sync failed", ex);
       throw ex;
     }
   },
 
   observe(subject, topic, data) {
--- a/services/sync/modules/service.js
+++ b/services/sync/modules/service.js
@@ -428,17 +428,17 @@ Sync11Service.prototype = {
       case "sync:collection_changed":
         // We check if we're running TPS here to avoid TPS failing because it
         // couldn't get to get the sync lock, due to us currently syncing the
         // clients engine.
         if (data.includes("clients") && !Svc.Prefs.get("testing.tps", false)) {
           // Sync in the background (it's fine not to wait on the returned promise
           // because sync() has a lock).
           // [] = clients collection only
-          this.sync([]).catch(e => {
+          this.sync({why: "collection_changed", engines: []}).catch(e => {
             this._log.error(e);
           });
         }
         break;
       case "fxaccounts:device_disconnected":
         data = JSON.parse(data);
         if (!data.isLocalDevice) {
           Async.promiseSpinningly(this.clientsEngine.updateKnownStaleClients());
@@ -1077,41 +1077,41 @@ Sync11Service.prototype = {
       reason = kFirefoxShuttingDown;
 
     if (ignore && ignore.indexOf(reason) != -1)
       return "";
 
     return reason;
   },
 
-  async sync(engineNamesToSync) {
+  async sync({engines, why} = {}) {
     let dateStr = Utils.formatTimestamp(new Date());
     this._log.debug("User-Agent: " + Utils.userAgent);
     this._log.info(`Starting sync at ${dateStr} in browser session ${browserSessionID}`);
     return this._catch(async function() {
       // Make sure we're logged in.
       if (this._shouldLogin()) {
         this._log.debug("In sync: should login.");
         if (!(await this.login())) {
           this._log.debug("Not syncing: login returned false.");
           return;
         }
       } else {
         this._log.trace("In sync: no need to login.");
       }
-      await this._lockedSync(engineNamesToSync);
+      await this._lockedSync(engines, why);
     })();
   },
 
   /**
    * Sync up engines with the server.
    */
-  async _lockedSync(engineNamesToSync) {
+  async _lockedSync(engineNamesToSync, why) {
     return this._lock("service.js: sync",
-                      this._notify("sync", "", async function onNotify() {
+                      this._notify("sync", JSON.stringify({why}), async function onNotify() {
 
       let histogram = Services.telemetry.getHistogramById("WEAVE_START_COUNT");
       histogram.add(1);
 
       let synchronizer = new EngineSynchronizer(this);
       await synchronizer.sync(engineNamesToSync); // Might throw!
 
       histogram = Services.telemetry.getHistogramById("WEAVE_COMPLETE_SUCCESS_COUNT");
--- a/services/sync/modules/telemetry.js
+++ b/services/sync/modules/telemetry.js
@@ -213,41 +213,45 @@ class EngineRecord {
         sent: counts.sent || undefined,
         failed: counts.failed || undefined,
       });
     }
   }
 }
 
 class TelemetryRecord {
-  constructor(allowedEngines) {
+  constructor(allowedEngines, why) {
     this.allowedEngines = allowedEngines;
     // Our failure reason. This property only exists in the generated ping if an
     // error actually occurred.
     this.failureReason = undefined;
     this.uid = "";
     this.when = Date.now();
     this.startTime = tryGetMonotonicTimestamp();
     this.took = 0; // will be set later.
+    this.why = why;
 
     // All engines that have finished (ie, does not include the "current" one)
     // We omit this from the ping if it's empty.
     this.engines = [];
     // The engine that has started but not yet stopped.
     this.currentEngine = null;
   }
 
   toJSON() {
     let result = {
       when: this.when,
       took: this.took,
       failureReason: this.failureReason,
       status: this.status,
       devices: this.devices,
     };
+    if (this.why) {
+      result.why = this.why;
+    }
     let engines = [];
     for (let engine of this.engines) {
       engines.push(engine.toJSON());
     }
     if (engines.length > 0) {
       result.engines = engines;
     }
     return result;
@@ -492,23 +496,24 @@ class SyncTelemetryImpl {
       log.trace(`submitting ${record.syncs.length} sync record(s) to telemetry`);
       TelemetryController.submitExternalPing("sync", record);
       return true;
     }
     return false;
   }
 
 
-  onSyncStarted() {
+  onSyncStarted(data) {
+    const why = data && JSON.parse(data).why;
     if (this.current) {
       log.warn("Observed weave:service:sync:start, but we're already recording a sync!");
       // Just discard the old record, consistent with our handling of engines, above.
       this.current = null;
     }
-    this.current = new TelemetryRecord(this.allowedEngines);
+    this.current = new TelemetryRecord(this.allowedEngines, why);
   }
 
   _checkCurrent(topic) {
     if (!this.current) {
       log.warn(`Observed notification ${topic} but no current sync is being recorded.`);
       return false;
     }
     return true;
@@ -600,17 +605,17 @@ class SyncTelemetryImpl {
 
     switch (topic) {
       case "profile-before-change":
         this.shutdown();
         break;
 
       /* sync itself state changes */
       case "weave:service:sync:start":
-        this.onSyncStarted();
+        this.onSyncStarted(data);
         break;
 
       case "weave:service:sync:finish":
         if (this._checkCurrent(topic)) {
           this.onSyncFinished(null);
         }
         break;
 
--- a/services/sync/tests/unit/sync_ping_schema.json
+++ b/services/sync/tests/unit/sync_ping_schema.json
@@ -48,17 +48,17 @@
             { "required": ["service"] }
           ],
           "additionalProperties": false,
           "properties": {
             "sync": { "type": "string" },
             "service": { "type": "string" }
           }
         },
-        "why": { "enum": ["startup", "schedule", "score", "user", "tabs"] },
+        "why": { "type": "string" },
         "took": { "type": "integer", "minimum": -1 },
         "failureReason": { "$ref": "#/definitions/error" },
         "engines": {
           "type": "array",
           "minItems": 1,
           "items": { "$ref": "#/definitions/engine" }
         }
       }
--- a/services/sync/tests/unit/test_engine_changes_during_sync.js
+++ b/services/sync/tests/unit/test_engine_changes_during_sync.js
@@ -389,17 +389,17 @@ add_task(async function test_bookmark_ch
       "toolbar",
       "unfiled",
     ].sort(), "Should track bookmark and folder created before first sync");
 
     // Unlike the tests above, we can't use `sync_engine_and_validate_telem`
     // because the bookmarks engine will automatically schedule a follow-up
     // sync for us.
     _("Perform first sync and immediate follow-up sync");
-    Service.sync(["bookmarks"]);
+    Service.sync({engines: ["bookmarks"]});
 
     let pings = await pingsPromise;
     equal(pings.length, 2, "Should submit two pings");
     ok(pings.every(p => {
       assert_success_ping(p);
       return p.syncs.length == 1;
     }), "Should submit 1 sync per ping");
 
--- a/services/sync/tests/unit/test_service_sync_specified.js
+++ b/services/sync/tests/unit/test_service_sync_specified.js
@@ -85,17 +85,17 @@ add_task(async function setup() {
 add_task(async function test_noEngines() {
   enableValidationPrefs();
 
   _("Test: An empty array of engines to sync does nothing.");
   let server = await setUp();
 
   try {
     _("Sync with no engines specified.");
-    await Service.sync([]);
+    await Service.sync({engines: []});
     deepEqual(syncedEngines, [], "no engines were synced");
 
   } finally {
     await Service.startOver();
     await promiseStopServer(server);
   }
 });
 
@@ -103,51 +103,51 @@ add_task(async function test_oneEngine()
   enableValidationPrefs();
 
   _("Test: Only one engine is synced.");
   let server = await setUp();
 
   try {
 
     _("Sync with 1 engine specified.");
-    await Service.sync(["steam"]);
+    await Service.sync({engines: ["steam"]});
     deepEqual(syncedEngines, ["steam"]);
 
   } finally {
     await Service.startOver();
     await promiseStopServer(server);
   }
 });
 
 add_task(async function test_bothEnginesSpecified() {
   enableValidationPrefs();
 
   _("Test: All engines are synced when specified in the correct order (1).");
   let server = await setUp();
 
   try {
     _("Sync with both engines specified.");
-    await Service.sync(["steam", "stirling"]);
+    await Service.sync({engines: ["steam", "stirling"]});
     deepEqual(syncedEngines, ["steam", "stirling"]);
 
   } finally {
     await Service.startOver();
     await promiseStopServer(server);
   }
 });
 
 add_task(async function test_bothEnginesSpecified() {
   enableValidationPrefs();
 
   _("Test: All engines are synced when specified in the correct order (2).");
   let server = await setUp();
 
   try {
     _("Sync with both engines specified.");
-    await Service.sync(["stirling", "steam"]);
+    await Service.sync({engines: ["stirling", "steam"]});
     deepEqual(syncedEngines, ["stirling", "steam"]);
 
   } finally {
     await Service.startOver();
     await promiseStopServer(server);
   }
 });
 
--- a/services/sync/tests/unit/test_telemetry.js
+++ b/services/sync/tests/unit/test_telemetry.js
@@ -520,16 +520,39 @@ add_task(async function test_nserror() {
       code: Cr.NS_ERROR_UNKNOWN_HOST
     });
   } finally {
     await cleanAndGo(engine, server);
     Service.engineManager.unregister(engine);
   }
 });
 
+add_task(async function test_sync_why() {
+  enableValidationPrefs();
+
+  await Service.engineManager.register(SteamEngine);
+  let engine = Service.engineManager.get("steam");
+  engine.enabled = true;
+  let server = await serverForFoo(engine);
+  await SyncTestingInfrastructure(server);
+  let e = new Error("generic failure message");
+  engine._errToThrow = e;
+
+  try {
+    _(`test_generic_engine_fail: Steam tracker contents: ${
+      JSON.stringify(engine._tracker.changedIDs)}`);
+    let ping = await wait_for_ping(() => Service.sync({why: "user"}), true, false);
+    _(JSON.stringify(ping))
+    equal(ping.why, "user");
+  } finally {
+    await cleanAndGo(engine, server);
+    Service.engineManager.unregister(engine);
+  }
+});
+
 add_task(async function test_discarding() {
   enableValidationPrefs();
 
   let helper = track_collections_helper();
   let upd = helper.with_updated_collection;
   let telem = get_sync_test_telemetry();
   telem.maxPayloadCount = 2;
   telem.submissionInterval = Infinity;