976205 - Uncaught async Promise errors should cause xpcshell tests to fail

Status: RESOLVED FIXED

(Testing :: XPCShell Harness, defect)

Description

[:Gijs (out for now; he/him)]

See e.g. bug 975372.

These issues should just cause orange, just like assertions do.

I don't know how hard this is.

Comment 1

[Ed Morley [:emorley]]

eg:
02:12:35     INFO -  TEST-PASS | chrome://mochitests/content/browser/browser/components/customizableui/test/browser_970511_undo_restore_default.js | Undo reset button should be enabled after reset
02:12:35     INFO -  *************************
02:12:35     INFO -  A coding exception was thrown and uncaught in a Task.
02:12:35     INFO -  Full message: TypeError: gSavedState is null
02:12:35     INFO -  Full stack: CustomizableUIInternal.undoReset@resource://app/modules/CustomizableUI.jsm:2142:1
02:12:35     INFO -  this.CustomizableUI.undoReset@resource://app/modules/CustomizableUI.jsm:2917:5
02:12:35     INFO -  CustomizeMode.prototype.undoReset/<@resource://app/modules/CustomizeMode.jsm:932:7
02:12:35     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:233:1
02:12:35     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:118:11
02:12:35     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:43:43
02:12:35     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:185:11
02:12:35     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:118:11
02:12:35     INFO -  then@resource://gre/modules/commonjs/sdk/core/promise.js:43:43
02:12:35     INFO -  resolve@resource://gre/modules/commonjs/sdk/core/promise.js:185:11
02:12:35     INFO -  TaskImpl_run@resource://gre/modules/Task.jsm:242:9
02:12:35     INFO -  Handler.prototype.process@resource://gre/modules/Promise.jsm:774:11
02:12:35     INFO -  this.PromiseWalker.walkerLoop@resource://gre/modules/Promise.jsm:653:7
02:12:35     INFO -  *************************

Comes from:
http://mxr.mozilla.org/mozilla-central/source/toolkit/modules/Promise.jsm#793
http://mxr.mozilla.org/mozilla-central/source/toolkit/modules/Task.jsm#287

Comment 2

[David Teller [:Yoric] - still alive but not very active]

Both messages report uncaught asynchronous errors – even worse, some of the messages in Promise.jsm are triggered after garbage-collection. I believe that we could still hook them onto the test's error handlers, if we have a way to detect that we are currently being executed in a test. Is there a way to do so?

Comment 3

[:Gijs (out for now; he/him)]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #2)
> Both messages report uncaught asynchronous errors – even worse, some of the
> messages in Promise.jsm are triggered after garbage-collection. I believe
> that we could still hook them onto the test's error handlers, if we have a
> way to detect that we are currently being executed in a test. Is there a way
> to do so?

I'm not sure, but also, making in-product-code have test-specific code makes me queasy. Instead, we could just use a log parser like we do for leaks?

Comment 4

[Ed Morley [:emorley]]

I think we should use Cu.reportError - I disagree with the comment in Task.jsm/Promise.jsm - after all, our CI should catch in-product instances & any caused by extensions would actually be needed in the console or the extension developer may not be aware of them surely?

Comment 5

[:Gijs (out for now; he/him)]

(In reply to Ed Morley [:edmorley UTC+0] from comment #4)
> I think we should use Cu.reportError - I disagree with the comment in
> Task.jsm/Promise.jsm - after all, our CI should catch in-product instances &
> any caused by extensions would actually be needed in the console or the
> extension developer may not be aware of them surely?

I would tend to agree. David?

Comment 6

[David Teller [:Yoric] - still alive but not very active]

I don't remember why we used dump() instead of Cu.reportError. I believe Paolo advocated this choice. Paolo, do you remember?

Comment 7

[:Paolo Amadini]

There are two things I should say about this bug, based on what I see in comment 0.

Firstly, this bug was based on the fact that one of the tests did not detect an error condition, reported in bug 975372. However, I think the focus in comment 1 was put on the least relevant part of the log. The actual lines that I think should have caused the test to fail are these:

02:12:35     INFO -  console.error:
02:12:35     INFO -    [CustomizeMode]
02:12:35     INFO -    Message: TypeError: gSavedState is null

That is, a call to "console.error" was done, but it didn't cause the test to fail, like a call to Cu.reportError is expected to do. This should probably be filed as a separate bug.

That said, the second part of the answer is to explain the reason why I don't think this should be a reportError visible in production code, that is the same reason why DOM Promises might even not implement this feature at all (while I think it's worth having it for tests).

