762025 - Failing to connect to certain sites [google.com]

Status: RESOLVED DUPLICATE of bug 762162

(Core :: Networking, defect)

Description

[Robert O'Callahan (:roc) (email my personal email if necessary)]

My browser session (homemade opt build, changeset 7c3cd4824f94) has got into a state where it can't load certain sites --- google.com and tbpl.mozilla.org are the ones I've noticed so far. Other sites are fine.

Using Wireshark, loading https://www.google.com/ seems to generate no network traffic, other than (sometimes) a DNS lookup. But the page never loads, it just hangs in "Connecting..." with the throbber spinning anticlockwise.

I think this is not a DNS issue, since I've seen this happen with a DNS lookup in the packet trace. The lookup looks like this:
5	3.250295	192.168.1.7	google-public-dns-a.google.com	DNS	74	Standard query A www.google.com	56361
6	3.378670	google-public-dns-a.google.com	192.168.1.7	DNS	174	Standard query response CNAME www.l.google.com A 173.194.38.83 A 173.194.38.82 A 173.194.38.81 A 173.194.38.80 A 173.194.38.84	domain
which seems valid.

When I load https://tbpl.mozilla.org, I get something slightly different. We open a LOT of TLS connections but they all hang pretty quick (and never close). I'm not sure if this is the same problem as the above one or not, but they both just happened at the same time and I don't remember seeing either of them before.

Comment 1

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: tbpl pcap

Comment 2

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Disabling SPDY fixes the https://www.google.com issue. Reenabling it brings the issue back.

The tbpl.mozilla.org issue seems to be fixed now. Maybe toggling SPDY did it. I'm not sure.

I can keep this browser session going for a while and do any debugging that would be helpful.

Comment 3

[Patrick McManus [:mcmanus]]

sounds like you can repro - can you get an http nspr log?

https://developer.mozilla.org/en/HTTP_Logging

Comment 4

[Patrick McManus [:mcmanus]]

if it just started happening, it could be fallout from 759438

Comment 5

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I'm not sure if I can reproduce it after a browser restart. I haven't tried. Certainly starting another browser session in a different profile does not reproduce it.

Comment 6

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I managed to enable HTTP logging at DEBUG level via the debugger.

Here's an NSPR log:
http://people.mozilla.org/~roc/prlog-copy.txt.gz
It's busy. The log was at line 114716 when I tried to load https://www.google.com. It looks like the transaction got added to a queue and nothing else happened?

Comment 7

[Patrick McManus [:mcmanus]]

(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #6)
> I managed to enable HTTP logging at DEBUG level via the debugger.
> 

awesome

there's some amgibuity here.. but it looks like it hits to logic to open a new connection but doesn't proceed with it beacuse there is either already another active spdy session (shouldn't happen because it shouldn't have gone down the newconnection path if that was true), or there is already a tcp session to this site that hasn't negotiated spdy/http-1 yet.. and we're waiting for that.

do you have a netstat output that includes www.google.com ?

Comment 8

[Patrick McManus [:mcmanus]]

if you have it in the debugger you could break on nsHttpConnectionMgr::RestrictConnections(ent) (print ent to make sure you're dealing with www.google.com) and step through that to confirm where the restriction is.

if ent->mHalfOpens.Length() > 0, I'd love to see the member variables of ent->mHalfOpens[0]

Comment 9

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Sorry, I lost my session ... something to do with Visual Studio hanging; killing Visual Studio killed the debuggee as well :-(.

Comment 10

[Olli Pettay [:smaug][[e-mail]]]

I've seen something similar lately, but only with one network connection.
And the problem has, for some reason, happened after resuming the laptop.

Comment 11

[Patrick McManus [:mcmanus]]

First, Has anyone seen this on FF16 or FF15 in the last 3 weeks? I have not.

Second, bug 770264 landed something that could help debug it even without an NSPR log. That's on FF16 and FF15.

If this happens to you again - open the JS console and then open about:config. Find network.http.diagnostics and flip it to true - that will trigger a dump of a whole bunch of stuff to the JS console. paste that here!

(a google summer of code project is working on better way with an about:network page, but this gives us something to work with right now.)

Comment 12

[Justin Lebar (not reading bugmail)]

> First, Has anyone seen this on FF16 or FF15 in the last 3 weeks? I have not.

I have not either.

Comment 13

[Patrick McManus [:mcmanus]]

I had a 3 hour ISP outage this morning during which firefox was left running, with one tab on twitter.

After connectivity returned, twitter failed to work. Its been broken for the last hour.

I dumped the diagnostic info as per comment 11, and it shows a half open connection perpetually outstanding for twitter.com and a stable transaction pending queue for it. That half open is going to trigger our restrictconnections() logic and cause the stall. This situation didn't change over the hour.

In this particular case it is actually the backup connection that has gone awol. There is an obvious optimization to make to not block if we have connected at all with the entry, but I don't immediately see in the code base why the bug would be restricted to that case. So we can do that as a normal-train enhancement.

There are not entries in my OS netstat table for 199.59.149.230 (the resolved IP) in any state. So the question is how the transport object never has OnOutputStreamReady() called on it with an error.

When we set it up we don't actually meaningfully check the return of transport_out->AsyncWait() in SetupStreams() .. but in nsSocketOutputStream::AsyncWait() it always returns NS_OK with the args we are passing in anyhow. So that's not it. Plus there wouldn't be a problem setting it up - my host was unaware of the outage (the routing table didn't change or anything) as it was at the cable modem level.

That makes it sound like a problem with nsSocketTransport2.cpp

I think it is time to go back and time out half opens while we sort it out. That gets us out of the deadlock.

I'll include two diag samples below - taken about an hour apart. Note there is a bug in there that shows the elapsed time since starting incorrectly (they are displayed as (started - now) by mistake. I don't think it undercuts the interpretation here in any way. (I'll file and fix that separately)

The two samples do show the pending transaction queue shrinking from 6 to 3, but that's just because I canceled the loading tab in the interim.

 ent host = twitter.com hashkey = .S..twitter.com:443
   AtActiveConnectionLimit = 0
   RestrictConnections = 1
   Pending Q Length = 6
   Active Conns Length = 0
   Idle Conns Length = 0
   Half Opens Length = 1
   Coalescing Key = 199.59.149.230~.:443
   Spdy using = 1, tested = 1, preferred = 1
   pipelinestate = 0 penalty = 0
   pipeline per class penalty 0x0 0
   pipeline per class penalty 0x1 0
   pipeline per class penalty 0x2 0
   pipeline per class penalty 0x3 25000
   pipeline per class penalty 0x4 0
   :: Half Open #0
     has connected = 1, isSpeculative = 0
    primary started -10388221.64ms ago
    backup started 1354772115ms ago
    primary transport 0, backup transport 1
   :: Pending Transaction #0
     ::: uri = /scribe
     caps = 0x29
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #1
     ::: uri = /phoenix_search.phoenix?q=spdy&headers%5BX-Twitter-Polling%5D=true&headers%5BX-PHX%5D=true&since_id=225214728572649472&include_entities=1&include_available_features=1&contributor_details=true&query_source=unknown
     caps = 0x21
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #2
     ::: uri = /scribe
     caps = 0x29
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #3
     ::: uri = /account/available_features
     caps = 0x21
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #4
     ::: uri = /
     caps = 0x29
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #5
     ::: uri = /users/following_followers_of.json?cursor=-1&user_id=298044746
     caps = 0x21
     priority = 0
     restart count = 0
     classification = 0x3

...LATER ON...

 ent host = twitter.com hashkey = .S..twitter.com:443
   AtActiveConnectionLimit = 0
   RestrictConnections = 1
   Pending Q Length = 3
   Active Conns Length = 0
   Idle Conns Length = 0
   Half Opens Length = 1
   Coalescing Key = 199.59.149.230~.:443
   Spdy using = 1, tested = 1, preferred = 1
   pipelinestate = 0 penalty = 0
   pipeline per class penalty 0x0 0
   pipeline per class penalty 0x1 0
   pipeline per class penalty 0x2 0
   pipeline per class penalty 0x3 25000
   pipeline per class penalty 0x4 0
   :: Half Open #0
     has connected = 1, isSpeculative = 0
    primary started -12994471.79ms ago
    backup started -2145188779ms ago
    primary transport 0, backup transport 1
   :: Pending Transaction #0
     ::: uri = /scribe
     caps = 0x29
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #1
     ::: uri = /phoenix_search.phoenix?q=spdy&headers%5BX-Twitter-Polling%5D=true&headers%5BX-PHX%5D=true&since_id=225214728572649472&include_entities=1&include_available_features=1&contributor_details=true&query_source=unknown
     caps = 0x21
     priority = 0
     restart count = 0
     classification = 0x3
   :: Pending Transaction #2
     ::: uri = /account/available_features
     caps = 0x21
     priority = 0
     restart count = 0
     classification = 0x3

Comment 14

[Patrick McManus [:mcmanus]]

interesting to note that having a half open hanging around like that is most problematic for spdy (as it just takes 1 to create a very visible problem) but it counts against quotas for regular HTTP too. (but is probably rare enough to only very extremely rarely be visible)

Comment 15

[Honza Bambas (:mayhemer)]

Could you reproduce this by disconnecting your modem from WAN?

Comment 16

[Patrick McManus [:mcmanus]]

(In reply to Honza Bambas (:mayhemer) from comment #15)
> Could you reproduce this by disconnecting your modem from WAN?

haven't tried that yet. I will. modem connection is in the basement :( .. 

but the orphaned half open doesn't happen if I try and connect to something like 8.8.8.8 which just eats all syns to port 80 which is pretty much the observable behavior.

there has to be a race condition of some sort in the mix too.

I'm very eager to work this new information - but I need to take an extended timeout to go have a wisdom tooth extracted. Hopefully will return to this tomorrow.

(browser with stuck half open is still running.. so we'll find out if it ever does clear.. though with nothing in netstat I don't know what event could trigger it).

Comment 17

[Patrick McManus [:mcmanus]]

(In reply to Patrick McManus [:mcmanus] from comment #16)

> (browser with stuck half open is still running.. so we'll find out if it
> ever does clear.. 

it's still there today. It now has a transaction queue of about 30.

Comment 18

[Patrick McManus [:mcmanus]]

I'm going to consolidate these bugs. If there turns out to be an actionable difference between them I suspect it is not actually at connect time and needs a different bug entry anyhow.