1554411 - Failing MOZ_ASSERT(FindTunnelCount(ci)) in Http2Session::UnRegisterTunnel

Status: RESOLVED FIXED

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

Description

[Honza Bambas (:mayhemer)]

>	xul.dll!mozilla::net::Http2Session::UnRegisterTunnel(0x0000013e96b80480) Line 4158	C++
 	xul.dll!mozilla::net::Http2Session::CloseStream(0x0000013e96b80480, NS_OK) Line 1301	C++
 	xul.dll!mozilla::net::Http2Session::CleanupStream(0x0000013e96b80480, NS_OK, CANCEL_ERROR) Line 1212	C++
 	xul.dll!mozilla::net::Http2Session::CleanupStream(0x0000000f, NS_OK, CANCEL_ERROR) Line 1263	C++
 	xul.dll!mozilla::net::Http2Session::WriteSegmentsAgain(0x0000013ea04be808, 0x00008000, 0x0000000fe69be788, 0x0000000fe69be787) Line 3423	C++
 	xul.dll!mozilla::net::nsHttpConnection::OnSocketReadable() Line 2101	C++
 	xul.dll!mozilla::net::nsHttpConnection::OnInputStreamReady(0x0000013ea04b6698) Line 2444	C++
 	xul.dll!mozilla::net::nsSocketInputStream::OnSocketReady(NS_OK) Line 282	C++
 	xul.dll!mozilla::net::nsSocketTransport::OnSocketReady(0x0000013ea10ba520, 0x0001) Line 2208	C++
 	xul.dll!mozilla::net::nsSocketTransportService::DoPollIteration(0x0000000fe69beec8) Line 1212	C++
 	xul.dll!mozilla::net::nsSocketTransportService::Run() Line 973	C++

void Http2Session::UnRegisterTunnel(Http2Stream* aTunnel) {
  MOZ_ASSERT(OnSocketThread(), "not on socket thread");
  nsHttpConnectionInfo* ci = aTunnel->Transaction()->ConnectionInfo();
> MOZ_ASSERT(FindTunnelCount(ci));
  uint32_t newcount = FindTunnelCount(ci) - 1;
  mTunnelHash.Remove(ci->HashKey());
  if (newcount) {
    mTunnelHash.Put(ci->HashKey(), newcount);
  }
  LOG3(("Http2Session::UnRegisterTunnel %p stream=%p tunnels=%d [%s]", this,
        aTunnel, newcount, ci->HashKey().get()));
}

locally applied patch for bug 1546924, going through the proxy via ipv6/trr, watching a yt video.

have a log (460mb), will look

Comment 1

[Honza Bambas (:mayhemer)]

The Http2Session.mConcurrent is incremented only on one place:
Http2Session::TryToActivate

and decremented on 3!
Http2Session::ResetDownstreamState
Http2Session::CloseStream
Http2Session::RecvRstStream

In my case, for which I have the log, there is only one tunneling stream on the affected session. We call decrement for it twice, once from ChangeDownstreamState (called from Http2Session::SetNeedsCleanup) and second from CloseStream. Something tells me that the one in ChangeDownstreamState called when we receive a FIN data frame is duplicate, since we will definitely end up calling CloseStream for that stream anyway.

Honestly, each stream should keep a flag that it's been added to and removed from the concurrent counter - only safe way to do it correctly. We should then assert in dtor it is not included in the counter (flag==false).

I'm dealing with this bug because the counter is unsigned. If we underflow it, it will remain at 2^32-1 and will block the session from accepting new tunnels. I'm not 100% sure, but we could then easily get blocked - queue tunnels for eternity (a combo of 1562885 and 1563027)..

here is the log snippet for reference:

2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::WriteSegments[0000013EA01D3800::68] Frame Header Read type 0 data len 0 flags 1 id 0xF
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0000013EA01D3800 from 1 to 4
 from = BUFFERING_FRAME_HEADER, to = PROCESSING_DATA_FRAME
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Start Processing Data Frame. Session=0000013EA01D3800 Stream ID 0xF Stream Ptr 0000013E96B80480 Fin=1 Len=0
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Stream::WriteSegments 0000013E96B80480 count=32768 state=1
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Stream::OnWriteSegment 0000013E96B80480 count=32768 state=1 0xF
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::SetNeedsCleanup 0000013EA01D3800 - recorded downstream fin of stream 0000013E96B80480 0xF
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::ResetDownstreamState() 0000013EA01D3800
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0000013EA01D3800 from 4 to 1
 from = PROCESSING_DATA_FRAME, to = BUFFERING_FRAME_HEADER
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp   SetRecvdFin id=0xf
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp MaybeDecrementConcurrent 0000013EA01D3800 id=0xF concurrent=1 active=1
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: D/nsHttp SpdyConnectTransaction::WriteSegments wrapped writer 0000013E9E67AC00 Error 80470002
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: V/nsHttp   no transaction; ignoring event
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::ResetDownstreamState() 0000013EA01D3800
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::ChangeDownstreamState() 0000013EA01D3800 from 4 to 1
 from = PROCESSING_DATA_FRAME, to = BUFFERING_FRAME_HEADER
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::WriteSegments session=0000013EA01D3800 id 0xF needscleanup=0000013E96B80480. cleanup stream based on stream->writeSegments returning code 80470002
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::CleanupStream 0000013EA01D3800 by ID 0xF to stream 0000013E96B80480
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::CleanupStream 0000013EA01D3800 0000013E96B80480 0xF 0
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp Http2Session::CloseStream 0000013EA01D3800 0000013E96B80480 0xf 0
2019-05-25 18:05:10.359000 UTC - [Parent 7988: Socket Thread]: I/nsHttp MaybeDecrementConcurrent 0000013EA01D3800 id=0xF concurrent=0 active=0

