970939 - Assertion failure: !mUsingSpdyVersion (Don't use TCP Keepalive with SPDY!), at netwerk/protocol/http/nsHttpConnection.cpp:1641

Status: RESOLVED FIXED

(Core :: Networking, defect)

Description

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

The assertion happens occasionally when starting a debug build of Firefox.

Comment 1

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

I see URLClassifier related warnings around that assertion.

Comment 2

[Honza Bambas (:mayhemer)]

Attachment: Log (nsHttp:4) if interested...

The interesting logs might be missing, tho..


>	xul.dll!mozilla::net::nsHttpConnection::StartShortLivedTCPKeepalives() Line 1641	C++
 	xul.dll!mozilla::net::nsHttpConnection::Activate(mozilla::net::nsAHttpTransaction * trans=0x09d103e0, unsigned int caps=0x00000001, int pri=0x00000000) Line 370	C++
 	xul.dll!mozilla::net::nsHttpConnectionMgr::DispatchAbstractTransaction(mozilla::net::nsHttpConnectionMgr::nsConnectionEntry * ent=0x09f41ea8, mozilla::net::nsAHttpTransaction * aTrans=0x09d103e0, unsigned int caps=0x00000001, mozilla::net::nsHttpConnection * conn=0x09312038, int priority=0x00000000) Line 1831	C++
 	xul.dll!mozilla::net::nsHttpConnectionMgr::DispatchTransaction(mozilla::net::nsHttpConnectionMgr::nsConnectionEntry * ent=0x09f41ea8, mozilla::net::nsHttpTransaction * trans=0x09d103e0, mozilla::net::nsHttpConnection * conn=0x09312038) Line 1773	C++
 	xul.dll!mozilla::net::nsHttpConnectionMgr::TryDispatchTransaction(mozilla::net::nsHttpConnectionMgr::nsConnectionEntry * ent=0x09f41ea8, bool onlyReusedConnection=false, mozilla::net::nsHttpTransaction * trans=0x09d103e0) Line 1680	C++
 	xul.dll!mozilla::net::nsHttpConnectionMgr::ProcessPendingQForEntry(mozilla::net::nsHttpConnectionMgr::nsConnectionEntry * ent=0x09f41ea8, bool considerAll=false) Line 1063	C++
 	xul.dll!mozilla::net::nsHttpConnectionMgr::OnMsgProcessPendingQ(int __formal=0x00000000, void * param=0x18b85228) Line 2235	C++
 	xul.dll!mozilla::net::nsHttpConnectionMgr::nsConnEvent::Run() Line 574	C++
 	xul.dll!nsThread::ProcessNextEvent(bool mayWait=true, bool * result=0x08bffa17) Line 643	C++
 	xul.dll!NS_ProcessNextEvent(nsIThread * thread=0x0846bd20, bool mayWait=true) Line 263	C++
 	xul.dll!nsSocketTransportService::Run() Line 741	C++

Comment 3

[Steve Workman [:sworkman] (INACTIVE)]

Attachment: Remove unwanted non-SPDY assertion from nsHttpConnection::StartShortLivedTCPKeepalives()

Pat, I think that this assertion should be removed since SPDY still uses nsHttpConnection, right?

Also fixed the failure LOG for the return value of StartShortLivedTCPKeepalives().

Comment 4

[Patrick McManus [:mcmanus]]

Comment on attachment 8374523 [details] [diff] [review]
Remove unwanted non-SPDY assertion from nsHttpConnection::StartShortLivedTCPKeepalives()

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

I think the problem here is that StartSpdy() can be called before StartShortLivedTCPKeepalives().. it can happen on the Activate()->OnOutputStreamReady()->OnSocketWritable()->EnsureNPNComplete()->StartSpdy() stack on that very first call from activate.

normally that doesn't happen because it takes a while to handshake things.. StartSpdy() is called after activate() has completed, but when this assertion goes off that's probably why

and the assertion makes sense, because the StartSpdy()->DisableTCPKeepAlives() code won't have any effect if it is called before StartShortLIved, right? (StartShortLived will undo it).

can the call to startshortlived just be moved to before the OnOutputStreamReady() function call?

::: netwerk/protocol/http/nsHttpConnection.cpp
@@ +370,5 @@
>          nsresult rv2 = StartShortLivedTCPKeepalives();
>          if (NS_WARN_IF(NS_FAILED(rv2))) {
>              LOG(("nsHttpConnection::Activate [%p] "
>                   "StartShortLivedTCPKeepalives failed rv2[0x%x]",
> +                 this, rv2));

:)

Comment 5

[Steve Workman [:sworkman] (INACTIVE)]

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

> can the call to startshortlived just be moved to before the
> OnOutputStreamReady() function call?
> 
I think so. I've pushed to try for a bit of verification...
https://tbpl.mozilla.org/?tree=Try&rev=c826da090325

Comment 6

[Steve Workman [:sworkman] (INACTIVE)]

Attachment: v1.1 Remove unwanted non-SPDY assertion from nsHttpConnection::StartShortLivedTCPKeepalives()

Try looks fine, so I think this should work.

Comment 7

[Patrick McManus [:mcmanus]]

Comment on attachment 8375706 [details] [diff] [review]
v1.1 Remove unwanted non-SPDY assertion from nsHttpConnection::StartShortLivedTCPKeepalives()

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

sorry - I think I figured out another problem here.

Activate can be called multiple times.. in the case of spdy it can be called twice
a] with a nullhttptransaction to perform the handshake of a speculative connect
b] after a completes, the connection is treated as a persistent connection then it is activated again with the first http transaction that will be gatewayed into spdy (future transactions are actually added to the live connection not through activate - so its just a max of twice)

