TLS assertion error in DoWrite

[lomaster1]

• Version: v10.16.3 (we're using nave)
• Platform: Linux zagent 4.4.0-159-generic configure: remove workarounds for GCC < 4.8 #187-Ubuntu SMP Thu Aug 1 16:28:06 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
• Subsystem: http2

We have this error in high loaded service when customers are making requests to amazon.com (not sure only amazon.com):

/var/lib/nave/installed/10.16.3/bin/node[15992]: ../src/tls_wrap.cc:682:virtual int node::TLSWrap::DoWrite(node::WriteWrap*, uv_buf_t*, size_t, uv_stream_t*): Assertion `(current_write_) == nullptr' failed.
 1: 0x8fa0c0 node::Abort() [/var/lib/nave/installed/10.16.3/bin/node]
 2: 0x8fa195  [/var/lib/nave/installed/10.16.3/bin/node]
 3: 0xa2c90b node::TLSWrap::DoWrite(node::WriteWrap*, uv_buf_t*, unsigned long, uv_stream_s*) [/var/lib/nave/installed/10.16.3/bin/node]
 4: 0xa2a5ec node::TLSWrap::EncOut() [/var/lib/nave/installed/10.16.3/bin/node]
 5: 0xa2b34b node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [/var/lib/nave/installed/10.16.3/bin/node]
 6: 0xa2aad1 node::TLSWrap::ClearOut() [/var/lib/nave/installed/10.16.3/bin/node]
 7: 0xa2b343 node::TLSWrap::OnStreamRead(long, uv_buf_t const&) [/var/lib/nave/installed/10.16.3/bin/node]
 8: 0x9cf801  [/var/lib/nave/installed/10.16.3/bin/node]
 9: 0xa7ae09  [/var/lib/nave/installed/10.16.3/bin/node]
10: 0xa7b430  [/var/lib/nave/installed/10.16.3/bin/node]
11: 0xa80dd8  [/var/lib/nave/installed/10.16.3/bin/node]
12: 0xa6fe6b uv_run [/var/lib/nave/installed/10.16.3/bin/node]
13: 0x904725 node::Start(v8::Isolate*, node::IsolateData*, std::vector<std::string, std::allocator<std::string> > const&, std::vector<std::string, std::allocator<std::string> > const&) [/var/lib/nave/installed/10.16.3/bin/node]
14: 0x90297f node::Start(int, char**) [/var/lib/nave/installed/10.16.3/bin/node]
15: 0x7f9536c18830 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
16: 0x8bbe85  [/var/lib/nave/installed/10.16.3/bin/node]

Can you suggest me what I can do to get you more info about error?
Or maybe you know why this may occur?
We have 1-2 this error per hour for one server.

[addaleax]

Can you suggest me what I can do to get you more info about error?

I’ll try to see if I can find out more based on the stack trace, but if it is even remotely possible for you, setting NODE_DEBUG_NATIVE=tls in the environment and sharing the output just before the crash would be massively helpful. It’s going to print quite a bit of data to stderr, though.

[wmertens]

FYI, I had some similar but not the same crashes, and I finally figured out that the VM had too little memory. I increased memory, no more crashes.

[jakelazaroff]

I'm having the same or a similar issue. Here's the stack trace:

/usr/local/bin/node[833]: ../src/env-inl.h:899:char* node::Environment::Allocate(size_t): Assertion `(ret) != (nullptr)' failed.
 1: 0x9bcac0 node::Abort() [/usr/local/bin/node]
 2: 0x9bcb47  [/usr/local/bin/node]
 3: 0xad9a1b node::TLSWrap::DoWrite(node::WriteWrap*, uv_buf_t*, unsigned long, uv_stream_s*) [/usr/local/bin/node]
 4: 0xa6876e node::StreamBase::Writev(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/bin/node]
 5: 0xa6df6e void node::StreamBase::JSMethod<&node::StreamBase::Writev>(v8::FunctionCallbackInfo<v8::Value> const&) [/usr/local/bin/node]
 6: 0xb840cc  [/usr/local/bin/node]
 7: 0xb85ed7 v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [/usr/local/bin/node]
 8: 0x134f199  [/usr/local/bin/node]

Version: v12.16.1 (installed via apt using the NodeSource repository) and v12.9.1 (using the binary from nodejs.org)
OS: Ubuntu 18.04.3 x64

It does not seem to happen running 12.9.1 on macOS 10.15.3. My best guess is that (in my code at least) the aws-sdk library is triggering it when uploading a large file. I'm not sure how to debug further; I don't really know what to do with this crash log. Will try to get that NODE_DEBUG_NATIVE=tls log if it helps.

[wmertens]

@jakelazaroff what about memory, do you have enough available on your Linux system?

[bnoordhuis]

@jakelazaroff That's a different issue. It's an out-of-memory error, like @wmertens suggests.

The error message can probably be improved. I'll open a new issue for that.

[jakelazaroff]

@wmertens @bnoordhuis Looks like you're right, I beefed up the server it was running on and it succeeded! Thanks a lot for the help. Sorry to distract from the topic in this issue 😕

[vladislavle]

Can you suggest me what I can do to get you more info about error?

I’ll try to see if I can find out more based on the stack trace, but if it is even remotely possible for you, setting NODE_DEBUG_NATIVE=tls in the environment and sharing the output just before the crash would be massively helpful. It’s going to print quite a bit of data to stderr, though.

Hi, looks like I have the same issue on node ver: 14.19.0
Operating System: Ubuntu 20.04.3 LTS
Kernel: Linux 5.4.0-80-generic
Architecture: x86-64

TLSWrap server (948469) OnClientHelloParseEnd()
TLSWrap client (642818) OnStreamAfterWrite(status = 0)
TLSWrap client (642818) Trying to write cleartext input
TLSWrap client (642818) Returning from ClearIn(), no pending data
TLSWrap client (642818) Trying to write encrypted output
TLSWrap client (642818) EncOut() setting write_callback_scheduled_
TLSWrap client (642818) No pending encrypted output
TLSWrap client (642818) No pending cleartext input, not inside DoWrite()
TLSWrap client (642818) InvokeQueued(0, (null))
TLSWrap client (621276) Read 121 bytes from underlying stream
TLSWrap client (621276) Trying to write cleartext input
TLSWrap client (621276) Returning from ClearIn(), no pending data
TLSWrap client (621276) Trying to read cleartext output
TLSWrap client (621276) Read 36 bytes of cleartext output
TLSWrap client (621276) Read 27 bytes of cleartext output
TLSWrap client (621276) Read -1 bytes of cleartext output
TLSWrap client (621276) Trying to write encrypted output
TLSWrap client (621276) No pending encrypted output
TLSWrap client (621276) No pending cleartext input, not inside DoWrite()
TLSWrap client (621276) InvokeQueued(0, (null))
TLSWrap server (948469) Read -1 bytes of cleartext output
TLSWrap server (948469) Trying to write encrypted output
TLSWrap server (948469) Writing 1 buffers to the underlying stream
TLSWrap server (944783) DoWrite()
/var/lib/nave/installed/14.19.0/bin/node[1080391]: ../src/tls_wrap.cc:756:virtual int node::TLSWrap::DoWrite(node::WriteWrap*, uv_buf_t*, size_t, uv_stream_t*): Assertion `!current_write_' failed.

[mackelito]

I'm getting similar errors

npm i[80088]: ../src/crypto/crypto_tls.cc:947:virtual int node::crypto::TLSWrap::DoWrite(node::WriteWrap , uv_buf_t , size_t, uv_stream_t ): Assertion `!current_write_' failed.
1: 0x107e01eb5 node::Abort() (.cold.1) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
2: 0x106877a69 node::Abort() [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
3: 0x106877811 node::Assert(node::AssertionInfo const&) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
4: 0x1069cc038 node::crypto::TLSWrap::DoWrite(node::WriteWrap, uv_buf_t, unsigned long, uv_stream_s) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
5: 0x1068a4892 node::StreamBase::Write(uv_buf_t*, unsigned long, uv_stream_s*, v8::Localv8::Object, bool) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
6: 0x1069ca8fc node::crypto::TLSWrap::EncOut() [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
7: 0x106a6f368 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
8: 0x106a6ee3b v8::internal::MaybeHandlev8::internal::Object v8::internal::(anonymous namespace)::HandleApiCallHelper(v8::internal::Isolate*, v8::internal::Handlev8::internal::HeapObject, v8::internal::Handlev8::internal::HeapObject, v8::internal::Handlev8::internal::FunctionTemplateInfo, v8::internal::Handlev8::internal::Object, v8::internal::BuiltinArguments) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
9: 0x106a6e54f v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
10: 0x1073cb8f9 Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_BuiltinExit [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]

This was working just fine yesterday and I'm not sure what could have done this..
Things I know I did yesterday was:

• xcode command line tools software update
• brew upgrade

I have uninstalled nvm, node, npm and reinstalled it
I have tried other node versions
I have installed using brew, clean nvm and even downloading the dmg file from website

problem still persists

[bnoordhuis]

The output of env NODE_DEBUG_NATIVE=tls node app.js may provide a clue.

[bnoordhuis]

Forgot to mention: but please always test with the most recent official node binary, not ones from homebrew or other package managers. If you want to use those, fine, but then bug reports should go to them.

[mackelito]

Of course and as I stated I did try direct download as well :)
The problem is solved for me now but I'm not exactly sure what the issue was.. I think it might have been a mix of .npmrc files, package-lock and corrupted node_modules...

[ywave620]

Something in the stack trace posted by @mackelito looks wired to me

6: 0x1069ca8fc node::crypto::TLSWrap::EncOut() [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]
7: 0x106a6f368 v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) [/Users/markus/.nvm/versions/node/v18.16.0/bin/node]

AFAIC, v8::internal::FunctionCallbackArguments::Call should always calls a binding function, a function that has the exact signature void (const FunctionCallbackInfo<Value>&). Apparently, TLSWrap::EncOut() is not a binding function, my curiosity is how come we get such a stack trace? @addaleax @bnoordhuis (It would be appreciated if you could shed some light on this)