Bug 903433 - Report unhandled Promise.jsm exceptions upon garbage-collection. r=paolo

toolkit/modules/Promise.jsm

@@ -98,6 +98,7 @@ const Cu = Components.utils;
 const Cr = Components.results;
 
 Cu.import("resource://gre/modules/Services.jsm");
+Cu.import("resource://gre/modules/XPCOMUtils.jsm");
 
 const STATUS_PENDING = 0;
 const STATUS_RESOLVED = 1;
@@ -113,7 +114,128 @@ const Name = (n) => "{private:" + n + ":" + salt + "}";
 const N_STATUS = Name("status");
 const N_VALUE = Name("value");
 const N_HANDLERS = Name("handlers");
+const N_WITNESS = Name("witness");
 
+
+/////// Warn-upon-finalization mechanism
+//
+// One of the difficult problems with promises is locating uncaught
+// rejections. We adopt the following strategy: if a promise is rejected
+// at the time of its garbage-collection *and* if the promise is at the
+// end of a promise chain (i.e. |thatPromise.then| has never been
+// called), then we print a warning.
+//
+//  let deferred = Promise.defer();
+//  let p = deferred.promise.then();
+//  deferred.reject(new Error("I am un uncaught error"));
+//  deferred = null;
+//  p = null;
+//
+// In this snippet, since |deferred.promise| is not the last in the
+// chain, no error will be reported for that promise. However, since
+// |p| is the last promise in the chain, the error will be reported
+// for |p|.
+//
+// Note that this may, in some cases, cause an error to be reported more
+// than once. For instance, consider:
+//
+//   let deferred = Promise.defer();
+//   let p1 = deferred.promise.then();
+//   let p2 = deferred.promise.then();
+//   deferred.reject(new Error("I am an uncaught error"));
+//   p1 = p2 = deferred = null;
+//
+// In this snippet, the error is reported both by p1 and by p2.
+//
+
+XPCOMUtils.defineLazyServiceGetter(this, "FinalizationWitnessService",
+                                   "@mozilla.org/toolkit/finalizationwitness;1",
+                                   "nsIFinalizationWitnessService");
+
+let PendingErrors = {
+  _counter: 0,
+  _map: new Map(),
+  register: function(error) {
+    let id = "pending-error-" + (this._counter++);
+    //
+    // At this stage, ideally, we would like to store the error itself
+    // and delay any treatment until we are certain that we will need
+    // to report that error. However, in the (unlikely but possible)
+    // case the error holds a reference to the promise itself, doing so
+    // would prevent the promise from being garbabe-collected, which
+    // would both cause a memory leak and ensure that we cannot report
+    // the uncaught error.
+    //
+    // To avoid this situation, we rather extract relevant data from
+    // the error and further normalize it to strings.
+    //
+    let value = {
+      date: new Date(),
+      message: "" + error,
+      fileName: null,
+      stack: null,
+      lineNumber: null
+    };
+    try { // Defend against non-enumerable values
+      if (typeof error == "object" && error) {
+        for (let k of ["fileName", "stack", "lineNumber"]) {
+          try { // Defend against fallible getters and string conversions
+            let v = error[k];
+            value[k] = v ? ("" + v):null;
+          } catch (ex) {
+            // Ignore field
+          }
+        }
+      }
+    } catch (ex) {
+      // Ignore value
+    }
+    this._map.set(id, value);
+    return id;
+  },
+  extract: function(id) {
+    let value = this._map.get(id);
+    this._map.delete(id);
+    return value;
+  },
+  unregister: function(id) {
+    this._map.delete(id);
+  }
+};
+
+// Actually print the finalization warning.
+Services.obs.addObserver(function observe(aSubject, aTopic, aValue) {
+  let error = PendingErrors.extract(aValue);
+  let {message, date, fileName, stack, lineNumber} = error;
+  let error = Cc['@mozilla.org/scripterror;1'].createInstance(Ci.nsIScriptError);
+  if (!error || !Services.console) {
+    // Too late during shutdown to use the nsIConsole
+    dump("*************************\n");
+    dump("A promise chain failed to handle a rejection\n\n");
+    dump("On: " + date + "\n");
+    dump("Full message: " + message + "\n");
+    dump("See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise\n");
+    dump("Full stack: " + (stack||"not available") + "\n");
+    dump("*************************\n");
+    return;
+  }
+  if (stack) {
+    message += " at " + stack;
+  }
+  error.init(
+             /*message*/"A promise chain failed to handle a rejection: on " +
+               date + ", " + message,
+             /*sourceName*/ fileName,
+             /*sourceLine*/ lineNumber?("" + lineNumber):0,
+             /*lineNumber*/ lineNumber || 0,
+             /*columnNumber*/ 0,
+             /*flags*/ Ci.nsIScriptError.errorFlag,
+             /*category*/ "chrome javascript");
+  Services.console.logMessage(error);
+}, "promise-finalization-witness", false);
+
+///////// Additional warnings for developers
+//
 // The following error types are considered programmer errors, which should be
 // reported (possibly redundantly) so as to let programmers fix their code.
 const ERRORS_TO_REPORT = ["EvalError", "RangeError", "ReferenceError", "TypeError"];