I think the only change you need to consider on top of this patch is to remove the MOZ_ASSERT(!mUsingSpdyVersion) in StartShortLived..() and the associated NS_WARNING.. you just want an early return if we're using spdy.

There are three cases afaict.

1] one activation - no way spdy can be negotiated before StartShortLived is called, if it is negotiated later it will disable KA itself
2] first activation doesn't see spdy, second activation might or might not.. that maps to case 1.
3] first activation did see spdy and canceled the timer.. startshortlived will be called again on second activation and this is now a nop.

what do you think?

Comment 8

[Steve Workman [:sworkman] (INACTIVE)]

I think I'm fine with this. The assert (and warning) only makes sense if we're 100% sure that when we enter StartShort the connection will not be SPDY. We could add some logic outside the call, but it would/should be called every time, so it makes sense to have it in the function as a silent return and protect the rest of the function body.

So, from my perspective (i.e. not knowing all the SPDY cases and wondering if there are more we/you haven't thought of), I think we're better having the code deal with the scenarios and move on happily rather than logging warnings about it.

In the current code, minus the assert, I think we're covered in both not-enabling and disabling as needed:
-- StartShortLived should return if the nsHttpConnection is a SPDY connection.
-- If it becomes SPDY after that, then we do DisableKeepalives. 

(Maybe there are missing cases, but we can add a DisableKeepalives call those should they become apparent).

So, yeah, I'm good with that.

Comment 9

[Steve Workman [:sworkman] (INACTIVE)]

Attachment: v1.2 Remove unwanted non-SPDY assertion from nsHttpConnection::StartShortLivedTCPKeepalives()

(Oh, I guess the description for the previous version of the patch was wrong, but now it's right again. Ssh. Let's pretend no-one noticed).

I kept the StartShort call before OnOutputStreamReady in Activate: no harm in starting the keepalives a brief moment earlier than writing out to the socket.

And I removed the assert from StartShort.

FYI, I kept the assert for StartLong. I think we can be more sure that it will/should not be called if the connection is SPDY. That's an easy fix later if not.

Comment 10

[Steve Workman [:sworkman] (INACTIVE)]

Thanks Pat!

https://hg.mozilla.org/integration/mozilla-inbound/rev/34c2df5a99a4

Comment 11

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/34c2df5a99a4