Bug 1455735 - Await running recipes r?Gijs draft
authorMike Cooper <mcooper@mozilla.com>
Tue, 24 Apr 2018 12:45:30 -0700
changeset 787389 be1e525b66b6ae82913f8a72df62f73ee1adc62d
parent 786478 dfb15917c057f17e5143f7d7c6e1972ba53efc49
push id107719
push userbmo:mcooper@mozilla.com
push dateTue, 24 Apr 2018 19:49:55 +0000
reviewersGijs
bugs1455735
milestone61.0a1
Bug 1455735 - Await running recipes r?Gijs MozReview-Commit-ID: Br3GqyPuoK6
toolkit/components/normandy/Normandy.jsm
toolkit/components/normandy/actions/PreferenceRolloutAction.jsm
toolkit/components/normandy/lib/PreferenceRollouts.jsm
toolkit/components/normandy/lib/RecipeRunner.jsm
toolkit/components/normandy/lib/TelemetryEvents.jsm
toolkit/components/normandy/test/browser/browser_RecipeRunner.js
--- a/toolkit/components/normandy/Normandy.jsm
+++ b/toolkit/components/normandy/Normandy.jsm
@@ -54,33 +54,33 @@ var Normandy = {
   observe(subject, topic, data) {
     if (topic === UI_AVAILABLE_NOTIFICATION) {
       Services.obs.removeObserver(this, UI_AVAILABLE_NOTIFICATION);
       this.finishInit();
     }
   },
 
   async finishInit() {
+    try {
+      TelemetryEvents.init();
+    } catch (err) {
+      log.error("Failed to initialize telemetry events:", err);
+    }
+
     await PreferenceRollouts.recordOriginalValues(this.rolloutPrefsChanged);
     await PreferenceExperiments.recordOriginalValues(this.studyPrefsChanged);
 
     // Setup logging and listen for changes to logging prefs
     LogManager.configure(Services.prefs.getIntPref(PREF_LOGGING_LEVEL, Log.Level.Warn));
     Services.prefs.addObserver(PREF_LOGGING_LEVEL, LogManager.configure);
     CleanupManager.addCleanupHandler(
       () => Services.prefs.removeObserver(PREF_LOGGING_LEVEL, LogManager.configure),
     );
 
     try {
-      TelemetryEvents.init();
-    } catch (err) {
-      log.error("Failed to initialize telemetry events:", err);
-    }
-
-    try {
       await AboutPages.init();
     } catch (err) {
       log.error("Failed to initialize about pages:", err);
     }
 
     try {
       await AddonStudies.init();
     } catch (err) {
--- a/toolkit/components/normandy/actions/PreferenceRolloutAction.jsm
+++ b/toolkit/components/normandy/actions/PreferenceRolloutAction.jsm
@@ -34,17 +34,17 @@ class PreferenceRolloutAction extends Ba
     await this._verifyRolloutPrefs(args);
 
     const newRollout = {
       slug: args.slug,
       state: "active",
       preferences: args.preferences.map(({preferenceName, value}) => ({
         preferenceName,
         value,
-        previousValue: null,
+        previousValue: PrefUtils.getPref("default", preferenceName),
       })),
     };
 
     const existingRollout = await PreferenceRollouts.get(args.slug);
     if (existingRollout) {
       const anyChanged = await this._updatePrefsForExistingRollout(existingRollout, newRollout);
 
       // If anything was different about the new rollout, write it to the db and send an event about it
@@ -66,19 +66,16 @@ class PreferenceRolloutAction extends Ba
             Cu.reportError(new Error(`Updated pref rollout in unexpected state: ${existingRollout.state}`));
           }
         }
       } else {
         this.log.debug(`No updates to preference rollout ${args.slug}`);
       }
 
     } else { // new enrollment
-      for (const prefSpec of newRollout.preferences) {
-        prefSpec.previousValue = PrefUtils.getPref("default", prefSpec.preferenceName);
-      }
       await PreferenceRollouts.add(newRollout);
 
       for (const {preferenceName, value} of args.preferences) {
         PrefUtils.setPref("default", preferenceName, value);
       }
 
       this.log.debug(`Enrolled in preference rollout ${args.slug}`);
       TelemetryEnvironment.setExperimentActive(args.slug, newRollout.state, {type: "normandy-prefrollout"});
@@ -131,34 +128,37 @@ class PreferenceRolloutAction extends Ba
   async _updatePrefsForExistingRollout(existingRollout, newRollout) {
     let anyChanged = false;
     const oldPrefSpecs = new Map(existingRollout.preferences.map(p => [p.preferenceName, p]));
     const newPrefSpecs = new Map(newRollout.preferences.map(p => [p.preferenceName, p]));
 
     // Check for any preferences that no longer exist, and un-set them.
     for (const {preferenceName, previousValue} of oldPrefSpecs.values()) {
       if (!newPrefSpecs.has(preferenceName)) {
+        this.log.debug(`updating ${existingRollout.slug}: ${preferenceName} no longer exists`);
         anyChanged = true;
         PrefUtils.setPref("default", preferenceName, previousValue);
       }
     }
 
     // Check for any preferences that are new and need added, or changed and need updated.
     for (const prefSpec of Object.values(newRollout.preferences)) {
       let oldValue = null;
       if (oldPrefSpecs.has(prefSpec.preferenceName)) {
         let oldPrefSpec = oldPrefSpecs.get(prefSpec.preferenceName);
         if (oldPrefSpec.previousValue !== prefSpec.previousValue) {
+          this.log.debug(`updating ${existingRollout.slug}: ${prefSpec.preferenceName} previous value changed from ${oldPrefSpec.previousValue} to ${prefSpec.previousValue}`);
           prefSpec.previousValue = oldPrefSpec.previousValue;
           anyChanged = true;
         }
         oldValue = oldPrefSpec.value;
       }
       if (oldValue !== newPrefSpecs.get(prefSpec.preferenceName).value) {
         anyChanged = true;
+        this.log.debug(`updating ${existingRollout.slug}: ${prefSpec.preferenceName} value changed from ${oldValue} to ${prefSpec.value}`);
         PrefUtils.setPref("default", prefSpec.preferenceName, prefSpec.value);
       }
     }
     return anyChanged;
   }
 
   async _finalize() {
     await PreferenceRollouts.saveStartupPrefs();
--- a/toolkit/components/normandy/lib/PreferenceRollouts.jsm
+++ b/toolkit/components/normandy/lib/PreferenceRollouts.jsm
@@ -1,21 +1,24 @@
 /* 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";
 
 ChromeUtils.import("resource://normandy/actions/BaseAction.jsm");
+ChromeUtils.import("resource://normandy/lib/LogManager.jsm");
 ChromeUtils.defineModuleGetter(this, "Services", "resource://gre/modules/Services.jsm");
 ChromeUtils.defineModuleGetter(this, "IndexedDB", "resource://gre/modules/IndexedDB.jsm");
 ChromeUtils.defineModuleGetter(this, "TelemetryEnvironment", "resource://gre/modules/TelemetryEnvironment.jsm");
 ChromeUtils.defineModuleGetter(this, "PrefUtils", "resource://normandy/lib/PrefUtils.jsm");
 ChromeUtils.defineModuleGetter(this, "TelemetryEvents", "resource://normandy/lib/TelemetryEvents.jsm");
 
+const log = LogManager.getLogger("recipe-runner");
+
 /**
  * PreferenceRollouts store info about an active or expired preference rollout.
  * @typedef {object} PreferenceRollout
  * @property {string} slug
  *   Unique slug of the experiment
  * @property {string} state
  *   The current state of the rollout: "active", "rolled-back", "graduated".
  *   Active means that Normandy is actively managing therollout. Rolled-back
@@ -111,16 +114,17 @@ var PreferenceRollouts = {
         }
       }
 
       if (prefMatchingDefaultCount === rollout.preferences.length) {
         // Firefox's builtin defaults have caught up to the rollout, making all
         // of the rollout's changes redundant, so graduate the rollout.
         rollout.state = this.STATE_GRADUATED;
         changed = true;
+        log.debug(`Graduating rollout: ${rollout.slug}`);
         TelemetryEvents.sendEvent("graduate", "preference_rollout", rollout.slug, {});
       }
 
       if (changed) {
         const db = await getDatabase();
         await getStore(db).put(rollout);
       }
     }
@@ -169,20 +173,20 @@ var PreferenceRollouts = {
   },
 
   /**
    * Update an existing rollout
    * @param {PreferenceRollout} rollout
    * @throws If a matching rollout does not exist.
    */
   async update(rollout) {
-    const db = await getDatabase();
     if (!await this.has(rollout.slug)) {
       throw new Error(`Tried to update ${rollout.slug}, but it doesn't already exist.`);
     }
+    const db = await getDatabase();
     return getStore(db).put(rollout);
   },
 
   /**
    * Test whether there is a rollout in storage with the given slug.
    * @param {string} slug
    * @returns {boolean}
    */
--- a/toolkit/components/normandy/lib/RecipeRunner.jsm
+++ b/toolkit/components/normandy/lib/RecipeRunner.jsm
@@ -237,17 +237,17 @@ var RecipeRunner = {
       }
     }
 
     // Execute recipes, if we have any.
     if (recipesToRun.length === 0) {
       log.debug("No recipes to execute");
     } else {
       for (const recipe of recipesToRun) {
-        actions.runRecipe(recipe);
+        await actions.runRecipe(recipe);
       }
     }
 
     await actions.finalize();
 
     // Close storage connections
     await AddonStudies.close();
 
--- a/toolkit/components/normandy/lib/TelemetryEvents.jsm
+++ b/toolkit/components/normandy/lib/TelemetryEvents.jsm
@@ -31,30 +31,30 @@ const TelemetryEvents = {
         methods: ["update"],
         objects: ["preference_rollout"],
         extra_keys: ["previousState"],
         record_on_release: true,
       },
 
       unenroll: {
         methods: ["unenroll"],
-        objects: ["preference_study", "addon_study"],
+        objects: ["preference_study", "addon_study", "preference_addon"],
         extra_keys: ["reason", "didResetValue", "addonId", "addonVersion"],
         record_on_release: true,
       },
 
       unenroll_failure: {
         methods: ["unenrollFailed"],
         objects: ["preference_rollout"],
         extra_keys: ["reason"],
         record_on_release: true,
       },
 
-      graduated: {
-        methods: ["graduated"],
+      graduate: {
+        methods: ["graduate"],
         objects: ["preference_rollout"],
         extra_keys: [],
         record_on_release: true,
       },
     });
   },
 
   sendEvent(method, object, value, extra) {
--- a/toolkit/components/normandy/test/browser/browser_RecipeRunner.js
+++ b/toolkit/components/normandy/test/browser/browser_RecipeRunner.js
@@ -139,30 +139,35 @@ decorate_task(
     closeSpy,
     reportRunnerStub,
     fetchRecipesStub,
     fetchRemoteActionsStub,
     preExecutionStub,
     runRecipeStub,
     finalizeStub
   ) {
+    const runRecipeReturn = Promise.resolve();
+    const runRecipeReturnThen = sinon.spy(runRecipeReturn, "then");
+    runRecipeStub.returns(runRecipeReturn);
+
     const matchRecipe = {id: "match", action: "matchAction", filter_expression: "true"};
     const noMatchRecipe = {id: "noMatch", action: "noMatchAction", filter_expression: "false"};
     const missingRecipe = {id: "missing", action: "missingAction", filter_expression: "true"};
     fetchRecipesStub.callsFake(async () => [matchRecipe, noMatchRecipe, missingRecipe]);
 
     await RecipeRunner.run();
 
     ok(fetchRemoteActionsStub.calledOnce, "remote actions should be fetched");
     ok(preExecutionStub.calledOnce, "pre-execution hooks should be run");
     Assert.deepEqual(
       runRecipeStub.args,
       [[matchRecipe], [missingRecipe]],
       "recipe with matching filters should be executed",
     );
+    ok(runRecipeReturnThen.called, "the run method should be used asyncronously");
 
     // Test uptake reporting
     Assert.deepEqual(
       reportRunnerStub.args,
       [[Uptake.RUNNER_SUCCESS]],
       "RecipeRunner should report uptake telemetry",
     );
 
@@ -264,17 +269,17 @@ decorate_task(
     await RecipeRunner.init();
     ok(runStub.called, "RecipeRunner.run is called immediately on first run");
     ok(
       !Services.prefs.getBoolPref("app.normandy.first_run"),
       "On first run, the first run pref is set to false"
     );
     ok(registerTimerStub.called, "RecipeRunner.registerTimer registers a timer");
 
-    // RecipeRunner.init() sets this to false, but SpecialPowers
+    // RecipeRunner.init() sets this pref to false, but SpecialPowers
     // relies on the preferences it manages to actually change when it
     // tries to change them. Settings this back to true here allows
     // that to happen. Not doing this causes popPrefEnv to hang forever.
     Services.prefs.setBoolPref("app.normandy.first_run", true);
   }
 );
 
 // Test that prefs are watched correctly