Last Comment Bug 728901 - onStopRequest triggered twice in TracingListener for some pages
: onStopRequest triggered twice in TracingListener for some pages
Product: Core
Classification: Components
Component: Networking (show other bugs)
: 8 Branch
: x86_64 Linux
: -- normal (vote)
: ---
Assigned To: Nobody; OK to take it and work on it
: Patrick McManus [:mcmanus]
Depends on:
Blocks: NetMonitor
  Show dependency treegraph
Reported: 2012-02-20 08:53 PST by Loic Duros
Modified: 2012-04-26 14:59 PDT (History)
4 users (show)
See Also:
Crash Signature:
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---

testcase.xpi (67.07 KB, application/octet-stream)
2012-02-20 08:53 PST, Loic Duros
no flags Details
main.js from the xpi (3.51 KB, application/x-javascript)
2012-04-02 02:06 PDT, Nickolay_Ponomarev
no flags Details
testcase2 with console.log in onStartRequest (71.34 KB, application/octet-stream)
2012-04-02 02:25 PDT, Loic Duros
no flags Details

Description Loic Duros 2012-02-20 08:53:33 PST
Created attachment 598893 [details]

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
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:
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 2012-02-20 10:22:47 PST
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 :
console.log('onStartRequest triggered', request.URI.spec);

and here is what I get when entering in the location bar:
info: onStartRequest triggered
info: onStartRequest triggered

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] (on vacation until Dec 5) 2012-04-01 08:59:48 PDT
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 [:bz] (still a bit busy) 2012-04-01 23:34:43 PDT
Where in the attached code is this TracingListener thing?  Or is that something that jetpack provides?
Comment 4 Nickolay_Ponomarev 2012-04-02 02:06:33 PDT
Created attachment 611401 [details]
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 2012-04-02 02:14:09 PDT
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.

Comment 6 Loic Duros 2012-04-02 02:25:59 PDT
Created attachment 611403 [details]
testcase2 with console.log in onStartRequest

Same add-on, but this time it has a console.log() onStartRequest.
Comment 7 Loic Duros 2012-04-02 02:33:29 PDT
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 "" in the location bar, I get in the console:
info: onStartRequest triggered
info: onStartRequest triggered
info: status is 0
info: onStopRequest called for html  and status is 0
info: status is 0
info: onStopRequest called for html  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 [:bz] (still a bit busy) 2012-04-02 06:30:41 PDT
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 2012-04-02 07:00:27 PDT
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 [:bz] (still a bit busy) 2012-04-02 07:02:44 PDT
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 2012-04-22 14:26:43 PDT
Thanks, bz!

I noted this on and sent an e-mail to Honza asking him to note this on as well.

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