Core dump with "double free detected in tcache 2" or assertion failure when using http2 client via @grpc/grpc-js

[mdouglass]

• 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:

1. npm ci
2. npm run server
3. npm 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:

1. Starting a duplex grpc call stream
2. Sending at least one request/response over the duplex stream
3. Starting and completing a unary grpc call
4. Cancelling the duplex stream

[aduh95]

Any chance you could provide a repro that doesn't include npm dependencies (or downloading a potentially sketchy zip file 🙃)?

[bl-ue]

Indeed, I can reproduce on macOS 11.4 with node v15.5.1 (that's what I last had 🙂).

❯ 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 (/Users/me/Downloads/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call.js:31:26)
    at Object.onReceiveStatus (/Users/me/Downloads/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client.js:390:49)
    at Object.onReceiveStatus (/Users/me/Downloads/repro-node-crash/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181)
    at /Users/me/Downloads/repro-node-crash/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78
    at processTicksAndRejections (node:internal/process/task_queues:75:11)
duplexEcho status {
  code: 1,
  details: 'Cancelled on client',
  metadata: Metadata { internalRepr: Map(0) {}, options: {} }
}
node(48717,0x104f70e00) malloc: *** error for object 0x104b31db0: pointer being freed was not allocated
node(48717,0x104f70e00) malloc: *** set a breakpoint in malloc_error_break to debug
zsh: abort      npm run client

I'll investigate some more and when I come to a conclusion, I'll pull in some guys.

[bl-ue]

@mdouglass is the problem (what's not expected) the error itself duplexEcho error Error: 1 CANCELLED: Cancelled on client (and its stacktrace) or the core dump? Or both? Never mind, I see the core dump is the proble.

[bl-ue]

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]

Any chance you could provide a repro that doesn't include npm dependencies (or downloading a potentially sketchy zip file upside_down_face)?

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]

@mdouglass save yourself the time — I'm investigating right now

[mdouglass]

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

That reminded me that I should have tried to run this with the grpc-node tracing turned on via:

export GRPC_TRACE=all
export GRPC_VERBOSITY=DEBUG

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]

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:

./configure --debug --debug-node --gdb --v8-non-optimized-debug --v8-enable-object-print --debug-nghttp2 --node-builtin-modules-path=$PWD/lib --enable-asan --debug-lib

[bl-ue]

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):

Assertion failed: (stream->dep_prev), function nghttp2_stream_dep_remove, file ../deps/nghttp2/lib/nghttp2_stream.c, line 777.
zsh: abort      npm run client

@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

assert(stream->dep_prev);

[bl-ue]

ping @jasnell

[mdouglass]

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/18514a2667572d742ef2c2d38f45249c