http2: fix stream reading resumption #16580

apapirovski · 2017-10-29T00:28:43Z

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately.

When readable._read() is called, if data is available from the resource, the implementation should begin pushing that data into the read queue using the this.push(dataChunk) method. _read() should continue reading from the resource and pushing data until readable.push() returns false. Only when _read() is called again after it has stopped should it resume pushing additional data onto the queue.

Fixes: #16578
Refs: https://nodejs.org/dist/latest-v8.x/docs/api/stream.html#stream_readable_read_size_1

Checklist

make -j4 test (UNIX), or vcbuild test (Windows) passes
tests and/or benchmarks are included
commit message follows commit guidelines

Affected core subsystem(s)

http2, test

apapirovski · 2017-10-29T03:20:27Z

CI: https://ci.nodejs.org/job/node-test-pull-request/11062/

apapirovski · 2017-10-29T14:58:10Z

CI failed on a whole bunch of systems. Not really sure why, will investigate.

mcollina

LGTM

apapirovski · 2017-10-29T16:06:29Z

Ok, this has been updated. Anyone that approved, PTAL. resumption in _read now happens on nextTick as otherwise there's a race condition between it and streamOnPause.

This is a similar issue to one that plagued the compatibility API _read for a while and the fix there was the same. (Also, performance on reads appears unaffected — possibly 1.5-2% better.)

CI: https://ci.nodejs.org/job/node-test-pull-request/11078/

mcollina · 2017-10-29T16:09:07Z

Still LGTM

jasnell · 2017-10-29T16:15:24Z

+1 for fast tracking this for the 9.0.0 release.

apapirovski · 2017-10-29T16:17:42Z

I'll get this merged into master as soon as CI comes back green, unless there are any objections.

jasnell · 2017-10-29T17:36:58Z

appears to have failed on freebsd

apapirovski · 2017-10-29T17:37:38Z

Yep, I just saw. Looking into it.

apapirovski · 2017-10-29T17:44:55Z

Setting up a freebsd box to test on. I would still like this to make 9.0.0 because it's a pretty significant bug fix but it might take me an hour or two to diagnose and fix.

apapirovski · 2017-10-29T18:52:15Z

Just a flaky test, it looks like. I changed it to compare the length of the buffer and it works fine.

Here's the FreeBSD CI: https://ci.nodejs.org/job/node-test-commit-freebsd/12804/ (all green)

apapirovski · 2017-10-29T19:02:24Z

Stress test on FreeBSD to make sure: https://ci.nodejs.org/job/node-stress-single-test/1473/

apapirovski · 2017-10-29T19:02:59Z

Just an FYI, if that's all green then this is going to master. ping @jasnell — you ok with that?

apapirovski · 2017-10-29T19:33:00Z

Ok, stress test on FreeBSD failed. This seems pretty serious since it's emitting finish after losing a significant chunk of the data.

jasnell · 2017-10-29T19:56:00Z

hmmm... let's see if we can get it fixed today. If not, we can land this as is, mark that test flaky on freebsd, and keep working on fixing it. That way we can make sure that it is at least working on most platforms.

apapirovski · 2017-10-29T19:56:50Z

Yeah, that seems sensible. Thought I had it but latest commit still didn't do it for FreeBSD. Tricky one... will keep this PR updated with my progress.

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately. Fixes: nodejs#16578

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately. Some other general cleanup around reading, resuming & draining. PR-URL: #16580 Fixes: #16578 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

rauchg · 2017-10-30T03:30:16Z

Awesome work @apapirovski 🖤

apapirovski · 2017-10-30T04:08:20Z

@jasnell some additional debugging output from nghttp2:

recv: [IB_READ_HEAD]
recv: payloadlen=16384, type=0, flags=0x00, stream_id=1
recv: DATA
recv: no padding in payload
recv: [IB_READ_DATA]
recv: readlen=16384, payloadleft=0
recv: data_readlen=16384
recv: [IB_READ_HEAD]
recv: payloadlen=7302178, type=58, flags=0x20, stream_id=577270900
recv: length is too large 7302178 > 16384
recv: [IB_IGN_PAYLOAD]
recv: readlen=16393, payloadleft=7285785
stream: adjusting kept idle streams num_idle_streams=0, max=100
send: next frame: payloadlen=28, type=7, flags=0x00, stream_id=0
send: start transmitting frame type=7, length=37

I mean, no wonder it's failing given "recv: length is too large 7302178 > 16384"... but now the question is 'why' in the world is the payloadlen so large.

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately. Some other general cleanup around reading, resuming & draining. PR-URL: #16580 Fixes: #16578 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

apapirovski · 2017-10-30T14:43:21Z

@jasnell So I now have a cause for that FreeBSD bug, it looks like the data at the buffer pointer passed into Http2Session::Send becomes overwritten by the time it actually gets sent. When I use memcpy there it fixes the bug but of course the performance is pretty bad (about 10% drop on writes). I'll see if there's something else we can be doing better instead of having to memcpy.

jasnell · 2017-10-30T14:45:56Z

Is the test case using tls or plain text?

jasnell · 2017-10-30T14:46:47Z

if plain text, switch it to use tls and see if you have the same problem

