http2: use and support non-empty DATA frame with END_STREAM flag #33875

clshortfuse · 2020-06-14T15:10:57Z

Checklist

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

addaleax

This sounds good, but I’m a bit surprised that we didn’t catch this already … is there a way to add a test for this?

clshortfuse · 2020-06-14T16:54:41Z

@addaleax Let me give it another shot now that I understand the original bug. It may not be possible because of the http2 client is based on nghttp2 which doesn't normal produce the issue (it's on Chrome or curl). I'll report back with my findings.

Also, let me know if commits needs to be squashed.

clshortfuse · 2020-06-14T17:57:49Z

@addaleax Doesn't seem possible to test with the internal http2 client. Http2Stream.end(chunk) will always send two frames. One with the data, and another empty frame with END_STREAM flag set. That means you can't send a DATA frame with data in it that also has END_STREAM and the bug can't be produced with the client.

On a side-note, we should probably fix that eventually. No reason to send in two frames what can be sent in one.

clshortfuse · 2020-06-14T18:30:36Z

WAIT!

Callback function invoked when a chunk of data in DATA frame is received. The stream_id is the stream ID this DATA frame belongs to. The flags is the flags of DATA frame which this data chunk is contained. (flags & NGHTTP2_FLAG_END_STREAM) != 0 does not necessarily mean this chunk of data is the last one in the stream. You should use nghttp2_on_frame_recv_callback to know all data frames are received. The user_data pointer is the third argument passed in to the call to nghttp2_session_client_new() or nghttp2_session_server_new().

https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback

This isn't a valid fix. We need to tackle it differently. I have no idea why it says that, but I think we should follow it. Do they mean out of order frames? I'll want a little more time to diagnose it better.

node/src/node_http2.cc

Line 1751 in f46ca0f

