onStopRequest triggered twice in TracingListener for some pages

RESOLVED INVALID

Status

()

Core
Networking
RESOLVED INVALID
5 years ago
5 years ago

People

(Reporter: Loic Duros, Unassigned)

Tracking

8 Branch
x86_64
Linux
Points:
---

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(3 attachments)

67.07 KB, application/octet-stream
Details
3.51 KB, application/x-javascript
Details
71.34 KB, application/octet-stream
Details
(Reporter)

Description

5 years ago
Created attachment 598893 [details]
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.
(Reporter)

Updated

5 years ago
Hardware: x86 → x86_64
(Reporter)

Comment 1

5 years ago
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...

Updated

5 years ago
Component: Untriaged → Networking
Product: Firefox → Core
QA Contact: untriaged → networking

Comment 2

5 years ago
Loic, could you attach whatever was in the pastebin here? It is not a viable permanent storage mechanism, and is now missing.
Where in the attached code is this TracingListener thing?  Or is that something that jetpack provides?

Comment 4

5 years ago
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.)
(Reporter)

Comment 5

5 years ago
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,
(Reporter)

Comment 6

5 years ago
Created attachment 611403 [details]
testcase2 with console.log in onStartRequest

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

Updated

5 years ago
Attachment #611403 - Attachment description: Same add-on, but this time it has a console.log() onStartRequest. → testcase2 with console.log in onStartRequest
(Reporter)

Comment 7

5 years ago
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.
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....
Status: UNCONFIRMED → RESOLVED
Last Resolved: 5 years ago
Resolution: --- → INVALID
(Reporter)

Comment 9

5 years ago
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?
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

5 years ago
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.
Blocks: 749411
You need to log in before you can comment on or make changes to this bug.