Wrong stack trace for requests fetched from the Console

RESOLVED FIXED in Firefox 69

Status

defect
P3
normal
RESOLVED FIXED
3 months ago
Last month

People

(Reporter: Honza, Assigned: nchevobbe)

Tracking

(Blocks 1 bug)

unspecified
Firefox 69
Dependency tree / graph

Firefox Tracking Flags

(firefox69 fixed)

Details

Attachments

(3 attachments)

STR:

  1. Load any page e.g. google.com
  2. Select the Console panel
  3. Execute fetch("google.com")
  4. Inspect stack trace of the request (in the Console panel directly or in the Network panel)
  5. The Stack Trace tab (side panel tab in Net panel) shows DevTools related frames -> BUG

Expected:
DevTools related frames should be there.

Honza

Priority: -- → P3
Has STR: --- → yes

:Honza, if you think that's a regression, then could you try to find a regression range in using for example mozregression?

:Honza, if you think that's a regression, then could you try to find a regression range in using for example mozregression?

My gut feeling is that this isn't a regression (note that it doesn't work in the current 66 release)

Honza

Assignee

Comment 4

3 months ago

I do see it in 66

Yep, I can confirm, that's what I meant my comment #3 (perhaps I could have been more clear)

Honza

:Honza, if you think that's a regression, then could you try to find a regression range in using for example mozregression?

Comment hidden (obsolete)

@Jim, another stack trace bug, what could be the issue?

Honza

Flags: needinfo?(jimb)

Comment 9

3 months ago

I'm not sure, but here's a hypothesis:

When a stack is captured, we always save all frames on the stack, regardless of privilege. It's only when JavaScript tries to inspect the stack that we consider the privilege level of the code doing the inspection and decide which frames to reveal: each saved frame records the principal of the compartment the code was executing in, and when code wants to view a frame, we check the viewer's principals against the frame's principals, and only reveal frames subsumed by or equal to the viewer's principal.

Thus, if devtools is somehow viewing the stack with chrome privilege, it will see all frames, including DevTools' own. Honza suggested that it might be this code:
https://searchfox.org/mozilla-central/rev/14dc5b7d8a6da1854b2f9f33f1da77a97368cd54/devtools/server/actors/network-monitor/stack-trace-collector.js#61-77

About a year ago I wrote up a proposal for improving the way we handle stack frame filtering. We didn't act on it at the time, but maybe we should consider picking it up:

Non-Leaky, Privilege-Sensitive Saved Stacks
https://gist.github.com/jimblandy/4f4f14d5a175f0106e1becee27437534

Flags: needinfo?(jimb)

Comment 10

3 months ago

Proposal. Attaching directly to Bugzilla, to avoid dependence on external sites.

Comment 11

3 months ago

Yeah, I think, see the section following "Unfortunately, this design is not working out as intended:". That looks a lot like this bug.

Brian, one more captured stack frames issue. Can you please look at this?

Honza

Flags: needinfo?(bhackett1024)

