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

[Trott]

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/634/RUN_SUBSET=3,nodes=win2012r2-COMPILED_BY-vs2019-x86/console

test-rackspace-win2012r2_vs2019-x64-2

00:24:35 not ok 295 parallel/test-http2-large-writes-session-memory-leak
00:24:35   ---
00:24:35   duration_ms: 0.266
00:24:35   severity: fail
00:24:35   exitcode: 1
00:24:35   stack: |-
00:24:35     events.js:297
00:24:35           throw er; // Unhandled 'error' event
00:24:35           ^
00:24:35     
00:24:35     Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_ENHANCE_YOUR_CALM
00:24:35         at ClientHttp2Stream._destroy (internal/http2/core.js:2117:13)
00:24:35         at ClientHttp2Stream.destroy (internal/streams/destroy.js:39:8)
00:24:35         at ClientHttp2Stream.[kMaybeDestroy] (internal/http2/core.js:2133:12)
00:24:35         at Http2Stream.onStreamClose (internal/http2/core.js:500:26)
00:24:35     Emitted 'error' event on ClientHttp2Stream instance at:
00:24:35         at emitErrorNT (internal/streams/destroy.js:94:8)
00:24:35         at emitErrorCloseNT (internal/streams/destroy.js:66:3)
00:24:35         at processTicksAndRejections (internal/process/task_queues.js:84:21) {
00:24:35       code: 'ERR_HTTP2_STREAM_ERROR'
00:24:35     }
00:24:35   ...

@nodejs/http2 @nodejs/platform-windows

[richardlau]

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/1088/RUN_SUBSET=1,nodes=win2012r2-COMPILED_BY-vs2019-x86/console

test-rackspace-win2012r2_vs2017-x64-3

21:55:20 not ok 298 parallel/test-http2-large-writes-session-memory-leak
21:55:20   ---
21:55:20   duration_ms: 0.401
21:55:20   severity: fail
21:55:20   exitcode: 1
21:55:20   stack: |-
21:55:20     events.js:298
21:55:20           throw er; // Unhandled 'error' event
21:55:20           ^
21:55:20     
21:55:20     Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_ENHANCE_YOUR_CALM
21:55:20         at ClientHttp2Stream._destroy (internal/http2/core.js:2160:13)
21:55:20         at ClientHttp2Stream.destroy (internal/streams/destroy.js:41:8)
21:55:20         at Http2Stream.onStreamClose (internal/http2/core.js:506:12)
21:55:20     Emitted 'error' event on ClientHttp2Stream instance at:
21:55:20         at emitErrorNT (internal/streams/destroy.js:96:8)
21:55:20         at emitErrorCloseNT (internal/streams/destroy.js:68:3)
21:55:20         at processTicksAndRejections (internal/process/task_queues.js:84:21) {
21:55:20       code: 'ERR_HTTP2_STREAM_ERROR'
21:55:20     }
21:55:20   ...

[lundibundi]

Didn't fail on my local Windows vs2017 machine with -j 32 --repeat 1000, trying out CI
https://ci.nodejs.org/job/node-stress-single-test/38/

[lundibundi]

Well, stress CI is green, perhaps the machine should be under heavy load (from other tests) for this to actually fail. Anyway, this doesn't seem to fail often (at all anymore?) so closing this for now.

[bzoz]

Happened again two times:

• https://ci.nodejs.org/job/node-test-binary-windows-js-suites/4109/RUN_SUBSET=0,nodes=win2012r2-COMPILED_BY-vs2019-x86/console
• https://ci.nodejs.org/job/node-test-binary-windows-js-suites/4142/RUN_SUBSET=2,nodes=win2012r2-COMPILED_BY-vs2019-x86/console

the stress test is green though: https://ci.nodejs.org/job/node-stress-single-test/83/

[Trott]

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/4745/RUN_SUBSET=2,nodes=win2012r2-COMPILED_BY-vs2019-x86/console

test-rackspace-win2012r2_vs2017-x64-4

