966452 - DOM Promises should report all unhandled rejections to the Console on GC (like Promise.jsm)

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[:Paolo Amadini]

DOM Promises should report all rejections to the Console when a Promise object is garbage collected, if no handlers have been registered.

This is partially implemented by bug 903419, in Promise::MaybeReportRejected:
http://mxr.mozilla.org/mozilla-central/source/dom/promise/Promise.cpp#869

However, this has the following limitations:
- It only handles Error objects, while it should handle all the objects and
  primitives that are reported by "throw" in a normal function.
- It seems that errors are reported unless a rejection handler has been
  registered, but the check should include success handlers, because any
  invocation of "then" will generate a new Promise that will receive the
  error, making reporting on the former promise unnecessary.
- It does not store the timestamp of the original error.
- Actually, I've not been able to make it work (see steps below).

The first item is particularly relevant, since it's quite common to throw
primitives like error messages and result codes:
http://mxr.mozilla.org/mozilla-central/search?string=throw+%22
http://mxr.mozilla.org/mozilla-central/search?string=throw+Cr.

STEPS TO REPRODUCE:
- Open the Web Console (CTRL+SHIFT+K)
- Type Promise.reject(new Error("Message."));0;
- Type Promise.reject("Message.");0;
- Type Promise.reject(1);0;

- Open the Browser Console (CTRL+SHIFT+J)
- Type Components.utils.forceGC();

ACTUAL RESULTS:
- No error message appears anywhere.

EXPECTED RESULTS:
- To compare with Promise.jsm, open the Browser Console (CTRL+SHIFT+J)
- Type Components.utils.import("resource://gre/modules/Promise.jsm");
- Type Promise.reject(new Error("Message."));0;
- Type Promise.reject("Message.");0;
- Type Promise.reject(1);0;
- Type Components.utils.forceGC();

Three error messages appear in the Console, each one including:
- Informative explanation ("A promise chain failed to handle a rejection.")
- Error message
- Original timestamp
- Stack trace

Comment 1

[Boris Zbarsky [:bzbarsky]]

> It only handles Error objects

That's because for other objects there's nothing useful we can say other than their existence: they have no file/line information, so are pretty much impossible to debug.  Maybe that's OK.

Note that anyone using something other than a subclass of Error as the rejection value are doing it wrong as far as I understand how promises are supposed to be used.

> because any invocation of "then" will generate a new Promise that will receive the
> error

Yes, by registering a rejection handler on the original promise that rejects the new promise.  So this case is in fact covered.

> - It does not store the timestamp of the original error.

That's fixable.

> - Actually, I've not been able to make it work (see steps below).

That's because the actual limitation of the current reporting mechanism is not "error objects" but "exceptions".  Here's a testcase that would report with your steps:

  new Promise(resolve => resolve()).then(function() { noSuchMethod(); }); 0;

As in, the current reporting was designed to catch accidental errors in functions passed to then(), not all explicit rejections (because of the assumption that the latter are fairly common even on promises with no reject handler).

If rejections are supposed to be a very rare case, it makes sense to change the setup to report them in general, of course.

> - Stack trace

You'll only be able to get that for rejections with an Error subclass, I expect.  Other JS values simply do not have an associated stack trace.  Yet another reason to never use anything else to reject promises.

Comment 2

[Boris Zbarsky [:bzbarsky]]

I suppose what you could do is that if you're rejected with a non-Error value you could snapshot the stack at that point.  But keep in mind that snapshotting the stack is pretty expensive.  :(

Comment 3

[:Paolo Amadini]

