Bug 1097406 - FHR data for sync migration. r=adw/gfritzsche

browser/base/content/browser-fxaccounts.js

@@ -10,6 +10,11 @@ let gFxAccounts = {
 
   _initialized: false,
   _inCustomizationMode: false,
+  // _expectingNotifyClose is a hack that helps us determine if the
+  // migration notification was closed due to being "dismissed" vs closed
+  // due to one of the migration buttons being clicked.  It's ugly and somewhat
+  // fragile, so bug 1119020 exists to help us do this better.
+  _expectingNotifyClose: false,
 
   get weave() {
     delete this.weave;
@@ -28,7 +33,8 @@ let gFxAccounts = {
       "weave:service:setup-complete",
       "fxa-migration:state-changed",
       this.FxAccountsCommon.ONVERIFIED_NOTIFICATION,
-      this.FxAccountsCommon.ONLOGOUT_NOTIFICATION
+      this.FxAccountsCommon.ONLOGOUT_NOTIFICATION,
+      "weave:notification:removed",
     ];
   },
 
@@ -110,6 +116,16 @@ let gFxAccounts = {
       case "fxa-migration:state-changed":
         this.onMigrationStateChanged(data, subject);
         break;
+      case "weave:notification:removed":
+        // this exists just so we can tell the difference between "box was
+        // closed due to button press" vs "was closed due to click on [x]"
+        let notif = subject.wrappedJSObject.object;
+        if (notif.title == this.SYNC_MIGRATION_NOTIFICATION_TITLE &&
+            !this._expectingNotifyClose) {
+          // it's an [x] on our notification, so record telemetry.
+          this.fxaMigrator.recordTelemetry(this.fxaMigrator.TELEMETRY_DECLINED);
+        }
+        break;
       default:
         this.updateUI();
         break;
@@ -263,7 +279,13 @@ let gFxAccounts = {
 
   updateMigrationNotification: Task.async(function* () {
     if (!this._migrationInfo) {
+      this._expectingNotifyClose = true;
       Weave.Notifications.removeAll(this.SYNC_MIGRATION_NOTIFICATION_TITLE);
+      // because this is called even when there is no such notification, we
+      // set _expectingNotifyClose back to false as we may yet create a new
+      // notification (but in general, once we've created a migration
+      // notification once in a session, we don't create one again)
+      this._expectingNotifyClose = false;
       return;
     }
     let note = null;
@@ -288,6 +310,7 @@ let gFxAccounts = {
         note = new Weave.Notification(
           undefined, msg, undefined, Weave.Notifications.PRIORITY_WARNING, [
             new Weave.NotificationButton(upgradeLabel, upgradeAccessKey, () => {
+              this._expectingNotifyClose = true;
               this.fxaMigrator.createFxAccount(window);
             }),
           ]
@@ -305,6 +328,7 @@ let gFxAccounts = {
         note = new Weave.Notification(
           undefined, msg, undefined, Weave.Notifications.PRIORITY_INFO, [
             new Weave.NotificationButton(resendLabel, resendAccessKey, () => {
+              this._expectingNotifyClose = true;
               this.fxaMigrator.resendVerificationMail();
             }),
           ]

browser/components/preferences/in-content/sync.js

@@ -403,6 +403,7 @@ let gSyncPane = {
     if (buttonChoice == 1)
       return;
 
+    fxaMigrator.recordTelemetry(fxaMigrator.TELEMETRY_UNLINKED);
     Weave.Service.startOver();
     this.updateWeavePrefs();
   },

services/healthreport/docs/dataformat.rst

@@ -1638,6 +1638,45 @@ desktop
 mobile
    Corresponds to a Fennec client.
 
+org.mozilla.sync.migration
+--------------------------
+
+This daily measurement contains information about sync migration (that is, the
+semi-automated process of migrating a legacy sync account to an FxA account.)
+
+Measurements will start being recorded after a migration is offered by the
+sync server and stop after migration is complete or the user elects to "unlink"
+their sync account.  In other words, it is expected that users with Sync setup
+for FxA or with sync unconfigured will not collect data, and that for users
+where data is collected, the collection will only be for a relatively short
+period.
+
+Version 1
+^^^^^^^^^
+
+Version 1 was introduced with Firefox 37 and includes the following properties:
+
+state
+   Corresponds to either a STATE_USER_* string or a STATE_INTERNAL_* string in
+   FxaMigration.jsm.  This reflects a state where we are waiting for the user,
+   or waiting for some internal process to complete on the way to completing
+   the migration.
+
+declined
+    Corresponds to the number of times the user closed the migration infobar.
+
+unlinked
+    Set if the user declined to migrate and instead "unlinked" Sync from the
+    browser.
+
+accepted
+    Corresponds to the number of times the user explicitly elected to start or
+    continue the migration - it counts how often the user clicked on any UI
+    created specifically for migration. The "ideal" UX for migration would see
+    this at exactly 1, some known edge-cases (eg, browser restart required to
+    finish) could expect this to be 2, and anything more means we are doing
+    something wrong.
+
 org.mozilla.sysinfo.sysinfo
 ---------------------------
 

services/sync/modules/FxaMigrator.jsm

@@ -27,13 +27,21 @@ XPCOMUtils.defineLazyModuleGetter(this, "Weave",
 let fxAccountsCommon = {};
 Cu.import("resource://gre/modules/FxAccountsCommon.js", fxAccountsCommon);
 
-// We send this notification whenever the migration state changes.
+// We send this notification whenever the "user" migration state changes.
 const OBSERVER_STATE_CHANGE_TOPIC = "fxa-migration:state-changed";
 // We also send the state notification when we *receive* this.  This allows
 // consumers to avoid loading this module until it receives a notification
 // from us (which may never happen if there's no migration to do)
 const OBSERVER_STATE_REQUEST_TOPIC = "fxa-migration:state-request";
 
+// We send this notification whenever the migration is paused waiting for
+// something internal to complete.
+const OBSERVER_INTERNAL_STATE_CHANGE_TOPIC = "fxa-migration:internal-state-changed";
+
+// We use this notification so Sync's healthreport module can record telemetry
+// (actually via "health report") for us.
+const OBSERVER_INTERNAL_TELEMETRY_TOPIC = "fxa-migration:internal-telemetry";
+
 const OBSERVER_TOPICS = [
   "xpcom-shutdown",
   "weave:service:sync:start",
@@ -86,6 +94,19 @@ Migrator.prototype = {
   STATE_USER_FXA: "waiting for user to be signed in to FxA",
   STATE_USER_FXA_VERIFIED: "waiting for a verified FxA user",
 
+  // What internal state are we at?  This is primarily used for FHR reporting so
+  // we can determine why exactly we might be stalled.
+  STATE_INTERNAL_WAITING_SYNC_COMPLETE: "waiting for sync to complete",
+  STATE_INTERNAL_WAITING_WRITE_SENTINEL: "waiting for sentinel to be written",
+  STATE_INTERNAL_WAITING_START_OVER: "waiting for sync to reset itself",
+  STATE_INTERNAL_COMPLETE: "migration complete",
+
+  // Flags for the telemetry we record.  The UI will call a helper to record
+  // the fact some UI was interacted with.
+  TELEMETRY_ACCEPTED: "accepted",
+  TELEMETRY_DECLINED: "declined",
+  TELEMETRY_UNLINKED: "unlinked",
+
   finalize() {
     for (let topic of OBSERVER_TOPICS) {
       Services.obs.removeObserver(this, topic);
@@ -199,10 +220,14 @@ Migrator.prototype = {
     if (Weave.Service._locked) {
       // our observers will kick us further along when complete.
       this.log.info("waiting for sync to complete")
+      Services.obs.notifyObservers(null, OBSERVER_INTERNAL_STATE_CHANGE_TOPIC,
+                                   this.STATE_INTERNAL_WAITING_SYNC_COMPLETE);
       return null;
     }
 
     // Write the migration sentinel if necessary.
+    Services.obs.notifyObservers(null, OBSERVER_INTERNAL_STATE_CHANGE_TOPIC,
+                                 this.STATE_INTERNAL_WAITING_WRITE_SENTINEL);
     yield this._setMigrationSentinelIfNecessary();
 
     // Get the list of enabled engines to we can restore that state.
@@ -249,6 +274,8 @@ Migrator.prototype = {
 
     Weave.Service.startOver();
     // need to wait for an observer.
+    Services.obs.notifyObservers(null, OBSERVER_INTERNAL_STATE_CHANGE_TOPIC,
+                                 this.STATE_INTERNAL_WAITING_START_OVER);
     yield startOverComplete;
     // observer fired, now kick things off with the FxA user.
     this.log.info("scheduling initial FxA sync.");
@@ -263,6 +290,8 @@ Migrator.prototype = {
     this.log.info("Migration complete");
     update(null);
 
+    Services.obs.notifyObservers(null, OBSERVER_INTERNAL_STATE_CHANGE_TOPIC,
+                                 this.STATE_INTERNAL_COMPLETE);
     return null;
   }),
 
@@ -425,6 +454,9 @@ Migrator.prototype = {
     let customize = !this._allEnginesEnabled();
     tail += "&customizeSync=" + customize;
 
+    // We assume the caller of this is going to actually use it, so record
+    // telemetry now.
+    this.recordTelemetry(this.TELEMETRY_ACCEPTED);
     return {
       url: "about:accounts?action=" + action + tail,
       options: {ignoreFragment: true, replaceQueryString: true}
@@ -448,6 +480,7 @@ Migrator.prototype = {
       this.log.error("Failed to resend verification mail: ${}", ex);
       ok = false;
     }
+    this.recordTelemetry(this.TELEMETRY_ACCEPTED);
     let fxauser = yield fxAccounts.getSignedInUser();
     let sb = Services.strings.createBundle("chrome://browser/locale/accounts.properties");
 
@@ -479,6 +512,19 @@ Migrator.prototype = {
     return fxAccounts.signOut();
   }),
 
+  recordTelemetry(flag) {
+    // Note the value is the telemetry field name - but this is an
+    // implementation detail which could be changed later.
+    switch (flag) {
+      case this.TELEMETRY_ACCEPTED:
+      case this.TELEMETRY_UNLINKED:
+      case this.TELEMETRY_DECLINED:
+        Services.obs.notifyObservers(null, OBSERVER_INTERNAL_TELEMETRY_TOPIC, flag);
+        break;
+      default:
+        throw new Error("Unexpected telemetry flag: " + flag);
+    }
+  }
 }
 
 // We expose a singleton

services/sync/modules/healthreport.jsm

@@ -63,6 +63,24 @@ SyncDevicesMeasurement1.prototype = Object.freeze({
   },
 });
 
+function SyncMigrationMeasurement1() {
+  Metrics.Measurement.call(this);
+}
+
+SyncMigrationMeasurement1.prototype = Object.freeze({
+  __proto__: Metrics.Measurement.prototype,
+
+  name: "migration",
+  version: 1,
+
+  fields: {
+    state: DAILY_LAST_TEXT_FIELD, // last "user" or "internal" state we saw for the day
+    accepted: DAILY_COUNTER_FIELD, // number of times user tried to start migration
+    declined: DAILY_COUNTER_FIELD, // number of times user closed nagging infobar
+    unlinked: DAILY_LAST_NUMERIC_FIELD, // did the user decline and unlink
+  },
+});
+
 this.SyncProvider = function () {
   Metrics.Provider.call(this);
 };
@@ -74,12 +92,16 @@ SyncProvider.prototype = Object.freeze({
   measurementTypes: [
     SyncDevicesMeasurement1,
     SyncMeasurement1,
+    SyncMigrationMeasurement1,
   ],
 
   _OBSERVERS: [
     "weave:service:sync:start",
     "weave:service:sync:finish",
     "weave:service:sync:error",
+    "fxa-migration:state-changed",
+    "fxa-migration:internal-state-changed",
+    "fxa-migration:internal-telemetry",
   ],
 
   postInit: function () {
@@ -99,6 +121,21 @@ SyncProvider.prototype = Object.freeze({
   },
 
   observe: function (subject, topic, data) {
+    switch (topic) {
+      case "weave:service:sync:start":
+      case "weave:service:sync:finish":
+      case "weave:service:sync:error":
+        return this._observeSync(subject, topic, data);
+
+      case "fxa-migration:state-changed":
+      case "fxa-migration:internal-state-changed":
+      case "fxa-migration:internal-telemetry":
+        return this._observeMigration(subject, topic, data);
+    }
+    Cu.reportError("unexpected topic in sync healthreport provider: " + topic);
+  },
+
+  _observeSync: function (subject, topic, data) {
     let field;
     switch (topic) {
       case "weave:service:sync:start":
@@ -112,6 +149,10 @@ SyncProvider.prototype = Object.freeze({
       case "weave:service:sync:error":
         field = "syncError";
         break;
+
+      default:
+        Cu.reportError("unexpected sync topic in sync healthreport provider: " + topic);
+        return;
     }
 
     let m = this.getMeasurement(SyncMeasurement1.prototype.name,
@@ -121,6 +162,47 @@ SyncProvider.prototype = Object.freeze({
     });
   },
 
+  _observeMigration: function(subject, topic, data) {
+    switch (topic) {
+      case "fxa-migration:state-changed":
+      case "fxa-migration:internal-state-changed": {
+        // We record both "user" and "internal" states in the same field.  This
+        // works for us as user state is always null when there is an internal
+        // state.
+        if (!data) {
+          return; // we don't count the |null| state
+        }
+        let m = this.getMeasurement(SyncMigrationMeasurement1.prototype.name,
+                                    SyncMigrationMeasurement1.prototype.version);
+        return this.enqueueStorageOperation(function() {
+          return m.setDailyLastText("state", data);
+        });
+      }
+
+      case "fxa-migration:internal-telemetry": {
+        // |data| is our field name.
+        let m = this.getMeasurement(SyncMigrationMeasurement1.prototype.name,
+                                    SyncMigrationMeasurement1.prototype.version);
+        return this.enqueueStorageOperation(function() {
+          switch (data) {
+            case "accepted":
+            case "declined":
+              return m.incrementDailyCounter(data);
+            case "unlinked":
+              return m.setDailyLastNumeric(data, 1);
+            default:
+              Cu.reportError("Unexpected migration field in sync healthreport provider: " + data);
+              return Promise.resolve();
+          }
+        });
+      }
+
+      default:
+        Cu.reportError("unexpected migration topic in sync healthreport provider: " + topic);
+        return;
+    }
+  },
+
   collectDailyData: function () {
     return this.storage.enqueueTransaction(this._populateDailyData.bind(this));
   },

services/sync/tests/unit/test_healthreport_migration.js

@@ -0,0 +1,155 @@
+/* Any copyright is dedicated to the Public Domain.
+ * http://creativecommons.org/publicdomain/zero/1.0/ */
+
+"use strict";
+
+Cu.import("resource://gre/modules/Metrics.jsm", this);
+Cu.import("resource://gre/modules/Preferences.jsm", this);
+Cu.import("resource://gre/modules/Promise.jsm", this);
+Cu.import("resource://services-sync/healthreport.jsm", this);
+Cu.import("resource://services-sync/FxaMigrator.jsm", this);
+Cu.import("resource://testing-common/services/common/logging.js", this);
+Cu.import("resource://testing-common/services/healthreport/utils.jsm", this);
+
+
+function run_test() {
+  initTestLogging();
+
+  run_next_test();
+}
+
+add_task(function* test_no_data() {
+  let storage = yield Metrics.Storage("collect");
+  let provider = new SyncProvider();
+  yield provider.init(storage);
+
+  try {
+    // Initially nothing should be configured.
+    let now = new Date();
+    yield provider.collectDailyData();
+
+    let m = provider.getMeasurement("migration", 1);
+    let values = yield m.getValues();
+    Assert.equal(values.days.size, 0);
+    Assert.ok(!values.days.hasDay(now));
+  } finally {
+    yield provider.shutdown();
+    yield storage.close();
+  }
+});
+
+function checkCorrectStateRecorded(provider, state) {
+  // Wait for storage to complete.
+  yield m.storage.enqueueOperation(() => {
+    return Promise.resolve();
+  });
+
+  let m = provider.getMeasurement("migration", 1);
+  let values = yield m.getValues();
+  Assert.equal(values.days.size, 1);
+  Assert.ok(values.days.hasDay(now));
+  let day = values.days.getDay(now);
+
+  Assert.ok(day.has("state"));
+  Assert.equal(day.get("state"), state);
+}
+
+add_task(function* test_state() {
+  let storage = yield Metrics.Storage("collect");
+  let provider = new SyncProvider();
+  yield provider.init(storage);
+
+  try {
+    // Initially nothing should be configured.
+    let now = new Date();
+
+    // We record both a "user" and "internal" state in the same field.
+    // So simulate a "user" state first.
+    Services.obs.notifyObservers(null, "fxa-migration:state-changed",
+                                 fxaMigrator.STATE_USER_FXA_VERIFIED);
+    checkCorrectStateRecorded(provider, fxaMigrator.STATE_USER_FXA_VERIFIED);
+
+    // And an internal state.
+    Services.obs.notifyObservers(null, "fxa-migration:internal-state-changed",
+                                 fxaMigrator.STATE_INTERNAL_WAITING_SYNC_COMPLETE);
+    checkCorrectStateRecorded(provider, fxaMigrator.STATE_INTERNAL_WAITING_SYNC_COMPLETE);
+  } finally {
+    yield provider.shutdown();
+    yield storage.close();
+  }
+});
+
+add_task(function* test_flags() {
+  let storage = yield Metrics.Storage("collect");
+  let provider = new SyncProvider();
+  yield provider.init(storage);
+
+  try {
+    // Initially nothing should be configured.
+    let now = new Date();
+
+    let m = provider.getMeasurement("migration", 1);
+
+    let record = function*(what) {
+      Services.obs.notifyObservers(null, "fxa-migration:internal-telemetry", what);
+      // Wait for storage to complete.
+      yield m.storage.enqueueOperation(Promise.resolve);
+      let values = yield m.getValues();
+      Assert.equal(values.days.size, 1);
+      return values.days.getDay(now);
+    }
+
+    let values = yield m.getValues();
+    Assert.equal(values.days.size, 1);
+    let day = values.days.getDay(now);
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_ACCEPTED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_DECLINED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_UNLINKED));
+
+    // let's send an unknown value to ensure our error mitigation works.
+    day = yield record("unknown");
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_ACCEPTED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_DECLINED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_UNLINKED));
+
+    // record an fxaMigrator.TELEMETRY_ACCEPTED state.
+    day = yield record(fxaMigrator.TELEMETRY_ACCEPTED);
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_ACCEPTED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_DECLINED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_UNLINKED));
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_ACCEPTED), 1);
+
+    // and again - it should get 2.
+    day = yield record(fxaMigrator.TELEMETRY_ACCEPTED);
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_ACCEPTED), 2);
+
+    // record fxaMigrator.TELEMETRY_DECLINED - also a counter.
+    day = yield record(fxaMigrator.TELEMETRY_DECLINED);
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_ACCEPTED));
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_DECLINED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_UNLINKED));
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_ACCEPTED), 2);
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_DECLINED), 1);
+
+    day = yield record(fxaMigrator.TELEMETRY_DECLINED);
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_ACCEPTED));
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_DECLINED));
+    Assert.ok(!day.has(fxaMigrator.TELEMETRY_UNLINKED));
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_ACCEPTED), 2);
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_DECLINED), 2);
+
+    // and fxaMigrator.TELEMETRY_UNLINKED - this is conceptually a "daily bool".
+    // (ie, it's DAILY_LAST_NUMERIC_FIELD and only ever has |1| written to it)
+    day = yield record(fxaMigrator.TELEMETRY_UNLINKED);
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_ACCEPTED));
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_DECLINED));
+    Assert.ok(day.has(fxaMigrator.TELEMETRY_UNLINKED));
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_UNLINKED), 1);
+    // and doing it again still leaves us with |1|
+    day = yield record(fxaMigrator.TELEMETRY_UNLINKED);
+    Assert.equal(day.get(fxaMigrator.TELEMETRY_UNLINKED), 1);
+  } finally {
+    yield provider.shutdown();
+    yield storage.close();
+  }
+});

services/sync/tests/unit/xpcshell.ini

@@ -171,6 +171,9 @@ skip-if = debug
 [test_healthreport.js]
 skip-if = ! healthreport
 
+[test_healthreport_migration.js]
+skip-if = ! healthreport
+
 [test_warn_on_truncated_response.js]
 
 # FxA migration