apapirovski · 2017-10-30T14:54:27Z

No issue with TLS. It copies the data itself, doesn't it? (I think that's rhetorical based on my reading of the source... 😅)

jasnell · 2017-10-30T15:02:23Z

Yep, that's the confirmation I was looking for. So it would appear that on freebsd we have a race condition happening. There is only a single outbound buffer allocated, and each write is supposed to happen sequentially, but on freebsd it's holding on to the buffer a bit longer. That definitely gives us a starting point to begin poking. I'm going to be working on some refactoring of that part of the code anyway as soon as I can be done preparing the 9.0.0 release (which is what was taking up my time this weekend instead of helping debugging this so I appreciate the time you were taking on it).

apapirovski · 2017-10-30T15:04:10Z

I'm going to be working on some refactoring of that part of the code anyway as soon as I can be done preparing the 9.0.0 release (which is what was taking up my time this weekend instead of helping debugging this so I appreciate the time you were taking on it).

Was happy to look into it. Got a good feel for nghttp2 and most of the http2 code after doing this.

jasnell · 2017-10-30T15:08:34Z

Awesome. Yeah I've never really been that happy with the data flow through that part of the implementation. It needs a refactor to avoid the memcpy's to improve the callback story. I've already been looking into it and will hopefully have something very soon.

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately. Some other general cleanup around reading, resuming & draining. PR-URL: #16580 Fixes: #16578 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately. Some other general cleanup around reading, resuming & draining. PR-URL: nodejs/node#16580 Fixes: nodejs/node#16578 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>

apapirovski added c++ Issues and PRs that require attention from people who are familiar with C++. http2 Issues or PRs related to the http2 subsystem. test Issues and PRs related to the tests. labels Oct 29, 2017

apapirovski requested a review from jasnell October 29, 2017 00:28

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. lib / src Issues and PRs related to general changes in the lib or src directory. labels Oct 29, 2017

apapirovski mentioned this pull request Oct 29, 2017

http2 client stops sending after stream has reached 16KiB #16578

Closed

addaleax approved these changes Oct 29, 2017

View reviewed changes

jasnell approved these changes Oct 29, 2017

View reviewed changes

cjihrig approved these changes Oct 29, 2017

View reviewed changes

mcollina approved these changes Oct 29, 2017

View reviewed changes

apapirovski mentioned this pull request Oct 29, 2017

Proposal: 2017-10-31, Version 9.0.0 (Current) #15135

Merged

apapirovski force-pushed the patch-http2-pipe-flow branch 2 times, most recently from e340ac0 to 2d76c4f Compare October 29, 2017 16:10

http2: fix stream reading resumption

5f6372b

_read should always resume the underlying code that is attempting to push data to a readable stream. Adjust http2 core code to resume its reading appropriately. Fixes: nodejs#16578

apapirovski deleted the patch-http2-pipe-flow branch October 30, 2017 02:56

pranaygp mentioned this pull request Oct 30, 2017

Issue with streams? grantila/fetch-h2#1

Closed

gibfahn mentioned this pull request Oct 31, 2017

v8.9.0 proposal #16630

Merged

MylesBorins added the dont-land-on-v6.x label Nov 16, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http2: fix stream reading resumption #16580

http2: fix stream reading resumption #16580

apapirovski commented Oct 29, 2017 •

edited

Loading

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

mcollina left a comment

apapirovski commented Oct 29, 2017 •

edited

Loading

mcollina commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017 •

edited

Loading

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

rauchg commented Oct 30, 2017

apapirovski commented Oct 30, 2017 •

edited

Loading

apapirovski commented Oct 30, 2017 •

edited

Loading

jasnell commented Oct 30, 2017

jasnell commented Oct 30, 2017

apapirovski commented Oct 30, 2017 •

edited

Loading

jasnell commented Oct 30, 2017

apapirovski commented Oct 30, 2017

jasnell commented Oct 30, 2017

http2: fix stream reading resumption #16580

http2: fix stream reading resumption #16580

Conversation

apapirovski commented Oct 29, 2017 • edited Loading

Checklist

Affected core subsystem(s)

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

mcollina left a comment

Choose a reason for hiding this comment

apapirovski commented Oct 29, 2017 • edited Loading

mcollina commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017 • edited Loading

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

apapirovski commented Oct 29, 2017

jasnell commented Oct 29, 2017

apapirovski commented Oct 29, 2017

rauchg commented Oct 30, 2017

apapirovski commented Oct 30, 2017 • edited Loading

apapirovski commented Oct 30, 2017 • edited Loading

jasnell commented Oct 30, 2017

jasnell commented Oct 30, 2017

apapirovski commented Oct 30, 2017 • edited Loading

jasnell commented Oct 30, 2017

apapirovski commented Oct 30, 2017

jasnell commented Oct 30, 2017

apapirovski commented Oct 29, 2017 •

edited

Loading

apapirovski commented Oct 29, 2017 •

edited

Loading

apapirovski commented Oct 29, 2017 •

edited

Loading

apapirovski commented Oct 30, 2017 •

edited

Loading

apapirovski commented Oct 30, 2017 •

edited

Loading

apapirovski commented Oct 30, 2017 •

edited

Loading