Bug 149790 – Web Inspector: When logging strings, detect stack traces and show them as StackTraceView

• Component: Web Inspector
• Status: RESOLVED FIXED

[Nikita Vasilyev]

It's fairly common to log stack traces like so:

    try {
        callback.apply(null, callbackArguments);
    } catch (e) {
        console.error("Error dispatching onMessage", e.stack);
    }

We do that in Web Inspector, too (https://github.com/WebKit/webkit/blob/b0d73b826459f733974f1f7dd084a426ead0a2dd/Source/WebInspectorUI/UserInterface/Protocol/InspectorBackend.js#L232-L236).

In the console, we display stack traces as all other strings. This causes issues: "Web Inspector: Can't click on a stack trace link when it's in a console message preview" https://webkit.org/b/149638.

In comparison, Chrome DevTools detect stack traces and folds source links.

[Radar WebKit Bug Importer]

<rdar://problem/22964512>

[Nikita Vasilyev]

Chrome DevTools detect stack traces and folds source paths. Instead of showing:

TypeError: obj.nope is not a function
    at foo (file:///Users/test/Code/Apple/OpenSource/Source/WebInspectorUI/_test/stacktrace-preview.html:12:9)
    at bar (file:///Users/test/Code/Apple/OpenSource/Source/WebInspectorUI/_test/stacktrace-preview.html:16:5)
    at HTMLDocument.<anonymous> (file:///Users/test/Code/Apple/OpenSource/Source/WebInspectorUI/_test/stacktrace-preview.html:21:9)

It shows:

TypeError: obj.nope is not a function
    at foo (stacktrace-preview.html:12:9)
    at bar (stacktrace-preview.html:16:5)
    at HTMLDocument.<anonymous> (stacktrace-preview.html:21:9)

Which is nice.

How does it know what's a stack trace and what's not?

Chrome's stack traces always have error message on the first line, e.g.:

    TypeError: obj.nope is not a function
        at HTMLDocument.<anonymous> (stacktrace-preview.html:21:9)

The error always starts with an error type, such as "TypeError". That how Chrome DevTools just look for that: https://chromium.googlesource.com/chromium/blink/+/master/Source/devtools/front_end/console/ConsoleViewMessage.js#1211.

I find it a bit strange to have error.message in front of error.stack. Safari and Firefox don't do that. It does, however, make the task easy.

[Nikita Vasilyev]

Detecting stack traces in Safari often can be hard.

<script>
document.addEventListener("DOMContentLoaded", function() {
    try {
        nope.nope++;
    } catch(error) {
        console.log(error.stack);
    }
});
</script>

Chrome:
"ReferenceError: nope is not defined
    at HTMLDocument.<anonymous> (file:///Users/nope/Code/Apple/OpenSource/Source/WebInspectorUI/_test/one-line-stack-trace.html:11:9)"

Firefox:
"@file:///Users/nope/Code/Apple/OpenSource/Source/WebInspectorUI/_test/one-line-stack-trace.html:11:9
EventListener.handleEvent*@file:///Users/nope/Code/Apple/OpenSource/Source/WebInspectorUI/_test/one-line-stack-trace.html:9:1"

Safari:
"file:///Users/nope/Code/Apple/OpenSource/Source/WebInspectorUI/_test/one-line-stack-trace.html:11:13"


In Safari, the whole stack trace is just an URI:lineNumber:columnNumber. (I'm not sure if ":lineNumber:columnNumber" part is optional.)

When Firefox can't infer a function name, it still puts "@" before the source path at least. Safari doesn't do it.

[Nikita Vasilyev]

This is a stack trace detection algorithm I came up with so far (pseudo-code):

[LINE](\n[LINE])*

LINE:
    /\D+:\d+:\d+$/ or
    /\[native code\]$/ or
    "eval code"


Just as an observation, in Firefox stack traces are way simpler to detect, since:

1. Each line has "@", no matter what. WebKit, as mentioned above, sometimes omits "@".

2. Each line ends with PATH:lineNumber:columnNumber, always. For eval, it ends with "eval:1:1". In WebKit, eval showed as "eval code" or "eval@[native code]".

[Nikita Vasilyev]

Created attachment 262400 [details]
WIP

[Nikita Vasilyev]

Created attachment 262401 [details]
[Image] Before/After

[Nikita Vasilyev]

Created attachment 262402 [details]
[HTML] Reduction

[Nikita Vasilyev]

Created attachment 262403 [details]
WIP

[Nikita Vasilyev]

Created attachment 263405 [details]
Patch

The previously attached before/after image (https://bug-149790-attachments.webkit.org/attachment.cgi?id=262401) is still relevant.

[Nikita Vasilyev]

Created attachment 263406 [details]
Patch

[Blaze Burg]

Comment on attachment 263406 [details]
Patch

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

Overall this looks good, but r- for not having any test coverage for the non-view code changes.

> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:53
> +    static mostLikelyStackTrace(stack)

This needs some test coverage. A test for WebInspector.StackTrace already exists in LayoutTests/inspector/debugger/js-stacktrace.html, so you should add some new test inputs and expected outputs to it. These should cover the good and bad cases for each of these heuristics.

> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:56
> +        if (stack.length < smallestPossibleStackTraceLength.length * 2)

Why *2?

Is it required that stack traces are prepended with the protocol?

> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:60
> +        if (stack.length > approximateStackLengthOf50Items)

Why is this a reasonable heuristic? Add a comment.

> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:66
> +        const stackTraceLine = "(.{1,400}:\\d+:\\d+|eval code|.{1,200}@\\[native code\\])";

The hardcoded {min,max} is mysterious.

> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:472
> +        if (WebInspector.RemoteObject.type(parameter) !== "string")

console.assert(typeof parameter === WebInspector.RemoteObject)

> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:475
> +        return WebInspector.StackTrace.mostLikelyStackTrace(parameter.description);

Hmm, this name reads poorly to me. If it returns a boolean, it should be something like isLikelyAStackTrace(). The current name could be misinterpreted as "this function returns the most likely stack trace in this string".

[Devin Rousso]

Comment on attachment 263406 [details]
Patch

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

> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:422
> +        if (shouldFormatWithStringSubstitution && this._isStackTrace(parameters[0]))

Instead of changing the value of this var, I think it's better to place the "this._isStackTrace(parameters[0])" as another arg in the if statement below (line 426).

> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:441
> +                let enclosedElement = builderElement.appendChild(document.createElement("span"));

I think you could pull this out of the if/else here since it is used in both statements.  Also, if you are making this one line "let", why not change the rest of the lines too?

[Nikita Vasilyev]

Comment on attachment 263406 [details]
Patch

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

>> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:56
>> +        if (stack.length < smallestPossibleStackTraceLength.length * 2)
> 
> Why *2?
> 
> Is it required that stack traces are prepended with the protocol?

This function will run on every logged string and it may negatively affect Web Inspector's performance. My assumption is that logging error.stack is fairly rare, possibly < 1% of all logged strings. I think it's okay to not detect some very short or very long stack traces. If we don't detect a very short one line stack trace it will still get linkified later.

*2 is rather arbitrary. It is very unlikely that the stack trace would be that short, yet it would allow us to exit early.

I haven't seen any relative URL in stack traces.

>> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:60
>> +        if (stack.length > approximateStackLengthOf50Items)
> 
> Why is this a reasonable heuristic? Add a comment.

Running a regular expression on a large string can be slow.

I once made a Safari extension to log XHRs http://n12v.com/xhr-logger/. It logs response bodies, which can easily be a several megabytes, which is often a case with base64 encoded inline images.

We need to define some reasonable upper bound. Why exactly 5000 characters? I haven't seen a stack trace that long, even with React.js. This one, for example, is only 1411 characters:

App_render@http://www.my-test-app.dev/:99:5
http://www.my-test-app.dev/vendor/react-with-addons.js:7030:40
ReactCompositeComponent__renderValidatedComponent@http://www.my-test-app.dev/vendor/react-with-addons.js:12914:26
http://www.my-test-app.dev/vendor/react-with-addons.js:6572:39
ReactCompositeComponent_mountComponent@http://www.my-test-app.dev/vendor/react-with-addons.js:12914:26
_mountComponentIntoNode@http://www.my-test-app.dev/vendor/react-with-addons.js:5565:39
perform@http://www.my-test-app.dev/vendor/react-with-addons.js:16876:24
mountComponentIntoNode@http://www.my-test-app.dev/vendor/react-with-addons.js:5541:26
http://www.my-test-app.dev/vendor/react-with-addons.js:11794:47
ReactMount__renderNewRootComponent@http://www.my-test-app.dev/vendor/react-with-addons.js:12914:26
render@http://www.my-test-app.dev/vendor/react-with-addons.js:11863:55
React_render@http://www.my-test-app.dev/vendor/react-with-addons.js:12914:26
React_render@http://www.my-test-app.dev/vendor/react-with-addons.js:17652:22
global code@http://www.my-test-app.dev/:364:22
appendChild@[native code]
appendChild@http://www.my-test-app.dev/utils.js:23:32
run@http://www.my-test-app.dev/vendor/JSXTransformer.js:188:21
check@http://www.my-test-app.dev/vendor/JSXTransformer.js:242:12
http://www.my-test-app.dev/vendor/JSXTransformer.js:277:14
onreadystatechange@http://www.my-test-app.dev/vendor/JSXTransformer.js:212:24

>> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:472
>> +        if (WebInspector.RemoteObject.type(parameter) !== "string")
> 
> console.assert(typeof parameter === WebInspector.RemoteObject)

I assume you meant `console.assert(parameter instanceof WebInspector.RemoteObject)`.

>> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:475
>> +        return WebInspector.StackTrace.mostLikelyStackTrace(parameter.description);
> 
> Hmm, this name reads poorly to me. If it returns a boolean, it should be something like isLikelyAStackTrace(). The current name could be misinterpreted as "this function returns the most likely stack trace in this string".

I like isLikelyAStackTrace more than the current name, thanks.

[Blaze Burg]

Comment on attachment 263406 [details]
Patch

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

>>> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:56
>>> +        if (stack.length < smallestPossibleStackTraceLength.length * 2)
>> 
>> Why *2?
>> 
>> Is it required that stack traces are prepended with the protocol?
> 
> This function will run on every logged string and it may negatively affect Web Inspector's performance. My assumption is that logging error.stack is fairly rare, possibly < 1% of all logged strings. I think it's okay to not detect some very short or very long stack traces. If we don't detect a very short one line stack trace it will still get linkified later.
> 
> *2 is rather arbitrary. It is very unlikely that the stack trace would be that short, yet it would allow us to exit early.
> 
> I haven't seen any relative URL in stack traces.

If it turns out to be a performance problem, we can always run this asynchronously and/or in batches. I wouldn't worry too much about performance unless you have some profiles showing some impact.

>>> Source/WebInspectorUI/UserInterface/Views/ConsoleMessageView.js:472
>>> +        if (WebInspector.RemoteObject.type(parameter) !== "string")
>> 
>> console.assert(typeof parameter === WebInspector.RemoteObject)
> 
> I assume you meant `console.assert(parameter instanceof WebInspector.RemoteObject)`.

Oops, yeah.

[Timothy Hatcher]

We should finish this up.

[Nikita Vasilyev]

Created attachment 267148 [details]
Patch

Added tests and rebaselined.

[Nikita Vasilyev]

Created attachment 267149 [details]
Patch

[Build Bot]

Comment on attachment 267149 [details]
Patch

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

New failing tests:
inspector/console/js-isLikelyStackTrace.html

[Build Bot]

Created attachment 267157 [details]
Archive of layout-test-results from ews113 for mac-yosemite

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

[Nikita Vasilyev]

Created attachment 267160 [details]
Patch

[WebKit Commit Bot]

Comment on attachment 267160 [details]
Patch

Clearing flags on attachment: 267160

Committed r193956: <http://trac.webkit.org/changeset/193956>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Timothy Hatcher]

*** Bug 149638 has been marked as a duplicate of this bug. ***