http2: ServerHttp2Session#close does not allow "any existing streams to complete on their own"

[murgatroid99]

Version

v16.7.0 (and later)

Platform

Linux mlumish.svl.corp.google.com 5.15.15-1rodete2-amd64 #1 SMP Debian 5.15.15-1rodete2 (2022-02-23) x86_64 GNU/Linux

Subsystem

http2

What steps will reproduce the bug?

const http2 = require('http2');

const {
  HTTP2_HEADER_PATH,
  HTTP2_HEADER_STATUS,
  HTTP2_HEADER_TE,
  HTTP2_HEADER_METHOD,
  HTTP2_HEADER_AUTHORITY
} = http2.constants;

const server = http2.createServer();
server.on('stream', (stream, headers) => {
  setTimeout(() => {
    stream.respond({[HTTP2_HEADER_STATUS]: 200});
    stream.end('some data');
  }, 2000);
});
server.on('session', session => {
  setTimeout(() => {
    server.close();
    session.close();
  }, 1000);
});

server.listen(0, () => {
  const port = server.address().port;
  const client = http2.connect(`http://localhost:${port}`);

  const startTime = new Date();
  const req = client.request({
    [HTTP2_HEADER_PATH]: '/'
  });
  req.end();
  req.on('response', (headers) => {
    console.log(headers[HTTP2_HEADER_STATUS]);
  });
  req.on('data', (chunk) => {console.log('received data')});
  req.on('end', () => {console.log('received end')});
  req.on('close', () => {
    const endTime = new Date();
    console.log(`Stream closed with code ${req.rstCode} after ${endTime - startTime}ms`);
  });
});

How often does it reproduce? Is there a required condition?

100%

What is the expected behavior?

The correct output, as seen on Node 16.6 and earlier:

200
received data
received end
Stream closed with code 0 after 2018ms

What do you see instead?

received end
Stream closed with code 8 after 2012ms

Additional information

As noted above, this works as expected in Node versions 16.6 and earlier.

This only happens if the stream.respond call is delayed in the stream handler. If that is not delayed but stream.end is delayed, this failure does not occur.

Increasing the delay before responding in the stream event handler increases the time before the close event is logged, even though the result of the call is fully determined once the server session is closed, making this bug worse for long-running workloads.

[RafaelGSS]

It seems "fixed" in v17.x.x. However, I do feel that the stream should be closed without receiving any data (as v16.7.0+ does), once you are closing the session before respond. I'm missing something?

[murgatroid99]

The documentation for Http2Session#close says

Gracefully closes the Http2Session, allowing any existing streams to complete on their own and preventing new Http2Stream instances from being created.

I don't understand how that could possibly be compatible with forcibly ending an existing stream when close is called.

[RafaelGSS]

I did a git bisect and this was introduced in a libuv update (v16.7.0): #39525, but, that's weird because the libuv version is the same as used in v17.0.0, which works fine. @lpinca The libuv deps upgrade was also merged in v17.x right?

[artificial-aidan]

I will double check, but I believe I was also seeing this issue on 17.x.x. When I did the original diagnosis in another library that led to @murgatroid99 finding the issue with node I was developing locally on OSX with node 17.

[RafaelGSS]

@artificial-aidan Are you getting the unexpected behavior in v17? I'm on linux, and it's working fine.

[artificial-aidan]

@artificial-aidan Are you getting the unexpected behavior in v17? I'm on linux, and it's working fine.

I will check later today, not at a computer right now. But that's what I recall.

[artificial-aidan]

So this is more confusing. @murgatroid99 using the example you provided I don't see the issue on v17.8.0 on OSX, but I'm 99% sure I was using that same version when I ran into issues with grpc-js. I didn't have nodenv installed until you mentioned it working on an older version, and I had not upgraded node. So I'm not sure how I could have had another version.

Edit: I just confirmed this is the case. On v17.8.0 the above HTTP example works fine, but the linked issue in the grpc-js library still occurs

[lpinca]

@lpinca The libuv deps upgrade was also merged in v17.x right?

Yes.