@@ -283,6 +405,13 @@ this.PromiseWalker = {
     aPromise[N_VALUE] = aValue;
     if (aPromise[N_HANDLERS].length > 0) {
       this.schedulePromise(aPromise);
+    } else if (aStatus == STATUS_REJECTED) {
+      // This is a rejection and the promise is the last in the chain.
+      // For the time being we therefore have an uncaught error.
+      let id = PendingErrors.register(aValue);
+      let witness =
+          FinalizationWitnessService.make("promise-finalization-witness", id);
+      aPromise[N_WITNESS] = [id, witness];
     }
   },
 
@@ -456,6 +585,15 @@ function PromiseImpl()
    */
   Object.defineProperty(this, N_HANDLERS, { value: [] });
 
+  /**
+   * When the N_STATUS property is STATUS_REJECTED and until there is
+   * a rejection callback, this contains an array
+   * - {string} id An id for use with |PendingErrors|;
+   * - {FinalizationWitness} witness A witness broadcasting |id| on
+   *   notification "promise-finalization-witness".
+   */
+  Object.defineProperty(this, N_WITNESS, { writable: true });
+
   Object.seal(this);
 }
 
@@ -511,6 +649,15 @@ PromiseImpl.prototype = {
     // Ensure the handler is scheduled for processing if this promise is already
     // resolved or rejected.
     if (this[N_STATUS] != STATUS_PENDING) {
+
+      // This promise is not the last in the chain anymore. Remove any watchdog.
+      if (this[N_WITNESS] != null) {
+        let [id, witness] = this[N_WITNESS];
+        this[N_WITNESS] = null;
+        witness.forget();
+        PendingErrors.unregister(id);
+      }
+
       PromiseWalker.schedulePromise(this);
     }
 
@@ -588,12 +735,15 @@ Handler.prototype = {
         // users to see it. Also, if the programmer handles errors correctly,
         // they will either treat the error or log them somewhere.
 
+        dump("*************************\n");
         dump("A coding exception was thrown in a Promise " +
              ((nextStatus == STATUS_RESOLVED) ? "resolution":"rejection") +
-             " callback.\n");
+             " callback.\n\n");
         dump("Full message: " + ex + "\n");
         dump("See https://developer.mozilla.org/Mozilla/JavaScript_code_modules/Promise.jsm/Promise\n");
         dump("Full stack: " + (("stack" in ex)?ex.stack:"not available") + "\n");
+        dump("*************************\n");
+
       }
 
       // Additionally, reject the next promise.

toolkit/modules/Task.jsm

@@ -291,9 +291,11 @@ TaskImpl.prototype = {
       // they will either treat the error or log them somewhere.
 
       let stack = ("stack" in aException) ? aException.stack : "not available";
-      dump("A coding exception was thrown and uncaught in a Task.\n");
+      dump("*************************\n");
+      dump("A coding exception was thrown and uncaught in a Task.\n\n");
       dump("Full message: " + aException + "\n");
       dump("Full stack: " + stack + "\n");
+      dump("*************************\n");
     }
 
     this.deferred.reject(aException);

toolkit/modules/tests/xpcshell/test_Promise.js

