Closed Bug 1611081 Opened 4 years ago Closed 4 years ago

Blank content area when reloading multipart/x-mixed-replace page with developer tools pane open

Categories

(DevTools :: Netmonitor, defect, P1)

Product:
DevTools
Component:
Netmonitor
Version:
73 Branch
Type:
defect

Tracking

(firefox-esr68 unaffected, firefox72 unaffected, firefox73+ disabled, firefox74+ wontfix, firefox75 fixed, firefox76 fixed)

Status:
RESOLVED FIXED
Milestone:
Firefox 76
Tracking Flags:
Tracking Status
firefox-esr68 --- unaffected
firefox72 --- unaffected
firefox73 + disabled
firefox74 + wontfix
firefox75 --- fixed
firefox76 --- fixed

People

(Reporter: dleborgne, Assigned: mattwoodrow)

References

(Blocks 1 open bug, Regression,
URL
)

Details

(Keywords: regression)

Attachments

(2 files)

Exception
204.25 KB, image/png
Details
Bug 1611081 - Add multipart support to nsStreamListenerTee. r?mayhemer
47 bytes, text/x-phabricator-request
jcristau
: approval-mozilla-beta+
Details | Review

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:73.0) Gecko/20100101 Firefox/73.0

Steps to reproduce:

  1. Start Firefox 73.0b8
  2. Open https://xenon.coheris.com/ff73/
  3. Press F12
  4. Press F5 in the Firefox window

Actual results:

  1. Page is blank

Expected results:

  1. Page should be displayed as in step 2

This is a regression from Firefox 72, which works as expected.

The problem came to our attention with our internal Bugzilla 5.0 server, which uses the "multipart/x-mixed-replace" content-type for displaying bug lists. On our server, the Firefox page load indicator never stops when displaying a bug list, and trying to use development tools revealed this bug.

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:74.0) Gecko/20100101 Firefox/74.0
20200123095433

  • Any developer tools tab will do.
  • Only happens when reloading. If you open a new tab, then the developer tools, then go to the link, it loads fine.
  • View Source on the blank page opens a new tab that's stuck loading forever.

