17500 - [dogfood] Viewsource is broken...

Status: VERIFIED FIXED

(Core :: Networking, defect, P1)

Description

[rickg]

In the last few days, the view-source command was broken.
Viewsource relies upon 2 things:
  1) the webshell member mViewSource, and
  2) the command "view-source" string

It appears that changes in either navigator.xul/navigator.js or in
nsGlobalWindow has stopped the menu command "view-source" from getting through.
Since your name appears in the cvs-blame log as having been in this code (and in
danm's case, he expertise in this area), I'm giving this bug to you.

I'd be greatful if you would send me mail explaining what got broken. I'm
interested in how this stuff works.

Thanks --
Rick

Comment 1

[leger]

Putting on [PDT+] radar.

Comment 2

[Pierre Saslawsky]

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

Comment 3

[Bill Law]

I'm taking this bug to do investigation.  I can't see the problem in my builds.
I did reproduce it with the official (release) build.  It appears that the
onload handler for navigator.xul is not getting called till the view source
window is closed!  Since I don't see it, it is likely a timing issue of some
sort.  After I learn more I'll probably be contacting Rick Potts since his baby
the doc loader is right in the middle of this.

Comment 4

[Bill Law]

Status update:

This problem appears on either fast machines or in optimized builds.  I did an
optimized build with debug symbols and can now reproduce it on my machine.

What I've gleaned thus far is that either some file transport operation does not
complete, or, notifications for those operations do not get sent properly.  This
was observed by setting a breakpoint in the load group's "on empty" routine
which should get called when the last chrome url load is completed.

I also found out why the onload handler is called when you close the view-source
window:  This causes the web shell to be Destroy'd at which point it cancels its
doc loader's load group.  Because the load group thinks it is still active, it
then sends out OnStopRequests (with a status indicating that it was cancelled).
The webshell doesn't distinguish this from a normal completion and triggers the
onload handler (which is perhaps correct, since the user hitting Stop ought to
still permit a document's onload handler firing).

I talked to Gagan.  The plan is to determine whether the problem is in the file
I/O itself, or, the notification mechanism.  He also suggested talking to
Warren, who reportedly is working on a problem related to some timing related
deadlock somewhere.

My theory is that we might see a similar problem in other scenarios that cause
the same timing quirks.  For example, opening a new browser window is almost
exactly the same code up till the onload handler's detection of the
"view-source" argument.  Gagan says he's seen problems viewing some
text/plain documents.

Comment 5

[Bill Law]

I added some logging code to nsFileChannel to verify that it was sending out
OnStopRequest notifications to match each OnStartRequest.  These seemed to
balance OK.

I next decided to try to monitor what was happening with the load groups.  I
rebuilt nsLoadGroup.cpp with PR_FORCE_LOG and produced this log:

0[5916e0]: LOADGROUP: 600bb0 Created.
0[5916e0]: LOADGROUP: 60f130 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 60f130.
0[5916e0]: LOADGROUP: 60f130 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b460 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 66b460.
0[5916e0]: LOADGROUP: 66b460 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 60f130 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b5c740 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 1b5c740.
0[5916e0]: LOADGROUP: 1b5c740 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1b61870 Created.
0[5916e0]: LOADGROUP: 66b460 Adding sub-group 1b61870.
0[5916e0]: LOADGROUP: 1b61870 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1b5c740 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b61870 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b460 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b61870 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b460 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1bd0320 Created.
0[5916e0]: LOADGROUP: 66b460 Adding sub-group 1bd0320.
0[5916e0]: LOADGROUP: 1bd0320 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1bd0320 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b61870 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b460 Firing OnStopRequest(...).
- Initial window open -
- Initial window closing -
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 66b460.
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 1b5c740.
0[5916e0]: LOADGROUP: 1b5c740 Destroyed.
0[5916e0]: LOADGROUP: 66b460 Removing sub-group 1bd0320.
0[5916e0]: LOADGROUP: 66b460 Removing sub-group 1b61870.
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 60f130.
0[5916e0]: LOADGROUP: 60f130 Destroyed.

I annotated this with my guess as to what was going on.  This log came from
starting mozilla.exe and closing the browser window once the load of
www.mozilla.org was complete.

Once I had that baseline, I tried View->Page Source.  This produced the
following:

0[5916e0]: LOADGROUP: 600bb0 Created.
0[5916e0]: LOADGROUP: 60f130 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 60f130.
0[5916e0]: LOADGROUP: 60f130 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 66b3b0.
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 60f130 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b5c700 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 1b5c700.
0[5916e0]: LOADGROUP: 1b5c700 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1b61a90 Created.
0[5916e0]: LOADGROUP: 66b3b0 Adding sub-group 1b61a90.
0[5916e0]: LOADGROUP: 1b61a90 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1b5c700 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b61a90 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b61a90 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1bd0320 Created.
0[5916e0]: LOADGROUP: 66b3b0 Adding sub-group 1bd0320.
0[5916e0]: LOADGROUP: 1bd0320 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 1bd0320 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 1b61a90 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
- Initial window open -
- Opening gif's etc. for toolbar/menus? -
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 66b3b0 Firing OnStopRequest(...).
- Opening view source window -
0[5916e0]: LOADGROUP: 1f616e0 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 1f616e0.
0[5916e0]: LOADGROUP: 1f616e0 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 2158670 Created.
0[5916e0]: LOADGROUP: 600bb0 Adding sub-group 2158670.
0[5916e0]: LOADGROUP: 2158670 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 215ac00 Created.
0[5916e0]: LOADGROUP: 1f616e0 Adding sub-group 215ac00.
0[5916e0]: LOADGROUP: 215ac00 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 2169a20 Created.
0[5916e0]: LOADGROUP: 1f616e0 Adding sub-group 2169a20.
0[5916e0]: LOADGROUP: 2169a20 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 2158670 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 215ac00 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 2169a20 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 2158670.
0[5916e0]: LOADGROUP: 2158670 Destroyed.
0[5916e0]: LOADGROUP: 1f616e0 Removing sub-group 2169a20.
0[5916e0]: LOADGROUP: 1f616e0 Firing OnStopRequest(...).
0[5916e0]: LOADGROUP: 215ac00 Firing OnStartRequest(...).
0[5916e0]: LOADGROUP: 215ac00 Firing OnStopRequest(...).
- View source window closing? -
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 1f616e0.
0[5916e0]: LOADGROUP: 1f616e0 Removing sub-group 215ac00.
0[5916e0]: LOADGROUP: 215ac00 Unable to remove channel 214be20. Not in group!
- Initial window closing -
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 66b3b0.
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 1b5c700.
0[5916e0]: LOADGROUP: 1b5c700 Destroyed.
0[5916e0]: LOADGROUP: 66b3b0 Removing sub-group 1bd0320.
0[5916e0]: LOADGROUP: 66b3b0 Removing sub-group 1b61a90.
0[5916e0]: LOADGROUP: 600bb0 Removing sub-group 60f130.
0[5916e0]: LOADGROUP: 60f130 Destroyed.

The "Unable to remove channel 214be20. Not in group!" near the end seems like a
good clue.  I'm not trying to discover how this load group got in this
predicament.

Comment 6

[rickg]

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

Comment 7

[Bill Law]

I'm giving up.  I can't figure out what's going on inside the networking code so
I'm turning it over to somebody more knowledgeable.

Comment 8

[Warren Harris]

Rick should look at this.

Comment 9

[rickg]

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

Comment 10

[rpotts (gone)]

Ok...  I've figured out what's going on.

Apparently the ViewSource window is a frame-set document.  [navigator.xul] is
the root with two children [about:blank] and [related-panel.xul].

in RemoveChannel(), when the OnStopRequest is fired for [related-panel.xul] it's
loadgroup is removed from its parent's list.

Unfortunately, when OnStopRequest() returns the very next line tries to
propagate the notification up to the parent.  But the parent is NULL because the
loadgroup was already removed!

So, the OnStopRequest for [navigator.xul] is lost :-(

I don't know what code changed to cause the loadgroup to get destroyed inside of
the call to OnStopRequest()...  But that's what's happening...

I have a fix...  I'll talk to jar to see if this is M11 material.

Comment 11

[Bill Law]

I'm curious as to why this appears to be timing dependent.  Perhaps no code
changed, just the timing (due to porkjockey-ing)?

Comment 12

[rpotts (gone)]

Attachment: Proposed patch...

Comment 13

[rpotts (gone)]

I've attached the patch...  Basically, I added some code in
nsLoadgroup::Cancel() to notify the parent group if the canceled group was
active...

Comment 14

[rpotts (gone)]

I've just checked the fix in...

Comment 15

[Paul MacQuiddy]

changing qa contact from leger to elig since he is such a swell guy

Comment 16

[David Baron :dbaron: (⌚️UTC-5, no longer working on Mozilla)]

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

Comment 17

[Eli Goldberg]

This is fixed on 1999110913 Mac OS, 1999110911 Win32 and 1999110808 Linux.

However, when selecting view-source text, non-alphanumeric characters are not
selected. (e.g. <, >, =) Will split out as separate bug, and then mark this one
as verified.

Comment 18

[Eli Goldberg]

Broke side-issue into 18453. Verifying this as fixed.

Comment 19

[leger]

Bulk move of all Networking-Core (to be deleted component) bugs to new
Networking component.