NGHTTP2_ENHANCE_YOUR_CALM when starting with version 10.16.3 #29223

jellelute · 2019-08-20T08:55:10Z

Version:
Platform:
Subsystem:

Version: 10.16.3
Platform: 4.15.0-1044-aws #46-Ubuntu SMP Thu Jul 4 13:38:28 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
Subsystem: http2

I'm reusing a session for performance reasons and opening 10 new requests to a server per second. On node 10.16.2 it runs forever with no problems. On 10.16.3 it starts throwing "Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_ENHANCE_YOUR_CALM" after a minute or two +- 1000 requests.

Is this a newly introduced bug or how to prevent this?

addaleax · 2019-08-20T11:52:58Z

Can you share any more information? Is the server the program running Node.js, is the client, or are both? What is the value of the maxSessionMemory option on either side (if it is set)? Does running node as node --security-reverts=CVE-2019-9514 help?

(See also #29122 (comment) for some background.)

jasnell · 2019-08-20T14:17:35Z

This is most likely related to the new denial of service attack mitigations. The revert workaround @addaleax suggests should make it work but this is something we're going to need to revisit.

jellelute · 2019-08-29T08:50:31Z

@addaleax I'm not aware of the server site implementation. You can use this url to reproduce:
https://api.binance.com/api/v1/depth?symbol=BTCUSDT. maxSessionMemory was not set explicitly. Running node with --security-reverts=CVE-2019-9514 does not solve the issue.
Probably another commit did cause this issue.

mikelehen · 2019-10-01T01:50:07Z

We are experiencing a similar issue in the Google Cloud Firestore SDK. We have 10 or so customers reporting their production apps hitting this error where our http/2 stream is closed with NGHTTP2_ENHANCE_YOUR_CALM.

I can reproduce the issue with node v10.16.3 but not v10.16.2 so it seems to be a regression. Running node with --security-reverts=CVE-2019-9514 does not help.

I've created a repro project here: https://github.com/mikelehen/node-http2-repro

Unfortunately it is not a minimal repro, but it is what I was able to piece together based on our customer reports. Is it enough to debug the issue and isolate a root cause? We would very much appreciate a workaround and/or a fix to node so that we can unblock our customers. Thank you!

MylesBorins · 2019-10-02T20:57:15Z

We managed to get a reproducible version of the bug we are experiencing. I can confirm that including the flags --security-reverts=CVE-2019-9514 --security-reverts=CVE-2019-9512 --security-reverts=CVE-2019-9516 --security-reverts=CVE-2019-9518 does not fix the issue.

I was able to bisect and identify this commit as the one causing the failure... @addaleax any thoughts?

/cc @nodejs/http2

jasnell · 2019-10-02T21:06:35Z

Couple of quick tests... can you try setting the maxSessionMemory option significantly higher and seeing if the problem persists? There are a few other knobs there that can be turned also but let's try that one first. The default value for maxSessionMemory is 10, indicating a max of ten megabytes per session, which could be eaten away quickly with a large number of streams.

addaleax · 2019-10-02T21:09:27Z

I was able to bisect and identify this commit as the one causing the failure... @addaleax any thoughts?

@MylesBorins Which commit?

mikelehen · 2019-10-02T21:23:29Z

The commit @MylesBorins meant to link is 164ac5b . 😄

addaleax · 2019-10-02T21:25:42Z

Okay, that’s interesting – I’ll take a look. It still would be good to know if turning the maxSessionMemory knob makes a difference here, as @jasnell suggested.

murgatroid99 · 2019-10-02T21:44:05Z

Based on that commit message, specifically "If we are waiting for the ability to send more output, we should not process more input", I think the overall goal of that commit is a bad idea. With that logic implemented on both sides of a connection, if one side ever pushes back on flow control for any reason, the other side will stop reading and start pushing back the other way, which will result in a deadlock where neither side will clear out their read buffer because they're waiting for the other side to do so.

And if just the client implements that logic, it's easy to imagine a scenario where the client doesn't read enough, resulting in the server being unable to write while still receiving more data. It wouldn't surprise me if some servers send ENHANCE_YOUR_CALM when that happens.

mikelehen · 2019-10-02T21:51:14Z

@addaleax @jasnell It looks like increasing maxSessionMemory does solve the problem. If I set it to 100, my repro works. If I set it to 1 then it fails much faster.

A couple notes:

Our repro is using http2.connect() not http2.createServer().
FWIW the general usage pattern of our repro is basically: send a request to the backend, wait for the response, send the next request to the backend, wait for the response, etc. It ends up failing after 300+ request/response pairs. Each request / response pair is roughly the same size (requests are < 1k, responses are maybe 1MB). Running on my machine / network, we end up doing around 2-3 requests / second.

mikelehen · 2019-10-02T22:24:06Z

FYI- If you need to run my repro in https://github.com/mikelehen/node-http2-repro you'll need access to my project which I'll have to grant you out-of-band. But hopefully the info above may be enough to resolve the issue? Thanks!

jasnell · 2019-10-02T22:37:39Z

@murgatroid99 ... the scenario you describe is entirely possible and worth exploring to see how much of an issue that is in our implementation. I'm thinking, however, that for this specific problem, it's more of a memory management issue. Specifically: we need to get better at it. The current maxSessionMemory limit was really just a finger in the air guesstimate and it's looking like we either need to (a) increase it or (b) find other ways of reducing the memory load per QuicSession.

mikelehen · 2019-10-02T23:23:03Z

@jasnell Any guesses why 164ac5b would have exacerbated the memory management issue?

FWIW the more I increase maxSessionMemory, the longer my repro runs before failing, even though we are doing fixed-size requests and responses and only have 1 outstanding at a time. So I would expect the necessary sessionMemory to be pretty much flat. So I'm wondering if 164ac5b has introduced a mismatch in IncrementCurrentSessionMemory() / DecrementCurrentSessionMemory() calls.

Like maybe 164ac5b#diff-a2de252da810db89f574ecafa0f8e95aR1901 should instead be:

DecrementCurrentSessionMemory(stream_buf_.len - stream_buf_offset_);

(this is a wild guess. I don't really understand the code; I'm just trying to apply some pattern matching...)

jasnell · 2019-10-02T23:35:01Z

Definitely sounds like a memory accounting issue then... or a straight up memory leak. That gives a good place to start the investigation. First place to check would be to rule out a memory leak, and if that looks good, then we can look at the accounting.

schmidt-sebastian · 2019-10-08T23:46:17Z

@jasnell Thanks for all your investigations so far.

I work with @mikelehen on Firestore and was wondering if you could let us know if you had an estimated timeline for a fix? We have a couple of users that are blocked on this. Thank you so much!

jasnell · 2019-10-09T00:03:41Z

With my current workload, it won't be until later this week at the earliest, but definitely haven't forgotten!

mikelehen · 2019-10-09T01:59:00Z

In case it helps, I actually tried out my guess above (#29223 (comment)) last week and with that tweak, the error seems to go away. That said, I don't know how to verify that all the accounting is actually coming out correct. It's possible I just messed up the accounting in a different way.

schmidt-sebastian · 2019-10-09T02:59:15Z

Thank you for the update @jasnell! Let us know if you need help verifying a fix.

jellelute · 2019-10-23T20:29:50Z

Hi, is there any news about this issue? Also could the fix be ported to NodeJS 12, as this version became the LTS version recently. Thanks for your efforts!

mikelehen · 2019-11-08T00:44:08Z

Any update here? Would it help if I sent a PR based on my guess in #29223 (comment) ? I don't know the code well enough to know if it's correct or how to definitively validate / test it, though. :-)

The ability to pause input processing was added in 8a4a193 but introduced a session memory accounting mismatch leading to potential NGHTTP2_ENHANCE_YOUR_CALM errors. After pausing (https://github.com/nodejs/node/blob/f36331c1bfa4c4c202346b05dc3bd672f653e4df/src/node_http2.cc#L871), the early return on line 873 skips the DecrementCurrentSessionMemory(stream_buf_.len) call below (line 878). When we later finished processing the input chunk (https://github.com/nodejs/node/blob/f36331c1bfa4c4c202346b05dc3bd672f653e4df/src/node_http2.cc#L1858), we were calling DecrementCurrentSessionMemory(stream_buf_offset_) [line 1875] which was a no-op since we just set stream_buf_offset_ to 0 [line 1873]. The correct amount to decrement by is still stream_buf_.len, since that's the amount we skipped previously (line 878). Fixes: nodejs#29223 Refs: nodejs@164ac5b

mikelehen · 2019-11-27T17:25:16Z

I'v opened a PR (#30684) that addresses the issue. 🤞 we can get it merged? 😄

The ability to pause input processing was added in 8a4a193 but introduced a session memory accounting mismatch leading to potential NGHTTP2_ENHANCE_YOUR_CALM errors. After pausing (https://github.com/nodejs/node/blob/f36331c1bfa4c4c202346b05dc3bd672f653e4df/src/node_http2.cc#L871), the early return on line 873 skips the DecrementCurrentSessionMemory(stream_buf_.len) call below (line 878). When we later finished processing the input chunk (https://github.com/nodejs/node/blob/f36331c1bfa4c4c202346b05dc3bd672f653e4df/src/node_http2.cc#L1858), we were calling DecrementCurrentSessionMemory(stream_buf_offset_) [line 1875] which was a no-op since we just set stream_buf_offset_ to 0 [line 1873]. The correct amount to decrement by is still stream_buf_.len, since that's the amount we skipped previously (line 878). Fixes: #29223 Refs: 164ac5b PR-URL: #30684 Reviewed-By: Anna Henningsen <[email protected]> Reviewed-By: Denys Otrishko <[email protected]> Reviewed-By: James M Snell <[email protected]> Reviewed-By: David Carlier <[email protected]>

addaleax added the http2 Issues or PRs related to the http2 subsystem. label Aug 20, 2019

schmidt-sebastian mentioned this issue Oct 1, 2019

Bandwidth Exhausted while doing Firestore calls through NodeJS Server deployed on Google App Engine. googleapis/nodejs-firestore#765

Closed

bnoordhuis mentioned this issue Oct 9, 2019

NodeJs 12.11.1 NGHTTP2_ENHANCE_YOUR_CALM #29907

Closed

stephenplusplus mentioned this issue Nov 7, 2019

Error: 8 RESOURCE_EXHAUSTED: Bandwidth exhausted googleapis/nodejs-datastore#525

Closed

mikelehen mentioned this issue Nov 27, 2019

http2: fix session memory accounting after pausing #30684

Closed

3 tasks

lundibundi mentioned this issue Nov 27, 2019

Nodejs v13.0.1 HTTP2 NGHTTP2_ENHANCE_YOUR_CALM & NGHTTP2_INTERNAL_ERROR #30193

Closed

addaleax closed this as completed in 18a1796 Nov 30, 2019

Trott mentioned this issue Jul 7, 2020

investigate flaky test-http2-large-writes-session-memory-leak on Windows CI #31089

Closed

davidmytton mentioned this issue Aug 24, 2024

HTTP2 connection not being reset when error received arcjet/arcjet-js#1401

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

NGHTTP2_ENHANCE_YOUR_CALM when starting with version 10.16.3 #29223

NGHTTP2_ENHANCE_YOUR_CALM when starting with version 10.16.3 #29223

jellelute commented Aug 20, 2019

addaleax commented Aug 20, 2019

jasnell commented Aug 20, 2019

jellelute commented Aug 29, 2019 •

edited

Loading

mikelehen commented Oct 1, 2019

MylesBorins commented Oct 2, 2019

jasnell commented Oct 2, 2019

addaleax commented Oct 2, 2019

mikelehen commented Oct 2, 2019

addaleax commented Oct 2, 2019

murgatroid99 commented Oct 2, 2019

mikelehen commented Oct 2, 2019

mikelehen commented Oct 2, 2019

jasnell commented Oct 2, 2019

mikelehen commented Oct 2, 2019 •

edited

Loading

jasnell commented Oct 2, 2019

schmidt-sebastian commented Oct 8, 2019

jasnell commented Oct 9, 2019

mikelehen commented Oct 9, 2019

schmidt-sebastian commented Oct 9, 2019

jellelute commented Oct 23, 2019

mikelehen commented Nov 8, 2019

mikelehen commented Nov 27, 2019

NGHTTP2_ENHANCE_YOUR_CALM when starting with version 10.16.3 #29223

NGHTTP2_ENHANCE_YOUR_CALM when starting with version 10.16.3 #29223

Comments

jellelute commented Aug 20, 2019

addaleax commented Aug 20, 2019

jasnell commented Aug 20, 2019

jellelute commented Aug 29, 2019 • edited Loading

mikelehen commented Oct 1, 2019

MylesBorins commented Oct 2, 2019

jasnell commented Oct 2, 2019

addaleax commented Oct 2, 2019

mikelehen commented Oct 2, 2019

addaleax commented Oct 2, 2019

murgatroid99 commented Oct 2, 2019

mikelehen commented Oct 2, 2019

mikelehen commented Oct 2, 2019

jasnell commented Oct 2, 2019

mikelehen commented Oct 2, 2019 • edited Loading

jasnell commented Oct 2, 2019

schmidt-sebastian commented Oct 8, 2019

jasnell commented Oct 9, 2019

mikelehen commented Oct 9, 2019

schmidt-sebastian commented Oct 9, 2019

jellelute commented Oct 23, 2019

mikelehen commented Nov 8, 2019

mikelehen commented Nov 27, 2019

jellelute commented Aug 29, 2019 •

edited

Loading

mikelehen commented Oct 2, 2019 •

edited

Loading