Bug 171416 – RejectedPromiseTracker should produce better callstacks and avoid capturing callstacks unless there is a debugger/inspector

• Status: RESOLVED
• Resolution: FIXED
• Component: WebCore JavaScript

[Joseph Pecoraro]

RejectedPromiseTracker should avoid capturing callstacks unless there is a debugger/inspector

The call stack captured by RejectedPromiseTracker is only used when logging to the console. Since most users will not open the debugger/inspector this wastes time to compute and memory to retain the stack trace.

[Joseph Pecoraro]

I think we can just not do the work if the !globalObject->hasDebugger().

[Joseph Pecoraro]

So this is interesting.

I think we will want a call stack when a runtime error occurs. Even if web inspector is not open. This is the way we behave for uncaught exceptions and it is very useful for developers to open the tools, see the issue, and see the backtrace. The engine already generated a call stack so we should be able to use it.

However, for promise rejections we have this weird situation where the JSC::Exception is gone and we just have the JSC::ErrorInstance:

    (lldb) btjs
    * thread #1: tid = 0x22b14ad, 0x0000000106ec3a92, queue = 'com.apple.main-thread, stop reason = step over
        frame #0: 0x0000000106ec3a92 WebCore`WebCore::createScriptCallStackFromReason(state=0x00007fff5f0ff770, reason=JSValue @ 0x00007fff5f0ff598) at RejectedPromiseTracker.cpp:112
        frame #1: 0x0000000106ec3994 WebCore`WebCore::RejectedPromiseTracker::promiseRejected(this=0x00007fbb9c521550, state=0x00007fff5f0ff770, globalObject=0x000000011fbd6040, promise=0x000000011fbdbd60) at RejectedPromiseTracker.cpp:123
        frame #2: 0x00000001064a3566 WebCore`WebCore::JSDOMWindowBase::promiseRejectionTracker(jsGlobalObject=0x000000011fbd6040, exec=0x00007fff5f0ff770, promise=0x000000011fbdbd60, operation=Reject) at JSDOMWindowBase.cpp:415
        frame #3: 0x0000000111f5d018 JavaScriptCore`JSC::globalFuncHostPromiseRejectionTracker(exec=0x00007fff5f0ff770) at JSGlobalObjectFunctions.cpp:758
        frame #4: 0x00005a1764a01028 0x1120b8725
        frame #5: 0x00000001120b8725 rejectPromise#DJDkwU [LLInt](Cell[Window ID: 518]: 0x11fbd6040, Cell[Promise ID: 486]: 0x11fbdbd60, Cell[Error ID: 472]: 0x11fbe6100)
        frame #6: 0x00000001120b106e JavaScriptCore`vmEntryToJavaScript at LowLevelInterpreter64.asm:254
        frame #7: 0x0000000111e8583e JavaScriptCore`JSC::JITCode::execute(this=0x000000011a0e8ac8, vm=0x000000011f800000, protoCallFrame=0x00007fff5f0ff9d8) at JITCode.cpp:81
        ...

    (lldb) p *reason.asCell()
    (JSC::JSCell) $12 = {
      m_structureID = 472
      m_indexingTypeAndMisc = '\0'
      m_type = ErrorInstanceType
      m_flags = '\0'
      m_cellState = DefinitelyWhite
    }


Basically when the page threw a runtime exception in a then handler, a built-in try/catch catches it and propagates the error value:

    @globalPrivate
    function promiseReactionJob(state, reaction, argument)
    {
        ...
        try {
            result = handler(argument);
        } catch (error) {
            return promiseCapability.@reject.@call(@undefined, error);
        }
        ...
    }

@reject goes to @rejectPromise:

    @globalPrivate
    function createResolvingFunctions(promise)
    {
        ...
        var reject = function (reason) {
            if (alreadyResolved)
                return @undefined;
            alreadyResolved = true;

            return @rejectPromise(promise, reason);
        };

        return {
            @resolve: resolve,
            @reject: reject
        };
    }

Up to the RejectionTracker:

    @globalPrivate
    function rejectPromise(promise, reason)
    {
        ...
        promise.@promiseResult = reason;    
        ...
        if (!promise.@promiseIsHandled)
            @hostPromiseRejectionTracker(promise, @promiseRejectionReject);
        ...
    }

---

So the RejectedPromiseTracker just has the Error instance, which has an e.stack string property but we lost the nicer call stack with StackFrames which was used to generate the e.stack.

[Joseph Pecoraro]

