1360515 - Improve behavior of H2 if TCP Fast Open is used

Status: RESOLVED FIXED

(Core :: Networking: HTTP, enhancement)

Description

[Dragana Damjanovic [:dragana]]

During TFO we can write only certain amount of data: 1460 for ipv4 and 1440 for IPv6. TCPFastOpenLayer is called to find out how many bytes are available. TCPFastOpenLayer accounts for TLS record headers as well.
We need to account for TLS header only if tls is used. This is a small fix that can go together with this patch.

If h2 is involved, we write tls handshake and h2 hello messages to the TCPFastOpenLayer buffer. There is still some place left and if we have a transaction we want to write the transaction request headers as well. So we have n bytes left (1460 - tls/ht hello - tls record header size) and we call H2 session to write n bytes. We have a stream that has a more than n bytes header size (uncompressed)  so the header parser reads only n bytes and does not write it to the network because it is waiting for more :)
In some cases the transaction headers can be compressed into n bytes and could have fit into syn packet.

A side problem is that stream Ids are added to m0RTTStreams during 0RTT. But our stream above does not write data during the first call and therefore it does not have a streamId. A 0 streamId will be added to m0RTTStreams, which is wrong :)

Another a very small performance optimization:
We have TFO and H2. A new transaction is added, this is happening after we have send the syn packet. H2 will try to send data to the network(h2 calls ReadSegments in AddStream function), but it cannot because we are waiting for syn-ack an TCPFastOpenLayer will return WOULD_BLOCK. This data will be stored in the tls layer. We could skip doing all of this if TFO is involved. This is really a very small problem and one can argue that the data is already ready to be written as soon as we get syn-ack.

Comment 1

[Dragana Damjanovic [:dragana]]

Patrick, you know h2 better: should we increase n if we want to write headers? If the compress headers do not fit into a syn packet the rest of the headers will be stored in H2Session buffer, so that is not a big problem, we cannot get response for that request anyway. We only need to take care that we do not send too much data to tls layer so that server can start decoding the data (if we send too much a tls record will be only partially sent and server cannot start decoding it).

Comment 2

[Patrick McManus [:mcmanus]]

I'm going to have to reply to this one in parts :)

Comment 3

[Patrick McManus [:mcmanus]]

