Bug 1441333: Part 4 - Add caller location to async API errors. r?zombie draft
authorKris Maglione <maglione.k@gmail.com>
Mon, 26 Feb 2018 15:25:03 -0800
changeset 762301 41d7c03ef11a5c95e5f661d231d1648abbf54fd2
parent 762300 ec9e15b5aae028c2c55e20c62dafe3729413ae26
child 762302 de4d9bfe7332f917734511a4ae9c26bdb1dde0ad
push id101126
push usermaglione.k@gmail.com
push dateFri, 02 Mar 2018 00:45:19 +0000
reviewerszombie
bugs1441333
milestone60.0a1
Bug 1441333: Part 4 - Add caller location to async API errors. r?zombie When we report errors generated by async API operations, they are currently not tied to any relevant extension source location. Instead, the locations in the error reports point to the location in the framework code which reported the error, which makes things extremely difficult to diagnose. This change saves the extension caller location at the beginning of async API operations, and adds it to the error reports genearted by that operation. This should give extension developers a useful starting point for debugging them. MozReview-Commit-ID: AkknkKEosFt
toolkit/components/extensions/ExtensionCommon.jsm
toolkit/components/extensions/test/xpcshell/test_ext_contexts.js
--- a/toolkit/components/extensions/ExtensionCommon.jsm
+++ b/toolkit/components/extensions/ExtensionCommon.jsm
@@ -267,39 +267,43 @@ class BaseContext {
   runSafe(callback, ...args) {
     return this.applySafe(callback, args);
   }
 
   runSafeWithoutClone(callback, ...args) {
     return this.applySafeWithoutClone(callback, args);
   }
 
-  applySafe(callback, args) {
+  applySafe(callback, args, caller) {
     if (this.unloaded) {
-      Cu.reportError("context.runSafe called after context unloaded");
+      Cu.reportError("context.runSafe called after context unloaded",
+                     caller);
     } else if (!this.active) {
-      Cu.reportError("context.runSafe called while context is inactive");
+      Cu.reportError("context.runSafe called while context is inactive",
+                     caller);
     } else {
       try {
         let {cloneScope} = this;
         args = args.map(arg => Cu.cloneInto(arg, cloneScope));
       } catch (e) {
         Cu.reportError(e);
         dump(`runSafe failure: cloning into ${this.cloneScope}: ${e}\n\n${filterStack(Error())}`);
       }
 
-      return this.applySafeWithoutClone(callback, args);
+      return this.applySafeWithoutClone(callback, args, caller);
     }
   }
 
-  applySafeWithoutClone(callback, args) {
+  applySafeWithoutClone(callback, args, caller) {
     if (this.unloaded) {
-      Cu.reportError("context.runSafeWithoutClone called after context unloaded");
+      Cu.reportError("context.runSafeWithoutClone called after context unloaded",
+                     caller);
     } else if (!this.active) {
-      Cu.reportError("context.runSafeWithoutClone called while context is inactive");
+      Cu.reportError("context.runSafeWithoutClone called while context is inactive",
+                     caller);
     } else {
       try {
         return Reflect.apply(callback, null, args);
       } catch (e) {
         dump(`Extension error: ${e} ${e.fileName} ${e.lineNumber}\n[[Exception stack\n${filterStack(e)}Current stack\n${filterStack(Error())}]]\n`);
         Cu.reportError(e);
       }
     }
@@ -407,32 +411,44 @@ class BaseContext {
 
   /**
    * Sets the value of `.lastError` to `error`, calls the given
    * callback, and reports an error if the value has not been checked
    * when the callback returns.
    *
    * @param {object} error An object with a `message` property. May
    *     optionally be an `Error` object belonging to the target scope.
+   * @param {SavedFrame?} caller
+   *        The optional caller frame which triggered this callback, to be used
+   *        in error reporting.
    * @param {function} callback The callback to call.
    * @returns {*} The return value of callback.
    */
-  withLastError(error, callback) {
+  withLastError(error, caller, callback) {
     this.lastError = this.normalizeError(error);
     try {
       return callback();
     } finally {
       if (!this.checkedLastError) {
-        Cu.reportError(`Unchecked lastError value: ${this.lastError}`);
+        Cu.reportError(`Unchecked lastError value: ${this.lastError}`, caller);
       }
       this.lastError = null;
     }
   }
 
   /**
+   * Captures the most recent stack frame which belongs to the extension.
+   *
+   * @returns {SavedFrame?}
+   */
+  getCaller() {
+    return ChromeUtils.getCallerLocation(this.principal);
+  }
+
+  /**
    * Wraps the given promise so it can be safely returned to extension
    * code in this context.
    *
    * If `callback` is provided, however, it is used as a completion
    * function for the promise, and no promise is returned. In this case,
    * the callback is called when the promise resolves or rejects. In the
    * latter case, `lastError` is set to the rejection value, and the
    * callback function must check `browser.runtime.lastError` or
@@ -448,71 +464,83 @@ class BaseContext {
    *     `callback` function or resolving the wrapped promise.
    *
    * @param {function} [callback] The callback function to wrap
    *
    * @returns {Promise|undefined} If callback is null, a promise object
    *     belonging to the target scope. Otherwise, undefined.
    */
   wrapPromise(promise, callback = null) {
+    let caller = this.getCaller();
     let applySafe = this.applySafe.bind(this);
     if (Cu.getGlobalForObject(promise) === this.cloneScope) {
       applySafe = this.applySafeWithoutClone.bind(this);
     }
 
     if (callback) {
       promise.then(
         args => {
           if (this.unloaded) {
-            dump(`Promise resolved after context unloaded\n`);
+            Cu.reportError(`Promise resolved after context unloaded\n`,
+                           caller);
           } else if (!this.active) {
-            dump(`Promise resolved while context is inactive\n`);
+            Cu.reportError(`Promise resolved while context is inactive\n`,
+                           caller);
           } else if (args instanceof NoCloneSpreadArgs) {
-            this.applySafeWithoutClone(callback, args.unwrappedValues);
+            this.applySafeWithoutClone(callback, args.unwrappedValues, caller);
           } else if (args instanceof SpreadArgs) {
-            applySafe(callback, args);
+            applySafe(callback, args, caller);
           } else {
-            applySafe(callback, [args]);
+            applySafe(callback, [args], caller);
           }
         },
         error => {
-          this.withLastError(error, () => {
+          this.withLastError(error, caller, () => {
             if (this.unloaded) {
-              dump(`Promise rejected after context unloaded\n`);
+              Cu.reportError(`Promise rejected after context unloaded\n`,
+                             caller);
             } else if (!this.active) {
-              dump(`Promise rejected while context is inactive\n`);
+              Cu.reportError(`Promise rejected while context is inactive\n`,
+                             caller);
             } else {
-              this.applySafeWithoutClone(callback, []);
+              this.applySafeWithoutClone(callback, [], caller);
             }
           });
         });
     } else {
       return new this.cloneScope.Promise((resolve, reject) => {
         promise.then(
           value => {
             if (this.unloaded) {
-              dump(`Promise resolved after context unloaded\n`);
+              Cu.reportError(`Promise resolved after context unloaded\n`,
+                             caller);
             } else if (!this.active) {
-              dump(`Promise resolved while context is inactive\n`);
+              Cu.reportError(`Promise resolved while context is inactive\n`,
+                             caller);
             } else if (value instanceof NoCloneSpreadArgs) {
               let values = value.unwrappedValues;
-              this.applySafeWithoutClone(resolve, values.length == 1 ? [values[0]] : [values]);
+              this.applySafeWithoutClone(resolve, values.length == 1 ? [values[0]] : [values],
+                                         caller);
             } else if (value instanceof SpreadArgs) {
-              applySafe(resolve, value.length == 1 ? value : [value]);
+              applySafe(resolve, value.length == 1 ? value : [value],
+                        caller);
             } else {
-              applySafe(resolve, [value]);
+              applySafe(resolve, [value], caller);
             }
           },
           value => {
             if (this.unloaded) {
-              dump(`Promise rejected after context unloaded: ${value && value.message}\n`);
+              Cu.reportError(`Promise rejected after context unloaded: ${value && value.message}\n`,
+                             caller);
             } else if (!this.active) {
-              dump(`Promise rejected while context is inactive: ${value && value.message}\n`);
+              Cu.reportError(`Promise rejected while context is inactive: ${value && value.message}\n`,
+                             caller);
             } else {
-              this.applySafeWithoutClone(reject, [this.normalizeError(value)]);
+              this.applySafeWithoutClone(reject, [this.normalizeError(value)],
+                                         caller);
             }
           });
       });
     }
   }
 
   unload() {
     this.unloaded = true;
--- a/toolkit/components/extensions/test/xpcshell/test_ext_contexts.js
+++ b/toolkit/components/extensions/test/xpcshell/test_ext_contexts.js
@@ -16,16 +16,20 @@ class StubContext extends BaseContext {
     let fakeExtension = {id: "test@web.extension"};
     super("testEnv", fakeExtension);
     this.sandbox = Cu.Sandbox(global);
   }
 
   get cloneScope() {
     return this.sandbox;
   }
+
+  get principal() {
+    return Cu.getObjectPrincipal(this.sandbox);
+  }
 }
 
 
 add_task(async function test_post_unload_promises() {
   let context = new StubContext();
 
   let fail = result => {
     ok(false, `Unexpected callback: ${result}`);