Repository navigation
Core dump with "double free detected in tcache 2" or assertion failure when using http2 client via @grpc/grpc-js #38964
Description
- Version: v16.3.0
- Platform: Linux rowlf 5.12.8-300.fc34.x86_64 deps: update openssl to 1.0.1j #1 SMP Fri May 28 15:20:54 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
- Subsystem: http2
What steps will reproduce the bug?
repro-node-crash.zip
Run the following steps on the same machine:
npm cinpm run servernpm run client
How often does it reproduce? Is there a required condition?
On my machine this is 100% reproducible in node v16.0 and up. I have not tried previous pre-v16 versions.
What is the expected behavior?
It is expected that the client process runs to completion without error.
What do you see instead?
The client process dies with a core dump or an assertion failure:
$ npm run client
> server@1.0.0 client
> node client.js
duplexEcho response: { message: 'Hello duplex world!' }
unaryEcho response: { message: 'Hello unary world!' }
duplexEcho error Error: 1 CANCELLED: Cancelled on client
at Object.callErrorFromStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call.js:31:26)
at Object.onReceiveStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client.js:390:49)
at Object.onReceiveStatus (/home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181)
at /home/matthew/spikes/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78
at processTicksAndRejections (node:internal/process/task_queues:78:11)
duplexEcho status {
code: 1,
details: 'Cancelled on client',
metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}
free(): double free detected in tcache 2
[1] 695652 IOT instruction (core dumped) npm run client
npm start
> client@1.0.0 start
> node index.js
duplexEcho response: { message: 'Hello duplex world!' }
unaryEcho response: { message: 'Hello unary world!' }
duplexEcho error Error: 1 CANCELLED: Cancelled on client
at Object.callErrorFromStatus (/Users/mark/oss/grpc-crash/repro-node-crash/client/node_modules/@grpc/grpc-js/build/src/call.js:31:26)
at Object.onReceiveStatus (/Users/mark/oss/grpc-crash/repro-node-crash/client/node_modules/@grpc/grpc-js/build/src/client.js:390:49)
at Object.onReceiveStatus (/Users/mark/oss/grpc-crash/repro-node-crash/client/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181)
at /Users/mark/oss/grpc-crash/repro-node-crash/client/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78
at processTicksAndRejections (node:internal/process/task_queues:78:11)
duplexEcho status {
code: 1,
details: 'Cancelled on client',
metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}
node[57071]: ../src/node_http2.cc:450:void node::http2::Http2Session::CheckAllocatedSize(size_t) const: Assertion `(current_nghttp2_memory_) >= (previous_size)' failed.
1: 0x1026e4ee5 node::Abort() (.cold.1) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
2: 0x10139adc9 node::Abort() [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
3: 0x10139ac31 node::Assert(node::AssertionInfo const&) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
4: 0x1013d5885 node::mem::NgLibMemoryManager<node::http2::Http2Session, nghttp2_mem>::FreeImpl(void*, void*) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
5: 0x102278942 nghttp2_session_close_stream [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
6: 0x102280266 nghttp2_session_mem_recv [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
7: 0x1013bf719 node::http2::Http2Session::ConsumeHTTP2Data() [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
8: 0x1013c2b8c node::http2::Http2Session::OnStreamRead(long, uv_buf_t const&) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
9: 0x10145da2b node::LibuvStreamWrap::OnUvRead(long, uv_buf_t const*) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
10: 0x101da205e uv__stream_io [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
11: 0x101daae4c uv__io_poll [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
12: 0x101d97521 uv_run [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
13: 0x1012ccedf node::SpinEventLoop(node::Environment*) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
14: 0x1013dc254 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
15: 0x10136973d node::Start(int, char**) [/Users/mark/.nvm/versions/node/v16.0.0/bin/node]
16: 0x7fff20564621 start [/usr/lib/system/libdyld.dylib]
17: 0x2
zsh: abort npm start
Additional information
This is related to grpc/grpc-node#1464.
There is a workaround available in my example client.js if you comment out line 45 and comment in line 46 (delaying stream.cancel via the use of setImmediate).
It seems to require this particular pattern of calls in the @grpc/grpc-js library as well:
- Starting a duplex grpc call stream
- Sending at least one request/response over the duplex stream
- Starting and completing a unary grpc call
- Cancelling the duplex stream
Activity
aduh95 commentedon Jun 8, 2021
Any chance you could provide a repro that doesn't include npm dependencies (or downloading a potentially sketchy zip file 🙃)?
bl-ue commentedon Jun 8, 2021
Indeed, I can reproduce on macOS 11.4 with node v15.5.1 (that's what I last had 🙂).
I'll investigate some more and when I come to a conclusion, I'll pull in some guys.
bl-ue commentedon Jun 8, 2021
@mdouglass is the problem (what's not expected) the error itselfNever mind, I see the core dump is the proble.duplexEcho error Error: 1 CANCELLED: Cancelled on client(and its stacktrace) or the core dump? Or both?bl-ue commentedon Jun 8, 2021
It seems like a bug in HTTP2. cc @jasnell @addaleax because you're familiar with HTTP2 in node. I think the line that causes the abort is https://github.com/grpc/grpc-node/blob/663fe77e7286910da0ae067cde5622dd2036bb30/packages/grpc-js/src/call-stream.ts#L679
mdouglass commentedon Jun 8, 2021
Apologies, I thought the zip of the repro would be most appropriate. I've posted the repo at https://github.com/mdouglass/repro-node-crash as well if you'd rather get it there.
I don't know enough about the @grpc/grpc-js internals to be able to create a repro without that lib quickly. If it turns out to be necessary to investigate it further, I can try to figure it out.
bl-ue commentedon Jun 8, 2021
@mdouglass save yourself the time — I'm investigating right now
mdouglass commentedon Jun 8, 2021
That reminded me that I should have tried to run this with the grpc-node tracing turned on via:
If I do that, the last log line out is indeed the one immediately before https://github.com/grpc/grpc-node/blob/663fe77e7286910da0ae067cde5622dd2036bb30/packages/grpc-js/src/call-stream.ts#L679 that @bl-ue identified.
See https://gist.github.com/mdouglass/a4c521167daf8e5e0246bb862b419f36
bl-ue commentedon Jun 8, 2021
Yep, I tried those vars too which is what got me that line.
I'm building node now with a bunch of debug params to see if I can spot anything obvious before digging in to the node source more:
bl-ue commentedon Jun 8, 2021
So, after the long (37min) build, I tried running the server which worked like normal, and the client eventually (this 393mb node takes an extraordinarily long time to start up 😄) started executing, and printed this error instead of the core dump or the assertion failure (both of which I've gotten earlier and got a bunch more on the next runs):
@jasnell does that look like a real problem or some unrelated issue caused by debugging?
node/deps/nghttp2/lib/nghttp2_stream.c
Line 777 in e46c680
bl-ue commentedon Jun 16, 2021
ping @jasnell
mdouglass commentedon Jun 16, 2021
I just built with
./configure --debug --enable-asan. After that I do see an ASAN heap-use-after-free. See https://gist.github.com/mdouglass/18514a2667572d742ef2c2d38f45249cbl-ue commentedon Jun 16, 2021
Wow, that's a lot of cool output — I didn't get any of that 🤔
Hmm, that almost looks like a bug in nghttp2 — but I'm not experienced enough to say that.
ping @jasnell I just know you're the best to take a look at this :)
mdouglass commentedon Jun 16, 2021
Adding a bit more context, I turned on the nghttp2 debug as well and got this: https://gist.github.com/mdouglass/fe9a159b6d9b167ac1da14386bf773a5.
I'm suspicious of this:
I'm seeing that the same stream was closed twice and that the address of that stream is within a short distance of where the heap-use-after-free. The first close is right before I receive the unary response and the second close is right after I call cancel on the duplex stream. So to my eyes that looks like the two streams getting confused somehow. Will keep poking at it.
mdouglass commentedon Jun 17, 2021
Continuing to poke at this as I can. I added logging at the top and bottom of
nghttp2_session_close_streamso I could see when we enter/exit calls to this method. In the working version of the repro, we enternghttp2_session_close_stream, exit it and then enter and exit it again.In the non-working version of the repro, we enter
nghttp2_session_close_streamand then re-enter it on the same thread:bad version:
The second call never exits as it ultimately crashes with the use after free call seen above.
I tried reading through the nghttp2 docs to see if this is allowed and can't see if it is allowed or not. There is a comment that a single
nghttp2_sessionobject must be used by a single thread (which is why I logged threadid) but nothing about reentrancy.edit: Ignore the unknown in the request close line, I am logging that before retrieving the stream pointer since I wanted to make sure the log line was as early as possible.
28 remaining items
SimonWoolf commentedon May 19, 2022
I'm afraid I don't have a script that I'm able to share, sorry (it's a loadtest of a non-open-source distributed system, I haven't been able to generate a minimal reproduction).
But if you have some debug flags I could turn on, or a custom build of node with extra logging or something that you'd like me to run the tests against to get more information when the crash happens, I'd be happy to do so.
facutuesca commentedon May 25, 2022
@SimonWoolf I'm looking into this issue right now. Is there any chance you could run the tests against a build with ASAN? The stack trace provided by it would give us a better clue of where the problematic
freeis happening.SimonWoolf commentedon May 26, 2022
Sure - unfortunately I'm about to go on holiday; I'll be back and hope to be able to get you that info on the 7th/8th of June.
SimonWoolf commentedon Jun 15, 2022
Sorry for the delay; some other things came up (plus I had some trouble compiling the asan build).
Running the loadtest with asan build of node, most of the instances quickly died with the following stacktrace. This is a different error to the above; no idea of whether this is the same bug being exposed earlier by the asan build or whether this is some other issue, hopefully you do 🙂
Matt-Esch commentedon Jan 28, 2023
@facutuesca I have managed to reproduce with an ASAN build, see:
Matt-Esch commentedon Jan 30, 2023
@mcollina @kumarak bumping this - would be good to get some eyes on this, let me know if you need anything else.
santigimeno commentedon Jan 30, 2023
@Matt-Esch any possibility of having code that reproduces the issue?
Matt-Esch commentedon Jan 30, 2023
@santigimeno I can only reproduce this on a large proprietary codebase, I've not been able to isolate this to a simple repro unfortunately. I do think the stack traces give us a lot of context. My feeling is that the stream should have been removed from the session in the first close call, the second call to close (on incoming RST) should not have been possible. So either the close callback is re-entrant (nghttp2 says explicitly not to do that) or the stream is not removed from that session, which would raise the question why is the session not removed on RST even if the underlying data is freed.
Matt-Esch commentedon Feb 3, 2023
Looking over the
nghttp2_session_close_streamcode, there are a few places where stream-related memory can be freed but the stream not removed from the list, for example https://github.com/nodejs/node/blob/v16.18.0/deps/nghttp2/lib/nghttp2_session.c#L1210I am going to instrument these points to see if they are the root cause.
Matt-Esch commentedon Feb 4, 2023
Logs from nghttp2 when segfault occurs on stream 65:
Looks like the transmission of a frame completes after the stream has already been closed.
http2: on receiving rst_stream with cancel code add it to pending list
github-actions commentedon Jun 27, 2026
This issue has been marked as stale due to 210 days of inactivity.
It will be automatically closed in 30 days if no further activity occurs. If this is still relevant, please leave a comment or update it to keep it open.
github-actions commentedon Jul 28, 2026
This issue has been automatically closed after 30 days of inactivity following its stale status (no activity for a total of 120 days).
If this is still relevant, feel free to reopen it or leave a comment with additional details so we can continue the discussion.