I can use vm.lastException() with some verification (the exception's error value is the reason value).

This actually gives the correct stack from when the exception happened inside the promise reaction, and not a muffled stack that was since the try/catch in built-in code. So this is a win-win: It use the pre-existing Exception stack and has more correct information when logging to the Inspector console.

I'm going to write some inspector tests for this now.

[Radar WebKit Bug Importer]

<rdar://problem/31899425>

[Joseph Pecoraro]

Created attachment 308616 [details]
[PATCH] Proposed Fix

[Build Bot]

Comment on attachment 308616 [details]
[PATCH] Proposed Fix

Attachment 308616 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/3629907

New failing tests:
js/promises-tests/promises-tests-2-2-6.html
imported/w3c/web-platform-tests/streams/piping/close-propagation-forward.html
http/tests/security/video-cross-origin-caching.html
imported/w3c/web-platform-tests/streams/piping/error-propagation-forward.html
streams/reference-implementation/readable-stream-templated.html
js/dom/unhandled-promise-rejection-console-report.html
inspector/debugger/break-on-exception-throw-in-promise.html
js/dom/unhandled-promise-rejection-bindings-type-error.html
streams/reference-implementation/writable-stream-abort.html
imported/w3c/web-platform-tests/streams/piping/general.html
imported/w3c/web-platform-tests/WebCryptoAPI/derive_bits_keys/test_ecdh_bits.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/paused_true_during_pause.html
inspector/debugger/break-on-uncaught-exception-throw-in-promise.html
imported/w3c/web-platform-tests/WebCryptoAPI/derive_bits_keys/test_ecdh_keys.html
streams/reference-implementation/writable-stream.html
imported/w3c/web-platform-tests/streams/piping/error-propagation-backward.html
imported/w3c/web-platform-tests/streams/piping/flow-control.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/event_play_noautoplay.html
streams/reference-implementation/pipe-to-options.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/event_pause_noautoplay.html

[Build Bot]

Created attachment 308635 [details]
Archive of layout-test-results from ews102 for mac-elcapitan

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-elcapitan  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 308616 [details]
[PATCH] Proposed Fix

Attachment 308616 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/3629890

New failing tests:
streams/reference-implementation/readable-stream-templated.html
inspector/debugger/break-on-uncaught-exception-throw-in-promise.html
http/tests/security/video-cross-origin-caching.html
imported/w3c/web-platform-tests/streams/piping/close-propagation-forward.html
webrtc/libwebrtc/release-while-creating-offer.html
imported/w3c/web-platform-tests/streams/piping/error-propagation-forward.html
imported/w3c/web-platform-tests/streams/piping/error-propagation-backward.html
fast/mediastream/MediaStream-MediaElement-setObject-null.html
js/promises-tests/promises-tests-2-2-6.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/event_pause_noautoplay.html
imported/w3c/web-platform-tests/streams/piping/general.html
inspector/debugger/break-on-exception-throw-in-promise.html
js/dom/unhandled-promise-rejection-bindings-type-error.html
imported/w3c/web-platform-tests/WebCryptoAPI/derive_bits_keys/test_ecdh_bits.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/paused_true_during_pause.html
streams/reference-implementation/writable-stream.html
webrtc/libwebrtc/release-while-setting-local-description.html
streams/reference-implementation/pipe-to-options.html
js/dom/unhandled-promise-rejection-console-report.html
streams/reference-implementation/writable-stream-abort.html
imported/w3c/web-platform-tests/WebCryptoAPI/derive_bits_keys/test_ecdh_keys.html
imported/w3c/web-platform-tests/streams/piping/flow-control.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/event_play_noautoplay.html

[Build Bot]

Created attachment 308637 [details]
Archive of layout-test-results from ews105 for mac-elcapitan-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews105  Port: mac-elcapitan-wk2  Platform: Mac OS X 10.11.6

[Build Bot]

Comment on attachment 308616 [details]
[PATCH] Proposed Fix

Attachment 308616 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/3629993

New failing tests:
js/promises-tests/promises-tests-2-2-6.html
imported/w3c/web-platform-tests/streams/piping/close-propagation-forward.html
imported/w3c/web-platform-tests/streams/piping/error-propagation-forward.html
streams/reference-implementation/readable-stream-templated.html
js/dom/unhandled-promise-rejection-console-report.html
inspector/debugger/break-on-exception-throw-in-promise.html
js/dom/unhandled-promise-rejection-bindings-type-error.html
streams/reference-implementation/writable-stream-abort.html
imported/w3c/web-platform-tests/streams/piping/general.html
imported/w3c/web-platform-tests/WebCryptoAPI/derive_bits_keys/test_ecdh_bits.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/paused_true_during_pause.html
inspector/debugger/break-on-uncaught-exception-throw-in-promise.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/event_pause_noautoplay.html
imported/w3c/web-platform-tests/WebCryptoAPI/derive_bits_keys/test_ecdh_keys.html
streams/reference-implementation/writable-stream.html
imported/w3c/web-platform-tests/streams/piping/error-propagation-backward.html
imported/w3c/web-platform-tests/streams/piping/flow-control.html
imported/w3c/web-platform-tests/html/semantics/embedded-content/media-elements/event_play_noautoplay.html
streams/reference-implementation/pipe-to-options.html
http/tests/security/video-cross-origin-caching.html

[Build Bot]

Created attachment 308640 [details]
Archive of layout-test-results from ews113 for mac-elcapitan

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews113  Port: mac-elcapitan  Platform: Mac OS X 10.11.6

[Joseph Pecoraro]

Created attachment 308641 [details]
[PATCH] Proposed Fix

+ Inspector folks since I include an inspector test to verify the stack.

[Build Bot]

Attachment 308641 [details] did not pass style-queue:


ERROR: LayoutTests/ChangeLog:19:  Line contains tab character.  [whitespace/tab] [5]
ERROR: LayoutTests/ChangeLog:20:  Line contains tab character.  [whitespace/tab] [5]
Total errors found: 2 in 32 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Joseph Pecoraro]

