1441333 - Include better location information in errors triggered by async APIs

Status: RESOLVED FIXED

(WebExtensions :: General, enhancement)

Comment 1

[Kris Maglione [:kmag]]

Attachment: Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

Most WebExtension APIs are async, and have fairly complicated error reporting
semantics. As a result, when we report an error, the current JS stack has very
little to do with the JS caller that triggered the error, which makes it
difficult to diagnose.

In order to improve the situation, we need to store the location of the caller
at the start of an async operation, so we can tie the error to some marginally
useful location. We don't have a reasonable way to do that now other than
proactively creating an error object when the API is called, or creating a
promise with a full async stack, both of which are too expensive.

This helper instead returns a single SavedStack frame with a given principal,
which should be considerably cheaper, and likely good enough to give a
starting point for debugging cryptic errors.

Review commit: https://reviewboard.mozilla.org/r/223386/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223386/

Comment 2

[Kris Maglione [:kmag]]

Attachment: Bug 1441333: Part 2 - Allow passing an error stack to reportError.

Building on top of part 1, we need a way to link a saved caller location to a
reported error message. This change allows us to pass a stack to `reportError`
when called with a string.

This part was written before part 3, and could probably be removed in favor of
using createError in every call. But this method also has the advantage of
being more consise and somewhate more efficient.

Review commit: https://reviewboard.mozilla.org/r/223388/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223388/

Comment 3

[Kris Maglione [:kmag]]

Attachment: Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack.

There's no standard way to create a JS error with full stack and location
information from a saved stack. Since we need this functionality in order to
reject promises with useful Error objects, this patch adds a simple helper to
make that possible.

Review commit: https://reviewboard.mozilla.org/r/223390/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223390/

Comment 4

[Kris Maglione [:kmag]]

Attachment: Bug 1441333: Part 4 - Add caller location to async API errors.

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.

Review commit: https://reviewboard.mozilla.org/r/223392/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223392/

Comment 5

[Kris Maglione [:kmag]]

Attachment: Bug 1441333: Part 6 - Use caller location in error reports for StrongPromise errors.

We currently report a useful location in error reports when extensions fail to
resolve a promise or call a response callback, but in some slightly
less-than-ideal ways. We currently generate a complete stack and parse its
string value (which is expensive), and then report the caller location as part
of the message, rather than as the error's location and stack.

This patch changes that behavior to store a single SavedStack frame, and to
properly report that as the location of the error.

Review commit: https://reviewboard.mozilla.org/r/223394/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223394/

Comment 6

[Kris Maglione [:kmag]]

Attachment: Bug 1441333: Part 5 - Use proper async caller location in normalizeError.

Currently, when we create an error object at the end of an aysnc operation, we
only get a useful caller location if async stacks are enabled.

This patch changes our behavior to use the saved caller location we've already
stored when creating an Error object based on a plain string message.

Review commit: https://reviewboard.mozilla.org/r/223396/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223396/

Comment 7

[Kris Maglione [:kmag]]

Comment on attachment 8954243 [details]
Bug 1441333: Part 5 - Use proper async caller location in normalizeError.

https://reviewboard.mozilla.org/r/223396/#review229446

::: js/xpconnect/src/XPCJSRuntime.cpp:2903
(Diff revision 1)
>      JS_AddFinalizeCallback(cx, FinalizeCallback, nullptr);
>      JS_AddWeakPointerZonesCallback(cx, WeakPointerZonesCallback, this);
>      JS_AddWeakPointerCompartmentCallback(cx, WeakPointerCompartmentCallback, this);
>      JS_SetWrapObjectCallbacks(cx, &WrapObjectCallbacks);
>      js::SetPreserveWrapperCallback(cx, PreserveWrapper);
> +    JS_InitReadPrincipalsCallback(cx, nsJSPrincipals::ReadPrincipals);

Ignore this. It's from a patch in another bug, but accidentally got rolled into this one.

Comment 8

