Closed Bug 862856 Opened 7 years ago Closed 5 years ago

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

Categories

(Core :: Networking: HTTP, defect, critical)

defect
Not set
critical

Tracking

()

RESOLVED FIXED
mozilla38

People

(Reporter: hengc39, Assigned: dragana)

References

Details

(Keywords: addon-compat)

Attachments

(1 file, 1 obsolete file)

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.
Keywords: addon-compat
Severity: normal → critical
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?
Component: Untriaged → Networking: HTTP
Product: Firefox → Core
We had a related discussion in our group[1] some time ago.

Sebastian

[1] https://groups.google.com/d/topic/firebug/WIOO3aIlGQo/discussion
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.
(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?
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?
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
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.
Status: UNCONFIRMED → NEW
Ever confirmed: true
OS: Linux → All
Hardware: x86_64 → All
Version: 19 Branch → Trunk
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?
Flags: needinfo?(dd.mozilla)
I will take a look
Flags: needinfo?(dd.mozilla)
Assignee: nobody → dd.mozilla
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.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INVALID
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..
Flags: needinfo?(dd.mozilla)
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?
Status: RESOLVED → REOPENED
Flags: needinfo?(dd.mozilla) → needinfo?(mcmanus)
Resolution: INVALID → ---
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.
Flags: needinfo?(mcmanus)
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.
Attached patch fix v1 (obsolete) — Splinter Review
Attachment #8547559 - Flags: review?(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)
Attachment #8547559 - Flags: review?(mcmanus) → review+
Comment on attachment 8547559 [details] [diff] [review]
fix v1

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

minor thing to address
Attached patch fix v2Splinter Review
Attachment #8547559 - Attachment is obsolete: true
Attachment #8548845 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/bc9ba0c25707
Status: REOPENED → RESOLVED
Closed: 5 years ago5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla38
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.
You need to log in before you can comment on or make changes to this bug.