The correct way to use Promises in production code is to always hook an error handler, like the CustomizeMode.jsm module currently does:

mxr.mozilla.org/mozilla-central/source/browser/components/customizableui/src/CustomizeMode.jsm#910

If this isn't done, we have a mechanism that reports the error later, on garbage collection. So, any uncaught error during browser usage will appear in the console in the end, without the need for this "dump". Turning this "dump" into a reportError would create mysterious duplicates, making it unclear how many times an error actually happened.

I think that what we want in regression tests may be different. In tests, we found the dump() useful while developing because it happens synchronously. Having tests fail when that happens is an option, but it should be seen as the analogous of reporting *all* coding exceptions (ReferenceError, RangeError, ...) in a normal function even if the JavaScript has wrapped the offending call inside a "try-catch".

Upon further thinking, I guess the wording "thrown and uncaught" might be misleading - the exception might be caught by a ".then(null, handler)", which incidentally is now also available with the name ".catch(handler)" in DOM promises.

So, I think this bug as stated in the subject may be valid, but not implemented by turning the "dump" into a Cu.reportError. Makes sense?

Comment 8

[David Teller [:Yoric] - still alive but not very active]

I have just been nearly bitten by this, too, with a xpcshell test that didn't fail despite an uncaught rejection, so I vote that we progress on this topic.

One way we could do this is to keep the current code but add a Cu.reportError only for some users, e.g.:
- in DEBUG builds; or
- if browser.dom.window.dump.enabled is true.

Comment 9

[:Paolo Amadini]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #8)
> One way we could do this is to keep the current code but add a
> Cu.reportError only for some users, e.g.:
> - in DEBUG builds; or
> - if browser.dom.window.dump.enabled is true.

I'd follow one of these two options:

1. Link the use of Cu.reportError to a separate preference. The preference would only be enabled by default in the prefs.js files used by test environments. This is similar to the Add-on SDK original Promises error handling.

2. Write a distinctive string to the console and use a log parser to catch the errors separately, as Gijs suggested.

Comment 10

[:Paolo Amadini]

There is also another possibility: before the test completes, we examine the list of pending uncaught rejections, and force all the errors to be written immediately to the console using Cu.reportError.

This should guarantee that the test fails, independently from the handling of coding exceptions.

Comment 11

[David Teller [:Yoric] - still alive but not very active]

I just double-checked and we already use Services.console.logMessage with an instance of nsIScriptError. Shouldn't this be sufficient to trigger a TEST-UNEXPECTED-FAIL?

Comment 12

[:Gijs (out for now; he/him)]

I think mochitest-bc only has a window.onerror handler, not something that actually checks in with the console service, and changing that will likely break a lot of tests. Not saying we shouldn't do it, but caveat emptor for that approach. :-)

Comment 13

[:Gavin Sharp [email: [e-mail]]]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #11)
> I just double-checked and we already use Services.console.logMessage with an
> instance of nsIScriptError. Shouldn't this be sufficient to trigger a
> TEST-UNEXPECTED-FAIL?

Not until we fix bug 920191.

Comment 14

[David Teller [:Yoric] - still alive but not very active]

Attachment: Experimental patch

Comment 15

[:Paolo Amadini]

David's patch is one of the ways we could fix the issue, there's also the better alternative of forcing reporting of asynchronous errors at the end of test file processing.

In both cases, at this point my question is whether using Cu.reportError, as it was suggested in previous comments, will help with making browser-chrome tests fail, or this change will only benefit xpcshell tests and would not have helped in the case of bug 975372.

Comment 16

[David Teller [:Yoric] - still alive but not very active]