[Tomislav Jovanovic :zombie]

Comment on attachment 8954238 [details]
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

https://reviewboard.mozilla.org/r/223386/#review230096

::: js/xpconnect/tests/unit/test_getCallerLocation.js:4
(Diff revision 1)
> +/* This Source Code Form is subject to the terms of the Mozilla Public
> + * License, v. 2.0. If a copy of the MPL was not distributed with this
> + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
> +

nit: "use strict";

Comment 9

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8954238 [details]
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

https://reviewboard.mozilla.org/r/223386/#review230406

r=me woth the nits below fixed.

::: dom/base/ChromeUtils.cpp:670
(Diff revision 1)
> +    JS_ClearPendingException(cx);
> +    return;

You need to explicitly assign null to aRetval in this case, I would think.

::: dom/webidl/ChromeUtils.webidl:302
(Diff revision 1)
> +
> +  /**
> +   * Returns the scripted location of the first ancestor stack frame with a
> +   * principal which subsumes the given principal.
> +   */
> +  object? getCallerLocation(Principal principal);

Please document what a null return value means (or can mean).

::: js/src/jsfriendapi.h:2992
(Diff revision 1)
>   * The savedFrame and cx do not need to be in the same compartment.
>   */
>  extern JS_FRIEND_API(JSObject*)
>  GetFirstSubsumedSavedFrame(JSContext* cx, JS::HandleObject savedFrame, JS::SavedFrameSelfHosted selfHosted);
>  
> +extern JS_FRIEND_API(JSObject*)

Needs to be documented.

