CI failures with no output/stack trace

[Trott]

• Version: 10.0.0-pre
• Platform: various Linux platforms
• Subsystem: test

We've been seeing these for quite some time. They look like this:

not ok 123 parallel/test-some-test
  ---
  duration_ms: 0.456
  severity: fail
  stack: |-

No contents for stdout or stderr but 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

[rvagg]

Last round of investigation happened in #18998

[addaleax]

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._rawDebug at the beginning of the script is shown by the test runner

[bnoordhuis]

Does dmesg show anything afterwards?

[addaleax]

@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.

[addaleax]

@bnoordhuis Okay, this turns out to be a pretty deep rabbit hole.

The reported exit code according to #19855 is -6, which would be SIGABRT – that would explain why we don’t see any output – HasCrashed() in tools/test.py explicitly excludes SIGABRT:

node/tools/test.py

Lines 582 to 583 in 5e68172

	return self.output.exit_code < 0 and \
	self.output.exit_code != -signal.SIGABRT

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 the listen callback 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 errno for the failing sem_post() call is EINVAL.

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.