Created attachment 308645 [details]
[PATCH] Proposed Fix

[Blaze Burg]

Comment on attachment 308645 [details]
[PATCH] Proposed Fix

View in context: https://bugs.webkit.org/attachment.cgi?id=308645&action=review

New test looks good to me.

> LayoutTests/inspector/console/message-stack-trace.html:73
> +                untilMessageMatches(condition).then((message) => {

Very nice.

> LayoutTests/inspector/console/resources/log-console-stack-trace.js:12
> +                let code = callFrame.nativeCode ? "N" : (callFrame.programCode ? "P" : "F");

I don't see the [P] case used anywhere. Is that expected? Would we ever see it if we remove test harness call frames?

[Joseph Pecoraro]

> I don't see the [P] case used anywhere. Is that expected? Would we ever see
> it if we remove test harness call frames?

P is Program code. Here we are dumping stacks that resulted from a `setTimeout(func)` so we don't expect to see program code. If callstacks included async code then we would see the Program code that triggered the setTimeout. Another case would be doing a console.error/trace from global code.

[Saam Barati]

Comment on attachment 308645 [details]
[PATCH] Proposed Fix

View in context: https://bugs.webkit.org/attachment.cgi?id=308645&action=review

> Source/WebCore/ChangeLog:22
> +        new stack since the try/catch. Instead, we want the stack from before

did you mean to say "since" here?

> Source/WebCore/ChangeLog:28
> +        Switch to a pointer since the staack could be empty.

staack =>stack

> Source/WebCore/dom/RejectedPromiseTracker.cpp:114
> +        if (exception->value() == reason)
> +            return createScriptCallStackFromException(&state, exception, ScriptCallStack::maxCallStackSizeToCapture);

Don't we only want to do this if the debugger is open?

[Joseph Pecoraro]

> > Source/WebCore/dom/RejectedPromiseTracker.cpp:114
> > +        if (exception->value() == reason)
> > +            return createScriptCallStackFromException(&state, exception, ScriptCallStack::maxCallStackSizeToCapture);
> 
> Don't we only want to do this if the debugger is open?

I'm intentionally doing this for Exceptions in Unhandled Rejections to match our behavior for Uncaught Exceptions when a debugger is not open. In these cases we have an existing JSC::Exception object that already walked the stack, so this should be a smaller operation in comparison. It is also a huge time saver for developers to open Web Inspector and see the full stack for runtime exceptions and not have to try to reproduce with Web Inspector open.

In cases where a Promise is explicitly rejected (someone calling `reject`) we don't capture the stack unless the debugger is open.

[Saam Barati]

(In reply to Joseph Pecoraro from comment #18)
> > > Source/WebCore/dom/RejectedPromiseTracker.cpp:114
> > > +        if (exception->value() == reason)
> > > +            return createScriptCallStackFromException(&state, exception, ScriptCallStack::maxCallStackSizeToCapture);
> > 
> > Don't we only want to do this if the debugger is open?
> 
> I'm intentionally doing this for Exceptions in Unhandled Rejections to match
> our behavior for Uncaught Exceptions when a debugger is not open. In these
> cases we have an existing JSC::Exception object that already walked the
> stack, so this should be a smaller operation in comparison. It is also a
> huge time saver for developers to open Web Inspector and see the full stack
> for runtime exceptions and not have to try to reproduce with Web Inspector
> open.
> 
> In cases where a Promise is explicitly rejected (someone calling `reject`)
> we don't capture the stack unless the debugger is open.

I think this might be worth it, but I looked at what this code does, and I'm not certain it will be less time than taking the stack trace itself. It looks like at the very least we binary search for line/column info at each frame.

[Joseph Pecoraro]

<https://trac.webkit.org/changeset/216035/webkit>

[Joseph Pecoraro]

> I think this might be worth it, but I looked at what this code does, and I'm
> not certain it will be less time than taking the stack trace itself. It
> looks like at the very least we binary search for line/column info at each
> frame.

You are correct, I overlooked that part.

I still feel it is justified since exceptions should be exceptional ("rare") cases. If this path gets hit for more than just exception cases we should reconsider.