@@ -33,7 +33,7 @@ let run_promise_tests = function run_promise_tests(tests, cb) {
 
 let make_promise_test = function(test) {
   return function runtest() {
-    do_print("Test starting: " + test);
+    do_print("Test starting: " + test.name);
     try {
       let result = test();
       if (result && "promise" in result) {
@@ -42,7 +42,7 @@ let make_promise_test = function(test) {
       if (!result || !("then" in result)) {
         let exn;
         try {
-          do_throw("Test " + test + " did not return a promise: " + result);
+          do_throw("Test " + test.name + " did not return a promise: " + result);
         } catch (x) {
           exn = x;
         }
@@ -52,7 +52,7 @@ let make_promise_test = function(test) {
       result = result.then(
         // Test complete
         function onResolve() {
-          do_print("Test complete: " + test);
+          do_print("Test complete: " + test.name);
         },
         // The test failed with an unexpected error
         function onReject(err) {
@@ -62,13 +62,13 @@ let make_promise_test = function(test) {
           } else {
             detail = "(no stack)";
           }
-          do_throw("Test " + test + " rejected with the following reason: "
+          do_throw("Test " + test.name + " rejected with the following reason: "
               + err + detail);
       });
       return result;
     } catch (x) {
       // The test failed because of an error outside of a promise
-      do_throw("Error in body of test " + test + ": " + x + " at " + x.stack);
+      do_throw("Error in body of test " + test.name + ": " + x + " at " + x.stack);
       return Promise.reject();
     }
   };
@@ -714,6 +714,124 @@ tests.push(
       });
   }));
 
+function wait_for_uncaught(aMustAppear, aTimeout = undefined) {
+  let remaining = new Set();
+  for (let k of aMustAppear) {
+    remaining.add(k);
+  }
+  let deferred = Promise.defer();
+  let print = do_print;
+  let execute_soon = do_execute_soon;
+  let observer = function(aMessage) {
+    execute_soon(function() {
+      let message = aMessage.message;
+      print("Observing " + message);
+      for (let expected of remaining) {
+        if (message.indexOf(expected) != -1) {
+          print("I found " + expected);
+          remaining.delete(expected);
+        }
+      }
+      if (remaining.size == 0 && observer) {
+        Services.console.unregisterListener(observer);
+        observer = null;
+        deferred.resolve();
+      }
+    });
+  };
+  Services.console.registerListener(observer);
+  if (aTimeout) {
+    do_timeout(aTimeout, function timeout() {
+      if (observer) {
+        Services.console.unregisterListener(observer);
+        observer = null;
+      }
+      deferred.reject(new Error("Timeout"));
+    });
+  }
+  return deferred.promise;
+}
+
+// Test that uncaught errors are reported as uncaught
+(function() {
+  let make_string_rejection = function make_string_rejection() {
+    let salt = (Math.random() * ( Math.pow(2, 24) - 1 ));
+    let string = "This is an uncaught rejection " + salt;
+    return {mustFind: [string], error: string};
+  };
+  let make_num_rejection = function make_num_rejection() {
+    let salt = (Math.random() * ( Math.pow(2, 24) - 1 ));
+    return {mustFind: [salt], error: salt};
+  };
+  let make_undefined_rejection = function make_undefined_rejection() {
+    return {mustFind: [], error: undefined};
+  };
+  let make_error_rejection = function make_error_rejection() {
+    let salt = (Math.random() * ( Math.pow(2, 24) - 1 ));
+    let error = new Error("This is an uncaught error " + salt);
+    return {
+      mustFind: [error.message, error.fileName, error.lineNumber, error.stack],
+      error: error
+    };
+  };
+  for (let make_rejection of [make_string_rejection,
+    make_num_rejection,
+    make_undefined_rejection,
+    make_error_rejection]) {
+      let {mustFind, error} = make_rejection();
+      let name = make_rejection.name;
+      tests.push(make_promise_test(function test_uncaught_is_reported() {
+        do_print("Testing with rejection " + name);
+        let promise = wait_for_uncaught(mustFind);
+        (function() {
+          // For the moment, we cannot be absolutely certain that a value is
+          // garbage-collected, even if it is not referenced anymore, due to
+          // the conservative stack-scanning algorithm.
+          //
+          // To be _almost_ certain that a value will be garbage-collected, we
+          // 1. isolate that value in an anonymous closure;
+          // 2. allocate 100 values instead of 1 (gc-ing a single value from
+          //    these is sufficient for the test);
+          // 3. place everything in a loop, as the JIT typically reuses memory;
+          // 4. call all the GC methods we can.
+          //
+          // Unfortunately, we might still have intermittent failures,
+          // materialized as timeouts.
+          //
+          for (let i = 0; i < 100; ++i) {
+            Promise.reject(error);
+          }
+        })();
+        Components.utils.forceGC();
+        Components.utils.forceCC();
+        Components.utils.forceShrinkingGC();
+        return promise;
+      }));
+  }
+})();
+
+
+// Test that caught errors are not reported as uncaught
+tests.push(
+make_promise_test(function test_caught_is_not_reported() {
+  let salt = (Math.random() * ( Math.pow(2, 24) - 1 ));
+  let promise = wait_for_uncaught([salt], 500);
+  (function() {
+    let uncaught = Promise.reject("This error, on the other hand, is caught " + salt);
+    uncaught.then(null, function() { /* ignore rejection */});
+    uncaught = null;
+  })();
+  // Isolate this in a function to increase likelihood that the gc will
+  // realise that |uncaught| has remained uncaught.
+  Components.utils.forceGC();
+
+  return promise.then(function onSuccess() {
+    throw new Error("This error was caught and should not have been reported");
+  }, function onError() {
+    do_print("The caught error was not reported, all is fine");
+  }
+  );
+}));
 
 function run_test()
 {

toolkit/modules/tests/xpcshell/xpcshell.ini

@@ -20,3 +20,4 @@ support-files =
 [test_task.js]
 [test_TelemetryTimestamps.js]
 [test_timer.js]
+