$ ./node   
Welcome to Node.js v17.0.0.
Type ".help" for more information.
> process.versions
{
  node: '17.0.0',
  v8: '9.5.172.21-node.12',
  uv: '1.42.0',
  zlib: '1.2.11',
  brotli: '1.0.9',
  ares: '1.17.2',
  modules: '102',
  nghttp2: '1.45.1',
  napi: '8',
  llhttp: '6.0.4',
  openssl: '3.0.0+quic',
  cldr: '39.0',
  icu: '69.1',
  tz: '2021a',
  unicode: '13.0',
  ngtcp2: '0.1.0-DEV',
  nghttp3: '0.1.0-DEV'
}
>

[murgatroid99]

This is not 100% fixed. The following code sample demonstrates a remaining behavior difference between Node 16.6 and 17.9 that breaks grpc-js:

const http2 = require('http2');

const {
  HTTP2_HEADER_PATH,
  HTTP2_HEADER_STATUS,
  HTTP2_HEADER_TE,
  HTTP2_HEADER_METHOD,
  HTTP2_HEADER_AUTHORITY
} = http2.constants;

const server = http2.createServer();
server.on('stream', (stream, headers) => {
  stream.on('wantTrailers', () => {
    console.log('sending trailers');
    stream.sendTrailers({ xyz: 'abc' });
  });
  setTimeout(() => {
    stream.respond({[HTTP2_HEADER_STATUS]: 200}, {waitForTrailers: true});
    stream.write('some data');
    stream.end();
  }, 2000);
});
server.on('session', session => {
  setTimeout(() => {
    server.close(() => console.log('server close completed'));
    session.close(() => console.log('session close completed'));
  }, 1000);
});

server.listen(0, () => {
  const port = server.address().port;
  const client = http2.connect(`http://localhost:${port}`);
  client.socket.on('close', () => {
    console.log('Client socket closed');
  })

  const startTime = new Date();
  const req = client.request({
    [HTTP2_HEADER_PATH]: '/'
  });
  req.end();
  req.on('response', (headers) => {
    console.log(headers[HTTP2_HEADER_STATUS]);
  });
  req.on('data', (chunk) => {console.log('received data')});
  req.on('end', () => {console.log('received end')});
  req.on('trailers', trailers => {console.log('received trailers')});
  req.on('close', () => {
    const endTime = new Date();
    console.log(`Stream closed with code ${req.rstCode} after ${endTime - startTime}ms`);
  });
});

On Node 16.6.2, this outputs

sending trailers
200
received data
session close completed
server close completed
received trailers
received end
Stream closed with code 0 after 2014ms
Client socket closed

On Node 17.9.0, it outputs

sending trailers
200
received data
session close completed
server close completed
Client socket closed
received end
Stream closed with code 8 after 2016ms

Note the lack of the received trailers line in the second log. gRPC waits for trailers to consider a request complete.

[RafaelGSS]

@murgatroid99 Thanks for the update. I'll try to look at it pretty soon (traveling atm)

[RafaelGSS]

@murgatroid99 just tried to reproduce the issue and I'm always getting the received trailers

rafaelgss@rafaelgss:~/repos/os/node$ node -v
v17.9.0
rafaelgss@rafaelgss:~/repos/os/node$ node issue.js
sending trailers
200
received data
received trailers
received end
Stream closed with code 0 after 2020ms
session close completed
server close completed
Client socket closed

[murgatroid99]

I screwed something up with synchronizing changes I made to my test code and my comment. I also do not see the issue with the test code I put into that comment, but I do see the issue if I include [HTTP2_HEADER_METHOD]: 'POST' in the client request headers. So the corrected code is:

Test code

const http2 = require('http2');

const {
  HTTP2_HEADER_PATH,
  HTTP2_HEADER_STATUS,
  HTTP2_HEADER_TE,
  HTTP2_HEADER_METHOD,
  HTTP2_HEADER_AUTHORITY
} = http2.constants;