(In reply to David Le Borgne from comment #1)

This is a regression from Firefox 72, which works as expected.

It would be very useful if you could find the exact regression range.
https://mozilla.github.io/mozregression/quickstart.html

Taking an educated guess here, it looks like this might've been regressed by bug 1600211.

URL: https://xenon.coheris.com/ff73/
Status: UNCONFIRMED → NEW
Has Regression Range: --- → no
Has STR: --- → yes
status-firefox72: --- → unaffected
status-firefox73: --- → affected
status-firefox74: --- → affected
status-firefox-esr68: --- → unaffected
Component: Untriaged → General
Ever confirmed: true
Flags: needinfo?(matt.woodrow)
Keywords: regression
Product: Firefox → DevTools
Summary: Content using "multipart/x-mixed-replace" breaks Developement tools → Blank content area when reloading multipart/x-mixed-replace page with developer tools pane open

(In reply to Gingerbread Man from comment #2)

Taking an educated guess here, it looks like this might've been regressed by bug 1600211.
You are right ! Using mozregression, I got these information :
Using url: https://hg.mozilla.org/integration/autoland/json-pushes?changeset=1e479194244ab14e9ebad664865c8e6bc2cdf1c7&full=1
Found commit message:
Bug 1600211 - Forward AllPartsStopped to HttpChannelChild to ensure that we notify the listeners correctly. r=mayhemer
Differential Revision: https://phabricator.services.mozilla.com/D55223

Has Regression Range: no → yes
Regressed by: 1600211

Using Firefox 73.0b10 or 73.0b11, everything is back to normal. I'm unable to reproduce the error described in comment 0 or the endless page load indicator on Bugzilla 5.0 lists

Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:74.0) Gecko/20100101 Firefox/74.0
20200129093157

I can still reproduce the issue as described at comment 0 and comment 2.

We disabled DocumentChannel in 73.0b9 (bug 1610888), so it makes sense that this bug isn't occurring on Fx73 anymore given the regression range.

status-firefox73: affected → disabled
tracking-firefox73: --- → +
tracking-firefox74: --- → +

The view-source issue appears to be somewhat separate to this bug (though regressed from the same change).

I've filed bug 1612992 for that.

Flags: needinfo?(matt.woodrow)
See Also: → 1612992

This is failing because we're hitting a JS error in the devtools network response observer, which then cancels the request.

The failure is here: https://searchfox.org/mozilla-central/rev/2e355fa82aaa87e8424a9927c8136be184eeb6c7/devtools/shared/platform/cache-entry.js#95

We're trying to access request.URI, but the JS object 'request' only has bindings for nsIRequest, not nsIChannel (where the 'URI' field is).

I believe this worked previously, because onStartRequest is usually called with the same object instance as the underlying channel we used when creating the NetworkResponseListener.

The code that creates the NetworkResponseListener makes sure we have bindings for nsIChannel (as a subset of nsIHttpChannel) here - https://searchfox.org/mozilla-central/rev/2e355fa82aaa87e8424a9927c8136be184eeb6c7/devtools/server/actors/network-monitor/network-observer.js#571

In this case, the request passed to onStartRequest is a wrapper for the current part of the multipart response, and thus is a separate object (which does implement nsIChannel, as well as nsIMultiPartChannel, but we haven't bound those).

Adding a 'request.QueryInterface(nsIChannel)' line into the onStartRequest listener is sufficient to fix this issue, but it's hard to reason about what other interfaces we're expecting to be available.

Flags: needinfo?(poirot.alex)
Component: General → Netmonitor

@Matt: is the following change the one you have in mind?

diff --git a/devtools/server/actors/network-monitor/network-response-listener.js b/devtools/server/actors/network-monitor/network-response-listener.js
--- a/devtools/server/actors/network-monitor/network-response-listener.js
+++ b/devtools/server/actors/network-monitor/network-response-listener.js
@@ -210,16 +210,18 @@ NetworkResponseListener.prototype = {
   /**
    * See documentation at
    * https://developer.mozilla.org/En/NsIRequestObserver
    *
    * @param nsIRequest request
    * @param nsISupports context
    */
   onStartRequest: function(request) {
+    request = request.QueryInterface(Ci.nsIChannel);
+
     // Converter will call this again, we should just ignore that.
     if (this.request) {
       return;
     }

     this.request = request;
     this._getSecurityInfo();
     this._findOpenResponse();

It seems to fix the issue on my machine.

Honza

Flags: needinfo?(matt.woodrow)

Yeah, that's what works for me, I just wasn't sure if we were implicitly relying on 'request' having any other interfaces available.

I see this.request.fromCache which isn't nsIChannel, but I'm not sure where that comes from.

Flags: needinfo?(matt.woodrow)

We should check if bug 1179250 is also fixed by this.

See Also: → 1179250

(In reply to Matt Woodrow (:mattwoodrow) from comment #8)

Adding a 'request.QueryInterface(nsIChannel)' line into the onStartRequest listener is sufficient to fix this issue, but it's hard to reason about what other interfaces we're expecting to be available.

Thanks a lot for tracking that down!

(In reply to Matt Woodrow (:mattwoodrow) from comment #10)

Yeah, that's what works for me, I just wasn't sure if we were implicitly relying on 'request' having any other interfaces available.

I see this.request.fromCache which isn't nsIChannel, but I'm not sure where that comes from.

Well... I think this code is just wrong. fromCache isn't exposed by any WebIDL. So it is, and probably always have been undefined. And so, it comes from nowhere!

Otherwise, from what I can see, we only use contentType and contentCharset. So nsIChannel looks enough.
We also pass it to nsIStreamListener.onDataAvailable, which expects a nsIRequest, but I imagine it is automagically queried by xpconnect, and nsIChannel inherits from nsIRequest anyway, right?

Flags: needinfo?(poirot.alex)

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #9)

It seems to fix the issue on my machine.

It doesn't work for me. I no longer have the request.URI is undefined, but it still prevents the page from loading correctly.

Hi Honza, could you assign someone to keep digging into this issue?

Flags: needinfo?(odvarko)

@Hubert: it would be great to do some analysis here. Could you please look at this?

Honza

Flags: needinfo?(odvarko) → needinfo?(hmanilla)
Assignee: nobody → hmanilla
Status: NEW → ASSIGNED

(In reply to Jan Honza Odvarko [:Honza] (always need-info? me) from comment #9)

@Matt: is the following change the one you have in mind?

diff --git a/devtools/server/actors/network-monitor/network-response-listener.js b/devtools/server/actors/network-monitor/network-response-listener.js
--- a/devtools/server/actors/network-monitor/network-response-listener.js
+++ b/devtools/server/actors/network-monitor/network-response-listener.js
@@ -210,16 +210,18 @@ NetworkResponseListener.prototype = {
   /**
    * See documentation at
    * https://developer.mozilla.org/En/NsIRequestObserver
    *
    * @param nsIRequest request
    * @param nsISupports context
    */
   onStartRequest: function(request) {
+    request = request.QueryInterface(Ci.nsIChannel);
+
     // Converter will call this again, we should just ignore that.
     if (this.request) {
       return;
     }

     this.request = request;
     this._getSecurityInfo();
     this._findOpenResponse();

It seems to fix the issue on my machine.

Honza

Should we just test if this fix helps ?

Flags: needinfo?(matt.woodrow)
Severity: normal → critical
Priority: P2 → P1

i'm looking into this now!

Flags: needinfo?(hmanilla)

(In reply to Jens Stutte [:jstutte] from comment #16)

Should we just test if this fix helps ?

It's a super simple fix, and we know that it fixes the issue as reported.

I'll wait for :bomsy to finish looking into it, to see if there other related issues, but I think it's worth getting the simple thing in and uplifted to beta ASAP.

Flags: needinfo?(matt.woodrow)

FYI, I would prefer an uplift to the beta branch before Monday morning (CET) so as to have this bug part of the Monday merge.

(In reply to Matt Woodrow (:mattwoodrow) from comment #18)

(In reply to Jens Stutte [:jstutte] from comment #16)

Should we just test if this fix helps ?

It's a super simple fix, and we know that it fixes the issue as reported.

Matt, I was testing again and the patch doesn't work for me. It just hides the error in the Browser console but, doesn't solve the original issue.
Can you please verify on your machine?

More comments:

  1. I was doing more testing and the only thing that helps me to avoid the problem is disabling NetworkResponseListener entirely
    Commenting out this line:
    https://searchfox.org/mozilla-central/rev/a3266997560904b484fd89d6a6bcdeace4a13652/devtools/server/actors/network-monitor/network-observer.js#767

Obviously this isn't a solution since this is disabling the way how DevTools are intercepting and collecting HTTP response bodies.
But, it points to a possible culprit.

  1. I was looking more into the NetworkResponseListener and found this place.
    https://searchfox.org/mozilla-central/rev/a3266997560904b484fd89d6a6bcdeace4a13652/devtools/server/actors/network-monitor/network-response-listener.js#56-60

I tried to disable the related setup but, it doesn't help. But the comment seems to be related to this bug so, something more might be needed
It points to this Bug 1309523 - [non-e10s] Wrong info in "Transferred" column

  1. I'd like to point out the previously found regressions:

Bug 1600211 - Handle multipart/x-mixed-replace responses in the parent process
Phab: https://phabricator.services.mozilla.com/D55223

These changes seems to be very related to this bug (and NetworkResponseListener) and I think more analysis & testing of this patch would be great help.

Mayhemer, can you please help here?

Honza

Flags: needinfo?(matt.woodrow)
Flags: needinfo?(honzab.moz)

To add to Honza's, i narrowed it down so far to
https://searchfox.org/mozilla-central/rev/a3266997560904b484fd89d6a6bcdeace4a13652/devtools/server/actors/network-monitor/network-observer.js#933

I've been getting this exception thrown, when pause on exception is turned on

Exception { 
name: "NS_ERROR_FAILURE", 
message: "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsITraceableChannel.setNewListener]", 
result: 2147500037, 
filename: "resource://devtools/server/actors/network-monitor/network-observer.js", 
lineNumber: 933, 
columnNumber: 0, 
data: null, 
stack: "
	_setupResponseListener@resource://devtools/server/actors/network-monitor/network-observer.js:933:38\n
	_createNetworkEvent@resource://devtools/server/actors/network-monitor/network-observer.js:767:12\n
	_onRequestHeader@resource://devtools/server/actors/network-monitor/network-observer.js:793:10\n
	NetworkObserver.prototype.observeActivity<@resource://devtools/server/actors/network-monitor/network-observer.js:580:12\n
	exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:111:22\n", 
location: XPCWrappedNative_NoHelper }

Only change in the channel's listener after possible SetNewListener call is DoApplyContentConversions which we either don't do at all for multipart top level document-channel driven loads, or actually should be reverted as well, we would do conversion twice.

Matt? I don't remember how decoding with docchannel and multipart works.

Set new listener is called on the parent process, not the child process. I am not hitting the exception in comment 21.

Flags: needinfo?(honzab.moz)

Hubert, please see the comment #24, can you help to to reproduce the exception?

Flags: needinfo?(hmanilla)
Attached image Exception —

Sorry for the long STR, it was part of my debugging process to figure out what was wrong
STR

Let me know if this does not work.

Flags: needinfo?(hmanilla)

@mayhemer: can you reproduce that now?

Honza

Flags: needinfo?(honzab.moz)

I am assigning this to :mayhemer since this looks most likely as the platform bug.

  • The STRs we found are in comment #26
  • The possible regression is Bug 1600211 - Handle multipart/x-mixed-replace responses in the parent process
  • Some more analysis in comment #20

:mayhemer please let me know if this makes sense.

Honza

Assignee: hmanilla → honzab.moz

I spent some time digging into this a bit further.

It looks like the devtools network-observer code is installing a stream-listener-tee listener so that it can observe the network traffic.

nsStreamListenerTee doesn't understand multipart, so it clears mSink on the first OnStopRequest, and then hits an error (cancelling the channel) when the next part start.

We can fix that fairly easily by querying for nsIMultiPartChannel, and only clearing mSink after the last part.

Flags: needinfo?(matt.woodrow)

As of bug 1600211, multipart responses are now handled in the parent, and we get a separate OnStartRequest/OnStopRequest for each part, with the correct content types set.

Previously devtools would have only seen a single OnStart/StopRequest, with the multipart content type, and the contents containing all the special markers and contents of all parts.

NetworkResponseListener doesn't handle this correctly, as it disconnects the output stream in onStopRequest. That means that we only add an entry for the first part, and ignore the other.

I think ideally we'd detect the presence of multiple parts (by QI'ing for nsIMultiPartChannel), and keep the stream open until we get onAfterLastPart. We'd want to make the code understand this and have multiple entries in the UI.

Flags: needinfo?(odvarko)

Thanks Matt for working on this!

Your comment #31 makes good sense to me.

I filed a bug 1622209 to cover the follow up work on the Network panel
(so, we can close this one as soon as the platform is fixed)

Honza

Flags: needinfo?(odvarko)
Assignee: honzab.moz → matt.woodrow
Flags: needinfo?(honzab.moz)
Pushed by mwoodrow@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/77436c074c25
Add multipart support to nsStreamListenerTee. r=mayhemer

https://hg.mozilla.org/mozilla-central/rev/77436c074c25

Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox76: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 76

The patch landed in nightly and beta is affected.
:mattwoodrow, is this bug important enough to require an uplift?
If not please set status_beta to wontfix.

For more information, please visit auto_nag documentation.

Flags: needinfo?(matt.woodrow)

+1 on Uplift if the patch is safe.

(I tested on Nightly and it works for me)

Honza

Comment on attachment 9133079 [details]
Bug 1611081 - Add multipart support to nsStreamListenerTee. r?mayhemer

Beta/Release Uplift Approval Request

  • User impact if declined: Failure to load page that uses multipart content type (rare), when devtools is open.
  • Is this code covered by automated tests?: No
  • Has the fix been verified in Nightly?: Yes
  • Needs manual test from QE?: No
  • If yes, steps to reproduce:
  • List of other uplifts needed: None
  • Risk to taking this patch: Low
  • Why is the change risky/not risky? (and alternatives if risky): Very simple change to add support for understanding multipart to another component, similar to ones we've done before.
  • String changes made/needed:
Flags: needinfo?(matt.woodrow)
Attachment #9133079 - Flags: approval-mozilla-beta?

Comment on attachment 9133079 [details]
Bug 1611081 - Add multipart support to nsStreamListenerTee. r?mayhemer

approved for 75.0b10

Attachment #9133079 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

The problem described in comment 0 is now fixed, as I was able to verify in Firefox 75.0 beta 11, but there are still two problems with multipart/x-mixed-replace pages, like bug lists in Bugzilla :

  • the page load indicator never stops (while page seems fully loaded) : bug 1627087
  • when developer tools are in use, reloading the page tools displays a truncated page : bug 1627089

Yes, I am also facing problems. There are some analysis in bug 1622490

Honza

You need to log in before you can comment on or make changes to this bug.