728901 - onStopRequest triggered twice in TracingListener for some pages

Status: RESOLVED INVALID

(Core :: Networking, defect)

Description

[Loic Duros]

Attachment: testcase.xpi

User Agent: Mozilla/5.0 (X11; Linux i686; rv:8.0) Gecko/20100101 Firefox/8.0 Iceweasel/8.0
Build ID: 20111130203654

Steps to reproduce:

I have set up a TracingListener in my add-on (addon SDK), and I have noticed on certain pages onStopRequest is being triggered twice (console.log output twice) in some pages. One of these pages is http://www.google.com
While I expect onDataAvailable to be triggered multiple times, I don't understand why onStopRequest is triggered multiple times as well. I have made a minimal test case that seems to do just fine despite the calls twice, but my actual real (much more complex)  add-on that does asynchronous manipulation of the received data doesn't output anything when there's two onStopRequest. What is the reason onStopRequest for triggering onStopRequest twice? Is this a bug or a feature?


Actual results:

I have pasted my main.js here: http://pastebin.mozilla.org/1488793
And I am attaching the xpi of the test case as well.
You will see that "onStopRequest called for html ....." 
is output twice in the console for some (not all) pages online. At first I expected this to be redirects, but it doesn't seem obvious.

Comment 1

[Loic Duros]

As it appears, it comes from the fact that onStartRequest is indeed triggered twice in the tracing listener.
I added the following line inside onStartRequest which is located on line 48 of http://pastebin.mozilla.org/1488793 :
console.log('onStartRequest triggered', request.URI.spec);

and here is what I get when entering http://www.google.com in the location bar:
info: onStartRequest triggered http://www.google.com/
info: onStartRequest triggered http://www.google.com/

and two onStopRequest follow. It looks like it should have something to do with a redirect.
This is not the case for many other webpages...

Comment 2

[Josh Matthews [:jdm]]

Loic, could you attach whatever was in the pastebin here? It is not a viable permanent storage mechanism, and is now missing.

Comment 3

[Boris Zbarsky [:bzbarsky]]

Where in the attached code is this TracingListener thing?  Or is that something that jetpack provides?

Comment 4

[Nickolay_Ponomarev]

Attachment: main.js from the xpi

bz: see resources/testcase/lib/main.js. I think this is what used to be on pastebin too. (The rest of files is jetpack's library, which shouldn't have any effect on this.)

Comment 5

[Loic Duros]

Correct, resources/testcase/lib/main.js in the attached xpi is what used to be in the pastebin.
Nicolay_Ponomarev, thanks for creating the attachment.

Thanks,

Comment 6

[Loic Duros]

Attachment: testcase2 with console.log in onStartRequest

Same add-on, but this time it has a console.log() onStartRequest.

Comment 7

[Loic Duros]

The testcase2.xpi file I've just attached has the console.log() in onStartRequest which I described in my second post. If looking in the console and going to certain sites you'll see the onStartRequest is triggered twice, same for onStopRequest. 

When having no cache and typing "google.com" in the location bar, I get in the console:
info: onStartRequest triggered http://www.google.com/
info: onStartRequest triggered http://www.google.com/
info: status is 0
info: onStopRequest called for html http://www.google.com/  and status is 0
info: status is 0
info: onStopRequest called for html http://www.google.com/  and status is 0


It doesn't seem to matter for me except for when there is some long asynchronous work performed onStopRequest before the data is passed to the original listener.

Comment 8

[Boris Zbarsky [:bzbarsky]]

Thanks for the link to the script.

This seems to be a bug in the script itself.  In the "http-on-examine-response" notification it unconditionally adds a TracingListener to the channel.  But "http-on-examine-response" is dispatched for all HTTP responses.  So consider this scenario:

1)  We do a GET
2)  The server responds with a 301 to another URL
3)  We do a get for the new URL
4)  The server responds with a 200.

There will be "http-on-examine-response" notifications for both the 301 and the 200, and the attached code will install two TracingListeners on the same channel, chaining to each other....

Comment 9

[Loic Duros]

Thanks for looking into this and sorry for not catching the bug was on the script end. So the solution would be to only install a TracingListener for 200 HTTP responses?

Comment 10

[Boris Zbarsky [:bzbarsky]]

Well, it would be _a_ solution.  Whether it's the right one depends on your goal.  Installing it for 3xx responses in general seems like a bad idea.

Comment 11

[Nickolay_Ponomarev]

Thanks, bz!

I noted this on https://developer.mozilla.org/en/XPCOM_Interface_Reference/NsITraceableChannel and sent an e-mail to Honza asking him to note this on http://www.softwareishard.com/blog/firebug/nsitraceablechannel-intercept-http-traffic/ as well.