(In reply to Dragana Damjanovic [:dragana] from comment #0)
> Another a very small performance optimization:
> We have TFO and H2. A new transaction is added, this is happening after we
> have send the syn packet. H2 will try to send data to the network(h2 calls
> ReadSegments in AddStream function), but it cannot because we are waiting
> for syn-ack an TCPFastOpenLayer will return WOULD_BLOCK. This data will be
> stored in the tls layer. We could skip doing all of this if TFO is involved.
> This is really a very small problem and one can argue that the data is
> already ready to be written as soon as we get syn-ack.

I would not do this optimization - it has to get serialized eventually - and if it doesn't get buffered in tls it might very well get buffered in h2session. And as you point out, that means we can respond quicker when we can actually transmit the data.

Also, deferring buffering tends to mean you can't assign stream ids until later (because the need to be done monotonically).. and that leads to a lot of bugs and unhappiness.

Comment 4

[Patrick McManus [:mcmanus]]

(In reply to Dragana Damjanovic [:dragana] from comment #0)
> During TFO we can write only certain amount of data: 1460 for ipv4 and 1440
> for IPv6. TCPFastOpenLayer is called to find out how many bytes are
> available. TCPFastOpenLayer accounts for TLS record headers as well.
> We need to account for TLS header only if tls is used. This is a small fix
> that can go together with this patch.
> 
> If h2 is involved, we write tls handshake and h2 hello messages to the
> TCPFastOpenLayer buffer. There is still some place left and if we have a
> transaction we want to write the transaction request headers as well. So we
> have n bytes left (1460 - tls/ht hello - tls record header size) and we call
> H2 session to write n bytes. We have a stream that has a more than n bytes
> header size (uncompressed)  so the header parser reads only n bytes and does
> not write it to the network because it is waiting for more :)
> In some cases the transaction headers can be compressed into n bytes and
> could have fit into syn packet.

I guess you're describing how ParseHttpRequestHeaders() (from h2stream::onreadsegment) fails to generate any h2 output if the h1 headers aren't complete? (That's because HEADERS frames need to be atomic on the wire).

and I guess that in turn happens because nshttptransaction::readsegments was provided such a short buffer in the face of tfo.

So what happens if we just provide the whole stack with a much bigger buffer and end up with excess eventually being PR_Write()'d ? just PR_Write() just give a short return and then EWOULDBLOCK? That would be ok as it would buffer stuff in http2session iirc.. or if it were buffered in TLS I think that would be OK too (but less desirable).

Comment 5

[Patrick McManus [:mcmanus]]

(In reply to Dragana Damjanovic [:dragana] from comment #0)

> A side problem is that stream Ids are added to m0RTTStreams during 0RTT. But
> our stream above does not write data during the first call and therefore it
> does not have a streamId. A 0 streamId will be added to m0RTTStreams, which
> is wrong :)
> 

I'm sure you're right - but I thought we fixed that as one of the early-data fixups. how does it happen with tfo?

Comment 6

[Dragana Damjanovic [:dragana]]

I will remove limiting the amount of data to be written in nshttptransaction::readsegments. This will remove problem with headers  not being complete and we will just buffer data in http2Session. 


On the other hand I will limit the amount of that we write into tls layer and that will eliminate buffering in tls layer.

1) remove the limit added in EnsureNPNComplete
2) add limit in nsSocketOutputStream::Write(const char *buf, uint32_t count, uint32_t *countWritten), i.e.
...
// During TFO we can write only a limited amount of data. Check how much space we have.
// If we write to much data and TCPFastOpenLayer does not take it all the rest will be buffered in tls layer
// checking how much space we have in TCPFastOpeLayer will eliminate buffering in tls layer.
uint32_t left = TCPFastOpenGetBufferSizeLeft(fd);
count = (left > count) ? count : left;
...
int32_t n = PR_Write(fd, buf, count);

Comment 7

[Dragana Damjanovic [:dragana]]

