HTTP/2 POST loop fails with ENHANCE_YOUR_CALM after 40701 iterations #23116

davedoesdev · 2018-09-27T06:28:35Z

Version: v10.10.0
Platform: Linux david-Latitude-E6440 4.15.0-34-generic logo ideas #37-Ubuntu SMP Mon Aug 27 15:21:48 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
Subsystem: http2

Here's a simple server app which reads HTTP/2 POST request bodies to their end and then responds:

const http2 = require('http2');
const fs = require('fs');
const path = require('path');
const { Writable } = require('stream');

const server = http2.createSecureServer({
    key: fs.readFileSync(path.join(__dirname, 'server.key')),
    cert: fs.readFileSync(path.join(__dirname, 'server.crt'))
});

server.on('session', function (session) {
    session.on('stream', function (stream, headers) {
        stream.on('end', function () {
            this.respond({
                ':status': 200,
                'Access-Control-Allow-Origin': 'http://localhost:8000'
            }, {
                endStream: true
            });
        });
        stream.pipe(new Writable({
            write: (chunk, encoding, cb) => cb()
        }));
    });
});

server.listen(7000, function () {
    console.log('READY.');
});

For this test, the cert and key are self-issued and my browser trusts them.

Here's a Web page which makes requests in series to the server:

<html>
<head>
<script>
async function test() {
  while (true) {
    response = await fetch('https://localhost:7000', { method: 'POST' });
    await response.arrayBuffer();
  }
}
</script>
</head>
<body onload='test()'>
</body>
</html>

I expect this to continue indefinitely.

However, what happens is I get the following error after 40701 iterations:

memtest.html:6 POST https://localhost:7000/ net::ERR_SPDY_PROTOCOL_ERROR

I did some debugging using Wireshark and found the error was ENHANCE_YOUR_CALM.

After adding some tracing to node_http2.cc, I found the error being produced here: https://github.com/nodejs/node/blob/v10.10.0/src/node_http2.cc#L863

I've tracked this down to current_nghttp2_memory_ continually growing.

