node process crashes in uv_try_write while using N-API C++ addon. OS sends SIGPIPE

[KRAUS1203]

Version

14.15.3

Platform

Linux NRP10 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Subsystem

uv

What steps will reproduce the bug?

There are no exact steps to reproduce the issue but it occurs almost every night. also this issue does not occur on every deployment, it occurs only at a single deployment bu causing production downtime.

How often does it reproduce? Is there a required condition?

The issue occurs almost every night when the production rate is very high.

What is the expected behavior?

node should show where exactly it is crashing on which input. Also if there are additional steps/tools that I can use to pinpoint the root cause, please let me know.

What do you see instead?

Signal=[13] Received
Walk Stack Trace Size=[14]
[0x5d171e0]
/lib64/libpthread.so.0(+0xf5e0) [0x7fc924a935e0]
/lib64/libc.so.6(writev+0x60) [0x7fc9247b0230]
/home/panadmin/bin/node() [0x1386621]
/home/panadmin/bin/node(uv_write2+0x203) [0x13878a3]
/home/panadmin/bin/node(uv_try_write+0x6d) [0x1387b7d]
/home/panadmin/bin/node(_ZThn88_N4node15LibuvStreamWrap10DoTryWriteEPP8uv_buf_tPm+0x26) [0xadace6]
/home/panadmin/bin/node(_ZN4node10StreamBase6WritevERKN2v820FunctionCallbackInfoINS1_5ValueEEE+0x322) [0xad11d2]
/home/panadmin/bin/node(_ZN4node10StreamBase8JSMethodIXadL_ZNS0_6WritevERKN2v820FunctionCallbackInfoINS2_5ValueEEEEEEEvS7_+0xa0) [0xad37f0]
/home/panadmin/bin/node() [0xbe456b]
/home/panadmin/bin/node() [0xbe5b16]
/home/panadmin/bin/node(_ZN2v88internal21Builtin_HandleApiCallEiPmPNS0_7IsolateE+0x16) [0xbe6196]
/home/panadmin/bin/node() [0x1400119]
Segmentation violation occured
Walk Stack Trace Size=[16]
[0x5d171e0]
/lib64/libpthread.so.0(+0xf5e0) [0x7fc924a935e0]
/lib64/libpthread.so.0(pthread_mutex_lock+0) [0x7fc924a8dc30]
/home/panadmin/bin10.14.0.0.SP5/Framework/cim_addons/pm/Release/pm_interface.node(_ZN4PLog12flush_outputEv+0x1c) [0x7fc8f43a1d52]
/home/panadmin/bin10.14.0.0.SP5/Framework/cim_addons/pm/Release/pm_interface.node(_ZN10PAppLogger12flush_outputEv+0x16) [0x7fc8f43a13ee]
/home/panadmin/bin10.14.0.0.SP5/Framework/cim_addons/pm/Release/pm_interface.node(_Z17linux_sig_handleri10sigcontext+0x125) [0x7fc8f43a11e7]
/lib64/libpthread.so.0(+0xf5e0) [0x7fc924a935e0]
/lib64/libc.so.6(writev+0x60) [0x7fc9247b0230]
/home/panadmin/bin/node() [0x1386621]
/home/panadmin/bin/node(uv_write2+0x203) [0x13878a3]
/home/panadmin/bin/node(uv_try_write+0x6d) [0x1387b7d]
/home/panadmin/bin/node(_ZThn88_N4node15LibuvStreamWrap10DoTryWriteEPP8uv_buf_tPm+0x26) [0xadace6]
/home/panadmin/bin/node(_ZN4node10StreamBase6WritevERKN2v820FunctionCallbackInfoINS1_5ValueEEE+0x322) [0xad11d2]
/home/panadmin/bin/node(_ZN4node10StreamBase8JSMethodIXadL_ZNS0_6WritevERKN2v820FunctionCallbackInfoINS2_5ValueEEEEEEEvS7_+0xa0) [0xad37f0]
/home/panadmin/bin/node() [0xbe456b]

Additional information

Below is the coredump for the same crash:-

__gmon_start__
_init
_fini
_ITM_deregisterTMCloneTable
_ITM_registerTMCloneTable
__cxa_finalize
_Jv_RegisterClasses
libgcc_s.so.1
_ZN2v88internal35IsolateFromNeverReadOnlySpaceObjectEm
_ZN2v811HandleScope12CreateHandleEPNS_8internal7IsolateEm
_ZNK2v88External5ValueEv
_ZN2v86Object20SlowGetInternalFieldEi
_Z4InitN2v85LocalINS_6ObjectEEE
_ZN2v87Isolate10GetCurrentEv
_ZN2v811HandleScopeC1EPNS_7IsolateE
_ZN2v820EscapableHandleScopeC1EPNS_7IsolateE
_ZN2v814ObjectTemplate3NewEPNS_7IsolateENS_5LocalINS_16FunctionTemplateEEE
_ZN2v814ObjectTemplate21SetInternalFieldCountEi
_ZN2v87Isolate17GetCurrentContextEv
_ZN2v814ObjectTemplate11NewInstanceENS_5LocalINS_7ContextEEE
_ZN2v820EscapableHandleScope6EscapeEPm
_ZN2v811HandleScopeD2Ev
_ZN2v88External3NewEPNS_7IsolateEPv
_ZN2v86Object16SetInternalFieldEiNS_5LocalINS_5ValueEEE
_ZN2v816FunctionTemplate3NewEPNS_7IsolateEPFvRKNS_20FunctionCallbackInfoINS_5ValueEEEENS_5LocalIS4_EENSA_INS_9SignatureEEEiNS_19ConstructorBehaviorENS_14SideEffectTypeEPKNS_9CFunctionE
_ZN2v86String11NewFromUtf8EPNS_7IsolateEPKcNS_13NewStringTypeEi
_ZN2v816FunctionTemplate12SetClassNameENS_5LocalINS_6StringEEE
_ZN2v816FunctionTemplate11GetFunctionENS_5LocalINS_7ContextEEE
_ZN2v86Object3SetENS_5LocalINS_7ContextEEENS1_INS_5ValueEEES5_
_ZN2v811HandleScopeD1Ev
_ZN2v82V812ToLocalEmptyEv
_Unwind_Resume
__gxx_personality_v0
_ZN3Nan10ThrowErrorEPKc
_ZN2v89Exception5ErrorENS_5LocalINS_6StringEEE
_ZN2v87Isolate14ThrowExceptionENS_5LocalINS_5ValueEEE
_ZNK2v85Value8ToStringENS_5LocalINS_7ContextEEE
_ZNK2v86String6LengthEv
_ZNK2v86String9WriteUtf8EPNS_7IsolateEPciPii
_Z12GetDiskUsagePKc
free
_ZN2v86Object3NewEPNS_7IsolateE
_ZN2v86Number3NewEPNS_7IsolateEd
malloc
__assert_fail
__cxa_begin_catch
__cxa_end_catch
_ZN4node14ErrnoExceptionEPN2v87Is

