Abort in uv_cond_wait

[rcombs]

• Version: v7.1.0
• Platform: Darwin Rodgers-MacBook-Pro.local 16.3.0 Darwin Kernel Version 16.3.0: Tue Nov 29 12:39:07 PST 2016; root:xnu-3789.31.2~11/RELEASE_X86_64 x86_64
• Subsystem: libuv

When running a gulp server on a complex project, I see a crash approximately daily. The backtrace on the crashing thread looks like this:

* thread #9: tid = 0x0008, 0x00007fffb73f5dd6 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGSTOP
  * frame #0: 0x00007fffb73f5dd6 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x00007fffb74e1787 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x00007fffb735b420 libsystem_c.dylib`abort + 129
    frame #3: 0x0000000100949c8e node`uv_cond_wait + 20
    frame #4: 0x000000010093d47b node`worker + 227
    frame #5: 0x00007fffb74deaab libsystem_pthread.dylib`_pthread_body + 180
    frame #6: 0x00007fffb74de9f7 libsystem_pthread.dylib`_pthread_start + 286
    frame #7: 0x00007fffb74de1fd libsystem_pthread.dylib`thread_start + 13

That's this call to abort(): https://github.com/libuv/libuv/blob/3064ae98e5c3cee223f9e229ff20f86cb1b06b8b/src/unix/thread.c#L498
In this call to uv_cond_wait():

node/deps/uv/src/threadpool.c

Line 75 in db1087c

uv_cond_wait(&cond, &mutex);

libuv doesn't provide any detail on the failure, but we can guess that pthread_cond_wait is returning EINVAL. This is odd, since main() hadn't exited and exit() hadn't been called, so we can assume we hadn't called cleanup(), so mutex and cond shouldn't have been destroyed. The mutex and condition variable are both static and only used together, so we don't have a mismatch, and quick overview indicates we definitely have the mutex locked when the call is made.
So… I really have no idea what's going on here. My only remaining guess is some sort of memory corruption, but you'd think we could eliminate that since we're crashing at the same point so consistently.
I notice I'm a minor-version behind, so I'll upgrade and see if it's resolved, but the relevant source file hasn't changed since 2015 and there's nothing in the recent changelog about this (that I can find), so I'd be surprised if that was the issue.
Any ideas?

[bnoordhuis]

I'm not sure what is happening. Can you try this patch and see if you hit the assert?