Comment 2

[Honza Bambas (:mayhemer)]

Ok, comment 1 describes actually a different problem (also IMO valid).

The real problem is that when we register the tunnel, ci on the spdysockettransaction is different than at the time we unregister it. It's not reassigned during the object lifetime and was up when the channel was being registered, so we are probably hitting the mutability problem of connection info here.

Comment 3

[Honza Bambas (:mayhemer)]

mConnectionInfo->SetNoSpdy(true); called is the cause:

 	xul.dll!mozilla::net::nsHttpConnectionInfo::SetNoSpdy(true) Line 128	C++
 	xul.dll!mozilla::net::nsHttpTransaction::DisableSpdy() Line 1958	C++
>	xul.dll!mozilla::net::Http2Session::WriteSegmentsAgain(0x000002239dd909e8, 32768, 0x000000593f7ecf88, 0x000000593f7ecf87) Line 3390	C++
 	xul.dll!mozilla::net::TLSFilterTransaction::WriteSegmentsAgain(0x000002239bc35c08, 32768, 0x000000593f7ecf88, 0x000000593f7ecf87) Line 385	C++
 	xul.dll!mozilla::net::nsHttpConnection::OnSocketReadable() Line 2134	C++
 	xul.dll!mozilla::net::nsHttpConnection::OnInputStreamReady(0x00000223a0028c10) Line 2486	C++
 	xul.dll!mozilla::net::SpdyConnectTransaction::WriteSegments(0x0000022399688b68, 32768, 0x000000593f7ee5b8) Line 1368	C++
 	xul.dll!mozilla::net::Http2Stream::WriteSegments(0x000002239c151820, 32768, 0x000000593f7ee5b8) Line 322	C++
 	xul.dll!mozilla::net::Http2Session::WriteSegmentsAgain(0x000002239bc2fc08, 32768, 0x000000593f7ee5b8, 0x000000593f7ee5b7) Line 3420	C++
 	xul.dll!mozilla::net::nsHttpConnection::OnSocketReadable() Line 2134	C++
 	xul.dll!mozilla::net::nsHttpConnection::OnInputStreamReady(0x000002239966a6a0) Line 2486	C++
 	xul.dll!mozilla::net::nsSocketInputStream::OnSocketReady(NS_OK) Line 284	C++
 	xul.dll!mozilla::net::nsSocketTransport::OnSocketReady(0x00000223a2fc0ca0, 3) Line 2233	C++
 	xul.dll!mozilla::net::nsSocketTransportService::DoPollIteration(0x000000593f7eecf8) Line 1210	C++
 	xul.dll!mozilla::net::nsSocketTransportService::Run() Line 971	C++

This is for the case my local buggy iis server returned http1 fallback rst frame.

IMO, fixing bug 1564120 is the best fix, but not for uplift... Other option is to simply let the stream remember what hash key it was registered under in the hashtable + the suggested fix from comment 1 (to let the stream remember it was already deregistered to avoid duplication).

Comment 4

[Honza Bambas (:mayhemer)]

(In reply to Honza Bambas (:mayhemer) from comment #1)

and decremented on 3!
Http2Session::ResetDownstreamState
Http2Session::CloseStream
Http2Session::RecvRstStream

This is actually deduplicated by the stream->CountAsActive() flag being dropped, so we are fine here.

only fix needed is immutability of the key for the session->mTunnelHash table.

Comment 5

[Honza Bambas (:mayhemer)]

Attachment: Bug 1554411 - Make sure to deregister each HTTP/2 tunnel with the same key as used for its registration, r=dragana

Comment 6

[Honza Bambas (:mayhemer)]

Attachment: 1554411-unstiked.tar.xz

Search for channel/transaction with https://test.local.tld/ as url.

Comment 7

[Honza Bambas (:mayhemer)]

Comment on attachment 9082586 [details]
1554411-unstiked.tar.xz

(wrong bug)

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4d1d749118c9
Make sure to deregister each HTTP/2 tunnel with the same key as used for its registration, r=dragana

Comment 9

[Alexandru Michis [:malexandru]]

https://hg.mozilla.org/mozilla-central/rev/4d1d749118c9

Comment 10

[Honza Bambas (:mayhemer)]

Comment on attachment 9082580 [details]
Bug 1554411 - Make sure to deregister each HTTP/2 tunnel with the same key as used for its registration, r=dragana

Beta/Release Uplift Approval Request

• User impact if declined: Small chance for indefinite blocking of making new connections to a single server when an h2 proxy is configured.
• Is this code covered by automated tests?: No
• Has the fix been verified in Nightly?: Yes
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): Very low as this is a) isolated to h2 tunneling and b) the code is not hit very often, if at all (need special circumstances).
• String changes made/needed:

Comment 11

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9082580 [details]
Bug 1554411 - Make sure to deregister each HTTP/2 tunnel with the same key as used for its registration, r=dragana

Fixes being unable to make new h2 connections to pages under some circumstances. Approved for 69.0b14.

Comment 12

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/ac7b9ed39750