Bug 1455735 - Await running recipes r=Gijs
authorMike Cooper <mcooper@mozilla.com>
Tue, 24 Apr 2018 12:45:30 -0700
changeset 471628 801fa27ae7b8b454bd56677c09038e264421c807
parent 471627 fb836a045f2024b51bdd9899fe2e8db19bd96f8a
child 471629 1d99f96c0aec2f65e4d17dd3d11a46615f1d690a
push id1728
push userjlund@mozilla.com
push dateMon, 18 Jun 2018 21:12:27 +0000
treeherdermozilla-release@c296fde26f5f [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersGijs
bugs1455735
milestone61.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
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