A function was introduced not long ago to strips out internal frames from a given stack (devtools/server/actors/webconsole/utils.js#197-218. Maybe it could be of some use here.

This fixes the issue:

diff --git a/devtools/server/actors/network-monitor/stack-trace-collector.js b/devtools/server/actors/network-monitor/stack-trace-collector.js
--- a/devtools/server/actors/network-monitor/stack-trace-collector.js
+++ b/devtools/server/actors/network-monitor/stack-trace-collector.js
@@ -15,6 +15,8 @@ loader.lazyRequireGetter(this, "ChannelE
 loader.lazyRequireGetter(this, "matchRequest",
                          "devtools/server/actors/network-monitor/network-observer",
                          true);
+loader.lazyRequireGetter(this, "WebConsoleUtils",
+                         "devtools/server/actors/webconsole/utils", true);
 
 function StackTraceCollector(filters, netmonitors) {
   this.filters = filters;
@@ -99,7 +101,7 @@ StackTraceCollector.prototype = {
   getStackTrace(channelId) {
     const trace = this.stacktracesById.get(channelId);
     this.stacktracesById.delete(channelId);
-    return trace;
+    return WebConsoleUtils.removeFramesAboveDebuggerEval(trace);
   },
 
   onGetStack(msg) {

Honza, maybe we could make this a good-first-bug? The fix is quite simple and would only require a mochitest.

Assignee

Updated

Last month
Assignee: nobody → nchevobbe
Status: NEW → ASSIGNED
Flags: needinfo?(bhackett1024)

Before sending back the stacktrace, we remove all the
devtools internal frames using removeFramesAboveDebuggerEval.
A test (that was failing without the fix) is added to ensure
this works as expected.
The test revealed some issues in webconsole-connection-proxy
(mostly trying to access webConsoleUI while closing the toolbox),
which we fix in the patch as well.

Comment 16

Last month
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/36ada63cb9fb
Don't display DevTools internal frames in Netmonitor stacktrace. r=Honza.

Backed out changeset 36ada63cb9fb for failing browser_webconsole_network_messages_stacktrace_console_initiated_request.js

Backout link: https://hg.mozilla.org/integration/autoland/rev/ef49ccf4f815928da7a64f045188a1696a26804d

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&resultStatus=testfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel%2Crunnable&group_state=expanded&revision=36ada63cb9fb9ff56e7556cfc1db8cfad2c46a2d&selectedJob=247364212

Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=247364212&repo=autoland

Failure snippet:
[task 2019-05-20T15:28:15.135Z] 15:28:15 INFO - TEST-START | devtools/client/webconsole/test/mochitest/browser_webconsole_network_messages_stacktrace_console_initiated_request.js
[task 2019-05-20T15:28:15.312Z] 15:28:15 INFO - GECKO(1462) | ++DOMWINDOW == 2 (0x7fe565b96400) [pid = 1590] [serial = 2] [outer = 0x7fe566ac8d40]
[task 2019-05-20T15:28:15.955Z] 15:28:15 INFO - GECKO(1462) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpVJBOPC.mozrunner/runtests_leaks_tab_pid1642.log
[task 2019-05-20T15:28:16.113Z] 15:28:16 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: '!mSelection', file /builds/worker/workspace/build/src/editor/libeditor/EditorBase.cpp, line 4881
[task 2019-05-20T15:28:16.114Z] 15:28:16 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: '!editActionData.CanHandle()', file /builds/worker/workspace/build/src/editor/libeditor/EditorBase.cpp, line 1292
[task 2019-05-20T15:28:16.256Z] 15:28:16 INFO - GECKO(1462) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-05-20T15:28:16.333Z] 15:28:16 INFO - GECKO(1462) | [Child 1613, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
[task 2019-05-20T15:28:16.625Z] 15:28:16 INFO - GECKO(1462) | --DOCSHELL 0x7f564e1a6000 == 4 [pid = 1512] [id = {823f4985-dcc7-45e9-98fa-f06d6bf07835}] [url = moz-extension://a2453ad0-bd45-49c3-a5c8-5d4a632e467b/_generated_background_page.html]
[task 2019-05-20T15:28:16.681Z] 15:28:16 INFO - GECKO(1462) | --DOCSHELL 0x7f43ac8a4800 == 0 [pid = 1533] [id = {515266e7-9f3e-4e38-9350-129d4e94cfe2}] [url = about:blank]
[task 2019-05-20T15:28:16.759Z] 15:28:16 INFO - GECKO(1462) | ++DOCSHELL 0x7f47e00a7000 == 1 [pid = 1642] [id = {d9744546-0d68-4aab-aa32-0105ac5cf31e}]
[task 2019-05-20T15:28:16.936Z] 15:28:16 INFO - GECKO(1462) | ++DOMWINDOW == 1 (0x7f47e1053d40) [pid = 1642] [serial = 1] [outer = (nil)]
[task 2019-05-20T15:28:16.952Z] 15:28:16 INFO - GECKO(1462) | [Child 1642, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
[task 2019-05-20T15:28:17.135Z] 15:28:17 INFO - GECKO(1462) | ++DOMWINDOW == 2 (0x7f47e0f4b400) [pid = 1642] [serial = 2] [outer = 0x7f47e1053d40]
[task 2019-05-20T15:28:17.434Z] 15:28:17 INFO - [1437, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
[task 2019-05-20T15:28:17.535Z] 15:28:17 INFO - GECKO(1462) | ++DOMWINDOW == 3 (0x7f47e096e400) [pid = 1642] [serial = 3] [outer = 0x7f47e1053d40]
[task 2019-05-20T15:28:18.198Z] 15:28:18 INFO - GECKO(1462) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpVJBOPC.mozrunner/runtests_leaks_tab_pid1669.log
[task 2019-05-20T15:28:18.509Z] 15:28:18 INFO - GECKO(1462) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2019-05-20T15:28:18.914Z] 15:28:18 INFO - GECKO(1462) | ++DOCSHELL 0x7f106c41e800 == 7 [pid = 1462] [id = {80639de0-1baa-4004-a3e6-35a531e50f9c}]
[task 2019-05-20T15:28:18.915Z] 15:28:18 INFO - GECKO(1462) | ++DOMWINDOW == 16 (0x7f106af96a60) [pid = 1462] [serial = 16] [outer = (nil)]
[task 2019-05-20T15:28:18.915Z] 15:28:18 INFO - GECKO(1462) | ++DOMWINDOW == 17 (0x7f106c1a0c00) [pid = 1462] [serial = 17] [outer = 0x7f106af96a60]
[task 2019-05-20T15:28:18.998Z] 15:28:18 INFO - GECKO(1462) | ++DOMWINDOW == 18 (0x7f106cf8e800) [pid = 1462] [serial = 18] [outer = 0x7f106af96a60]
[task 2019-05-20T15:28:19.612Z] 15:28:19 INFO - GECKO(1462) | ++DOCSHELL 0x7f106c421000 == 8 [pid = 1462] [id = {cceeaab9-d82d-44b0-a44b-5d02b0e615e6}]
[task 2019-05-20T15:28:19.614Z] 15:28:19 INFO - GECKO(1462) | ++DOMWINDOW == 19 (0x7f106c172c40) [pid = 1462] [serial = 19] [outer = (nil)]
[task 2019-05-20T15:28:19.616Z] 15:28:19 INFO - GECKO(1462) | ++DOMWINDOW == 20 (0x7f106d55c800) [pid = 1462] [serial = 20] [outer = 0x7f106c172c40]
[task 2019-05-20T15:28:20.031Z] 15:28:20 INFO - GECKO(1462) | [Parent 1462, StreamTrans #2] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 371
[task 2019-05-20T15:28:20.033Z] 15:28:20 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 994
[task 2019-05-20T15:28:20.521Z] 15:28:20 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 43
[task 2019-05-20T15:28:20.522Z] 15:28:20 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 55
[task 2019-05-20T15:28:20.784Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 3 (0x7f43aca65800) [pid = 1533] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.792Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 14 (0x7f564f0b9800) [pid = 1512] [serial = 6] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.793Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 13 (0x7f564ea3c400) [pid = 1512] [serial = 7] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.793Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 12 (0x7f564ea3ec00) [pid = 1512] [serial = 10] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.794Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 11 (0x7f564ea3d000) [pid = 1512] [serial = 8] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.794Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 10 (0x7f564ea3d800) [pid = 1512] [serial = 9] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.842Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 2 (0x7f43ac8e8d40) [pid = 1533] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:20.919Z] 15:28:20 INFO - GECKO(1462) | --DOMWINDOW == 9 (0x7f564df2f6a0) [pid = 1512] [serial = 5] [outer = (nil)] [url = moz-extension://a2453ad0-bd45-49c3-a5c8-5d4a632e467b/_generated_background_page.html]
[task 2019-05-20T15:28:21.912Z] 15:28:21 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 43
[task 2019-05-20T15:28:21.913Z] 15:28:21 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file /builds/worker/workspace/build/src/extensions/permissions/nsPermission.cpp, line 55
[task 2019-05-20T15:28:22.200Z] 15:28:22 INFO - [1437, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
[task 2019-05-20T15:28:24.459Z] 15:28:24 INFO - GECKO(1462) | --DOMWINDOW == 19 (0x7f10752d8000) [pid = 1462] [serial = 5] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:24.460Z] 15:28:24 INFO - GECKO(1462) | --DOMWINDOW == 18 (0x7f10724df000) [pid = 1462] [serial = 12] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:24.845Z] 15:28:24 INFO - GECKO(1462) | --DOMWINDOW == 1 (0x7f43ad8a9c00) [pid = 1533] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:24.847Z] 15:28:24 INFO - GECKO(1462) | --DOMWINDOW == 0 (0x7f43ac866400) [pid = 1533] [serial = 4] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:24.934Z] 15:28:24 INFO - GECKO(1462) | --DOMWINDOW == 8 (0x7f564ea45800) [pid = 1512] [serial = 15] [outer = (nil)] [url = moz-extension://a2453ad0-bd45-49c3-a5c8-5d4a632e467b/_generated_background_page.html]
[task 2019-05-20T15:28:26.566Z] 15:28:26 INFO - GECKO(1462) | --DOMWINDOW == 2 (0x7fd47646ac00) [pid = 1613] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:29.077Z] 15:28:29 INFO - GECKO(1462) | --DOMWINDOW == 17 (0x7f106c1a0c00) [pid = 1462] [serial = 17] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:28:29.580Z] 15:28:29 INFO - GECKO(1462) | [Parent 1462, StreamTrans #8] WARNING: 'NS_FAILED(rv)', file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 371
[task 2019-05-20T15:28:29.591Z] 15:28:29 INFO - GECKO(1462) | [Parent 1462, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /builds/worker/workspace/build/src/modules/libjar/nsJARChannel.cpp, line 994
[task 2019-05-20T15:28:29.696Z] 15:28:29 INFO - GECKO(1462) | --DOMWINDOW == 2 (0x7f47e0f4b400) [pid = 1642] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2019-05-20T15:29:46.094Z] 15:29:46 INFO - TEST-INFO | started process screentopng
[task 2019-05-20T15:29:46.908Z] 15:29:46 INFO - TEST-INFO | screentopng: exit 0
[task 2019-05-20T15:29:46.910Z] 15:29:46 INFO - Buffered messages logged at 15:28:15
[task 2019-05-20T15:29:46.911Z] 15:29:46 INFO - Entering test bound task
[task 2019-05-20T15:29:46.911Z] 15:29:46 INFO - Adding a new tab with URL: https://example.com/browser/devtools/client/webconsole/test/mochitest/test-network-request.html
[task 2019-05-20T15:29:46.912Z] 15:29:46 INFO - Buffered messages logged at 15:28:17
[task 2019-05-20T15:29:46.912Z] 15:29:46 INFO - Tab added and finished loading
[task 2019-05-20T15:29:46.912Z] 15:29:46 INFO - Opening the toolbox
[task 2019-05-20T15:29:46.912Z] 15:29:46 INFO - Buffered messages logged at 15:28:21
[task 2019-05-20T15:29:46.912Z] 15:29:46 INFO - Toolbox opened and focused
[task 2019-05-20T15:29:46.912Z] 15:29:46 INFO - Fire an XHR POST request from the console.
[task 2019-05-20T15:29:46.913Z] 15:29:46 INFO - Buffered messages logged at 15:28:22
[task 2019-05-20T15:29:46.913Z] 15:29:46 INFO - Matched a message with text: "https://example.com/browser/devtools/client/webconsole/test/mochitest/sjs_slow-response-test-server.sjs", all messages received.
[task 2019-05-20T15:29:46.913Z] 15:29:46 INFO - TEST-PASS | devtools/client/webconsole/test/mochitest/browser_webconsole_network_messages_stacktrace_console_initiated_request.js | Network message found. -
[task 2019-05-20T15:29:46.913Z] 15:29:46 INFO - Buffered messages logged at 15:28:23
[task 2019-05-20T15:29:46.913Z] 15:29:46 INFO - Expand the network message
[task 2019-05-20T15:29:46.916Z] 15:29:46 INFO - Click on XHR message and wait for the network detail panel to be displayed
[task 2019-05-20T15:29:46.917Z] 15:29:46 INFO - Buffered messages finished
[task 2019-05-20T15:29:46.917Z] 15:29:46 INFO - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/mochitest/browser_webconsole_network_messages_stacktrace_console_initiated_request.js | Test timed out -
[task 2019-05-20T15:29:46.918Z] 15:29:46 INFO - GECKO(1462) | ++DOMWINDOW == 18 (0x7f1066b7c000) [pid = 1462] [serial = 21] [outer = 0x7f106af96a60]
[task 2019-05-20T15:29:46.919Z] 15:29:46 INFO - GECKO(1462) | console.warn: "Error while detaching the thread front: 'detach' request packet to 'server1.conn0.child1/context18' can't be sent as the connection is closed."
[task 2019-05-20T15:29:47.622Z] 15:29:47 INFO - GECKO(1462) | --DOCSHELL 0x7f106c421000 == 7 [pid = 1462] [id = {cceeaab9-d82d-44b0-a44b-5d02b0e615e6}] [url = chrome://devtools/content/webconsole/index.html]
[task 2019-05-20T15:29:47.623Z] 15:29:47 INFO - GECKO(1462) | --DOCSHELL 0x7f106c41e800 == 6 [pid = 1462] [id = {80639de0-1baa-4004-a3e6-35a531e50f9c}] [url = about:blank]
[task 2019-05-20T15:29:47.645Z] 15:29:47 INFO - Removing tab.
[task 2019-05-20T15:29:47.647Z] 15:29:47 INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2019-05-20T15:29:47.693Z] 15:29:47 INFO - Got event: 'TabClose' on [object XULElement].
[task 2019-05-20T15:29:47.693Z] 15:29:47 INFO - GECKO(1462) | [Child 1590, Main Thread] WARNING: No active window: file /builds/worker/workspace/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
[task 2019-05-20T15:29:47.719Z] 15:29:47 INFO - Tab removed and finished closing
[task 2019-05-20T15:29:47.828Z] 15:29:47 INFO - GECKO(1462) | MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
[task 2019-05-20T15:29:47.829Z] 15:29:47 INFO - GECKO(1462) | MEMORY STAT | vsize 3016MB | residentFast 337MB | heapAllocated 94MB
[task 2019-05-20T15:29:47.830Z] 15:29:47 INFO - TEST-OK | devtools/client/webconsole/test/mochitest/browser_webconsole_network_messages_stacktrace_console_initiated_request.js | took 92696ms

Flags: needinfo?(nchevobbe)

Comment 19

Last month
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/baf86b77635c
Don't display DevTools internal frames in Netmonitor stacktrace. r=Honza.
Status: ASSIGNED → RESOLVED
Closed: Last month
Resolution: --- → FIXED
Target Milestone: --- → Firefox 69
You need to log in before you can comment on or make changes to this bug.