Closed Bug 1541355 Opened 6 years ago Closed 5 years ago

Wrong stack trace for requests fetched from the Console

Categories

(DevTools :: Netmonitor, defect, P3)

Product:
DevTools
Component:
Netmonitor
Type:
defect

Tracking

(firefox69 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 69
Tracking Flags:
Tracking Status
firefox69 --- fixed

People

(Reporter: Honza, Assigned: nchevobbe)

References

(Blocks 1 open bug)

Details

Attachments

(3 files)

Network entry stacktrace in Firefox 66
(deleted), image/png
Details
Non-Leaky, Privilege-Sensitive Saved Stacks
(deleted), text/plain
Details
Bug 1541355 - Don't display DevTools internal frames in Netmonitor stacktrace. r=Honza.
(deleted), text/x-phabricator-request
Details

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

Attached image Network entry stacktrace in Firefox 66 (deleted) —

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?

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

Honza

Flags: needinfo?(jimb)

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)

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

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: 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.

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)

Fix attempt: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ce6c22672f37dd385713c7ce07890c94bd33d279

Flags: needinfo?(nchevobbe)
Pushed by nchevobbe@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/baf86b77635c
Don't display DevTools internal frames in Netmonitor stacktrace. r=Honza.

https://hg.mozilla.org/mozilla-central/rev/baf86b77635c

Status: ASSIGNED → RESOLVED
Closed: 5 years ago
status-firefox69: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 69
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: