From 41f5248b744e7ce9fd63cda2efab072a80bda8f0 Mon Sep 17 00:00:00 2001 From: Mark Hammond Date: Wed, 4 Feb 2015 17:36:44 +1100 Subject: [PATCH] Bug 1097406 - FHR data for sync migration. r=adw/gfritzsche --- browser/base/content/browser-fxaccounts.js | 26 ++- .../components/preferences/in-content/sync.js | 1 + services/healthreport/docs/dataformat.rst | 39 +++++ services/sync/modules/FxaMigrator.jsm | 48 +++++- services/sync/modules/healthreport.jsm | 82 +++++++++ .../tests/unit/test_healthreport_migration.js | 155 ++++++++++++++++++ services/sync/tests/unit/xpcshell.ini | 3 + 7 files changed, 352 insertions(+), 2 deletions(-) create mode 100644 services/sync/tests/unit/test_healthreport_migration.js diff --git a/browser/base/content/browser-fxaccounts.js b/browser/base/content/browser-fxaccounts.js index 11eaba13f1b..fbfa6997dfe 100644 --- a/browser/base/content/browser-fxaccounts.js +++ b/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(); }), ] diff --git a/browser/components/preferences/in-content/sync.js b/browser/components/preferences/in-content/sync.js index 92617360794..b6c7951071f 100644 --- a/browser/components/preferences/in-content/sync.js +++ b/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(); }, diff --git a/services/healthreport/docs/dataformat.rst b/services/healthreport/docs/dataformat.rst index cadef4cbe06..575b01ba7cd 100644 --- a/services/healthreport/docs/dataformat.rst +++ b/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 --------------------------- diff --git a/services/sync/modules/FxaMigrator.jsm b/services/sync/modules/FxaMigrator.jsm index 737ff36ab2d..9fb07a3fdc2 100644 --- a/services/sync/modules/FxaMigrator.jsm +++ b/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 diff --git a/services/sync/modules/healthreport.jsm b/services/sync/modules/healthreport.jsm index c50efc6e272..47161c09564 100644 --- a/services/sync/modules/healthreport.jsm +++ b/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)); }, diff --git a/services/sync/tests/unit/test_healthreport_migration.js b/services/sync/tests/unit/test_healthreport_migration.js new file mode 100644 index 00000000000..23f75674870 --- /dev/null +++ b/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(); + } +}); diff --git a/services/sync/tests/unit/xpcshell.ini b/services/sync/tests/unit/xpcshell.ini index 2ec59fb2d88..dc33c0eb283 100644 --- a/services/sync/tests/unit/xpcshell.ini +++ b/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