RESOLVED FIXED 149790
Web Inspector: When logging strings, detect stack traces and show them as StackTraceView
https://bugs.webkit.org/show_bug.cgi?id=149790
Summary Web Inspector: When logging strings, detect stack traces and show them as Sta...
Nikita Vasilyev
Reported 2015-10-03 19:05:03 PDT
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.
Attachments
WIP (7.91 KB, patch)
2015-10-04 06:37 PDT, Nikita Vasilyev
nvasilyev: review-
nvasilyev: commit-queue-
[Image] Before/After (541.11 KB, image/png)
2015-10-04 07:01 PDT, Nikita Vasilyev
no flags
[HTML] Reduction (1.52 KB, text/html)
2015-10-04 07:03 PDT, Nikita Vasilyev
no flags
WIP (7.90 KB, patch)
2015-10-04 07:04 PDT, Nikita Vasilyev
nvasilyev: review-
nvasilyev: commit-queue-
Patch (1.20 KB, patch)
2015-10-17 21:04 PDT, Nikita Vasilyev
no flags
Patch (7.00 KB, patch)
2015-10-17 21:05 PDT, Nikita Vasilyev
bburg: review-
bburg: commit-queue-
Patch (10.64 KB, patch)
2015-12-10 19:12 PST, Nikita Vasilyev
no flags
Patch (10.75 KB, patch)
2015-12-10 19:24 PST, Nikita Vasilyev
buildbot: commit-queue-
Archive of layout-test-results from ews113 for mac-yosemite (816.67 KB, application/zip)
2015-12-10 20:14 PST, Build Bot
no flags
Patch (11.45 KB, patch)
2015-12-10 20:40 PST, Nikita Vasilyev
no flags
Radar WebKit Bug Importer
Comment 1 2015-10-03 19:05:30 PDT
Nikita Vasilyev
Comment 2 2015-10-03 19:26:27 PDT
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
Comment 3 2015-10-03 19:37:56 PDT
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
Comment 4 2015-10-03 20:02:43 PDT
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
Comment 5 2015-10-04 06:37:17 PDT
Nikita Vasilyev
Comment 6 2015-10-04 07:01:10 PDT
Created attachment 262401 [details] [Image] Before/After
Nikita Vasilyev
Comment 7 2015-10-04 07:03:04 PDT
Created attachment 262402 [details] [HTML] Reduction
Nikita Vasilyev
Comment 8 2015-10-04 07:04:22 PDT
Nikita Vasilyev
Comment 9 2015-10-17 21:04:42 PDT
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
Comment 10 2015-10-17 21:05:57 PDT
Blaze Burg
Comment 11 2015-10-18 16:23:24 PDT
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 12 2015-10-18 17:45:32 PDT
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 13 2015-10-18 22:25:36 PDT
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 14 2015-10-19 10:02:17 PDT
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
Comment 15 2015-12-09 16:10:34 PST
We should finish this up.
Nikita Vasilyev
Comment 16 2015-12-10 19:12:02 PST
Created attachment 267148 [details] Patch Added tests and rebaselined.
Nikita Vasilyev
Comment 17 2015-12-10 19:24:18 PST
Build Bot
Comment 18 2015-12-10 20:14:53 PST
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
Comment 19 2015-12-10 20:14:56 PST
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
Comment 20 2015-12-10 20:40:16 PST
WebKit Commit Bot
Comment 21 2015-12-11 09:34:54 PST
Comment on attachment 267160 [details] Patch Clearing flags on attachment: 267160 Committed r193956: <http://trac.webkit.org/changeset/193956>
WebKit Commit Bot
Comment 22 2015-12-11 09:34:58 PST
All reviewed patches have been landed. Closing bug.
Timothy Hatcher
Comment 23 2016-02-11 17:38:05 PST
*** Bug 149638 has been marked as a duplicate of this bug. ***
Note You need to log in before you can comment on or make changes to this bug.