Bug 1464938 - Add extension lifecycle state information to shutdown blocker for better diagnostics. r=aswan, a=pascalc
authorKris Maglione <maglione.k@gmail.com>
Thu, 20 Sep 2018 11:18:39 -0700
changeset 490058 ba673d83c7c4fe6d1c5eb03ec5e7f68bd27510b6
parent 490057 49d0176204ccc7e0b175b70adfc46a4fc1a01df5
child 490059 fa2e947e77840ff57cff06b02815e94efa30fe2a
push id9892
push userryanvm@gmail.com
push dateWed, 26 Sep 2018 09:05:06 +0000
treeherdermozilla-beta@ba673d83c7c4 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersaswan, pascalc
bugs1464938
milestone63.0
Bug 1464938 - Add extension lifecycle state information to shutdown blocker for better diagnostics. r=aswan, a=pascalc Differential Revision: https://phabricator.services.mozilla.com/D6419
toolkit/components/extensions/Extension.jsm
toolkit/mozapps/extensions/internal/XPIProvider.jsm
--- a/toolkit/components/extensions/Extension.jsm
+++ b/toolkit/components/extensions/Extension.jsm
@@ -1200,28 +1200,35 @@ class BootstrapScope {
   uninstall(data, reason) {
     AsyncShutdown.profileChangeTeardown.addBlocker(
       `Uninstalling add-on: ${data.id}`,
       Management.emit("uninstall", {id: data.id}).then(() => {
         Management.emit("uninstall-complete", {id: data.id});
       }));
   }
 
+  fetchState() {
+    if (this.extension) {
+      return {state: this.extension.state};
+    }
+    return null;
+  }
+
   update(data, reason) {
     Management.emit("update", {id: data.id, resourceURI: data.resourceURI});
   }
 
   startup(data, reason) {
     // eslint-disable-next-line no-use-before-define
     this.extension = new Extension(data, this.BOOTSTRAP_REASON_TO_STRING_MAP[reason]);
     return this.extension.startup();
   }
 
-  shutdown(data, reason) {
-    let result = this.extension.shutdown(this.BOOTSTRAP_REASON_TO_STRING_MAP[reason]);
+  async shutdown(data, reason) {
+    let result = await this.extension.shutdown(this.BOOTSTRAP_REASON_TO_STRING_MAP[reason]);
     this.extension = null;
     return result;
   }
 }
 
 XPCOMUtils.defineLazyGetter(BootstrapScope.prototype, "BOOTSTRAP_REASON_TO_STRING_MAP", () => {
   const {BOOTSTRAP_REASONS} = AddonManagerPrivate;
 
@@ -1275,16 +1282,18 @@ let activeExtensionIDs = new Set();
  * This class is the main representation of an active WebExtension
  * in the main process.
  * @extends ExtensionData
  */
 class Extension extends ExtensionData {
   constructor(addonData, startupReason) {
     super(addonData.resourceURI);
 
+    this.state = "Not started";
+
     this.sharedDataKeys = new Set();
 
     this.uuid = UUIDMap.get(addonData.id);
     this.instanceId = getUniqueId();
 
     this.MESSAGE_EMIT_EVENT = `Extension:EmitEvent:${this.instanceId}`;
     Services.ppmm.addMessageListener(this.MESSAGE_EMIT_EVENT, this);
 
@@ -1640,24 +1649,44 @@ class Extension extends ExtensionData {
     this.updateContentScripts();
   }
 
   updateContentScripts() {
     this.setSharedData("contentScripts", this.registeredContentScripts);
   }
 
   runManifest(manifest) {
+    let state = new Set();
+    let updateState = () => {
+      this.state = `Startup: Run manifest: ${Array.from(state)}`;
+    };
+
     let promises = [];
+    let addPromise = (name, promise) => {
+      if (promise) {
+        promises.push(promise);
+
+        state.add(name);
+        promise.finally(() => {
+          state.delete(name);
+          updateState();
+        });
+      }
+    };
+
     for (let directive in manifest) {
       if (manifest[directive] !== null) {
-        promises.push(Management.emit(`manifest_${directive}`, directive, this, manifest));
+        addPromise(`manifest_${directive}`,
+                   Management.emit(`manifest_${directive}`, directive, this, manifest));
 
-        promises.push(Management.asyncEmitManifestEntry(this, directive));
+        addPromise(`asyncEmitManifestEntry("${directive}")`,
+                   Management.asyncEmitManifestEntry(this, directive));
       }
     }
+    updateState();
 
     activeExtensionIDs.add(this.id);
     sharedData.set("extensions/activeIDs", activeExtensionIDs);
 
     Services.ppmm.sharedData.flush();
     this.broadcast("Extension:Startup", this.id);
 
     return Promise.all(promises);
@@ -1741,16 +1770,18 @@ class Extension extends ExtensionData {
       } else if (reason !== "APP_STARTUP" &&
                  testPermission("geo") === Services.perms.ALLOW_ACTION) {
         Services.perms.removeFromPrincipal(principal, "geo");
       }
     }
   }
 
   async startup() {
+    this.state = "Startup";
+
     // Create a temporary policy object for the devtools and add-on
     // manager callers that depend on it being available early.
     this.policy = new WebExtensionPolicy({
       id: this.id,
       mozExtensionHostname: this.uuid,
       baseURL: this.baseURI.spec,
       allowedOrigins: new MatchPatternSet([]),
       localizeCallback() {},
@@ -1762,20 +1793,24 @@ class Extension extends ExtensionData {
       // there's another active add-on with the same ID.
       this.policy.active = true;
     }
 
     this.policy.extension = this;
 
     TelemetryStopwatch.start("WEBEXT_EXTENSION_STARTUP_MS", this);
     try {
+      this.state = "Startup: Loading manifest";
       await this.loadManifest();
+      this.state = "Startup: Loaded manifest";
 
       if (!this.hasShutdown) {
+        this.state = "Startup: Init locale";
         await this.initLocale();
+        this.state = "Startup: Initted locale";
       }
 
       if (this.errors.length) {
         return Promise.reject({errors: this.errors});
       }
 
       if (this.hasShutdown) {
         return;
@@ -1812,25 +1847,38 @@ class Extension extends ExtensionData {
       }
 
       // The "startup" Management event sent on the extension instance itself
       // is emitted just before the Management "startup" event,
       // and it is used to run code that needs to be executed before
       // any of the "startup" listeners.
       this.emit("startup", this);
 
+      let state = new Set(["Emit startup", "Run manifest"]);
+      this.state = `Startup: ${Array.from(state)}`;
       await Promise.all([
-        Management.emit("startup", this),
-        this.runManifest(this.manifest),
+        Management.emit("startup", this).finally(() => {
+          state.delete("Emit startup");
+          this.state = `Startup: ${Array.from(state)}`;
+        }),
+        this.runManifest(this.manifest).finally(() => {
+          state.delete("Run manifest");
+          this.state = `Startup: ${Array.from(state)}`;
+        }),
       ]);
+      this.state = "Startup: Ran manifest";
 
       Management.emit("ready", this);
       this.emit("ready");
       TelemetryStopwatch.finish("WEBEXT_EXTENSION_STARTUP_MS", this);
+
+      this.state = "Startup: Complete";
     } catch (errors) {
+      this.state = `Startup: Error: ${errors}`;
+
       for (let e of [].concat(errors)) {
         dump(`Extension error: ${e.message || e} ${e.filename || e.fileName}:${e.lineNumber} :: ${e.stack || new Error().stack}\n`);
         Cu.reportError(e);
       }
 
       if (this.policy) {
         this.policy.active = false;
       }
@@ -1856,37 +1904,44 @@ class Extension extends ExtensionData {
       // closed it (because Windows is dumb). So we wait for all the
       // child processes (including the parent) to flush their JAR
       // caches. These caches may keep the file open.
       file.remove(false);
     }).catch(Cu.reportError);
   }
 
   async shutdown(reason) {
+    this.state = "Shutdown";
+
     this.shutdownReason = reason;
     this.hasShutdown = true;
 
     if (!this.policy) {
       return;
     }
 
     if (this.hasPermission("storage") && ExtensionStorageIDB.selectedBackendPromises.has(this)) {
+      this.state = "Shutdown: Storage";
+
       // Wait the data migration to complete.
       try {
         await ExtensionStorageIDB.selectedBackendPromises.get(this);
       } catch (err) {
         Cu.reportError(
           `Error while waiting for extension data migration on shutdown: ${this.policy.debugName} - ` +
           `${err.message}::${err.stack}`);
       }
+      this.state = "Shutdown: Storage complete";
     }
 
     if (this.rootURI instanceof Ci.nsIJARURI) {
+      this.state = "Shutdown: Flush jar cache";
       let file = this.rootURI.JARFile.QueryInterface(Ci.nsIFileURL).file;
       Services.ppmm.broadcastAsyncMessage("Extension:FlushJarCache", {path: file.path});
+      this.state = "Shutdown: Flushed jar cache";
     }
 
     if (this.cleanupFile ||
         ["ADDON_INSTALL", "ADDON_UNINSTALL", "ADDON_UPGRADE", "ADDON_DOWNGRADE"].includes(reason)) {
       StartupCache.clearAddonData(this.id);
     }
 
     activeExtensionIDs.delete(this.id);
@@ -1896,16 +1951,17 @@ class Extension extends ExtensionData {
       sharedData.delete(key);
     }
 
     Services.ppmm.removeMessageListener(this.MESSAGE_EMIT_EVENT, this);
 
     this.updatePermissions(this.shutdownReason);
 
     if (!this.manifest) {
+      this.state = "Shutdown: Complete: No manifest";
       this.policy.active = false;
 
       return this.cleanupGeneratedFile();
     }
 
     GlobalManager.uninit(this);
 
     for (let obj of this.onShutdown) {
@@ -1914,28 +1970,31 @@ class Extension extends ExtensionData {
 
     ParentAPIManager.shutdownExtension(this.id);
 
     Management.emit("shutdown", this);
     this.emit("shutdown");
 
     const TIMED_OUT = Symbol();
 
+    this.state = "Shutdown: Emit shutdown";
     let result = await Promise.race([
       this.broadcast("Extension:Shutdown", {id: this.id}),
       promiseTimeout(CHILD_SHUTDOWN_TIMEOUT_MS).then(() => TIMED_OUT),
     ]);
+    this.state = `Shutdown: Emitted shutdown: ${result === TIMED_OUT}`;
     if (result === TIMED_OUT) {
       Cu.reportError(`Timeout while waiting for extension child to shutdown: ${this.policy.debugName}`);
     }
 
     MessageChannel.abortResponses({extensionId: this.id});
 
     this.policy.active = false;
 
+    this.state = `Shutdown: Complete (${this.cleanupFile})`;
     return this.cleanupGeneratedFile();
   }
 
   observe(subject, topic, data) {
     if (topic === "xpcom-shutdown") {
       this.cleanupGeneratedFile();
     }
   }
--- a/toolkit/mozapps/extensions/internal/XPIProvider.jsm
+++ b/toolkit/mozapps/extensions/internal/XPIProvider.jsm
@@ -1489,16 +1489,30 @@ class BootstrapScope {
     return this.addon.file || this.addon._sourceBundle;
   }
 
   get runInSafeMode() {
     return "runInSafeMode" in this.addon ? this.addon.runInSafeMode : canRunInSafeMode(this.addon);
   }
 
   /**
+   * Returns state information for use by an AsyncShutdown blocker. If
+   * the wrapped bootstrap scope has a fetchState method, it is called,
+   * and its result returned. If not, returns null.
+   *
+   * @returns {Object|null}
+   */
+  fetchState() {
+    if (this.scope && this.scope.fetchState) {
+      return this.scope.fetchState();
+    }
+    return null;
+  }
+
+  /**
    * Calls a bootstrap method for an add-on.
    *
    * @param {string} aMethod
    *        The name of the bootstrap method to call
    * @param {integer} aReason
    *        The reason flag to pass to the bootstrap's startup method
    * @param {Object} [aExtraParams = {}]
    *        An object of additional key/value pairs to pass to the method in
@@ -2187,19 +2201,22 @@ var XPIProvider = {
             } else if (addon.location.name == KEY_APP_TEMPORARY) {
               reason = BOOTSTRAP_REASONS.ADDON_UNINSTALL;
               let existing = XPIStates.findAddon(addon.id, loc => !loc.isTemporary);
               if (existing) {
                 reason = XPIInstall.newVersionReason(addon.version, existing.version);
               }
             }
 
-            let promise = BootstrapScope.get(addon).shutdown(reason);
+            let scope = BootstrapScope.get(addon);
+            let promise = scope.shutdown(reason);
             AsyncShutdown.profileChangeTeardown.addBlocker(
-              `Extension shutdown: ${addon.id}`, promise);
+              `Extension shutdown: ${addon.id}`, promise, {
+                fetchState: scope.fetchState.bind(scope),
+              });
           }
         });
 
       // Detect final-ui-startup for telemetry reporting
       Services.obs.addObserver(function observer() {
         AddonManagerPrivate.recordTimestamp("XPI_finalUIStartup");
         Services.obs.removeObserver(observer, "final-ui-startup");
       }, "final-ui-startup");