23733 
m(yH
__gmon_start__
_init
_fini
_ITM_deregisterTMCloneTable
_ITM_registerTMCloneTable
__cxa_finalize
_Jv_RegisterClasses
libgcc_s.so.1
_ZN3Nan11AsyncWorker7DestroyEv
_ZN3Nan12AsyncExecuteEP9uv_work_s
_ZN3Nan20AsyncExecuteCompleteEP9uv_work_si
_ZN3Nan11AsyncWorker12WorkCompleteEv
_ZN2v87Isolate10GetCurrentEv
_ZN2v811HandleScopeC1EPNS_7IsolateE
_ZN2v82V813DisposeGlobalEPm
_ZdlPv
_ZN2v811HandleScopeD1Ev
closelog
syslog
_ZN2v88internal35IsolateFromNeverReadOnlySpaceObjectEm
_ZN2v811HandleScope12CreateHandleEPNS_8internal7IsolateEm
_ZNK2v88External5ValueEv
_ZN2v86Object20SlowGetInternalFieldEi
_ZN3Nan11AsyncWorkerD2Ev
_ZTVN3Nan11AsyncWorkerE
_ZdaPv
_ZN4node16EmitAsyncDestroyEPN2v87IsolateENS_13async_contextE
_ZN3Nan11AsyncWorkerD1Ev
_ZN3Nan11AsyncWorker19HandleErrorCallbackEv
_ZN2v86String11NewFromUtf8EPNS_7IsolateEPKcNS_13NewStringTypeEi
_ZN2v89Exception5ErrorENS_5LocalINS_6StringEEE
_ZN2v87Isolate17GetCurrentContextEv
_ZN2v87Context6GlobalEv
_ZN2v820EscapableHandleScopeC1EPNS_7IsolateE
_ZN4node12MakeCallbackEPN2v87IsolateENS0_5LocalINS0_6ObjectEEENS3_INS0_8FunctionEEEiPNS3_INS0_5ValueEEENS_13async_contextE
_ZN2v820EscapableHandleScope6EscapeEPm
_ZN2v811HandleScopeD2Ev
_ZN2v82V812ToLocalEmptyEv
_ZN3Nan11AsyncWorker16HandleOKCallbackEv
_ZNK2v85Value8ToStringENS_5LocalINS_7ContextEEE
_ZNK2v86String6LengthEv
malloc
_ZNK2v86String9WriteUtf8EPNS_7IsolateEPciPii
_Znam
memcpy
free
__assert_fail
_ZN3Nan11AsyncWorkerD0Ev
_ZNK2v85Value7ToInt32ENS_5LocalINS_7ContextEEE
strncpy
_ZNK2v85Int325ValueEv
openlog
_ZNK2v85Value10IsFunctionEv
_Znwm
_ZN2v82V818GlobalizeReferenceEPNS_8internal7IsolateEPm
_ZN4node6Buffer11HasIn
([A\A]]
../../nan/nan.h

[bnoordhuis]

Converted to a discussion because more likely than not this is a bug in the add-on and not in node.

Node blocks SIGPIPE by default so if the process gets killed by that signal, then it probably means something unblocked it. And indeed, this line in the stack trace looks rather suspicious:

/home/panadmin/bin10.14.0.0.SP5/Framework/cim_addons/pm/Release/pm_interface.node(_Z17linux_sig_handleri10sigcontext+0x125) [0x7fc8f43a11e7]

[KRAUS1203]

@bnoordhuis There was an issue earlier that on SIGPIPE node process got hang so we added an event listener process.on('SIGPIPE') to handle the same and exit the process. does that has anything to do with it? also when the issue occurs system load goes very high and system become unstable until reboot.

[bnoordhuis]

Intercepting SIGPIPE is a bad idea, yes.

[KRAUS1203]

I tried by removing the SIGPIPE handlers but still when SIGPIPE is received, application crashes with same linux_sig_handler stack trace. i tested using manully sending command 13 to PID. by the way is there any way to identify the root cause why OS is sending this signal? @bnoordhuis

[bnoordhuis]

Yes, so you have some investigating to do w.r.t. that module. This is the wrong place to ask.

is there any way to identify the root cause why OS is sending this signal?

You can probably see it when you attach strace(1).

SIGPIPE in itself isn't unexpected though, that just means the other end of (for example) a pipe or TCP connection went away.