if (nread < 0) {

is my next guess for a better solution.

addaleax · 2020-06-14T18:57:29Z

@clshortfuse I don’t really know either… also, we do have a check for NGHTTP2_FLAG_END_STREAM in HandleDataFrame() that sounds like it would be invalid according to this definition?

clshortfuse · 2020-06-14T19:16:18Z

@addaleax The usage there is right and we're doing it right.

node/src/node_http2.cc

Line 1277 in f46ca0f

frame->hd.flags & NGHTTP2_FLAG_END_STREAM) {

The only thing I can think of that the nghttp2_on_data_chunk_recv_callback isn't a 1:1 mapping of the DATA frame. In other words, the callback can send less data than that's actually in the frame, meaning the callback can be fired multiple times per frame. Unlikely, but possible. The flag here is just letting know that frame we're in is the last one, but not the current chunk of the frame.

Taking a look back, the real problem is the pause. We can do a hack and just not pause on the last DATA frame. That will surely solve the problem because it'll continue reading until it ends. But the better solution is make sure that even if we do pause here, for whatever reason, it can get the nghttp2_on_frame_recv_callback when it should.

It's also entirely possible this could be a nghttp2 bug where if you just happen to pause on the last chunk of the last DATA frame, it won't resume properly. So I put it as a draft until I can figure out where the real source of the issue is.

clshortfuse · 2020-06-14T23:49:18Z

So here's what's going on:

When we call

node/src/node_http2.cc

Line 1098 in f46ca0f

return NGHTTP2_ERR_PAUSE;

We are telling nghttp2 to pause. It doesn't only pause reading the chunk, but the frame as a whole. That means we paused it sending us the eventual nghttp2_on_frame_recv_callback that gives us EOF. The problem is that calling NGHTTP2_ERR_PAUSE will give the same result as when we don't, which is amount of bytes read.

And while we check to see if we paused:

node/src/node_http2.cc

Lines 752 to 763 in f46ca0f

    
           if (is_receive_paused()) { 
        
             CHECK(is_reading_stopped()); 
        
             CHECK_GT(ret, 0); 
        
             CHECK_LE(static_cast<size_t>(ret), read_len); 
        
             if (static_cast<size_t>(ret) < read_len) { 
        
               // Mark the remainder of the data as available for later consumption. 
        
               stream_buf_offset_ += ret; 
        
               return ret; 
        
             } 
        
           }

We only return here if and only if what we read (ret) is less than amount of bytes available (readlen). So, when we actually read everything available and are still paused, we continue on to the next part, which resets everything:

node/src/node_http2.cc

Lines 765 to 768 in f46ca0f

    
           // We are done processing the current input chunk. 
        
           DecrementCurrentSessionMemory(stream_buf_.len); 
        
           stream_buf_offset_ = 0; 
        
           stream_buf_ab_.Reset();

We pause but never resume. When we do resume, because a NEW frame comes in, then in that sequence we get both the nghttp2_on_frame_recv_callback
of the frame we never finished and continue on to reading the next frame. This is what happens when a PING is received (9bytes header + 8 bytes payload) 5 seconds later:

Http2Session server (100) receiving 17 bytes, offset 0
Http2Session server (100) receiving 17 bytes [wants data? 1]
Http2Session server (100) complete frame received: type: 0   <---- Previous DATA frame
Http2Session server (100) handling data frame for stream 1   <---- Emits EOF
Http2Session server (100) complete frame received: type: 6   <---- PING frame

So despite the comment saying we are done with the chunk, we actually aren't. There's still the nghttp2_on_frame_recv_callback missing. Since we did pause to write, and perform the write, it calls OnStreamAfterWrite and doesn't read the data because stream_buf_offset_ has been reset.

node/src/node_http2.cc

Lines 1457 to 1459 in f46ca0f

    
           if (stream_buf_offset_ > 0) { 
        
             ConsumeHTTP2Data(); 
        
           }

So one possible fix is to always return in ConsumeHTTP2Data is the stream is paused, even if all data has been consumed, since the next call to nghttp2_session_mem_recv will unpause it, even if the length is 0.

Or, check is_receive_paused() instead of (or in addition to) stream_buf_offset_ > 0 inside OnStreamAfterWrite. I'll work on testing both solutions.

addaleax · 2020-06-14T23:57:01Z

src/node_http2.cc

@@ -755,7 +755,7 @@ ssize_t Http2Session::ConsumeHTTP2Data() {
    CHECK_GT(ret, 0);
    CHECK_LE(static_cast<size_t>(ret), read_len);

-    if (static_cast<size_t>(ret) < read_len) {
+    if (static_cast<size_t>(ret) <= read_len) {


Hm – the CHECK_LE above this verifies that this is always the case, right?

(Also, thanks for digging into this so deeply!)

I spotted that too, but I wasn't sure. It's very possible this all comes from a single missing character!

In reality, the whole conditional of if (static_cast<size_t>(ret) < read_len) { is suspect. I don't think we need it, but I leaned on <= instead because it replicates the CHECK_LE line.

Hm … trying to think this through: If reading is paused but we still consumed the entire buffer, doesn’t that mean that we should clear the Buffer in the code below (i.e. stream_buf_offset_ = 0; etc)?

We don't need the buffer, no. But we can't reset stream_buf_offset_ because we need to recall ConsumeHTTP2Data() later:

https://github.com/nodejs/node/blob/f46ca0fd29361215ac8a26cd6647dc45221eb9d7/src/node_http2.cc#L1457-1459

I was thinking (stream_buf_offset_ > 0 || is_receive_paused()), but then it'll try to run ConsumeHTTP2Data() every time you write something, even if the readable side is completed.

@clshortfuse So, just to make sure I understand this correctly: We should also call nghttp2_session_mem_recv() even if no new data is available from the socket, and the previous nghttp2_session_mem_recv() call reported all data as read, if we entered pause state during that previous call?

Maybe we just shouldn’t pause in the first place if NGHTTP2_FLAG_END_STREAM is set?

@addaleax Yes. I tried to keep the comment to the point, since I'm known for blabbing 🙃, but the nghttp2 documentation states:

If the application uses nghttp2_session_mem_recv(), it can return NGHTTP2_ERR_PAUSE to make nghttp2_session_mem_recv() return without processing further input bytes. The memory by pointed by the data is retained until nghttp2_session_mem_recv() or nghttp2_session_recv() is called. The application must retain the input bytes which was used to produce the data parameter, because it may refer to the memory region included in the input bytes.

https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback

Maybe we just shouldn’t pause in the first place if NGHTTP2_FLAG_END_STREAM is set?

Sorry, I missed this. That is entirely possible, but it would be less efficient memory-wise. The sooner we pause to send out an output chunk, the sooner it's released from RAM. Also, we have no way of knowing how many times the current data frame (though it has an END_STREAM flag) will trigger a read callback. Frames can be upto 16MiB in size. So, hypothetically, if nghttp2 is sending us things in 1KB chunks, it could take 16,384 iterations before we send out whatever data we want. That could be any outbound frame type, including PING responses.

jeffmcmahan · 2020-06-15T16:37:09Z

First, thanks to everyone who is working to make all this stuff great for workaday Nodejs users like me. It looks like all that we're waiting on is the cpp linter issue. Is there any guess as to how long it might take to see this in a release? If I could help, I would! Thanks again.

clshortfuse · 2020-06-16T13:32:58Z

@jeffmcmahan Thanks for the encouragement. While it may look like it's just linters that's missing, that's just the CI (continuous integration). There's still some actual testing being needed. Some of this may be have to be manually tested due to this issue: #33891

I can't speak to how NodeJS determines their release schedule, but, personally, I'm targeting resolving things this week. I'll be posting a comment with a workaround in the related issue, so you're not waiting on this exact PR to be merged or the eventually release.

jeffmcmahan · 2020-06-16T14:09:27Z

@clshortfuse - Thanks so much.

clshortfuse · 2020-06-16T14:13:35Z

I can confirm this fixes the issue with Chrome, curl, and Safari. I added a receive paused debug line so this can be seen in the output log:

Http2Session server (134) sending pending data
Http2Session server (134) receiving 14 bytes, offset 0
Http2Session server (134) receiving 14 bytes [wants data? 1]
Http2Session server (134) buffering data chunk for stream 1, size: 5, flags: 1
Http2Session server (134) receive paused
Http2Session server (134) write finished with status 0
Http2Session server (134) receiving 0 bytes [wants data? 1]
Http2Session server (134) complete frame received: type: 0
Http2Session server (134) handling data frame for stream 1
Http2Session server (134) sending pending data
----BEGIN 'readable'----
  ----BEGIN CHUNK-----
   5 <Buffer 68 65 6c 6c 6f> hello
  ----END CHUNK-----
----END 'readable'----
!!!!!END!!!!!
HttpStream 1 (141) [Http2Session server (134)] queuing 1 buffers to send
Http2Session server (134) scheduling write
Completed stream 1 for /form in 4.71ms on gghmxo1e71m

We actually just removed an extra readable event from the Javascript side since the EOF is now tied with it. So this can actually be considered a performance boost. Neat.

Still working on devising a test, if at all possible.

clshortfuse · 2020-06-16T15:01:24Z

I can't build a test because we're blocked by #33891

I'll leave the in-depth details there, but essentially, this the associated bug only occurs on a final DATA frame with a payload. Our client never sends a final DATA frame with a payload. It will only send a blank one. Once that is resolved, then we can build a test for this. Though... once the client does start sending non-blank final DATA frames, then it'll have a compatibility issue with NodeJS HTTP2 servers that don't have this PR's fix.

clshortfuse · 2020-06-17T22:50:39Z

I couldn't make both fixes into separate PRs. The client and server portions have to happen in the same commit. Now I can write some new tests.

Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: nodejs#31309 Fixes: nodejs#33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback

clshortfuse · 2020-08-18T23:39:33Z

I'm a bit new to backporting, but I'll take a shot. I should learn it at some point. So, this PR is for master, and we need a new PR for v14.x branch? Or is it the v14.x-staging?

MylesBorins · 2020-08-19T00:36:44Z

It would be a PR against the v14.x-staging branch

If you branch off v14.x-staging you can land my backport via

curl -L https://github.com/MylesBorins/node/commit/5ab93d517c54bb3e8fe8951eb5d2abb7834a4654.patch | git am

Alternatively you can git cherry-pick 0e30c5b and work throutthe conflicts yourself

clshortfuse · 2020-08-20T14:21:54Z

v14.x and v12.x backport PRs are in.

v10.x backport might need to be degraded to just "support non-empty DATA frame with END_STREAM flag" instead of "use and support". It's a bit more complicated to make it pack the last frame on send because of how old the codebase is. In reality, v10.x is in maintenance anyway. Supporting non-empty DATA frames is a bugfix. Using them is added functionality which goes outside the scope of LTS maintenance.

Edit: v10.x PR is in.

Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. Fixes: nodejs#31309 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: nodejs#33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: #31309 Fixes: #33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: #33875 Backport-PR-URL: #34838 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

niftylettuce · 2020-08-23T07:42:30Z

This is also a related HTTP/2 bug, that would be great to have backported to v12 #30894.

niftylettuce · 2020-09-10T17:41:28Z

It looks like this was released in v14.9.0 already per https://nodejs.org/en/blog/release/v14.9.0/. Any updates on the backports being merged and released before September 15 security updates @mhdawson ? cc @MylesBorins @addaleax

Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. Fixes: #31309 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: #33875 Backport-PR-URL: #34857 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: nodejs#31309 Fixes: nodejs#33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback PR-URL: nodejs#33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

Adds support for reading from a stream where the final frame is a non-empty DATA frame with the END_STREAM flag set, instead of hanging waiting for another frame. When writing to a stream, uses a END_STREAM flag on final DATA frame instead of adding an empty DATA frame. BREAKING: http2 client now expects servers to properly support END_STREAM flag Fixes: #31309 Fixes: #33891 Refs: https://nghttp2.org/documentation/types.html#c.nghttp2_on_data_chunk_recv_callback Backport-PR-URL: #34845 PR-URL: #33875 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: James M Snell <jasnell@gmail.com>

nodejs-github-bot added c++ Issues and PRs that require attention from people who are familiar with C++. http2 Issues or PRs related to the http2 subsystem. labels Jun 14, 2020

addaleax approved these changes Jun 14, 2020

View reviewed changes

jasnell approved these changes Jun 14, 2020

View reviewed changes

clshortfuse marked this pull request as draft June 14, 2020 18:30

clshortfuse requested review from jasnell and addaleax June 14, 2020 23:50

addaleax reviewed Jun 14, 2020

View reviewed changes

clshortfuse changed the title ~~http2: emit EOF on data chunk with END_STREAM flag~~ http2: resume nghttp2 data streams for missing frame callback Jun 15, 2020

clshortfuse marked this pull request as ready for review June 16, 2020 14:57

clshortfuse force-pushed the patch-1 branch from b95e692 to 864ff2e Compare June 17, 2020 22:48

clshortfuse marked this pull request as draft June 17, 2020 22:51

clshortfuse changed the title ~~http2: resume nghttp2 data streams for missing frame callback~~ http2: use and support non-empty DATA frame with END_STREAM flag Jun 18, 2020

clshortfuse added 5 commits June 18, 2020 11:33

remove whitespace

1e35afd

Update node_http2.cc

30b1c06

Update node_http2.cc

6f7c361

Update node_http2.cc

cbddeb6

clshortfuse mentioned this pull request Aug 19, 2020

[v14.x] http2: use and support non-empty DATA frame with END_STREAM flag #34838

Closed

4 tasks

danielleadams mentioned this pull request Aug 21, 2020

V14.9.0 proposal #34852

Merged

This was referenced Aug 22, 2020

http2 support koajs/koa#1193

Closed

How to get the "Date" set on a response header for HTTP2? #30894

Closed

rahbari mentioned this pull request Oct 6, 2020

node_http2.cc fatal error #33156

Closed

richardlau added backported-to-v10.x and removed lts-watch-v10.x labels Oct 7, 2020

richardlau mentioned this pull request Oct 7, 2020

v10.23.0 proposal #35544

Merged

3 tasks

MylesBorins mentioned this pull request Nov 3, 2020

v12.20.0 proposal #35950

Merged

targos added backported-to-v14.x and removed author ready PRs that have at least one approval, no pending requests for changes, and a CI started. backport-requested-v14.x labels Apr 25, 2021

szmarczak mentioned this pull request Jul 11, 2021

The HTTP2 streams sometimes don't emit the end event #32978

Closed

nwtgck mentioned this pull request Jul 14, 2021

Request to HTTP/2 server is not handled on("end") or on("close"), and behave differently from HTTP/1 #33537

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

http2: use and support non-empty DATA frame with END_STREAM flag #33875

http2: use and support non-empty DATA frame with END_STREAM flag #33875

clshortfuse commented Jun 14, 2020 •

edited

Loading

addaleax left a comment

clshortfuse commented Jun 14, 2020

clshortfuse commented Jun 14, 2020

clshortfuse commented Jun 14, 2020 •

edited

Loading

addaleax commented Jun 14, 2020

clshortfuse commented Jun 14, 2020 •

edited

Loading

clshortfuse commented Jun 14, 2020 •

edited

Loading

addaleax Jun 14, 2020

clshortfuse Jun 15, 2020

clshortfuse Jun 15, 2020

addaleax Jun 15, 2020

clshortfuse Jun 15, 2020

addaleax Jun 15, 2020

addaleax Jun 15, 2020

clshortfuse Jun 15, 2020 •

edited

Loading

clshortfuse Jun 16, 2020 •

edited

Loading

jeffmcmahan commented Jun 15, 2020

clshortfuse commented Jun 16, 2020

jeffmcmahan commented Jun 16, 2020

clshortfuse commented Jun 16, 2020 •

edited

Loading

clshortfuse commented Jun 16, 2020

clshortfuse commented Jun 17, 2020

clshortfuse commented Aug 18, 2020

MylesBorins commented Aug 19, 2020

clshortfuse commented Aug 20, 2020 •

edited

Loading

niftylettuce commented Aug 23, 2020

niftylettuce commented Sep 10, 2020

http2: use and support non-empty DATA frame with END_STREAM flag #33875

http2: use and support non-empty DATA frame with END_STREAM flag #33875

Conversation

clshortfuse commented Jun 14, 2020 • edited Loading

Checklist

addaleax left a comment

Choose a reason for hiding this comment

clshortfuse commented Jun 14, 2020

clshortfuse commented Jun 14, 2020

clshortfuse commented Jun 14, 2020 • edited Loading

addaleax commented Jun 14, 2020

clshortfuse commented Jun 14, 2020 • edited Loading

clshortfuse commented Jun 14, 2020 • edited Loading

addaleax Jun 14, 2020

Choose a reason for hiding this comment

clshortfuse Jun 15, 2020

Choose a reason for hiding this comment

clshortfuse Jun 15, 2020

Choose a reason for hiding this comment

addaleax Jun 15, 2020

Choose a reason for hiding this comment

clshortfuse Jun 15, 2020

Choose a reason for hiding this comment

addaleax Jun 15, 2020

Choose a reason for hiding this comment

addaleax Jun 15, 2020

Choose a reason for hiding this comment

clshortfuse Jun 15, 2020 • edited Loading

Choose a reason for hiding this comment

clshortfuse Jun 16, 2020 • edited Loading

Choose a reason for hiding this comment

jeffmcmahan commented Jun 15, 2020

clshortfuse commented Jun 16, 2020

jeffmcmahan commented Jun 16, 2020

clshortfuse commented Jun 16, 2020 • edited Loading

clshortfuse commented Jun 16, 2020

clshortfuse commented Jun 17, 2020

clshortfuse commented Aug 18, 2020

MylesBorins commented Aug 19, 2020

clshortfuse commented Aug 20, 2020 • edited Loading

niftylettuce commented Aug 23, 2020

niftylettuce commented Sep 10, 2020

clshortfuse commented Jun 14, 2020 •

edited

Loading

clshortfuse commented Jun 14, 2020 •

edited

Loading

clshortfuse commented Jun 14, 2020 •

edited

Loading

clshortfuse commented Jun 14, 2020 •

edited

Loading

clshortfuse Jun 15, 2020 •

edited

Loading

clshortfuse Jun 16, 2020 •

edited

Loading

clshortfuse commented Jun 16, 2020 •

edited

Loading

clshortfuse commented Aug 20, 2020 •

edited

Loading