06:21:27 not ok 320 parallel/test-http2-large-writes-session-memory-leak
06:21:27   ---
06:21:27   duration_ms: 0.257
06:21:27   severity: fail
06:21:27   exitcode: 1
06:21:27   stack: |-
06:21:27     events.js:291
06:21:27           throw er; // Unhandled 'error' event
06:21:27           ^
06:21:27     
06:21:27     Error [ERR_HTTP2_STREAM_ERROR]: Stream closed with error code NGHTTP2_ENHANCE_YOUR_CALM
06:21:27         at new NodeError (internal/errors.js:254:15)
06:21:27         at ClientHttp2Stream._destroy (internal/http2/core.js:2151:13)
06:21:27         at _destroy (internal/streams/destroy.js:62:8)
06:21:27         at ClientHttp2Stream.destroy (internal/streams/destroy.js:55:5)
06:21:27         at Http2Stream.onStreamClose (internal/http2/core.js:515:12)
06:21:27     Emitted 'error' event on ClientHttp2Stream instance at:
06:21:27         at emitErrorNT (internal/streams/destroy.js:133:8)
06:21:27         at emitErrorCloseNT (internal/streams/destroy.js:98:3)
06:21:27         at processTicksAndRejections (internal/process/task_queues.js:80:21) {
06:21:27       code: 'ERR_HTTP2_STREAM_ERROR'
06:21:27     }
06:21:27   ...

[Trott]

Should the test gracefully handle NGHTTP2_ENHANCE_YOUR_CALM? @nodejs/http2

[jasnell]

Given what the test is doing, this is most likely hitting up against the max session memory limit. If the test has not accounted for that already, perhaps try increasing that limit significantly and seeing if the failure continues

[Trott]

Hmmm, this comment in the test suggests that the failures may indicate a memory leak.

// Regression test for https://github.com/nodejs/node/issues/29223.
// There was a "leak" in the accounting of session memory leading
// to streams eventually failing with NGHTTP2_ENHANCE_YOUR_CALM.

[Trott]

https://ci.nodejs.org/job/node-test-binary-windows-js-suites/4749/RUN_SUBSET=2,nodes=win2012r2-COMPILED_BY-vs2019-x86/console failed too. test-rackspace-win2012r2_vs2017-x64-4

As with the other one I posted earlier and all the ones before that, it's a rackspace host. I haven't seen this fail on an azure host yet. If I recall correctly, the rackspace hosts are configured with different memory and CPU than the azure hosts.

[Trott]

I have been unable to duplicate this in the node-stress-single-test, running things in parallel, etc. This is frustrating....

[Trott]

Given what the test is doing, this is most likely hitting up against the max session memory limit. If the test has not accounted for that already, perhaps try increasing that limit significantly and seeing if the failure continues

The test sets maxSessionMemory to 1 Mb:

    // Set maxSessionMemory to 1MB so the leak causes errors faster.

[Trott]

I've figured out how to replicate this in CI. I've applied 5a8e165 which makes changes to vcbuild.bat such that it only runs this test a bunch of times, and then I run node-test-commit-windows-fanned jobs against the branch with that patch applied.

Here's the master branch with that patch applied showing many failures: https://ci.nodejs.org/job/node-test-commit-windows-fanned/37176/

Will apply to the first branch that introduced this test and see if it was failing from the beginning. If not, I'll bisect to find the commit that introduced the failures.

[Trott]

Argh, I can't get 18a1796 to compile in CI so I can't test it. Here's the result: https://ci.nodejs.org/view/All/job/node-compile-windows/34942/ Any chance someone knowledgable from @nodejs/build and/or @nodejs/platform-windows can take a look and maybe make a suggestion for getting it to compile? I guess something changed with how we build in CI at some point?

I suspect the issue is this, but I'm also pretty ignorant about building on Windows:

23:57:12 > msbuild "C:\workspace\node-compile-windows\node\tools\msvs\msi\nodemsi.sln" /m /t:Clean,Build /p:WindowsTargetPlatformVersion=10.0.18362.0 /p:PlatformToolset=v142 /p:GypMsvsVersion=2019 /p:Configuration=Release /p:Platform=x64 /p:NodeVersion=14.0.0 /p:FullVersion=14.0.0 /p:DistTypeDir=release  /clp:NoSummary;NoItemAndPropertyList;Verbosity=minimal /nologo 
23:57:13   custom_actions.cc
23:57:14 C:\workspace\node-compile-windows\node\tools\msvs\msi\custom_actions.cc(5,10): fatal error C1083: Cannot open include file: 'wcautil.h': No such file or directory [C:\workspace\node-compile-windows\node\tools\msvs\msi\custom_actions.vcxproj]

[Trott]

Argh, I can't get 18a1796 to compile in CI so I can't test it. Here's the result: https://ci.nodejs.org/view/All/job/node-compile-windows/34942/ Any chance someone knowledgable from @nodejs/build and/or @nodejs/platform-windows can take a look and maybe make a suggestion for getting it to compile? I guess something changed with how we build in CI at some point?

Turns out I don't need to compile that commit because a later commit (415bba) built just fine and stress test was good, so I'm going to bisect and find the bad commit now....

[Trott]

Bisected! The problematic commit is 51ccf1b.