862856 - nsIHttpActivityObserver not working well for monitoring HTTP activity in recent version firefox

Status: RESOLVED FIXED

(Core :: Networking: HTTP, defect)

Description

[heng]

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:19.0) Gecko/20100101 Firefox/19.0
Build ID: 20130224092553

Steps to reproduce:

I am using Mozilla API nsIHttpActivityObserver for the capturing of HTTP activity, such as the dns resolving event or connecting event. However, I found a strange thing that, by using the example shown in Mozilla web page (https://developer.mozilla.org/en-US/docs/Monitoring_HTTP_activity), it works perfect with firefox version <=14, but when I am using higher recent version, (e.g. 15, 16, 17), the activity capturing seems does NOT work so well.


here are some details (including the script):

1. test case URL: http://www.google.com (lets just pick up one simple web page as an example)

2. versions of Firefox that tested:
a) used to work: version 3.0, 5.0, 6.0, 12.0, 14.0
b) NOT working well: version 15.0, 16.0, 17.0

It seems that, firefox 14.0 and 15.0 is a break point to differentiate .. I also tested in many different OS such as windows XP, windows 7, ubuntu, fedora, and the observations are the same for these OSes.


3. the precise code:
actually, I follow the example provided at https://developer.mozilla.org/en-US/docs/Monitoring_HTTP_activity, and just change to nsISocketTransport.STATUS_CONNECTING_TO as the example that shows the problem

the script is as following:

var nsIHttpActivityObserver = Components.interfaces.nsIHttpActivityObserver;
var nsISocketTransport = Components.interfaces.nsISocketTransport;
var NetHttpActivityObserver =
{
  observeActivity: function(httpChannel, activityType, activitySubtype, timestamp, extraSizeData, extraStringData){
     try{
       if ( httpChannel instanceof Components.interfaces.nsIHttpChannel ){
         if ( activityType == nsIHttpActivityObserver.ACTIVITY_TYPE_SOCKET_TRANSPORT ){
           if (activitySubtype == nsISocketTransport.STATUS_CONNECTING_TO){
             dump( "got it???  " + httpChannel.URI.asciiSpec + "\n")
          }
        }
     }
   }catch (exc){}
  }
}
var activityDistributor = Components.classes["@mozilla.org/network/http-activity-distributor;1"]
                          .getService(Components.interfaces.nsIHttpActivityDistributor);
activityDistributor.addObserver(NetHttpActivityObserver);




Actual results:

Take an example, with an empty cache browser, when browse a new page, there should be always some new (tcp) connections, especially at the beginning period of downloading, but with the newer version(>=15), sometimes, we can NOT capture such tcp connect events, neither for the dns resolving for most of the cases, it ONLY provides events like "HTTP wait etc."

by using similar tool like firebug, it also shows me no connecting delay at the beginning, instead, it shows me as "blocking" delay.... 



Expected results:


if we browse a new page from an empty page (also not using cache), we should be able to get the dumped message from my script example, and dump information that there are NEW tcp connections.

Comment 1

[Jason Duell]

I haven't verified the bustage here, and alas we have no automated tests :( but the interface for firing nsIHttpActivityObserver events is all in nsHttpTransaction.cpp, and "hg grep --all ObserveActivity nsHttpTransaction.cpp" shows that the only change involving calls to ObserveActivity() near that timeframe was bug 671591 (but that landed in Firefox 14, and the reporter is saying the bustage happens starting in 15).

Patrick, that changeset does modify things so that we fire off NS_HTTP_ACTIVITY_TYPE_SOCKET_TRANSPORT notification only if "!mRestartInProgressVerifier.Active()".  Perhaps there's some cases where that test is being overly restrictive?

Comment 2

[Sebastian Zartner [:sebo]]

We had a related discussion in our group[1] some time ago.

Sebastian

[1] https://groups.google.com/d/topic/firebug/WIOO3aIlGQo/discussion

Comment 3

[Patrick McManus [:mcmanus]]

we now do all kinds of connection level things speculatively and (at best) loosely bundled to a particular transaction.. dns, tcp, ssl handshakes all fall into that bucket. That's going to be hard on any model than assumes a tightly bound lifecycle.

Comment 4

[Matthew Gertner]