(In reply to Patrick McManus [:mcmanus] from comment #5)
> (In reply to Dragana Damjanovic [:dragana] from comment #0)
> 
> > A side problem is that stream Ids are added to m0RTTStreams during 0RTT. But
> > our stream above does not write data during the first call and therefore it
> > does not have a streamId. A 0 streamId will be added to m0RTTStreams, which
> > is wrong :)
> > 
> 
> I'm sure you're right - but I thought we fixed that as one of the early-data
> fixups. how does it happen with tfo?

This is a side effect of giving a too short buffer to nshttptransaction::readsegments. So the complete header cannot be buffer, therefore we do not parse it and we do not send it to the network (or buffer it in http2session) and we do not have a streamId.

Comment 8

[Dragana Damjanovic [:dragana]]

(In reply to Dragana Damjanovic [:dragana] from comment #7)
> (In reply to Patrick McManus [:mcmanus] from comment #5)
> > (In reply to Dragana Damjanovic [:dragana] from comment #0)
> > 
> > > A side problem is that stream Ids are added to m0RTTStreams during 0RTT. But
> > > our stream above does not write data during the first call and therefore it
> > > does not have a streamId. A 0 streamId will be added to m0RTTStreams, which
> > > is wrong :)
> > > 
> > 
> > I'm sure you're right - but I thought we fixed that as one of the early-data
> > fixups. how does it happen with tfo?
> 
> This is a side effect of giving a too short buffer to
> nshttptransaction::readsegments. So the complete header cannot be buffer,
> therefore we do not parse it and we do not send it to the network (or buffer
> it in http2session) and we do not have a streamId.

I need to check if a similar problem can be cause by http2Session buffer being full. The buffer is not aligned during fastopen, the buffered data are kept in the buffer. What if the buffer gets full and we do not have place for the complete header of a new stream and therefore the stream header are not written to the buffer and of course the stream do not have a streamId to be added to m0RTTStreams. This could be a problem for 0rtt with or without TFO!

Comment 9

[Dragana Damjanovic [:dragana]]

Attachment: bug_1360515_v1.patch

Comment 10

[Dragana Damjanovic [:dragana]]

(In reply to Dragana Damjanovic [:dragana] from comment #8)
> (In reply to Dragana Damjanovic [:dragana] from comment #7)
> > (In reply to Patrick McManus [:mcmanus] from comment #5)
> > > (In reply to Dragana Damjanovic [:dragana] from comment #0)
> > > 
> > > > A side problem is that stream Ids are added to m0RTTStreams during 0RTT. But
> > > > our stream above does not write data during the first call and therefore it
> > > > does not have a streamId. A 0 streamId will be added to m0RTTStreams, which
> > > > is wrong :)
> > > > 
> > > 
> > > I'm sure you're right - but I thought we fixed that as one of the early-data
> > > fixups. how does it happen with tfo?
> > 
> > This is a side effect of giving a too short buffer to
> > nshttptransaction::readsegments. So the complete header cannot be buffer,
> > therefore we do not parse it and we do not send it to the network (or buffer
> > it in http2session) and we do not have a streamId.
> 
> I need to check if a similar problem can be cause by http2Session buffer
> being full. The buffer is not aligned during fastopen, the buffered data are
> kept in the buffer. What if the buffer gets full and we do not have place
> for the complete header of a new stream and therefore the stream header are
> not written to the buffer and of course the stream do not have a streamId to
> be added to m0RTTStreams. This could be a problem for 0rtt with or without
> TFO!

It is possible to hit this by starting enough http requests during 0rtt. Http2Session/Http2Streams are able to deal it this.
I do not know h2 code as well as you and if you prefer that we limit how many requests are add during 0rtt, I can do it. Probably adding a check in TryToActivate.
I could do this in a separate bug.

Comment 11

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=2a495cb667622b5009d8c7ace62d3decdf1befcb

Comment 12

[Patrick McManus [:mcmanus]]

how does this patch address the streamID = 0 problem? For TFO? For 0RTT? For both? For neither?

Comment 13

[Patrick McManus [:mcmanus]]

so, afaict, we should generally have a streamID irrespective of the amount of buffer provided, because after GenerateOpen() is called (which is what sets the stream ID and generates the HEADERS frame)they are sent with TransmitFrame(..,.., true) - which forces the expansion of the http2session buffer if necessary to hold the frame. (because we have created hpack state we need to enforce the order - so this has to be buffered if we can't send it).

I think the only time we dip into http2stream::onreadsegment and don't set the stream ID is when nsHttpTransaction calls it with truncated http request headers - it shouldn't matter what our output buffering looks like.

I'm surprised you can see this in testing.. I think there is some channel interface it can happen through, but I didn't think it was normal.

Comment 14

[Patrick McManus [:mcmanus]]

fwiw we can't generate streamID any earlier, because they have to be part of the HEADERS frame and the need to appear on the wire in a strictly increasing fashion (which means we can't create them until we have all the headers necessary for the HEADERS frame).

what if we changed m0RTTStreams to an nsTArray of WeakPtrs (to streams) ? Those could be assigned early.

Comment 15

[Dragana Damjanovic [:dragana]]

This is from a log that tries to fetch 30 images:

This request is written to the h2session buffer


2017-05-02 11:51:32.286008 UTC - [Socket Thread]: I/nsHttp Http2Stream::Http2Stream 0x7f441006bea0
2017-05-02 11:51:32.286010 UTC - [Socket Thread]: I/nsHttp Http2Session::AddStream session=0x7f441003b7e0 stream=0x7f441006bea0 serial=12 NextID=0x27 (tentative)
2017-05-02 11:51:32.286016 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.286018 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.286020 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.286021 UTC - [Socket Thread]: I/nsHttp Http2Session::ConfirmTLSProfile 0x7f441003b7e0 mConnection=0x7f441000f500
2017-05-02 11:51:32.286023 UTC - [Socket Thread]: I/nsHttp Http2Session::ConfirmTLSProfile 0x7f441003b7e0 temporarily passing due to early data
2017-05-02 11:51:32.286024 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegments 0x7f441003b7e0
2017-05-02 11:51:32.286027 UTC - [Socket Thread]: I/nsHttp Http2Session 0x7f441003b7e0 will write from Http2Stream 0x7f44100b30d0 0x0 block-input=0 block-output=0
2017-05-02 11:51:32.286028 UTC - [Socket Thread]: I/nsHttp Http2Stream 0x7f44100b30d0 ReadSegments reader=0x7f441003b7f8 count=1095 state=0
2017-05-02 11:51:32.286030 UTC - [Socket Thread]: I/nsHttp Http2Stream::OnReadSegment 0x7f44100b30d0 count=1025 state=0
2017-05-02 11:51:32.286032 UTC - [Socket Thread]: I/nsHttp Http2Stream::ParseHttpRequestHeaders 0x7f44100b30d0 avail=1025 state=0
2017-05-02 11:51:32.286058 UTC - [Socket Thread]: I/nsHttp Pushed Stream Lookup session=0x7f441003b7e0 key=https://blog.cloudflare.com/[]/[http2.12]/content/images/2017/03/image31.jpg requestcontext=0x141b750 cache=(nil) hit=(nil)
2017-05-02 11:51:32.286060 UTC - [Socket Thread]: I/nsHttp Http2Session::TryToActivate 0x7f441003b7e0 stream=0x7f44100b30d0
2017-05-02 11:51:32.286062 UTC - [Socket Thread]: I/nsHttp Http2Session::IncrementCounter 0x7f441003b7e0 counting stream 0x7f44100b30d0 Currently 14 streams in session, high water mark is 14
2017-05-02 11:51:32.286063 UTC - [Socket Thread]: I/nsHttp Http2Session::RegisterStreamID session=0x7f441003b7e0 stream=0x7f44100b30d0 id=0x27 concurrent=14
2017-05-02 11:51:32.286065 UTC - [Socket Thread]: I/nsHttp Http2Stream 0x7f44100b30d0 Stream ID 0x27 [session=0x7f441003b7e0] for URI /content/images/2017/03/image31.jpg
2017-05-02 11:51:32.286068 UTC - [Socket Thread]: V/nsHttp Http2Compressor::ProcessHeader :method GET
2017-05-02 11:51:32.286070 UTC - [Socket Thread]: V/nsHttp HTTP compressor 0x7f441003ba58 index 1 :method GET
2017-05-02 11:51:32.286072 UTC - [Socket Thread]: V/nsHttp Compressor state after index
2017-05-02 11:51:32.286073 UTC - [Socket Thread]: V/nsHttp Header Table

.....

2017-05-02 11:51:32.290142 UTC - [Socket Thread]: I/nsHttp Http2Stream 0x7f44100b30d0 Generating 69 bytes of HEADERS for stream 0x27 with priority weight 13 dep 0xB frames 1 uri=/content/images/2017/03/image31.jpg
2017-05-02 11:51:32.290145 UTC - [Socket Thread]: I/nsHttp ParseHttpRequestHeaders 0x7f44100b30d0 used 1025 of 1025. requestheadersdone = 1 mOpenGenerated = 1
2017-05-02 11:51:32.290147 UTC - [Socket Thread]: I/nsHttp AdjustInitialwindow increased flow control window 0x7f44100b30d0 0x27 12451840
2017-05-02 11:51:32.290149 UTC - [Socket Thread]: I/nsHttp Http2Stream::TransmitFrame 0x7f44100b30d0 inline=82 stream=0
2017-05-02 11:51:32.290150 UTC - [Socket Thread]: I/nsHttp Http2Stream::TransmitFrame for inline BufferOutput session=0x7f441003b7e0 stream=0x7f44100b30d0 result 0 len=82
2017-05-02 11:51:32.290152 UTC - [Socket Thread]: V/nsHttp Http2Session::LogIO 0x7f441003b7e0 stream=0x7f44100b30d0 id=0x27 [Writing from Inline Buffer]
2017-05-02 11:51:32.290155 UTC - [Socket Thread]: V/nsHttp 00000000: 00 00 3C 01 25 00 00 00 27 00 00 00 0B 0D 82 05
2017-05-02 11:51:32.290158 UTC - [Socket Thread]: V/nsHttp 00000010: 99 60 87 A9 25 A9 2C 1A 91 CC 54 30 20 05 D6 00
2017-05-02 11:51:32.290160 UTC - [Socket Thread]: V/nsHttp 00000020: CB 06 A4 73 15 90 AF D2 B9 BF CC 87 CB CA C9 C8
2017-05-02 11:51:32.290163 UTC - [Socket Thread]: V/nsHttp 00000030: C7 C6 C5 1F 37 88 8A 33 7B 8A A8 60 0B FF C4 C3
2017-05-02 11:51:32.290165 UTC - [Socket Thread]: V/nsHttp 00000040: C2 C1 C0 BF BE 00 00 04 08 00 00 00 00 27 00 BE
2017-05-02 11:51:32.290167 UTC - [Socket Thread]: V/nsHttp 00000050: 00 00
2017-05-02 11:51:32.290169 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=0x4474750 status=804b0005 progress=82]
2017-05-02 11:51:32.290171 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnTransportStatus 0x4474750 SENDING_TO without request body
2017-05-02 11:51:32.290173 UTC - [Socket Thread]: D/nsHttp nsHttpTransaction::OnSocketStatus [this=0x4474750 status=804b000a progress=0]
2017-05-02 11:51:32.290174 UTC - [Socket Thread]: D/nsSocketTransport nsSocketTransport::GetSelfAddr [this=0x7f4410021360 state=3] NOT_AVAILABLE because not yet connected.
2017-05-02 11:51:32.290176 UTC - [Socket Thread]: D/nsSocketTransport nsSocketTransport::GetPeerAddr [this=0x7f4410021360 state=3] NOT_AVAILABLE because not yet connected.
2017-05-02 11:51:32.290182 UTC - [Socket Thread]: I/nsHttp Http2Stream::ChangeState() 0x7f44100b30d0 from 0 to 1
2017-05-02 11:51:32.290184 UTC - [Socket Thread]: I/nsHttp Http2Stream::ReadSegments 0x7f44100b30d0 trans readsegments rv 0 read=1025
2017-05-02 11:51:32.290185 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegmentsAgain adding stream 39 to m0RTTStreams
2017-05-02 11:51:32.290187 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::Write [this=0x7f4410021618 count=1035]
2017-05-02 11:51:32.290189 UTC - [Socket Thread]: I/nsHttp Http2Session::FlushOutputQueue 0x7f441003b7e0 sz=1035 rv=80470007 actual=0
2017-05-02 11:51:32.290191 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=0x7f4410013940]
2017-05-02 11:51:32.290193 UTC - [Socket Thread]: D/nsSocketTransport nsSocketInputStream::AsyncWait [this=0x7f44100215e0]
2017-05-02 11:51:32.290195 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegments 0x7f441003b7e0 stream=0x7f44100b30d0 countread=1978
2017-05-02 11:51:32.290196 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290198 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290202 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290204 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290206 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290209 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290212 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 0x7f4410013940 caps=0x21 .S.....blog.cloudflare.com:443


Here comes the next 2:


2017-05-02 11:51:32.290215 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::DispatchTransaction [ent-ci=.S.....blog.cloudflare.com:443 0x7f441000b550 trans=0x4474d30 caps=21 conn=0x7f4410013940 priority=8]
2017-05-02 11:51:32.290217 UTC - [Socket Thread]: V/nsHttp Spdy Dispatch Transaction via Activate(). Transaction host = blog.cloudflare.com, Connection host = blog.cloudflare.com
2017-05-02 11:51:32.290219 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Activate [this=0x7f4410013940 trans=0x4474d30 caps=21]
2017-05-02 11:51:32.290220 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::AddTransaction for SPDY
2017-05-02 11:51:32.290223 UTC - [Socket Thread]: I/nsHttp Http2Stream::Http2Stream 0x7f44100227d0
2017-05-02 11:51:32.290227 UTC - [Socket Thread]: I/nsHttp Http2Session::AddStream session=0x7f441003b7e0 stream=0x7f44100227d0 serial=12 NextID=0x29 (tentative)
2017-05-02 11:51:32.290229 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290230 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290232 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290234 UTC - [Socket Thread]: I/nsHttp Http2Session::ConfirmTLSProfile 0x7f441003b7e0 mConnection=0x7f441000f500
2017-05-02 11:51:32.290236 UTC - [Socket Thread]: I/nsHttp Http2Session::ConfirmTLSProfile 0x7f441003b7e0 temporarily passing due to early data
2017-05-02 11:51:32.290206 UTC - [Main Thread]: D/nsHttp sending progress and status notification [this=0x1516600 status=804b000a progress=0/0]
2017-05-02 11:51:32.290238 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegments 0x7f441003b7e0
2017-05-02 11:51:32.290250 UTC - [Socket Thread]: I/nsHttp Http2Session 0x7f441003b7e0 will write from Http2Stream 0x7f44100ff6d0 0x1B block-input=0 block-output=0
2017-05-02 11:51:32.290251 UTC - [Socket Thread]: I/nsHttp Http2Stream 0x7f44100ff6d0 ReadSegments reader=0x7f441003b7f8 count=1013 state=1
2017-05-02 11:51:32.290253 UTC - [Socket Thread]: I/nsHttp Http2Stream::ReadSegments 0x7f44100ff6d0 trans readsegments rv 0 read=0
2017-05-02 11:51:32.290265 UTC - [Socket Thread]: I/nsHttp Http2Stream::ReadSegments 0x7f44100ff6d0 0x1B: Sending request data complete, mUpstreamState=1
2017-05-02 11:51:32.290267 UTC - [Socket Thread]: I/nsHttp Http2Stream::ChangeState() 0x7f44100ff6d0 from 1 to 4
2017-05-02 11:51:32.290269 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::Write [this=0x7f4410021618 count=1035]
2017-05-02 11:51:32.290271 UTC - [Socket Thread]: I/nsHttp Http2Session::FlushOutputQueue 0x7f441003b7e0 sz=1035 rv=80470007 actual=0
2017-05-02 11:51:32.290272 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeRecv [this=0x7f4410013940]
2017-05-02 11:51:32.290274 UTC - [Socket Thread]: D/nsSocketTransport nsSocketInputStream::AsyncWait [this=0x7f44100215e0]
2017-05-02 11:51:32.290276 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegments 0x7f441003b7e0 stream=0x7f44100ff6d0 countread=1035
2017-05-02 11:51:32.290277 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290281 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290283 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290284 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290286 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290288 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290290 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::SetupSSL 0x7f4410013940 caps=0x21 .S.....blog.cloudflare.com:443
2017-05-02 11:51:32.290292 UTC - [Socket Thread]: V/nsHttp nsHttpConnectionMgr::DispatchTransaction [ent-ci=.S.....blog.cloudflare.com:443 0x7f441000b550 trans=0x446aba0 caps=21 conn=0x7f4410013940 priority=8]
2017-05-02 11:51:32.290294 UTC - [Socket Thread]: V/nsHttp Spdy Dispatch Transaction via Activate(). Transaction host = blog.cloudflare.com, Connection host = blog.cloudflare.com
2017-05-02 11:51:32.290295 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::Activate [this=0x7f4410013940 trans=0x446aba0 caps=21]
2017-05-02 11:51:32.290309 UTC - [Socket Thread]: I/nsHttp Http2Stream::Http2Stream 0x7f4410022920
2017-05-02 11:51:32.290312 UTC - [Socket Thread]: I/nsHttp Http2Session::AddStream session=0x7f441003b7e0 stream=0x7f4410022920 serial=12 NextID=0x29 (tentative)
2017-05-02 11:51:32.290314 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290315 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290317 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290319 UTC - [Socket Thread]: I/nsHttp Http2Session::ConfirmTLSProfile 0x7f441003b7e0 mConnection=0x7f441000f500
2017-05-02 11:51:32.290330 UTC - [Socket Thread]: I/nsHttp Http2Session::ConfirmTLSProfile 0x7f441003b7e0 temporarily passing due to early data
2017-05-02 11:51:32.290331 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegments 0x7f441003b7e0
2017-05-02 11:51:32.290334 UTC - [Socket Thread]: I/nsHttp Http2Session 0x7f441003b7e0 will write from Http2Stream 0x7f441004cd90 0x0 block-input=0 block-output=0
2017-05-02 11:51:32.290335 UTC - [Socket Thread]: I/nsHttp Http2Stream 0x7f441004cd90 ReadSegments reader=0x7f441003b7f8 count=1013 state=0
2017-05-02 11:51:32.290337 UTC - [Socket Thread]: I/nsHttp Http2Stream::OnReadSegment 0x7f441004cd90 count=1013 state=0
2017-05-02 11:51:32.290339 UTC - [Socket Thread]: I/nsHttp Http2Stream::ParseHttpRequestHeaders 0x7f441004cd90 avail=1013 state=0
2017-05-02 11:51:32.290338 UTC - [Main Thread]: V/nsHttp HttpChannelChild::OnStatus [this=0x19dd9e0 status=804b000a]
2017-05-02 11:51:32.290346 UTC - [Socket Thread]: I/nsHttp Http2Stream::ParseHttpRequestHeaders 0x7f441004cd90 Need more header bytes. Len = 1013
2017-05-02 11:51:32.290348 UTC - [Socket Thread]: I/nsHttp ParseHttpRequestHeaders 0x7f441004cd90 used 1013 of 1013. requestheadersdone = 0 mOpenGenerated = 0
2017-05-02 11:51:32.290350 UTC - [Socket Thread]: I/nsHttp Http2Stream::ReadSegments 0x7f441004cd90 trans readsegments rv 0 read=1013
2017-05-02 11:51:32.290352 UTC - [Socket Thread]: I/nsHttp Http2Session::TransactionHasDataToWrite 0x7f441003b7e0 stream=0x7f441004cd90 ID=0x0
2017-05-02 11:51:32.290353 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940]
2017-05-02 11:51:32.290355 UTC - [Socket Thread]: D/nsSocketTransport nsSocketOutputStream::AsyncWait [this=0x7f4410021618]
2017-05-02 11:51:32.290358 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ResumeSend [this=0x7f4410013940] mWaitingFor0RTTResponse=1 mForceSendDuringFastOpenPending=0 mReceivedSocketWouldBlockDuringFastOpen=1
2017-05-02 11:51:32.290360 UTC - [Socket Thread]: V/nsHttp nsHttpConnection::ForceSend [this=0x7f4410013940]
2017-05-02 11:51:32.290372 UTC - [Socket Thread]: I/nsHttp Http2Stream 0x7f441004cd90 ReadSegments forcing OnReadSegment call
2017-05-02 11:51:32.290374 UTC - [Socket Thread]: I/nsHttp Http2Stream::OnReadSegment 0x7f441004cd90 count=0 state=0
2017-05-02 11:51:32.290375 UTC - [Socket Thread]: I/nsHttp Http2Stream::ParseHttpRequestHeaders 0x7f441004cd90 avail=0 state=0
2017-05-02 11:51:32.290396 UTC - [Socket Thread]: I/nsHttp Http2Stream::ParseHttpRequestHeaders 0x7f441004cd90 Need more header bytes. Len = 1013
2017-05-02 11:51:32.290398 UTC - [Socket Thread]: I/nsHttp ParseHttpRequestHeaders 0x7f441004cd90 used 0 of 0. requestheadersdone = 0 mOpenGenerated = 0
2017-05-02 11:51:32.290408 UTC - [Socket Thread]: I/nsHttp Http2Session::ReadSegmentsAgain adding stream 0 to m0RTTStreams

and the next 2 streams do get header parsed and flushed to h2session buffer and do get streamId

I have not done further debugging. Maybe it i enough just to change m0RTTStreams to an nsTArray of WeakPtrs.
The page is a localhost that try to load 30-40 images from https://blog.cloudflare.com (because they speak 0rtt).

Comment 16

[Dragana Damjanovic [:dragana]]

(In reply to Patrick McManus [:mcmanus] from comment #12)
> how does this patch address the streamID = 0 problem? For TFO? For 0RTT? For
> both? For neither?

It does not. this patch just makes TFO perform better with H2, because it lets h2 perform it its normal way and buffer parsed requests that will be written to the network as soon as tcp synack is received.

Comment 17

[Patrick McManus [:mcmanus]]

(In reply to Dragana Damjanovic [:dragana] from comment #15)

> I have not done further debugging. Maybe it i enough just to change
> m0RTTStreams to an nsTArray of WeakPtrs.

interesting. it might have nothing to do with early data - before early data having a stream id 0 there would not be a problem. And it certainly can happen - so I think the weakptr thing is right. using id is just trying to be a manual weakptr anyhow.

Comment 18

[Dragana Damjanovic [:dragana]]

(In reply to Patrick McManus [:mcmanus] from comment #12)
> how does this patch address the streamID = 0 problem? For TFO? For 0RTT? For
> both? For neither?

Actually without this patch the problem with streamID = 0 was happening all the time if TFO is enabled and 0rtt is performed, really every time with a example of localhost page that loads 2 images:
https://blog.cloudflare.com/content/images/2017/03/image05.jpg
and
https://blog.cloudflare.com/content/images/2017/03/image06.jpg

Comment 19

[Dragana Damjanovic [:dragana]]

(In reply to Patrick McManus [:mcmanus] from comment #17)
> (In reply to Dragana Damjanovic [:dragana] from comment #15)
> 
> > I have not done further debugging. Maybe it i enough just to change
> > m0RTTStreams to an nsTArray of WeakPtrs.
> 
> interesting. it might have nothing to do with early data - before early data
> having a stream id 0 there would not be a problem. And it certainly can
> happen - so I think the weakptr thing is right. using id is just trying to
> be a manual weakptr anyhow.

I will make that change in a separate bug, because it is independent of TFO.

Comment 20

[Dragana Damjanovic [:dragana]]

And I think this is the last bug for TFO: now it can land :)

H2-0rtt was not there in autumn so I could not test it with h2, therefore all this after bugs.

Comment 21

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=83fcfe9e368cf4668cdf8c62ccb8d7be18713d11

Comment 22

[Dragana Damjanovic [:dragana]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1784ff83720074384ff165c9040aeaa9876facc1

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/352f22e37dc3
During TCP Fast Open let necko works as it is used to, but only limit amount of data we write to lower layers, i.e. nss, tcpFastOpenLayer, tcp socket. r=mcmanus

Comment 24

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/352f22e37dc3