The cause for this is nghttp2 allocation of 232 bytes for each stream (https://github.com/nodejs/node/blob/v10.10.0/deps/nghttp2/lib/nghttp2_session.c#L1029) is never being released.

This is because nghttp2 keeps closed streams around (up to the concurrent connection limit).

If I add the following line to Http2Options::Http2Options in src/node_http2.cc:

nghttp2_option_set_no_closed_streams(options_, 1);

then the test works as expected and doesn't fail at 40701 iterations.

The text was updated successfully, but these errors were encountered:

davedoesdev · 2018-09-27T06:39:07Z

The relevant code in nghttp2 is here: https://github.com/nodejs/node/blob/v10.10.0/deps/nghttp2/lib/nghttp2_session.c#L1211

if ((session->opt_flags & NGHTTP2_OPTMASK_NO_CLOSED_STREAMS) == 0 &&
      session->server && !is_my_stream_id &&
      nghttp2_stream_in_dep_tree(stream)) {
    /* On server side, retain stream at most MAX_CONCURRENT_STREAMS
       combined with the current active incoming streams to make
       dependency tree work better. */
    nghttp2_session_keep_closed_stream(session, stream);
  } else {
    rv = nghttp2_session_destroy_stream(session, stream);
    if (rv != 0) {
      return rv;
    }
  }

I think this is going to cause a failure for any Node.js HTTP/2 app which processes many requests in the same session, due to tracking and limiting current_nghttp2_memory_ in node_http2.cc.

lpinca · 2018-09-27T06:41:00Z

cc: @nodejs/http2

davedoesdev · 2018-09-27T06:51:58Z

Note in the conditional above, !is_my_stream_id is checking that the stream is an incoming request and nghttp2_stream_in_dep_tree(stream) is checking the stream is in the dependency tree.

I'm seeing both true in the logs. The requests are inserted as dependencies of the root, e.g.:

stream: dep_insert dep_stream(0x56129a772c78)=0, stream(0x56129a77ec58)=27

jasnell · 2018-09-27T08:31:39Z

This is specifically there to prevent denial of service attacks. It is possible to change the default maximum session memory limit using the maxSessionMemory option (https://nodejs.org/dist/latest-v10.x/docs/api/http2.html#http2_http2_createserver_options_onrequesthandler). Use of the no_closed_streams option is not ideal because it prevents nghttp2 from performing a number of security and state checks.

Try setting a significantly higher maxSessionMemory limit and giving it another go.

mcollina · 2018-09-27T08:36:53Z

To clarify, a single session would keep around 232 bytes for every stream that was closed?

Use of the no_closed_streams option is not ideal because it prevents nghttp2 from performing a number of security and state checks.

From the nghttp2 docs, it seems nghttp2_option_set_no_closed_streams is only doing

This option prevents the library from retaining closed streams to maintain the priority tree. If this option is set to nonzero, applications can discard closed stream completely to save memory.

what other checks it is doing?

jasnell · 2018-09-27T08:41:42Z

Ah, right, given that we're not really make use of priority, this likely can be switched off. Still, in this particular use case, I would still set a significantly higher maxSessionMemory.

davedoesdev · 2018-09-27T19:05:43Z

If I increase maxSessionMemory to 100Mb, the server starts failing requests after 400k of them on a session.

The Web page has no way of resetting its session with the server - the fetch API has no way to tell the browser to use a new connection when the failures start (unless I've missed something).

So this means long running sessions to Node over HTTP/2 don't work reliably.

jasnell · 2018-09-27T19:57:54Z

Will investigate further! :)

PR-URL: #23134 Fixes: #23116 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: James M Snell <[email protected]>

lpinca added the http2 Issues or PRs related to the http2 subsystem. label Sep 27, 2018

davedoesdev mentioned this issue Sep 27, 2018

Forget closed http2 streams #23134

Closed

3 tasks

danbev closed this as completed in e8121d5 Oct 3, 2018

targos pushed a commit that referenced this issue Oct 4, 2018

http2: set nghttp2_option_set_no_closed_streams

001881f

PR-URL: #23134 Fixes: #23116 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: James M Snell <[email protected]>

jasnell pushed a commit that referenced this issue Oct 17, 2018

http2: set nghttp2_option_set_no_closed_streams

bdf1871

PR-URL: #23134 Fixes: #23116 Reviewed-By: Matteo Collina <[email protected]> Reviewed-By: Luigi Pinca <[email protected]> Reviewed-By: James M Snell <[email protected]>

akukas mentioned this issue Apr 25, 2019

HTTP/2 requests eventually start throwing NGHTTP2_ENHANCE_YOUR_CALM errors #27416

Closed

davidwallacejackson mentioned this issue Dec 21, 2021

fix(dev): increase default session memory limit in HTTPS dev server to prevent disconnections on large projects. vitejs/vite#6207

Merged

8 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

HTTP/2 POST loop fails with ENHANCE_YOUR_CALM after 40701 iterations #23116

HTTP/2 POST loop fails with ENHANCE_YOUR_CALM after 40701 iterations #23116

davedoesdev commented Sep 27, 2018

davedoesdev commented Sep 27, 2018 •

edited

Loading

lpinca commented Sep 27, 2018

davedoesdev commented Sep 27, 2018

jasnell commented Sep 27, 2018

mcollina commented Sep 27, 2018 •

edited

Loading

jasnell commented Sep 27, 2018

davedoesdev commented Sep 27, 2018 •

edited

Loading

jasnell commented Sep 27, 2018

HTTP/2 POST loop fails with ENHANCE_YOUR_CALM after 40701 iterations #23116

HTTP/2 POST loop fails with ENHANCE_YOUR_CALM after 40701 iterations #23116

Comments

davedoesdev commented Sep 27, 2018

davedoesdev commented Sep 27, 2018 • edited Loading

lpinca commented Sep 27, 2018

davedoesdev commented Sep 27, 2018

jasnell commented Sep 27, 2018

mcollina commented Sep 27, 2018 • edited Loading

jasnell commented Sep 27, 2018

davedoesdev commented Sep 27, 2018 • edited Loading

jasnell commented Sep 27, 2018

davedoesdev commented Sep 27, 2018 •

edited

Loading

mcollina commented Sep 27, 2018 •

edited

Loading

davedoesdev commented Sep 27, 2018 •

edited

Loading