::: js/src/vm/SavedStacks.cpp:576
(Diff revision 1)
> -// principals are subsumed by |principals|, according to |subsumes|. If there is
> -// no such frame, return nullptr. |skippedAsync| is set to true if any of the
> -// skipped frames had the |asyncCause| property set, otherwise it is explicitly
> -// set to false.
>  static SavedFrame*
> -GetFirstSubsumedFrame(JSContext* cx, HandleSavedFrame frame, JS::SavedFrameSelfHosted selfHosted,
> +GetFirstMatchedFrame(JSContext* cx, Matcher& matches,

Needs to be documented.

::: js/src/vm/SavedStacks.cpp:601
(Diff revision 1)
>  
>      return nullptr;
>  }
>  
> +// Return the first SavedFrame in the chain that starts with |frame| whose
> +// principals are subsumed by |principals|, according to |subsumes|. If there is

This comment doesn't make sense; we have no |principals| here.  Yes, that was a preexisting problem.


Presumably should be talking about being subsumed by the current principal of cx?

Comment 10

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8954239 [details]
Bug 1441333: Part 2 - Allow passing an error stack to reportError.

https://reviewboard.mozilla.org/r/223388/#review230416

r=me modulo the two caveats below.

::: js/xpconnect/src/XPCComponents.cpp:2092
(Diff revision 1)
>      if (!scripterr) {
> +        RootedObject stackObj(cx);
> +        if (stack.isObject()) {
> +            stackObj = &stack.toObject();
> +
> +            if (GetSavedFrameLine(cx, stackObj, &lineNo) != SavedFrameResult::Ok) {

So this will do horrible things if stackObj is not a SavedFrame object.  Please test IsSavedFrame() before calling saved-frame APIs here.  Actually, before even assigning to stackObj.

I almost wonder whether it's worth using nsIStackFrame as the representation of these stacks.  It would be a tiny bit more overhead on capture (extra allocation), but make the code way simpler here.  For example, you coudld share it with the existing nsIStackFrame code.

Comment 11

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8954240 [details]
Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack.

https://reviewboard.mozilla.org/r/223390/#review230418

::: dom/base/ChromeUtils.cpp:700
(Diff revision 1)
> +      stack = UncheckedUnwrap(aStack);
> +      ac.emplace(cx, stack);
> +
> +      if (JS::GetSavedFrameLine(cx, stack, &line) != JS::SavedFrameResult::Ok ||

Something here needs to check that this is really a StackFrame.

::: dom/base/ChromeUtils.cpp:733
(Diff revision 1)
> +    MOZ_ASSERT(err.isObject());
> +    aRetVal.set(&err.toObject());
> +  }
> +
> +  if (aStack) {
> +    JS_WrapObject(cx, aRetVal);

This call can fail.

Comment 12

[Kris Maglione [:kmag]]

Comment on attachment 8954238 [details]
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223386/diff/1-2/

Comment 13

[Kris Maglione [:kmag]]

Comment on attachment 8954239 [details]
Bug 1441333: Part 2 - Allow passing an error stack to reportError.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223388/diff/1-2/

Comment 14

[Kris Maglione [:kmag]]

Comment on attachment 8954240 [details]
Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223390/diff/1-2/

Comment 15

[Kris Maglione [:kmag]]

Comment on attachment 8954241 [details]
Bug 1441333: Part 4 - Add caller location to async API errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223392/diff/1-2/

Comment 16

[Kris Maglione [:kmag]]

Comment on attachment 8954242 [details]
Bug 1441333: Part 6 - Use caller location in error reports for StrongPromise errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223394/diff/1-2/

Comment 17

[Kris Maglione [:kmag]]

Comment on attachment 8954243 [details]
Bug 1441333: Part 5 - Use proper async caller location in normalizeError.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223396/diff/1-2/

Comment 18

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8954240 [details]
Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack.

https://reviewboard.mozilla.org/r/223390/#review230430

Comment 19

[Tomislav Jovanovic :zombie]

Comment on attachment 8954241 [details]
Bug 1441333: Part 4 - Add caller location to async API errors.

https://reviewboard.mozilla.org/r/223392/#review230104

::: toolkit/components/extensions/ExtensionCommon.jsm:287
(Diff revision 2)
>      } else {
>        try {
>          let {cloneScope} = this;
>          args = args.map(arg => Cu.cloneInto(arg, cloneScope));
>        } catch (e) {
>          Cu.reportError(e);

I think it makes sense to use the caller location for this error as well.

::: toolkit/components/extensions/ExtensionCommon.jsm:291
(Diff revision 2)
>        } catch (e) {
>          Cu.reportError(e);
>          dump(`runSafe failure: cloning into ${this.cloneScope}: ${e}\n\n${filterStack(Error())}`);
>        }
>  
>        return this.applySafeWithoutClone(callback, args);

Pass the caller here.

::: toolkit/components/extensions/ExtensionCommon.jsm:297
(Diff revision 2)
>      }
>    }
>  
> -  applySafeWithoutClone(callback, args) {
> +  applySafeWithoutClone(callback, args, caller) {
>      if (this.unloaded) {
>        Cu.reportError("context.runSafeWithoutClone called after context unloaded");

Missed this?  And below.

::: toolkit/components/extensions/ExtensionCommon.jsm:305
(Diff revision 2)
>      } 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);

Though we shouldn't use the caller here, if I'm understanding this correctly.

::: toolkit/components/extensions/ExtensionCommon.jsm:423
(Diff revision 2)
> +   * @param {SavedFrame} [caller]
> +   *        The optional caller frame which triggered this callback, to be used
> +   *        in error reporting.
>     * @returns {*} The return value of callback.
>     */
> -  withLastError(error, callback) {
> +  withLastError(error, callback, caller) {

Not thrilled about the param order. :/
Perhaps put callback first?

Comment 20

[Kris Maglione [:kmag]]

Comment on attachment 8954241 [details]
Bug 1441333: Part 4 - Add caller location to async API errors.

https://reviewboard.mozilla.org/r/223392/#review230104

> I think it makes sense to use the caller location for this error as well.

Nope. Passing the caller to reportError is only useful when we pass a string rather than an error object, which shouldn't happen here.

> Not thrilled about the param order. :/
> Perhaps put callback first?

Having the callback first makes the calls with inline functions hard to read. I suppose the caller could be the second argument, and we could pass null if we don't have one.

Comment 21

[Tomislav Jovanovic :zombie]

Comment on attachment 8954242 [details]
Bug 1441333: Part 6 - Use caller location in error reports for StrongPromise errors.

https://reviewboard.mozilla.org/r/223394/#review230464

r=me once the test passes.

::: toolkit/components/extensions/ExtensionChild.jsm:116
(Diff revision 2)
> -  observe(subject, topic, tag) {
> -    const pos = tag.indexOf("|");
> -    const channel = Number(tag.substr(0, pos));
> -    const location = tag.substr(pos + 1);
> -    const message = `Promised response from onMessage listener at ${location} went out of scope`;
> -    MessageChannel.abortChannel(channel, {message});
> +  observe(subject, topic, channelId) {
> +    channelId = Number(channelId);
> +    let location = this.locations.get(channelId);
> +    this.locations.delete(channelId);
> +
> +    const message = `Promised response from onMessage listener went out of scope`;

You likely need to update the test I added for this, I think it explicitly checks that location is present in the error message.

Comment 22

[Tomislav Jovanovic :zombie]

Comment on attachment 8954243 [details]
Bug 1441333: Part 5 - Use proper async caller location in normalizeError.

https://reviewboard.mozilla.org/r/223396/#review230472

r=me with the test added.

Comment 23

[Tomislav Jovanovic :zombie]

Comment on attachment 8954241 [details]
Bug 1441333: Part 4 - Add caller location to async API errors.

https://reviewboard.mozilla.org/r/223392/#review230104

> Nope. Passing the caller to reportError is only useful when we pass a string rather than an error object, which shouldn't happen here.

Right, though I meant it would be more useful to point to the extension code that called into our api.  But now that I think about it, if we failed to clone the callback argument, that's probably our error, and not an error with the extension.

Comment 24

[Kris Maglione [:kmag]]

Comment on attachment 8954238 [details]
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223386/diff/2-3/

Comment 25

[Kris Maglione [:kmag]]

Comment on attachment 8954239 [details]
Bug 1441333: Part 2 - Allow passing an error stack to reportError.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223388/diff/2-3/

Comment 26

[Kris Maglione [:kmag]]

Comment on attachment 8954240 [details]
Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223390/diff/2-3/

Comment 27

[Kris Maglione [:kmag]]

Comment on attachment 8954241 [details]
Bug 1441333: Part 4 - Add caller location to async API errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223392/diff/2-3/

Comment 28

[Kris Maglione [:kmag]]

Comment on attachment 8954243 [details]
Bug 1441333: Part 5 - Use proper async caller location in normalizeError.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223396/diff/2-3/

Comment 29

[Kris Maglione [:kmag]]

Comment on attachment 8954242 [details]
Bug 1441333: Part 6 - Use caller location in error reports for StrongPromise errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223394/diff/2-3/

Comment 30

[Tomislav Jovanovic :zombie]

Comment on attachment 8954241 [details]
Bug 1441333: Part 4 - Add caller location to async API errors.

https://reviewboard.mozilla.org/r/223392/#review230496

r=me with the test added.

Comment 31

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/f9eb113f179f94145a575f602e359186d71b2b34
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal. r=bz

https://hg.mozilla.org/integration/mozilla-inbound/rev/61f204267373b1806950985a5b5abd4933f15009
Bug 1441333: Part 2 - Allow passing an error stack to reportError. r=bz

https://hg.mozilla.org/integration/mozilla-inbound/rev/c21a778bab3dac0c4c436f7473e80c4fa751d491
Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack. r=bz

https://hg.mozilla.org/integration/mozilla-inbound/rev/47c2e679000ff75affdb8314a7ee83726411806e
Bug 1441333: Part 4 - Add caller location to async API errors. r=zombie

https://hg.mozilla.org/integration/mozilla-inbound/rev/cf87433f501d755e6cde616a6ec77a4f37c69a00
Bug 1441333: Part 5 - Use proper async caller location in normalizeError. r=zombie

https://hg.mozilla.org/integration/mozilla-inbound/rev/930b44b7adc7e26e0b76cb46178489fc2e6704dc
Bug 1441333: Part 6 - Use caller location in error reports for StrongPromise errors. r=zombie

Comment 32

[Kris Maglione [:kmag]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/2e11c53b5a51948e8afb845e2c1603cc2ecd8b9f
Bug 1441333: Follow-up: Fix OS-X failure due to extra console warning. r=bustage

Comment 33

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/mozilla-central/rev/f9eb113f179f
https://hg.mozilla.org/mozilla-central/rev/61f204267373
https://hg.mozilla.org/mozilla-central/rev/c21a778bab3d
https://hg.mozilla.org/mozilla-central/rev/47c2e679000f
https://hg.mozilla.org/mozilla-central/rev/cf87433f501d
https://hg.mozilla.org/mozilla-central/rev/930b44b7adc7
https://hg.mozilla.org/mozilla-central/rev/2e11c53b5a51

Comment 34

[marius.santa]

Is manual testing required on this bug? If Yes, please provide some STR and the proper webextension(if required), if No set the “qe-verify-“ flag.

Comment 35

[Andrea Marchesini [:baku]]

Comment on attachment 8954238 [details]
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

https://reviewboard.mozilla.org/r/223386/#review231970

You must ask a JS peer to review this code.

::: dom/base/ChromeUtils.h:171
(Diff revision 3)
>                                   const nsAString& id,
>                                   const nsAString& resourceURI,
>                                   ErrorResult& aRv);
> +
> +  static void
> +  GetCallerLocation(const GlobalObject& global, nsIPrincipal* principal,

aGlobal, aPrincipal

::: js/src/jsfriendapi.h:2999
(Diff revision 3)
> + * subsumed by the given |principals|. If there is no such frame, return nullptr.
> + *
> + * Do NOT pass a non-SavedFrame object here.
> + */
> +extern JS_FRIEND_API(JSObject*)
> +GetFirstSubsumedSavedFrame(JSContext* cx, JSPrincipals* principals, JS::HandleObject savedFrame, JS::SavedFrameSelfHosted selfHosted);

I cannot review this code.

Comment 36

[Andrea Marchesini [:baku]]

Comment on attachment 8954238 [details]
Bug 1441333: Part 1 - Add helper to retrieve closest stack frame with a given principal.

https://reviewboard.mozilla.org/r/223386/#review231974

r+ for the DOM part.

Comment 37

[Andrea Marchesini [:baku]]

Comment on attachment 8954239 [details]
Bug 1441333: Part 2 - Allow passing an error stack to reportError.

https://reviewboard.mozilla.org/r/223388/#review231972

You need a r+ from a JS peer here as well.

::: js/xpconnect/src/XPCComponents.cpp:2090
(Diff revision 3)
> -    int32_t lineNo = 0;
> +    uint32_t lineNo = 0;
>  
>      if (!scripterr) {
> +        RootedObject stackObj(cx);
> +        if (stack.isObject()) {
> +            if (!JS::IsSavedFrame(&stack.toObject())) {

no {} in JS code style.

::: js/xpconnect/src/XPCComponents.cpp:2096
(Diff revision 3)
> +                return NS_ERROR_INVALID_ARG;
> +            }
> +
> +            stackObj = &stack.toObject();
> +
> +            if (GetSavedFrameLine(cx, stackObj, &lineNo) != SavedFrameResult::Ok) {

same here.

Comment 38

[Andrea Marchesini [:baku]]

Comment on attachment 8954240 [details]
Bug 1441333: Part 3 - Add helper to create a JS error with a saved stack.

https://reviewboard.mozilla.org/r/223390/#review231976