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

[clshortfuse]

fixes #31309
fixes #33891

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]

@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]

@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]

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]

@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]

@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]

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]

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

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

[clshortfuse]

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

[clshortfuse]

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.

[addaleax]

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)?

[clshortfuse]

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.

[addaleax]

@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?

[addaleax]

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

[clshortfuse]

@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

[clshortfuse]

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]

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]

@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]

@clshortfuse - Thanks so much.

[clshortfuse]

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]

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]

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.

[clshortfuse]

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]

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]

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.

[niftylettuce]

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

[niftylettuce]

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