So, after checking, Cu.reportError indeed doesn't cause test failures, so back to square 1.

Here's the strategy we discussed with Paolo:
1. If some testing preference is set, expose the list of all uncaught errors through some API of Promise.jsm, ensuring that we do not clear the errors;
2. Patch the test suite to fail if at least one such uncaught error exists;
3. In some followup bug(s), find a strategy to progressively ensure that Cu.reportError does cause test failures, e.g. by starting with Cu.reportError in code triggered during the execution of a promise callback.

Comment 17

[:Paolo Amadini]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #16)
> 1. If some testing preference is set, expose the list of all uncaught errors
> through some API of Promise.jsm, ensuring that we do not clear the errors;
> 2. Patch the test suite to fail if at least one such uncaught error exists;

We can also make the API available unconditionally, but we would only use it at the end of tests. In any case, errors that are explicitly handled (for example, those that are intercepted by "add_task" and already cause the test to fail, but also legitimate errors that are explicitly triggered and then caught) would not be in this list at the end of the test.

> 3. In some followup bug(s), find a strategy to progressively ensure that
> Cu.reportError does cause test failures, e.g. by starting with
> Cu.reportError in code triggered during the execution of a promise callback.

For the record, the purpose of this check is to promote best practices. The correct way to handle an asynchronous error is to catch it and call Cu.reportError, but when the solution above is implemented, this correct way would not cause the test to fail, while the incorrect way would be more strict in catching failures.

Since we cannot just trigger the switch and make Cu.reportError always fail in mochitests (because of the myriad of existing cases where it occurs), we can start by making it fail in code that uses promises, considering that it is relatively new and easier to tackle.

Comment 18

[David Teller [:Yoric] - still alive but not very active]

Attachment: Causing mochitests to fail in case of uncaught async error

Comment 19

[David Teller [:Yoric] - still alive but not very active]

Attachment: Causing tests to fail in case of uncaught async error

Same one, with mochitests, too.

Comment 20

[David Teller [:Yoric] - still alive but not very active]

Let's see what this yields:
https://tbpl.mozilla.org/?tree=Try&rev=c3266cf3a411

Comment 21

[:Paolo Amadini]

Comment on attachment 8392815 [details] [diff] [review]
Causing tests to fail in case of uncaught async error

Review of attachment 8392815 [details] [diff] [review]:
-----------------------------------------------------------------

I gave some general feedback. I don't know in detail the testing framework, Ted might know whether the calls are located in the best places.