const server = http2.createServer();
server.on('stream', (stream, headers) => {
  stream.on('wantTrailers', () => {
    console.log('sending trailers');
    stream.sendTrailers({ xyz: 'abc' });
  });
  setTimeout(() => {
    stream.respond({[HTTP2_HEADER_STATUS]: 200}, {waitForTrailers: true});
    stream.write('some data');
    stream.end();
  }, 2000);
});
server.on('session', session => {
  setTimeout(() => {
    server.close(() => console.log('server close completed'));
    session.close(() => console.log('session close completed'));
  }, 1000);
});

server.listen(0, () => {
  const port = server.address().port;
  const client = http2.connect(`http://localhost:${port}`);
  client.socket.on('close', () => {
    console.log('Client socket closed');
  })

  const startTime = new Date();
  const req = client.request({
    [HTTP2_HEADER_PATH]: '/',
    [HTTP2_HEADER_METHOD]: 'POST'
  });
  req.end();
  req.on('response', (headers) => {
    console.log(headers[HTTP2_HEADER_STATUS]);
  });
  req.on('data', (chunk) => {console.log('received data')});
  req.on('end', () => {console.log('received end')});
  req.on('trailers', trailers => {console.log('received trailers')});
  req.on('close', () => {
    const endTime = new Date();
    console.log(`Stream closed with code ${req.rstCode} after ${endTime - startTime}ms`);
  });
});

[santigimeno]

I think #45153 may fix this issue

[murgatroid99]

This seems to have been re-broken in #46721. Can we reopen this issue?

[murgatroid99]

Ping on this again. It seems that there has not been any activity since it was re-broken.

[murgatroid99]

I have been debugging this, here is what causes this problem, as far as I can tell:

1. The server session closes
2. The server stream tries to send trailers, which eventually calls Http2Session::SendPendingData
3. This calls nghttp2_session_mem_send to serialize the outgoing frame data
4. After serializing the frame data, nghttp2 sees that the stream has finished reading and writing, and calls Http2Session::OnStreamClose
5. That in turn calls the JS function stream.onStreamClose.
6. That calls stream.destroy, which calls stream._destroy
7. That calls session[kMaybeDestroy]
8. Because the session is closed and the last open stream was just closed, that calls session.destroy
9. That calls closeSession
10. That calls Http2Session::Destroy
11. That calls Http2Session::Close
12. Before closing the session, that function tries to flush the remaining outgoing data by calling Http2Session::SendPendingData. However, Http2::SendPendingData is non-reentrant. The call fails, so the data is not actually flushed, but this call site does not check the return value, so it continues on destroying the session and closing the underlying socket.

One option I see to fix that is to handle the failure of Http2::SendPendingData in Http2Session::Close, but the comment there indicates that the purpose is to send a GOAWAY and that sending is best-effort, so ignoring the error code might be intentional. Alternatively, adding an asynchronous delay somewhere in that call stack should resolve the problem by allowing the original Http2Session::SendPendingData call to finish before closing the session.

Update: I have tried adding an async delay in various parts of this call stack, and it always causes a few other tests to fail. It is not yet clear if those failures are legitimate problems, or if those tests have unreasonably narrow expectations.

Update 2: I have been looking in to those test failures, here is what I have found so far:

• test-http2-client-jsstream-destroy.js fails on this assert, apparently because the final http2 session data flush can happen after the socket has finished closing. I think the JSStreamSocket class just needs to be able to handle receiving writes after close, and do nothing instead of erroring.
• test-http2-close-while-writing.js times out. I don't know exactly why this is happening, but it seems to be some kind of race related to the fact that data is still buffered to be written as connections are shutting down.
• A couple of other tests fail because of an unhandled error event. I think the client receives more data than it previously did because the server successfully flushes data that it otherwise discarded. So, the client should see that error, and the test should be changed to expect it.
• The rest of the tests fail because the client request object gets an unexpected end event when expecting an error. This seems to be related to how the client handles the new data at the end of the stream/session, but I haven't yet investigated what exactly is happening there.

Update 3: The timeout and unexpected end events appear to be caused by delaying the callback in addition to the call to session[kMaybeDestroy] when adding an asynchronous delay in stream.destroy, and there is no need to delay the callback.