diff --git a/deps/uv/src/unix/thread.c b/deps/uv/src/unix/thread.c
index a9b5e4c..d77f896 100644
--- a/deps/uv/src/unix/thread.c
+++ b/deps/uv/src/unix/thread.c
@@ -96,9 +96,6 @@ int uv_thread_equal(const uv_thread_t* t1, const uv_thread_t* t2) {
 
 
 int uv_mutex_init(uv_mutex_t* mutex) {
-#if defined(NDEBUG) || !defined(PTHREAD_MUTEX_ERRORCHECK)
-  return -pthread_mutex_init(mutex, NULL);
-#else
   pthread_mutexattr_t attr;
   int err;
 
@@ -114,7 +111,6 @@ int uv_mutex_init(uv_mutex_t* mutex) {
     abort();
 
   return -err;
-#endif
 }
 
 
@@ -494,6 +490,8 @@ void uv_cond_broadcast(uv_cond_t* cond) {
 }
 
 void uv_cond_wait(uv_cond_t* cond, uv_mutex_t* mutex) {
+  assert(EDEADLK == pthread_mutex_lock(mutex));
+
   if (pthread_cond_wait(cond, mutex))
     abort();
 }

[addaleax]

ping @rcombs, can you try the above patch and let us know what the result is? Can you provide some way of reproducing this?

[mjmasn]

Just to add some more context, a lot of Meteor users are seeing a similar issue with node 4.8.x (and possibly earlier) on OSX. Given this report is for gulp which is in many ways similar to Meteor it could well be a libuv issue around file watching. As I've mentioned on various issues in the https://github.com/meteor/meteor repository I'm fairly out of my depth with this one but very interested in helping in some way to find a solution.

[rcombs]

I haven't actually run into this in a while and never had a reliable way to reproduce it on command, unfortunately.

[realyze]

@addaleax here's the relevant Meteor issue with some stacktraces (seems like it might be useful): meteor/meteor#8648 .

[sdarnell]

@bnoordhuis I've been trying to catch the problem in a Meteor environment and have some extra info.
Firstly, I was able to reproduce the abort in both node 4.8.3 and v8.0.0, though it isn't easily reproducible.

Secondly, I made the patch change you suggested above to node 4.8.3 and the assert did not go off, either in uv_mutex_init() or uv_cond_wait().

Here's the v8 bt output:

(lldb) v8 bt
 * thread #8: tid = 0x693805, 0x0000000101309d42 libsystem_kernel.dylib`__pthread_kill + 10, stop reason = signal SIGABRT
  * frame #0: 0x0000000101309d42 libsystem_kernel.dylib`__pthread_kill + 10
    frame #1: 0x0000000101451457 libsystem_pthread.dylib`pthread_kill + 90
    frame #2: 0x000000010123b420 libsystem_c.dylib`abort + 129
    frame #3: 0x00000001006c9299 node`uv_cond_wait(cond=<unavailable>, mutex=<unavailable>) at thread.c:446 [opt]
    frame #4: 0x00000001006bceaf node`worker(arg=<unavailable>) at threadpool.c:75 [opt]
    frame #5: 0x00000001006c8eaa node`uv__thread_start(arg=<unavailable>) at thread.c:52 [opt]
    frame #6: 0x000000010144e93b libsystem_pthread.dylib`_pthread_body + 180
    frame #7: 0x000000010144e887 libsystem_pthread.dylib`_pthread_start + 286
    frame #8: 0x000000010144e08d libsystem_pthread.dylib`thread_start + 13

[bnoordhuis]

@sdarnell Can you try this patch with node (not meteor) and see what it prints?

diff --git a/deps/uv/src/unix/thread.c b/deps/uv/src/unix/thread.c
index 236f591..bf85708 100644
--- a/deps/uv/src/unix/thread.c
+++ b/deps/uv/src/unix/thread.c
@@ -440,7 +440,10 @@ void uv_cond_broadcast(uv_cond_t* cond) {
 }
 
 void uv_cond_wait(uv_cond_t* cond, uv_mutex_t* mutex) {
-  if (pthread_cond_wait(cond, mutex))
+  int err;
+  if ((err = pthread_cond_wait(cond, mutex)))
+    fprintf(stderr, "pthread_cond_wait: error %d\n", err),
+    fflush(stderr),
     abort();
 }
 

[sdarnell]

@bnoordhuis Sorry, but the only way I know of reproducing the issue is to run a non-trivial (Angular) app on top of Meteor. I basically attach the debugger and carry on working until it triggers again.

When it went off this time, the err values was 22 (EINVAL).
I added an fprintf of the cond and mutex values: cond 0x100b29830 mutex 0x100b297f0.

This time I also put a breakpoint on abort() rather than wait for the SIGABRT, but that didn't help too much as the variables were still unavailable due to optimisation. But given the pointers here's a bit more detail (sadly the pthread structures are opaque):

(lldb) p *(uv_cond_t*)0x100b29830
(uv_cond_t) $1 = (__sig = 1129270852, __opaque = char [40] @ 0x00007ffcc1fbe738)
# __sig = 1129270852 =  #define _PTHREAD_COND_SIG 0x434F4E44  /* 'COND' */
(lldb) memory read --size 4 --format x --count 12 0x100b29830
0x100b29830: 0x434f4e44 0x00000000 0x00000000 0x80000000
0x100b29840: 0x00b297f0 0x00000001 0x6698c600 0x6698c500 // 0x100b297f0 is mutex ptr
0x100b29850: 0x6698c600 0x00000000 0x00000000 0x00000000

(lldb) p *(uv_mutex_t*)0x100b297f0
(uv_mutex_t) $4 = (__sig = 1297437784, __opaque = char [56] @ 0x00007ffcc47c9df8)
# __sig = 1297437784 = #define _PTHREAD_MUTEX_SIG 0x4D555458  /* 'MUTX' */
(lldb) p sizeof(uv_mutex_t)
(unsigned long) $6 = 64
(lldb) memory read --size 4 --format x --count 16 0x100b297f0
0x100b297f0: 0x4d555458 0x00000000 0x00000000 0x00002064
0x100b29800: 0x00000000 0x4d555458 0x0081b33f 0x00000000  // 0x0081b33f is the tid of this thread
0x100b29810: 0xf1db8403 0xf1db8000 0xffffffff 0xffffffff
0x100b29820: 0xff4d680f 0xfffffffe 0x4d555458 0x4d555458

Here's the list of threads (with tids):

Process 34124 stopped
  thread #1: tid = 0x81b32c, 0x000000010130ac22 libsystem_kernel.dylib`__psynch_mutexwait + 10, queue = 'com.apple.main-thread'
  thread #2: tid = 0x81b32d, 0x0000000101303386 libsystem_kernel.dylib`semaphore_wait_trap + 10
  thread #3: tid = 0x81b32e, 0x0000000101303386 libsystem_kernel.dylib`semaphore_wait_trap + 10, name = 'V8 WorkerThread'
  thread #4: tid = 0x81b32f, 0x0000000101303386 libsystem_kernel.dylib`semaphore_wait_trap + 10, name = 'V8 WorkerThread'
  thread #5: tid = 0x81b330, 0x0000000101303386 libsystem_kernel.dylib`semaphore_wait_trap + 10, name = 'V8 WorkerThread'
  thread #6: tid = 0x81b331, 0x0000000101303386 libsystem_kernel.dylib`semaphore_wait_trap + 10, name = 'V8 WorkerThread'
  thread #7: tid = 0x81b33a, 0x000000010130bd96 libsystem_kernel.dylib`kevent + 10
  thread #8: tid = 0x81b33d, 0x000000010130ac22 libsystem_kernel.dylib`__psynch_mutexwait + 10
  thread #9: tid = 0x81b33e, 0x000000010130ac22 libsystem_kernel.dylib`__psynch_mutexwait + 10
* thread #10: tid = 0x81b33f, 0x000000010123c39f libsystem_c.dylib`abort, stop reason = breakpoint 1.1 2.1 3.1
  thread #11: tid = 0x81b340, 0x000000010130abf2 libsystem_kernel.dylib`__psynch_cvwait + 10

So it looks to me like the two parameters are valid and point at the correct type of objects, the condition variable points at the given mutex, and that the mutex is probably owned by the current thread (the previous assert(EDEADLK == pthread_mutex_lock(mutex)) confirmed this).
Which appears to eliminate the documented reasons for EINVAL from: http://pubs.opengroup.org/onlinepubs/7908799/xsh/pthread_cond_wait.html (the apple page is rather scant: https://opensource.apple.com/source/libpthread/libpthread-218.51.1/man/pthread_cond_wait.3.auto.html)

One other nugget of information is that initially I rebuilt node with CFLAGS="-g -O0" set when calling make -j4 (in an effort to get better info from the debugger). I noticed that some directories overrode this setting and still optimised. But, I ran with the resulting node executable for a good two days of fairly intensive use without an abort.
I did a clean rebuild without those CFLAGS and it only took about 30-60mins to reproduce the abort.
Obviously, absence of an abort does not guarantee anything, but it was surprising that it lasted as long as it did without an abort.

Just in case it is relevant I'm using:

$ cc --version
Apple LLVM version 8.1.0 (clang-802.0.42)
Target: x86_64-apple-darwin16.6.0
Thread model: posix
InstalledDir: /Library/Developer/CommandLineTools/usr/bin`

[bnoordhuis]

If it only happens intermittently and the error is always EINVAL, I'd suspect some kind of memory corruption. I can speculate about possible causes but that won't help much. When you passed -O0, was V8 built with that flag?

[sdarnell]

Sorry for the delay, but I've been running for a bit, on and off with the above build. In each case of the abort the error was EINVAL.

deps/v8 and node/src do not seem to take any notice of the CFLAGS setting, the modules that take notice are: deps/cares, deps/openssl, deps/uv

[bnoordhuis]

@sdarnell Try patching the Release cflags in common.gypi.

[apapirovski]

Doesn't seem like there's much else that can be done here. The Meteor issue appears like it was resolved and 7.x from the original issue is no longer supported. If any new information is available, feel free to open a new issue with more info.