::: testing/mochitest/browser-test.js
@@ +225,5 @@
>                           "\tTodo: " + todoCount + "\n");
> +        if (Promise.Debugging.Uncaught.size != 0) {
> +          this.dumper.dump("\tUncaught: " + Promise.Debugging.Uncaught.size + "\n");
> +          this.dumper.dump("\n\nTEST-UNEXPECTED-FAIL | (browser-test.js) | " +
> +                           "Some promise chains failed to handle rejections.\n");

TEST-UNEXPECTED-FAIL | (browser-test.js) | <num> rejections were uncaught in Promise chains.

I get this check should be done before the line that forces the actual reporting?

::: testing/xpcshell/head.js
@@ +186,5 @@
> +   Promise.Debugging.Uncaught.force();
> +   if (Promise.Debugging.Uncaught.size != 0) {
> +       _log("test_unexpected_fail",
> +            {_message: "TEST-UNEXPECTED-FAIL | (xpcshell/head.js) | " +
> +             "Some promise chains failed to handle rejections.\n"});

Do we need the "size" test in xpcshell? The console listener should already cause the test to fail. If not, maybe we should just report pending errors earlier in the test quit process.

::: toolkit/modules/Promise.jsm
@@ +268,5 @@
> +  /**
> +   * Display all errors and untrack them.
> +   */
> +  reportAll: function() {
> +    for (let id of this._map.keys()) {

Is this safe to use if we mutate the collection inside the loop?

@@ +283,5 @@
> +      this._map.delete(id);
> +    } catch (ex) {
> +      // Error has already been reported.
> +      return;
> +    }

I don't think this catch block is required, I think delete just returns false.

@@ +290,5 @@
> +  /**
> +   * Return the number of errors that have been reported at some point
> +   * in the past.
> +   */
> +  get reported() {

reportedCount / numReported

@@ +341,5 @@
>  };
>  
>  // Actually print the finalization warning.
>  Services.obs.addObserver(function observe(aSubject, aTopic, aValue) {
> +    PendingErrors.report(aValue);

nit: two spaces

@@ +596,5 @@
> +Promise.Debugging = {
> +  /**
> +   * Tools for debugging uncaught errors.
> +   */
> +  Uncaught: {

PendingRejections?

@@ +602,5 @@
> +     * Ensure that all errors that are currently uncaught have been
> +     * printed. Note that this may cause the display of asynchronous
> +     * errors that can still be caught in the future.
> +     */
> +    force: function() {

forceReporting

@@ +603,5 @@
> +     * printed. Note that this may cause the display of asynchronous
> +     * errors that can still be caught in the future.
> +     */
> +    force: function() {
> +      Cu.forceGC();

I don't think we need to force garbage collection to report the registered errors. We report errors on orphaned object on garbage collection, potentially leaving other unreported errors in the list, in this case we're just reporting everything.

Comment 22

[David Teller [:Yoric] - still alive but not very active]

(In reply to :Paolo Amadini from comment #21)
> I get this check should be done before the line that forces the actual
> reporting?

I don't understand the question.

> ::: testing/xpcshell/head.js
> @@ +186,5 @@
> > +   Promise.Debugging.Uncaught.force();
> > +   if (Promise.Debugging.Uncaught.size != 0) {
> > +       _log("test_unexpected_fail",
> > +            {_message: "TEST-UNEXPECTED-FAIL | (xpcshell/head.js) | " +
> > +             "Some promise chains failed to handle rejections.\n"});
> 
> Do we need the "size" test in xpcshell? The console listener should already
> cause the test to fail. If not, maybe we should just report pending errors
> earlier in the test quit process.

Are you talking about using a console listener and failing if we find a specific string?
I prefer this approach, which is concise and simple.

> ::: toolkit/modules/Promise.jsm
> @@ +268,5 @@
> > +  /**
> > +   * Display all errors and untrack them.
> > +   */
> > +  reportAll: function() {
> > +    for (let id of this._map.keys()) {
> 
> Is this safe to use if we mutate the collection inside the loop?

Well, I'm iterating over an array of keys, so I don't see how it could be unsafe.

Comment 23

[David Teller [:Yoric] - still alive but not very active]

I realize that we could also go for an alternative approach, with the following API:

- Promise.Debugging.addUncaughtErrorObserver
- Promise.Debugging.flushPendingErrors

Both xpcshell and mochitest could then register listeners and turn uncaught error reports directly into unexpected failures.

Comment 24

[David Teller [:Yoric] - still alive but not very active]

Attachment: Causing tests to fail in case of uncaught async error, v2

After looking at the Try run, I realized that the output was not very readable.
Reimplemented everything with uncaught error observers and the standard TEST-UNEXPECTED-FAIL mechanisms, which let us show the errors closer to where they have been caused.

Try: https://tbpl.mozilla.org/?tree=Try&rev=930fa4a66c2b

Comment 25

[:Paolo Amadini]

Comment on attachment 8393182 [details] [diff] [review]
Causing tests to fail in case of uncaught async error, v2

Review of attachment 8393182 [details] [diff] [review]:
-----------------------------------------------------------------

This looks quite good!

::: toolkit/modules/Promise-backend.js
@@ +181,5 @@
> +   *
> +   * @param id The identifier of the pending error, as returned by
> +   * |register|.
> +   */
> +  trigger: function(id) {

nit: I liked the name "report" more, "trigger" makes it seem to me that it is creating a new error.

@@ +234,5 @@
> +   * observers.
> +   */
> +  removeObserver: function(observer) {
> +    if (observer == "*") {
> +      this._observers.clear();

Let's use a separate removeAllObservers function (and removeAllUncaughtErrorObservers below) instead of magic values.

@@ +243,4 @@
>  };
>  
> +// Default mechanism for displaying errors
> +PendingErrors.addObserver(function({message, date, fileName, stack, lineNumber}) {

Global nit: I'd not overuse destructuring assignments. For example, in this context just an aErrorDetails parameter would look clearer to me, even in the body of the function below.

Comment 26

[David Teller [:Yoric] - still alive but not very active]

Same Try, but without the missing file: https://tbpl.mozilla.org/?tree=Try&rev=27b7b74b8df5

Comment 27

[David Teller [:Yoric] - still alive but not very active]

Attachment: Causing tests to fail in case of uncaught async error, v3

Applied feedback and improved a little the error messages.

Comment 28

[:Paolo Amadini]

Comment on attachment 8393474 [details] [diff] [review]
Causing tests to fail in case of uncaught async error, v3

Review of attachment 8393474 [details] [diff] [review]:
-----------------------------------------------------------------

I reviewed everything except the actual location of the function calls within the test runners.

::: testing/mochitest/browser-test.js
@@ +92,5 @@
>    this.Promise = Components.utils.import("resource://gre/modules/commonjs/sdk/core/promise.js", null).Promise;
>    this.Assert = Components.utils.import("resource://testing-common/Assert.jsm", null).Assert;
> +  this._uncaughtErrorObserver = function({message, date, fileName, stack, lineNumber}) {
> +    let error = null;
> +    if (fileName || lineNumber) {

Hm, what happens to the message if there is no fileName or lineNumber? Is this even possible?

Maybe we should have a specific test for which parameters are passed to the observer based on which way the error is raised, for example if a rejection occurs with a string, an integer, or an Error object.

@@ +402,5 @@
> +                         " promise rejections remain uncaught by their" +
> +                         " promise chains.\n");
> +      }
> +      Promise.Debugging.PendingErrors.clear(); // Don't spill on other tests
> +*/

This seems like a leftover.

::: testing/xpcshell/head.js
@@ +352,5 @@
> +  let Promise = Components.utils.import("resource://gre/modules/Promise.jsm", null).Promise;
> +  Promise.Debugging.clearUncaughtErrorObservers();
> +  Promise.Debugging.addUncaughtErrorObserver(function observer({message, date, fileName, stack, lineNumber}) {
> +    let text = "A promise chain failed to handle a rejection: " +
> +        message + " - rejection date:" + date;

missing space after "date:"

::: toolkit/modules/Promise-backend.js
@@ +90,5 @@
> +   */
> +  init: function() {
> +    Services.obs.addObserver(function observe(aSubject, aTopic, aValue) {
> +        PendingErrors.report(aValue);
> +      }, "promise-finalization-witness", false);

indentation nit: remove two spaces from the above two lines

@@ +204,1 @@
>      return value;

Leftover "return value;"

@@ +210,5 @@
> +  flush: function() {
> +    // Since we are going to modify the map while walking it,
> +    // let's start with copying the keys.
> +    let keys = [k for(k of this._map.keys())];
> +    for (let key of keys) {

Array.slice() can also be used to make a shallow copy.

@@ +233,5 @@
> +   * All arguments are optional.
> +   */
> +  addObserver: function(observer) {
> +    this._observers.add(observer);
> +  },

Since you decided to keep this as a separate internal object anyways, I'm thinking that just exposing the "observers" set (without underscore) and accessing it from Promise.Debugging might remove some verbosity.

Comment 29

[David Teller [:Yoric] - still alive but not very active]

(In reply to :Paolo Amadini from comment #28)
> ::: testing/mochitest/browser-test.js
> @@ +92,5 @@
> >    this.Promise = Components.utils.import("resource://gre/modules/commonjs/sdk/core/promise.js", null).Promise;
> >    this.Assert = Components.utils.import("resource://testing-common/Assert.jsm", null).Assert;
> > +  this._uncaughtErrorObserver = function({message, date, fileName, stack, lineNumber}) {
> > +    let error = null;
> > +    if (fileName || lineNumber) {
> 
> Hm, what happens to the message if there is no fileName or lineNumber? Is
> this even possible?

Yes, we have cases in which fileName or lineNumber are not set – in particular if the rejection was not an exception.

> Maybe we should have a specific test for which parameters are passed to the
> observer based on which way the error is raised, for example if a rejection
> occurs with a string, an integer, or an Error object.

What's the objective?

> @@ +233,5 @@
> > +   * All arguments are optional.
> > +   */
> > +  addObserver: function(observer) {
> > +    this._observers.add(observer);
> > +  },
> 
> Since you decided to keep this as a separate internal object anyways, I'm
> thinking that just exposing the "observers" set (without underscore) and
> accessing it from Promise.Debugging might remove some verbosity.

I don't really like exposing this stuff. Unless you insist, I'd prefer keeping _observers as it is.

Comment 30

[:Paolo Amadini]

(In reply to David Rajchenbach Teller [:Yoric] (please use "needinfo?") from comment #29)
> Yes, we have cases in which fileName or lineNumber are not set – in
> particular if the rejection was not an exception.
> 
> > Maybe we should have a specific test for which parameters are passed to the
> > observer based on which way the error is raised, for example if a rejection
> > occurs with a string, an integer, or an Error object.
> 
> What's the objective?

To test the interface of the observers. This prevents unintentional changes to how errors are reported, that might cause the observers you just added in the testing framework to still work but not report the right thing (for example because the name of a parameter changes accidentally).

> > Since you decided to keep this as a separate internal object anyways, I'm
> > thinking that just exposing the "observers" set (without underscore) and
> > accessing it from Promise.Debugging might remove some verbosity.
> 
> I don't really like exposing this stuff. Unless you insist, I'd prefer
> keeping _observers as it is.

While I don't see a reason to keep the collection private, since the entire object is internal, I've no strong objections to keeping the code as is.

Comment 31

[(not currently active) Ted Mielczarek]

Comment on attachment 8393474 [details] [diff] [review]
Causing tests to fail in case of uncaught async error, v3

Review of attachment 8393474 [details] [diff] [review]:
-----------------------------------------------------------------

I don't have any additional comments beyond Paolo's. This seems reasonable.

Comment 32

[Boris Zbarsky [:bzbarsky]]

Is there a corresponding bug for DOM/ES6 promises?  We should definitely be making tests fail on a DOM promise with an unhandled rejection.

Comment 33

[David Teller [:Yoric] - still alive but not very active]

bz: None yet, but if you open one, can you make it block bug 920191?

Comment 34

[David Teller [:Yoric] - still alive but not very active]

bz: I meant bug 987139.

Comment 35

[:Paolo Amadini]

Filed bug 989960, this can be taken into account when designing bug 966452.

Comment 36

[David Teller [:Yoric] - still alive but not very active]

To simplify landing, I'll only handle xpcshell in this bug and mochitests in a followup.

Comment 37

[David Teller [:Yoric] - still alive but not very active]

Attachment: Causing tests to fail in case of uncaught async error, v4

Same patch, but only the xpcshell parts.
Try: https://tbpl.mozilla.org/?tree=Try&rev=c817990110d0
(including patch for bug 991040)

Comment 38

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/0f91a3f28a44

Comment 39

[Carsten Book [:Tomcat]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #38)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/0f91a3f28a44

had to back this out per request from yoric

05:38 < Yoric> My patch for bug 976205 is incorrect.
05:38 < Yoric> (shouldn't cause bugs, but won't fix the intended issue)

Comment 40

[David Teller [:Yoric] - still alive but not very active]

Attachment: Causing tests to fail in case of uncaught async error, v5

Since the patch has been landed piecewise, replacing with full patch with the last remaining bit.
Try: https://tbpl.mozilla.org/?tree=Try&rev=012b9e88093b

Comment 41

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/fx-team/rev/f4eb512f0d6e

Comment 42

[Tim Taubert [:ttaubert] (inactive)]

https://hg.mozilla.org/mozilla-central/rev/f4eb512f0d6e