Repository navigation
CI failures with no output/stack trace #19903
Description
Activity
Two things I found out, which don’t give a lot of insight but might narrow things down a bit:
- This appears to happen more frequently when tests are not being run in parallel
- Output that is inserted through
process._rawDebugat the beginning of the script is shown by the test runner
Does
dmesgshow anything afterwards?@bnoordhuis Unfortunately, no. :/ There are only a handful lines reported after boot on the debian-x86 machine, a few from invalid incoming external UDP packages, and 7 segfault notices for
node; but those don’t match the times (or the frequency) with which I could reproduce the issue on that machine.@bnoordhuis Okay, this turns out to be a pretty deep rabbit hole.
The reported exit code according to #19855 is
-6, which would beSIGABRT– that would explain why we don’t see any output –HasCrashed()intools/test.pyexplicitly excludesSIGABRT:Lines 582 to 583 in 5e68172
Also, I found out there’s a magical place where all the core dumps go on debian machines with
systemd– so we actually have those available, too, we just didn’t know that.This is the stack trace I’m getting from the most recent core dump that I could produce:
#0 0xb775bd40 in __kernel_vsyscall () #1 0xb7453367 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #2 0xb7454a23 in __GI_abort () at abort.c:89 #3 0x0857e86c in uv_sem_post (sem=0xbf83b360) at ../deps/uv/src/unix/thread.c:520 #4 0x0856edff in worker (arg=0xbf83b360) at ../deps/uv/src/threadpool.c:55 #5 0xb75d8ecb in start_thread (arg=0xb50ffb40) at pthread_create.c:309 #6 0xb7510d0e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:129(main thread stack)
#0 0x0850cda5 in node::TCPWrap::Connect(v8::FunctionCallbackInfo<v8::Value> const&) () #1 0x0866afc9 in v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo<v8::Value> const&)) () #2 0x086de729 in v8::internal::MaybeHandle<v8::internal::Object> v8::internal::(anonymous namespace)::HandleApiCallHelper<false>(v8::internal::Isolate*, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::HeapObject>, v8::internal::Handle<v8::internal::FunctionTemplateInfo>, v8::internal::Handle<v8::internal::Object>, v8::internal::BuiltinArguments) () #3 0x086deed1 in v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*) () #4 0x3fd061be in ?? () #5 0x3fd11fd8 in ?? () #6 0x3fd0c11d in ?? () #7 0x3fd11fd8 in ?? () #8 0x3fd11fd8 in ?? () #9 0x3fd0c11d in ?? () #10 0x3fd11fd8 in ?? () #11 0x3fd11fd8 in ?? () #12 0x3fd0fe04 in ?? () #13 0x3fd09b51 in ?? () #14 0x089c589d in v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*) () #15 0x08658bf6 in v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*) () #16 0x08475359 in node::InternalMakeCallback(node::Environment*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context) () #17 0x0844b4d8 in node::AsyncWrap::MakeCallback(v8::Local<v8::Function>, int, v8::Local<v8::Value>*) () #18 0x08450522 in node::cares_wrap::(anonymous namespace)::AfterGetAddrInfo(uv_getaddrinfo_s*, int, addrinfo*) () #19 0x085772e0 in uv__getaddrinfo_done (w=0xb342e94, status=0) at ../deps/uv/src/unix/getaddrinfo.c:134 #20 0x0856f23c in uv__work_done (handle=0x9ba2da0 <default_loop_struct+96>) at ../deps/uv/src/threadpool.c:251 #21 0x08571210 in uv__async_io (loop=0x9ba2d40 <default_loop_struct>, w=0x9ba2e30 <default_loop_struct+240>, events=1) at ../deps/uv/src/unix/async.c:118 #22 0x08581ff8 in uv__io_poll (loop=0x9ba2d40 <default_loop_struct>, timeout=-1) at ../deps/uv/src/unix/linux-core.c:400 #23 0x08571b59 in uv_run (loop=0x9ba2d40 <default_loop_struct>, mode=UV_RUN_DEFAULT) at ../deps/uv/src/unix/core.c:368 #24 0x08480456 in node::Start(uv_loop_s*, int, char const* const*, int, char const* const*) () #25 0x0847f1da in node::Start(int, char**) () #26 0x084416da in main ()(Also, in
test-tls-buffersize, this always happens after thelistencallback is finished, but before the socket is registered as connected. I assume that it’s related to moving the DNS lookup to the thread pool.)The
errnofor the failingsem_post()call isEINVAL.It seems this was introduced by libuv/libuv@647fbc0 – we picked this up in #18260 on Jan 24 on
master, which roughly matches my feeling of when these things started happening. Also, reverting it seems to resolve the issue. (I got 7/20000 failures before, and now it’s down to 0/20000.)I don’t see anything wrong with that commit. However, more debugging, and digging through the glibc source code and its git history brings up https://sourceware.org/bugzilla/show_bug.cgi?id=12674, which seems like it’s exactly the bug that we’re experiencing. (Here’s a pure-C reproduction that is similar to the libuv code and is fixed by bminor/glibc@042e152.)
The fix is included in glibc >= 2.21, but I’m not sure what that means for us going forward.
Reacted by Gireesh Punathil, Anatoli Papirovski, Gibson Fahnestock, Ruben Bridgewater and Joyee CheungReacted by Rich Trott, Anatoli Papirovski, Richard Lau, Ruben Bridgewater and Joyee Cheungnice work!
For the record, the cores collected by systemd are only there because I had
LimitCORE=unlimitedturned on and an upgraded systemd installed (via jessie-backports) on the debian 8 machines because @joyeecheung requested core dumps. I've since removedLimitCORE(yesterday, via nodejs/build#1224) but there hasn't been a restart so they are still collecting cores until that happens. If someone needs cores again in the future we'll have to turn them back on. I think the problem that @joyeecheung ran into though was that the matching binaries don't persist so unless you're capturing the cores on the machine yourself, having them generated via our CI runs is not as useful.- added a commit that references this issue
on Apr 12, 2018 I think the problem that @joyeecheung ran into though was that the matching binaries don't persist so unless you're capturing the cores on the machine yourself, having them generated via our CI runs is not as useful.
We could work around that by writing a custom script that saves the binary to somewhere and use it in
/proc/sys/kernel/core_pattern, although that could be pretty involved operation-wise. When #19661 lands we might also turn on node-report in tests like this to get the JS stack and native stack, among other useful information.- added a commit that references this issue
on Apr 12, 2018 @addaleax - I was playing around with your C-reproduce, but it always succeeded - is there any precondition for it to fail? my system's glibc is 2.11, and have ample # of CPUs.
10 remaining items
- added a commit that references this issue
on Apr 23, 2018 - added a commit that references this issue
on May 1, 2018 - added a commit that references this issue
on Jun 29, 2018 - added a commit that references this issue
on Aug 7, 2018 - added a commit that references this issue
on Jan 29, 2025 - added a commit that references this issue
on Jul 27, 2026
We've been seeing these for quite some time. They look like this:
No contents for
stdoutorstderrbut the test failed. Huh? Wha?Might be a problem in
tools/test.py.@BridgeAR and @addaleax have looked to varying degrees at this issue but haven't discovered anything as far as I know.
@refack and I have a PR open to add exit code to the output when these things happen in case that helps. #19855
@nodejs/testing @nodejs/build