(In reply to Patrick McManus [:mcmanus] from comment #3)
> we now do all kinds of connection level things speculatively and (at best)
> loosely bundled to a particular transaction.. dns, tcp, ssl handshakes all
> fall into that bucket. That's going to be hard on any model than assumes a
> tightly bound lifecycle.

Does that mean it simply isn't possible to provide reliable networking statistics in recent Firefox versions? How does the Network Panel do it? Are the values in Navigation Timing (https://developer.mozilla.org/en-US/docs/Navigation_timing) wrong?

Comment 5

[Matthew Gertner]

Nudging this. Can someone clarify? Do I understand correctly that it is no longer possible in recent Firefox versions to get reliable measurements for DNS resolution and connection times? Is there any workaround available or planned?

Comment 6

[Sebastian Zartner [:sebo]]

FWIW here's another report against Firebug:

https://code.google.com/p/fbug/issues/detail?id=7668

And Matthew's question is still waiting for an answer.

Sebastian

Comment 7

[Asen Bozhilov]

I've exactly the same issue with xulrunner 34. I use page on the local server with content: 

<img src="http://i.cdn.turner.com/cnn/cnnintl_adspaces/2.0/creatives/2010/1/20/31613Impact_Your_World_728X90_011410.jpg">
<img src="https://www.yahoo.com/sy/nn/fp/rsz/113014/images/smush/obama-sasha-malia_635x250_1417318680.jpg">

The testing code is: 

const nsIHttpActivityObserver = {
    observeActivity : function (aHttpChannel, aActivityType, aActivitySubtype, aTimestamp, aExtraSizeData, aExtraStringData) {
        let nsIHttpActivityObserver = Ci.nsIHttpActivityObserver;
        let nsISocketTransport = Ci.nsISocketTransport;
        if (aActivityType == nsIHttpActivityObserver.ACTIVITY_TYPE_SOCKET_TRANSPORT) {
            aHttpChannel.QueryInterface(Ci.nsIHttpChannel);
            switch(aActivitySubtype) {
                case nsISocketTransport.STATUS_RESOLVING:
                    window.dump('DNS resolving URL: ' + aHttpChannel.URI.spec + '\n');
                break;
                case nsISocketTransport.STATUS_RESOLVED:
                    window.dump('DNS resolved URL: ' + aHttpChannel.URI.spec + '\n');
                break;
                case nsISocketTransport.STATUS_CONNECTING_TO:
                    window.dump('Connecting URL: ' + aHttpChannel.URI.spec + '\n');
                break;
                case nsISocketTransport.STATUS_CONNECTED_TO:
                    window.dump('Connected URL: ' + aHttpChannel.URI.spec + '\n');
                break;
            }
        }
    },
    
    QueryInterface: function(iid)
    {
        if (iid.equals(Ci.nsISupports) ||
            iid.equals(Ci.nsIActivityObserver)) {
            return this;
         }

        throw Cr.NS_ERROR_NO_INTERFACE;
    }
};

const httpActivityDistributor = Cc["@mozilla.org/network/http-activity-distributor;1"].getService(Ci.nsIHttpActivityDistributor);
httpActivityDistributor.addObserver(nsIHttpActivityObserver);

The output is: 

DNS resolving URL: http://192.168.0.65/test.php
DNS resolved URL: http://192.168.0.65/test.php
Connecting URL: http://192.168.0.65/test.php
Connected URL: http://192.168.0.65/test.php


There are no dns and connection events for the images and I'm wondering why it performs dns resolving on my local IP. Hope it will be fixed as soon as possible.

Comment 8

[Patrick McManus [:mcmanus]]

not every event (transaction or socket event) has a channel these days - lots of it is done speculatively.

I bet those tings are getting lost.

Dragana, want to take a shot at it?

Comment 9

[Dragana Damjanovic [:dragana]]

I will take a look

Comment 10

[Dragana Damjanovic [:dragana]]

The image is fetched using the same channel as the http body so there is no new connection and no new socket event. I have confirmed this using wireshark.

DNS resolving event is in socket transport which sends request to dns service (part of firefox dealing with dns resolution and caching), therefore this event exist even for host name that is an ip address (and local host). DNS service does not send any dns request out because it figures out that this is an ip address.
This is for comment 7.

Regarding to the original problem I have check and i see dns request and STATUS_CONNECTING_TO event.

Comment 11

[Patrick McManus [:mcmanus]]

dragana, are you sure that there aren't circumstances where DNS and CONNECTING events do not get generated at all for a particular origin?

I'm thinking about where those things may get done speculatively and completed before a channel comes along and reuses them.. the reuse is like you describe in comment 10, but if the lookup and connect are never reported at all then its a bit of a problem.

I guess I'm asking for confirmation that all connections and lookups get reported..

Comment 12

[Dragana Damjanovic [:dragana]]

You are right. 

Events are reported in nsHttpTransaction, but they are not reported in NullHttpTransaction.
When NullHttpTransaction is used there is no channel. Activity events report the channel they are related to. Should we use nsITransport instead?

Comment 13

[Patrick McManus [:mcmanus]]

I think just using a null value for the channel is the right thing to do and we can document what it means. Some consumer out there is no dooubt using the channel to get the uri and that's ok as long as the items are paired up.

Comment 14

[Dragana Damjanovic [:dragana]]

According to out discussion today, we will have a "NullChannel" that is only going to have correct host name, and no other functionality so that these events (comment 12) can be connected to a certain host. It should implement something like nsINullChannel so that it can be distinguished between real nsHttpChannel and the fake one.

Comment 15

[Dragana Damjanovic [:dragana]]

Attachment: fix v1

Comment 16

[Patrick McManus [:mcmanus]]

Comment on attachment 8547559 [details] [diff] [review]
fix v1

Review of attachment 8547559 [details] [diff] [review]:
-----------------------------------------------------------------

::: netwerk/protocol/http/NullHttpTransaction.cpp
@@ +43,5 @@
> +  {
> +  }
> +  NS_IMETHOD Run() MOZ_OVERRIDE
> +  {
> +    nsCOMPtr<nsIURI> uri;

assert main thread

@@ +44,5 @@
> +  }
> +  NS_IMETHOD Run() MOZ_OVERRIDE
> +  {
> +    nsCOMPtr<nsIURI> uri;
> +    nsresult rv = NS_NewURI(getter_AddRefs(uri),

you need full origin here scheme://host:port if the port isn't the default port for the scheme... connection info has that info (sometimes it returns -1 for default.. but I would also check it against 80/443 as apropos)

Comment 17

[Patrick McManus [:mcmanus]]

Comment on attachment 8547559 [details] [diff] [review]
fix v1

Review of attachment 8547559 [details] [diff] [review]:
-----------------------------------------------------------------

minor thing to address

Comment 18

[Dragana Damjanovic [:dragana]]

Attachment: fix v2

Comment 19

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5cb1e772af5a

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/bc9ba0c25707

Comment 21

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/bc9ba0c25707

Comment 22

[Asen Bozhilov]

Why this is marked as fixed and meanwhile the problem is still alive in Firefox 38? Am I missing something? After Firefox 15 we are not able to do real network statistic. Firebug is still wrong.