(In reply to Boris Zbarsky [:bz] from comment #1)
> Note that anyone using something other than a subclass of Error as the
> rejection value are doing it wrong as far as I understand how promises are
> supposed to be used.

Yes, like using strings and integers for the argument of "throw", but we have lots of such calls in chrome code. We should expect them also in non-chrome code, and do something useful with them.

> Yes, by registering a rejection handler on the original promise that rejects
> the new promise.  So this case is in fact covered.

Good to hear, I just misread the code there.

> As in, the current reporting was designed to catch accidental errors in
> functions passed to then(), not all explicit rejections

I see, so that's more similar to the case in bug 966462.

> If rejections are supposed to be a very rare case, it makes sense to change
> the setup to report them in general, of course.

I recommend this on GC, as it will automatically catch "uncaught" handler exceptions. In case the coding exception is "caught" through a rejection handler, there is no need to report to the Console, though we found the "dump" useful.

> I suppose what you could do is that if you're rejected with a non-Error
> value you could snapshot the stack at that point.  But keep in mind that
> snapshotting the stack is pretty expensive.  :(

In Promise.jsm we snapshot the stack if there are no handlers registered at the time of the rejection. Since this case is rare, we don't collect stack traces unnecessarily. If a handler is then registered after rejection and before GC, we discard the error so that nothing duplicate appears on GC.

Comment 4

[Boris Zbarsky [:bzbarsky]]

> we snapshot the stack if there are no handlers registered at the time of the rejection.

That includes basic Promise.reject() usage, right?

If this is blocking us actually moving chrome code over to platform promises, we should probably significantly increase the priority here...

Comment 5

[Nikhil Marathe [:nsm] (No longer reading bugmail, please needinfo?)]

I probably won't have time to work on this within the next month.

Comment 6

[:Paolo Amadini]

(In reply to Boris Zbarsky [:bz] from comment #4)
> > we snapshot the stack if there are no handlers registered at the time of the rejection.
> 
> That includes basic Promise.reject() usage, right?

Right. A nice optimization would be to omit the stack capture when an Error object is already used as the argument.

> If this is blocking us actually moving chrome code over to platform
> promises, we should probably significantly increase the priority here...

Agreed (and reflected in bug 939636).

Comment 7

[Boris Zbarsky [:bzbarsky]]

> omit the stack capture when an Error object is already used as the argument.

Right, I was assuming that.

Let me see what I can do here.

Comment 8

[James Long (:jlongster)]

Any movement here? Our debugger server needs to work inside a worker now, and I'm refactoring a lot of our script actors, but I can't use the new async promises (or Task) because Promise.jsm doesn't work inside a worker (no XPCOM). We need to move to the platform promises before I can use them (and the glorious Task library).

Comment 9

[Boris Zbarsky [:bzbarsky]]

Ok, let's just stop trying to boil the ocean and do this incrementally (perfect is the enemy of the good and all that).

Specifically, I think we shoul switch to reporting all unhandled rejections.  If you reject with an Error like you're supposed to, you get the same output you'd normally get in console for throwing an Error.  Note that we currently do NOT show stack traces there; we just show the file/line.  Fixing that would be lovely, but seems out of scope for this bug, and applies equally to unhandled rejections and uncaught exceptions.

I also don't think we should worry the timestamp, since, again, we don't actually have any facilities for reporting _that_ to the console.  If and when the console grows such facilities, we should make use of them in Promise code, of course.

The thing we _do_ need here is an API that lets us do something similar to js_ReportUncaughtException.  Let me see if I can factor out something like that.

Comment 10

[Boris Zbarsky [:bzbarsky]]

Attachment: part 1. Refactor the js_ReportUncaughtException to produce a (message, JSErrorReport*) pair before reporting

Comment 11

[Boris Zbarsky [:bzbarsky]]

Attachment: part 2. Report all unhandled Promise rejections

Comment 12

[Nikhil Marathe [:nsm] (No longer reading bugmail, please needinfo?)]

Comment on attachment 8445463 [details] [diff] [review]
part 2.  Report all unhandled Promise rejections

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

r=me

::: dom/promise/Promise.cpp
@@ +1046,5 @@
> +  JS::Rooted<JS::Value> val(cx, mResult);
> +  if (val.isObject()) {
> +    obj.construct(cx, &val.toObject());
> +    ac.construct(cx, obj.ref());
> +  } else if (!JS_WrapValue(cx, &val)) {

Susceptible to bug 1027221 so lets wait for that to land.

Comment 13

[James Long (:jlongster)]

Many thanks for working on this!

Comment 14

[Jeff Walden [:Waldo]]

Comment on attachment 8445462 [details] [diff] [review]
part 1.  Refactor the js_ReportUncaughtException to produce a (message, JSErrorReport*) pair before reporting

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

Enough comments, and probably some back-and-forth discussion required, that this probably wants another go.  I'll poke you on IRC and we can discuss quickly so you're not held up too much longer here.

::: js/src/jsexn.cpp
@@ +747,5 @@
>      RootedValue exn(cx);
>      if (!cx->getPendingException(&exn))
>          return false;
>  
> +    JS_ClearPendingException(cx);

cx->setPendingException(value), cx->clearPendingException(), etc. throughout.

@@ +766,5 @@
> +    : reportp(nullptr)
> +    , message_(nullptr)
> +    , ownedMessage(nullptr)
> +    , str(cx)
> +    , exnObject(cx)

ErrorReport::ErrorReport(JSContext *cx)
  : reportp(nullptr),
    message_(nullptr),
    ...

@@ +774,5 @@
> +ErrorReport::~ErrorReport()
> +{
> +    if (!ownedMessage) {
> +        return;
> +    }

No braces.

@@ +783,5 @@
> +         * js_ExpandErrorArguments owns its messageArgs only if it had to
> +         * inflate the arguments (from regular |char *|s), which is always in
> +         * our case.
> +         */
> +        int i = 0;

size_t please, since you're indexing.

@@ +788,5 @@
> +        while (ownedReport.messageArgs[i])
> +            js_free((void *)ownedReport.messageArgs[i++]);
> +        js_free((void *)ownedReport.messageArgs);
> +    }
> +    js_free((void *)ownedReport.ucmessage);

Get rid of all the unnecessary void* casts here.

@@ +792,5 @@
> +    js_free((void *)ownedReport.ucmessage);
> +}
> +
> +bool
> +ErrorReport::init(JSContext *cx, HandleValue exn)

This method returns true, at the end, only.  Should it be returning false somewhere, and not clearing pending exceptions if it triggers any?  Or should it be void?

(It's clear madness for any of this to reenter, and eventually we want to stop doing that.  Something to fix later, but in that world, would returning false, or returning void, make more sense here?  I'm not sure offhand.)

@@ +798,1 @@
>      /*

Maybe a MOZ_ASSERT(!cx->isExceptionPending()); at the start, since this method seems to assume this, and promise it on exit?

@@ +803,1 @@
>          exnObject = exn.toObjectOrNull();

exn.isObject(), &exn.toObject() now.

@@ +872,5 @@
>          uint32_t lineno;
>          if (!JS_GetProperty(cx, exnObject, js_lineNumber_str, &val) ||
>              !ToUint32(cx, val, &lineno))
>          {
>              lineno = 0;

Don't you need cx->clearPendingException() here?

@@ +879,5 @@
>          uint32_t column;
>          if (!JS_GetProperty(cx, exnObject, js_columnNumber_str, &val) ||
>              !ToUint32(cx, val, &column))
>          {
>              column = 0;

And here?

@@ +887,5 @@
> +        PodZero(&ownedReport);
> +        ownedReport.filename = filename.ptr();
> +        ownedReport.lineno = (unsigned) lineno;
> +        ownedReport.exnType = int16_t(JSEXN_NONE);
> +        ownedReport.column = (unsigned) column;

Neither of these unsigned casts is necessary.

@@ +914,5 @@
> +        //                        JSMSG_UNCAUGHT_EXCEPTION, message_);
> +        //
> +        // but without the reporting bits.  Instead it just puts all
> +        // the stuff we care about in our ownedReport and message_.
> +        MessageToReport(cx, message_);

populateUncaughtExceptionReport seems like a better name.

@@ +929,5 @@
> +{
> +    va_list ap;
> +    va_start(ap, cx);
> +    MessageToReportVA(cx, ap);
> +    va_end(ap);    

WS

::: js/src/jsfriendapi.h
@@ +17,5 @@
>  #include "js/CallArgs.h"
>  #include "js/CallNonGenericMethod.h"
>  #include "js/Class.h"
>  
> +#include "jsapi.h" // For JSAutoByteString

File a followup to make this JS::AutoByteString in js/public/AutoByteString.h, please.

@@ +1119,5 @@
>  // which generally matches the toString() behavior of an ErrorObject.
>  extern JS_FRIEND_API(JSString *)
>  ErrorReportToString(JSContext *cx, JSErrorReport *reportp);
>  
> +struct JS_FRIEND_API(ErrorReport)

Adding an explicit MOZ_STACK_CLASS might be nice for quick readability, even if it'll get inferred from containing a Rooted.

@@ +1136,5 @@
> +    {
> +        return message_;
> +    }
> +
> +private:

Indent this two spaces.

@@ +1139,5 @@
> +
> +private:
> +    // More or less an equivalent of JS_ReportErrorNumber/js_ReportErrorNumberVA
> +    // but fills in a ErrorReport instead of reporting it.  Uses varargs to make
> +    // it simpler to cll js_ExpandErrorArguments.

an ErrorReport, call

@@ +1141,5 @@
> +    // More or less an equivalent of JS_ReportErrorNumber/js_ReportErrorNumberVA
> +    // but fills in a ErrorReport instead of reporting it.  Uses varargs to make
> +    // it simpler to cll js_ExpandErrorArguments.
> +    void MessageToReport(JSContext *cx, ...);
> +    void MessageToReportVA(JSContext *cx, va_list ap);

camelCaps

@@ +1142,5 @@
> +    // but fills in a ErrorReport instead of reporting it.  Uses varargs to make
> +    // it simpler to cll js_ExpandErrorArguments.
> +    void MessageToReport(JSContext *cx, ...);
> +    void MessageToReportVA(JSContext *cx, va_list ap);
> +                             

WS

Comment 15

[Boris Zbarsky [:bzbarsky]]

> This method returns true, at the end, only.

No, it has some early return false.  Specifically on OOM when trying to concat strings.

> Don't you need cx->clearPendingException() here?
> And here?

Probably a good idea.  Will add.

Will address the other comments.

Comment 16

[Boris Zbarsky [:bzbarsky]]

<Waldo> so ToString<CanGC>(cx, val) can perfectly well set a pending exception
<Waldo> so I think we need to clear if !str in that case, too

Comment 17

[Boris Zbarsky [:bzbarsky]]

Attachment: Interdiff addressing review comments

Comment 18

[Boris Zbarsky [:bzbarsky]]

Attachment: Patch updated to review comments

Comment 19

[Boris Zbarsky [:bzbarsky]]

> Get rid of all the unnecessary void* casts here.

Some of them are necessary, because free() needs a non-const pointer but those things are const.  I replaced them with the appropriate const_casts as needed.

> File a followup to make this JS::AutoByteString in js/public/AutoByteString.h, please.

Filed bug 1033916.

Comment 20

[Jeff Walden [:Waldo]]

Comment on attachment 8449952 [details] [diff] [review]
Interdiff addressing review comments

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

::: js/src/jsexn.cpp
@@ +766,5 @@
> +    : reportp(nullptr),
> +      message_(nullptr),
> +      ownedMessage(nullptr),
> +      str(cx),
> +      exnObject(cx)

ErrorReport::ErrorReport(JSContext  *cx)
  : reportp(nullptr),
^^
two spaces initial indentation,
    message_(nullptr),
    ownedMessage(nullptr),
    str(cx),
    exnObject(cx)
^^^^
four spaces for each member after the first

::: js/src/jsfriendapi.h
@@ +17,5 @@
>  #include "js/CallArgs.h"
>  #include "js/CallNonGenericMethod.h"
>  #include "js/Class.h"
>  
> +#include "jsapi.h" // For JSAutoByteString.  See bug 1033916.

One lastest problem.  This needs to go above the "jsbytecode.h" include.  As it is right now, try running

make -s -C objdir/js/src/ check-style

which will break on Tinderbox.  (We need to get this run as part of the normal build, yeah.  There's a bug on file for it, on my list to do very soon.)

Comment 21

[Boris Zbarsky [:bzbarsky]]

Fixed the indent and header order.

   https://hg.mozilla.org/integration/mozilla-inbound/rev/207ccc9f5c2c
   https://hg.mozilla.org/integration/mozilla-inbound/rev/42f348168125

Comment 22

[Carsten Book [:Tomcat]]

sorry had to this out in https://tbpl.mozilla.org/?tree=Mozilla-Inbound&rev=7231daefbb28 since one this changes caused bustages/test failures like

https://tbpl.mozilla.org/php/getParsedLog.php?id=43106706&tree=Mozilla-Inbound
and
https://tbpl.mozilla.org/php/getParsedLog.php?id=43107088&tree=Mozilla-Inbound

Comment 23

[Boris Zbarsky [:bzbarsky]]

The compile issue was from this bug.  PopulateReportBlame is a static in jscntxt.cpp, so it only compiled because of unified build bits.  Fixed by just inlining it into populateUncaughtExceptionReportVA like so:

    NonBuiltinFrameIter iter(cx);
    if (!iter.done()) {
        ownedReport.filename = iter.scriptFilename();
        ownedReport.lineno = iter.computeLine(&report->column);
        ownedReport.originPrincipals = iter.originPrincipals();
    }

Comment 24

[Boris Zbarsky [:bzbarsky]]

Some of the crashes, though, also look like they're from this bug.  I'm looking at https://tbpl.mozilla.org/php/getParsedLog.php?id=43107619&tree=Mozilla-Inbound&full=1#error1

Olli, is it possible for us to be getting an async delete without ever getting an unlink?  It sure looks like we got to ~Promise without ever calling MaybeReportRejectedOnce, but are being deleted async by the snowwhite stuff!

If that's possible, can we find out when we're about to be added to the list so we can do the MaybeReportRejectedOnce at that point?

Comment 25

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Boris Zbarsky [:bz] from comment #24)
> Olli, is it possible for us to be getting an async delete without ever
> getting an unlink?
Yes. If refcnt drops to 0 there isn't anything to unlink.
Snowwhite didn't change that.

> If that's possible, can we find out when we're about to be added to the list
> so we can do the MaybeReportRejectedOnce at that point?
Which list? Have a Release implementation which checks when refcnt drops to 0?

Comment 26

[Boris Zbarsky [:bzbarsky]]

> Yes. If refcnt drops to 0 there isn't anything to unlink.

No, the key part is _async_ delete.  If you look at the stack linked to in comment 24, we're getting deleted off AsyncFreeSnowWhite::Run.

And in particular, our C++ object here is keeping a JS value alive.  But I assume that once our refcount goes to 0 we stop doing that, right?  And then it can die before we try to report it, if we don't report when the refcount goes to 0?

> Which list?

The list processed by nsCycleCollector::FreeSnowWhite.

> Have a Release implementation which checks when refcnt drops to 0?

I can do that; the question is whether that's what needs to be done here.

Comment 27

[Andrew McCreight [:mccr8]]

Snow white just means we call the destructor async.  If an object isn't part of a cycle, it can die with only the destructor and not unlink being called.

Comment 28

[Andrew McCreight [:mccr8]]

The C++ object should keep the JS object alive until the C++ object calls DropJSObjects() in its destructor.

Comment 29

[Olli Pettay [:smaug][[e-mail]]]

Or C++ object can call DropJSObjects() earlier (and set the relevant JS member variables to null before that)

Comment 30

[Boris Zbarsky [:bzbarsky]]

Also, we apparently have tests that depend on js_ReportUncaughtException sometimes failing to report the exception: bug 1034616.

Comment 31

[Boris Zbarsky [:bzbarsky]]

> Snow white just means we call the destructor async. 

Right.  This can happen without unlink ever getting called, right?

> The C++ object should keep the JS object alive until the C++ object calls DropJSObjects()
> in its destructor.

Hrm.  We're definitely doing that, and not calling DropJSObjects before the dtor.  I wonder how this JS value is ending up dead...

Comment 32

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Boris Zbarsky [:bz] from comment #31)
> > Snow white just means we call the destructor async. 
> 
> Right.  This can happen without unlink ever getting called, right?
Yes.
Unlink is basically for breaking cycles, and if there are no cycles, no need to call it.



> Hrm.  We're definitely doing that, and not calling DropJSObjects before the
> dtor.  I wonder how this JS value is ending up dead...
Do we ever set js values before HoldJSObjects have been called?

Comment 33

[Boris Zbarsky [:bzbarsky]]

> Do we ever set js values before HoldJSObjects have been called?

No.  We call it in the ctor.

Comment 34

[Boris Zbarsky [:bzbarsky]]

Attachment: This should fix the crash

Bobby, is there a saner way to do things here?  :(

Comment 35

[Boris Zbarsky [:bzbarsky]]

So I finally reproduced the crash locally.  We land in Promise::MaybeReportRejected.  We're rejected with a string.  We do JS_WrapValue(cx, &val), but cx is not in a compartment, since ThreadsafeAutoJSContext doesn't put it in one, so we end up crashing on a null deref on cx->compartment() inside the JS engine.

The attached patch tries hard to find a compartment to enter in this case, but would it make sense to just enter some system compartment and be done, for a string?

Anyway, try run with this patch: https://tbpl.mozilla.org/?tree=Try&rev=bf9341f8e259

Comment 36

[Bobby Holley (:bholley)]

(In reply to Boris Zbarsky [:bz] from comment #34)
> Created attachment 8454275 [details] [diff] [review]
> This should fix the crash
> 
> Bobby, is there a saner way to do things here?  :(

bz and I discussed this on IRC. We're going to eagerly create + preserve Promise reflectors, and then use an AutoJSAPI and JSAutoCompartment in to the reflector's compartment.

Comment 37

[Boris Zbarsky [:bzbarsky]]

Attachment: Crash fix now just using the reflector

Comment 38

[Bobby Holley (:bholley)]

Comment on attachment 8458225 [details] [diff] [review]
Crash fix now just using the reflector

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

r=me with that.

::: dom/promise/Promise.cpp
@@ +1089,5 @@
>  
>    if (MOZ_LIKELY(NS_IsMainThread())) {
>      nsIPrincipal* principal;
> +    win =
> +      do_QueryInterface(nsJSUtils::GetStaticScriptGlobal(obj));

xpc::WindowGlobalOrNull

Comment 39

[Boris Zbarsky [:bzbarsky]]

Done and:

https://hg.mozilla.org/integration/mozilla-inbound/rev/a2f5fa870c8a
https://hg.mozilla.org/integration/mozilla-inbound/rev/f169e4abd298

Comment 40

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/a2f5fa870c8a
https://hg.mozilla.org/mozilla-central/rev/f169e4abd298