Deadlocks when signal handlers/callbacks are called from other threads

[sdroege]

E.g. the following change to examples/gst.js:

diff --git a/examples/gst.js b/examples/gst.js
index e9635d5..2d549dd 100644
--- a/examples/gst.js
+++ b/examples/gst.js
@@ -31,6 +31,12 @@ bus.addWatch(0, (bus, msg) => {
     return true
 })

+bus.setSyncHandler((bus, msg) => {
+    console.log("Got msg " + msg)
+
+    return Gst.BusSyncReply.PASS
+});
+
 const src = Gst.ElementFactory.make("videotestsrc", "src1")
 const sink = Gst.ElementFactory.make("autovideosink", "sink1")

When running it prints the log output from the sync handler but not any longer from the normal addWatch() callback that would happen from the main thread, and it also doesn't show the video window as before.

Backtrace is as follows. It waits for something in GNodeJS::AsyncCallWrapper::Wait() in one of the threads that would call the new callback.

``` Thread 10 (Thread 0x7fffda7ef700 (LWP 1394940)): #0 futex_wait_cancelable (private=0, expected=0, futex_word=0x7fffda7ee938) at ../sysdeps/nptl/futex-internal.h:183 #1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x7fffda7ee940, cond=0x7fffda7ee910) at pthread_cond_wait.c:508 #2 __pthread_cond_wait (cond=0x7fffda7ee910, mutex=0x7fffda7ee940) at pthread_cond_wait.c:638 #3 0x00007ffff664cf19 in uv_cond_wait () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #4 0x00007ffff0a3a09d in GNodeJS::AsyncCallWrapper::Wait() (this=) at ../src/async_call_wrapper.cc:32 #5 0x00007ffff0a39d4a in GNodeJS::AsyncCallEnvironment::Call(std::function) (this=this@entry=0x55555565afc0, fn=...) at ../src/async_call_environment.cc:43 #6 0x00007ffff0a3be1f in GNodeJS::Callback::Call(ffi_cif*, void*, void**, void*) (cif=, result=, args=, user_data=) at /usr/include/c++/10/bits/std_function.h:87 #7 0x00007ffff7fb7b02 in () at /usr/lib/x86_64-linux-gnu/libffi.so.7 #8 0x00007ffff7fb7e60 in () at /usr/lib/x86_64-linux-gnu/libffi.so.7 #9 0x00007fffdb5a9a6e in gst_bus_post (bus=bus@entry=0x5555559b4e80 [GstBus], message=message@entry=0x7fffcc001820 [GstMessage]) at ../gst/gstbus.c:359 #10 0x00007fffdb5bebc6 in gst_element_post_message_default (element=element@entry=0x555555c04100 [GstPipeline], message=0x7fffcc001820 [GstMessage]) at ../gst/gstelement.c:2080 #11 0x00007fffdb59b6cc in gst_bin_post_message (element=0x555555c04100 [GstPipeline], msg=0x7fffcc001820 [GstMessage]) at ../gst/gstmessage.h:376 #12 0x00007fffdb5c2066 in gst_element_post_message (element=0x555555c04100 [GstPipeline], message=0x7fffcc001820 [GstMessage]) at ../gst/gstelement.c:2123 #13 0x00007fffdb598278 in bin_bus_handler (bus=, message=, bin=) at ../gst/gstbin.c:3286 #14 0x00007fffdb5a9a6e in gst_bus_post (bus=bus@entry=0x5555559b4dc0 [GstBus], message=message@entry=0x7fffcc001820 [GstMessage]) at ../gst/gstbus.c:359 #15 0x00007fffdb5bebc6 in gst_element_post_message_default (element=0x555555c0e8e0 [GstVideoTestSrc], message=0x7fffcc001820 [GstMessage]) at ../gst/gstelement.c:2080 #16 0x00007fffdb5c2066 in gst_element_post_message (element=element@entry=0x555555c0e8e0 [GstVideoTestSrc], message=message@entry=0x7fffcc001820 [GstMessage]) at ../gst/gstelement.c:2123 #17 0x00007fffdb5dd25e in do_stream_status (pad=0x555555c101c0 [GstPad], type=GST_STREAM_STATUS_TYPE_ENTER, task=0x555555c3a050 [GstTask], thread=) at ../gst/gstpad.c:6182 #18 0x00007fffdb616198 in gst_task_func (task=0x555555c3a050 [GstTask]) at ../gst/gsttask.c:299 #19 0x00007ffff08926e4 in g_thread_pool_thread_proxy (data=) at ../../../glib/gthreadpool.c:354 #20 0x00007ffff0891dfd in g_thread_proxy (data=0x5555559d3c00) at ../../../glib/gthread.c:820 #21 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #22 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 9 (Thread 0x7fffdaff0700 (LWP 1394939)): #0 0x00007ffff5b6fbc1 in __GI___clock_nanosleep (clock_id=clock_id@entry=0, flags=flags@entry=0, req=req@entry=0x7fffdafefd40, rem=rem@entry=0x7fffdafefd50) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:48 #1 0x00007ffff5b753a3 in __GI___nanosleep (requested_time=requested_time@entry=0x7fffdafefd40, remaining=remaining@entry=0x7fffdafefd50) at nanosleep.c:27 #2 0x00007ffff089388f in g_usleep (microseconds=microseconds@entry=50000) at ../../../glib/gtimer.c:277 #3 0x00007fffdb6bd5f2 in gst_xv_image_sink_event_thread (xvimagesink=0x555555c232a0 [GstXvImageSink]) at ../sys/xvimage/xvimagesink.c:591 #4 0x00007ffff0891dfd in g_thread_proxy (data=0x5555559d3aa0) at ../../../glib/gthread.c:820 #5 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #6 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 7 (Thread 0x7ffff7fcb700 (LWP 1394927)): #0 futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0x7ffff7f76ce0) at ../sysdeps/nptl/futex-internal.h:320 #1 do_futex_wait (sem=sem@entry=0x7ffff7f76ce0, abstime=0x0, clockid=0) at sem_waitcommon.c:112 #2 0x00007ffff5c81278 in __new_sem_wait_slow (sem=0x7ffff7f76ce0, abstime=0x0, clockid=0) at sem_waitcommon.c:184 #3 0x00007ffff664cfa2 in uv_sem_wait () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #4 0x00007ffff6598bcd in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #5 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #6 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 6 (Thread 0x7ffff129c700 (LWP 1394926)): #0 futex_wait_cancelable (private=0, expected=0, futex_word=0x555555592e20) at ../sysdeps/nptl/futex-internal.h:183 #1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555555592dd0, cond=0x555555592df8) at pthread_cond_wait.c:508 #2 __pthread_cond_wait (cond=0x555555592df8, mutex=0x555555592dd0) at pthread_cond_wait.c:638 #3 0x00007ffff664cf19 in uv_cond_wait () at /usr/lib/x86_64-linux-gnu/libnode.so.72 --Type for more, q to quit, c to continue without paging-- #4 0x00007ffff650e673 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #5 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #6 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 5 (Thread 0x7ffff1a9d700 (LWP 1394925)): #0 futex_wait_cancelable (private=0, expected=0, futex_word=0x555555592e20) at ../sysdeps/nptl/futex-internal.h:183 #1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555555592dd0, cond=0x555555592df8) at pthread_cond_wait.c:508 #2 __pthread_cond_wait (cond=0x555555592df8, mutex=0x555555592dd0) at pthread_cond_wait.c:638 #3 0x00007ffff664cf19 in uv_cond_wait () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #4 0x00007ffff650e673 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #5 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #6 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 4 (Thread 0x7ffff229e700 (LWP 1394924)): #0 futex_wait_cancelable (private=0, expected=0, futex_word=0x555555592e24) at ../sysdeps/nptl/futex-internal.h:183 #1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555555592dd0, cond=0x555555592df8) at pthread_cond_wait.c:508 #2 __pthread_cond_wait (cond=0x555555592df8, mutex=0x555555592dd0) at pthread_cond_wait.c:638 #3 0x00007ffff664cf19 in uv_cond_wait () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #4 0x00007ffff650e673 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #5 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #6 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 3 (Thread 0x7ffff2a9f700 (LWP 1394923)): #0 futex_wait_cancelable (private=0, expected=0, futex_word=0x555555592e24) at ../sysdeps/nptl/futex-internal.h:183 #1 __pthread_cond_wait_common (abstime=0x0, clockid=0, mutex=0x555555592dd0, cond=0x555555592df8) at pthread_cond_wait.c:508 #2 __pthread_cond_wait (cond=0x555555592df8, mutex=0x555555592dd0) at pthread_cond_wait.c:638 #3 0x00007ffff664cf19 in uv_cond_wait () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #4 0x00007ffff650e673 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #5 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #6 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 2 (Thread 0x7ffff32a0700 (LWP 1394922)): #0 0x00007ffff5ba8076 in epoll_wait (epfd=9, events=0x7ffff329cdc0, maxevents=1024, timeout=-1) at ../sysdeps/unix/sysv/linux/epoll_wait.c:30 #1 0x00007ffff6651356 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #2 0x00007ffff663f379 in uv_run () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #3 0x00007ffff6512c26 in node::WorkerThreadsTaskRunner::DelayedTaskScheduler::Start()::{lambda(void*)#1}::_FUN(void*) () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #4 0x00007ffff5c77ea7 in start_thread (arg=) at pthread_create.c:477 #5 0x00007ffff5ba7d4f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95 Thread 1 (Thread 0x7ffff32c6580 (LWP 1394910)): #0 0x00007ffff5b9d35f in __GI___poll (fds=0x555555c38a50, nfds=3, timeout=-1) at ../sysdeps/unix/sysv/linux/poll.c:29 #1 0x00007ffff0868e1e in g_main_context_poll (priority=, n_fds=3, fds=0x555555c38a50, timeout=, context=0x5555556611b0) at ../../../glib/gmain.c:4422 #2 g_main_context_iterate (context=0x5555556611b0, block=block@entry=1, dispatch=dispatch@entry=1, self=) at ../../../glib/gmain.c:4114 #3 0x00007ffff086917b in g_main_loop_run (loop=0x5555559cb770) at ../../../glib/gmain.c:4317 #4 0x00007ffff7fb7ccd in () at /usr/lib/x86_64-linux-gnu/libffi.so.7 #5 0x00007ffff7fb725a in () at /usr/lib/x86_64-linux-gnu/libffi.so.7 #6 0x00007ffff0a3f9f3 in GNodeJS::FunctionCall(GNodeJS::FunctionInfo*, Nan::FunctionCallbackInfo const&, _GIArgument*, _GError**) (func=, info=..., return_value=return_value@entry=0x0, error=error@entry=0x0) at ../src/function.cc:276 #7 0x00007ffff0a3fe44 in GNodeJS::FunctionInvoker(Nan::FunctionCallbackInfo const&) (info=...) at ../src/function.cc:677 #8 0x00007ffff0a3e089 in Nan::imp::FunctionCallbackWrapper(v8::FunctionCallbackInfo const&) (info=...) at ../node_modules/nan/nan_callbacks_12_inl.h:176 #9 0x00007ffff66bb3cf in v8::internal::FunctionCallbackArguments::Call(v8::internal::CallHandlerInfo) () at /usr/lib/x86_64-linux-gnu/libnode.so.72 --Type for more, q to quit, c to continue without paging-- #10 0x00007ffff66bb768 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #11 0x00007ffff66bbfea in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #12 0x00007ffff66bc819 in v8::internal::Builtin_HandleApiCall(int, unsigned long*, v8::internal::Isolate*) () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #13 0x00007ffff70bde59 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #14 0x00007fffffffd240 in () #15 0x000000000000002a in () #16 0x00007fffffffd2d0 in () #17 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #18 0x00002006020804b1 in () #19 0x00001a810b487219 in () #20 0x0000000500000000 in () #21 0x0000200602080591 in () #22 0x00002d5939aea201 in () #23 0x0000241d23386009 in () #24 0x00002d5939aea201 in () #25 0x00001a810b487219 in () #26 0x00002c766cf64491 in () #27 0x00003ccb299402d1 in () #28 0x0000006e00000000 in () #29 0x0000150de6995651 in () #30 0x000023969f967591 in () #31 0x0000241d23385fd1 in () #32 0x00007fffffffd368 in () #33 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #34 0x00002d5939aea201 in () #35 0x0000395b052eca79 in () #36 0x0000000400000000 in () #37 0x00002d5939aea201 in () #38 0x000023969f967591 in () #39 0x000039c79d9421f9 in () #40 0x00002d5939aed9e9 in () #41 0x00002d5939aecf19 in () #42 0x00002d5939aebf91 in () #43 0x00002d5939aeafb1 in () #44 0x00002d5939aea2e1 in () #45 0x00003ccb29940281 in () #46 0x0000080633368e81 in () #47 0x0000024200000000 in () #48 0x000014d956fb0001 in () #49 0x000008063336d711 in () #50 0x000008063336d751 in () #51 0x00007fffffffd458 in () #52 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #53 0x000008063336d791 in () #54 0x000014d956fa6a99 in () #55 0x000008063336d639 in () #56 0x000008063336d691 in () #57 0x000008063336d7b1 in () #58 0x000008063336d7b1 in () #59 0x000008063336d791 in () #60 0x000014d956fa6a99 in () --Type for more, q to quit, c to continue without paging-- #61 0x000008063336d639 in () #62 0x000008063336d691 in () #63 0x000008063336d7b1 in () #64 0x000008063336d7b1 in () #65 0x000008063336d711 in () #66 0x000039c79d942f21 in () #67 0x000008063336d639 in () #68 0x000008063336d7b1 in () #69 0x000008063336d7b1 in () #70 0x00002006020804b1 in () #71 0x000008063336d691 in () #72 0x000008063336d791 in () #73 0x00002006020801b9 in () #74 0x000008063336d711 in () #75 0x00002006020804b1 in () #76 0x00002006020804b1 in () #77 0x000001fb00000000 in () #78 0x000014d956fae9a1 in () #79 0x000014d956fa20b1 in () #80 0x00001457a12ff899 in () #81 0x00007fffffffd4e0 in () #82 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #83 0x000014d956fa6a99 in () #84 0x000008063336d7e9 in () #85 0x000008063336d639 in () #86 0x000021ff4fdb1e11 in () #87 0x000039c79d976bf9 in () #88 0x00001457a12ffc51 in () #89 0x000014d956fa20b1 in () #90 0x00002006020804b1 in () #91 0x00002006020804b1 in () #92 0x000008063336dd49 in () #93 0x000008063336d7e9 in () #94 0x000000d100000000 in () #95 0x000014d956fab881 in () #96 0x000014d956fa2109 in () #97 0x00001457a12ff899 in () #98 0x00007fffffffd568 in () #99 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #100 0x000014d956fa6a99 in () #101 0x000008063336d639 in () #102 0x0000080633367151 in () #103 0x00001457a12ffbc1 in () #104 0x000008063336dd71 in () #105 0x000014d956f99681 in () #106 0x0000080633367151 in () #107 0x000014d956fa2109 in () #108 0x00002006020804b1 in () #109 0x00002006020804b1 in () #110 0x000039c79d976bf9 in () #111 0x000000d500000000 in () --Type for more, q to quit, c to continue without paging-- #112 0x000014d956faabd1 in () #113 0x000014d956fa2001 in () #114 0x00001457a12ff899 in () #115 0x00007fffffffd638 in () #116 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #117 0x000014d956fa6a99 in () #118 0x000008063336d639 in () #119 0x00002006020804b1 in () #120 0x00002006020804b1 in () #121 0x00002006020804b1 in () #122 0x0000200602080639 in () #123 0x000014d956fa2001 in () #124 0x00001457a12ff899 in () #125 0x000014d956fa6a99 in () #126 0x0000080633367139 in () #127 0x00002006020804b1 in () #128 0x00002006020804b1 in () #129 0x00002006020804b1 in () #130 0x00002006020804b1 in () #131 0x0000200602080639 in () #132 0x000008063336d639 in () #133 0x00002006020804b1 in () #134 0x00002006020804b1 in () #135 0x000014d956fa6a99 in () #136 0x00002006020804b1 in () #137 0x000001ab00000000 in () #138 0x000014d956fa8551 in () #139 0x000014d956fa1ef1 in () #140 0x00001457a12ff899 in () #141 0x00007fffffffd6c8 in () #142 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #143 0x0000200602080639 in () #144 0x00002006020801b9 in () #145 0x000008063336dd91 in () #146 0x000014d956fbff81 in () #147 0x0000200602080639 in () #148 0x00002006020801b9 in () #149 0x000008063336dd91 in () #150 0x000014d956fbff81 in () #151 0x000014d956fa1ef1 in () #152 0x00002006020806e9 in () #153 0x000014d956fa6a99 in () #154 0x000008063336dd91 in () #155 0x0000008c00000000 in () #156 0x000014d956fa3d91 in () #157 0x000008063336ddd1 in () #158 0x000008063336de11 in () #159 0x00007fffffffd728 in () #160 0x00007ffff70435e4 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #161 0x000008063336dd91 in () #162 0x000014d956fbff81 in () --Type for more, q to quit, c to continue without paging-- #163 0x000008063336dd91 in () #164 0x000014d956fbff81 in () #165 0x000008063336ddd1 in () #166 0x00001457a12ffca9 in () #167 0x0000007300000000 in () #168 0x00002e0cd96af271 in () #169 0x00001457a12ffce9 in () #170 0x000039c79d9421f9 in () #171 0x00007fffffffd778 in () #172 0x00007ffff7040b5d in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #173 0x00002e0cd96aeed9 in () #174 0x00001ba345ec0351 in () #175 0x00001ba345ec0369 in () #176 0x00001ba345ec0419 in () #177 0x00001ba345ec03a9 in () #178 0x00002006020804b1 in () #179 0x00001457a12ffce9 in () #180 0x0000000000000022 in () #181 0x00007fffffffd7e0 in () #182 0x00007ffff7040938 in () at /usr/lib/x86_64-linux-gnu/libnode.so.72 #183 0x0000000000000000 in () ```

[romgrk]

Can reproduce, I'll investigate more.

@wotzlaff if you have any hints here I'd be happy to have your input.

One thing I've noted, uv's doc says:

Note
1. Callers should be prepared to deal with spurious wakeups on uv_cond_wait() and uv_cond_timedwait().

It's surely not the cause of this but our uv_cond_wait() isn't in a loop, we probably need to wrap it.

[romgrk]

The case can be simplified to the following code. Any synchronous out-of-thread callback fails. Async callbacks are fine.

const task = new Gio.Task(null)

task.runInThreadSync(() => {
  console.log('callback called')
})

Edit: I think I see what's happening. libuv/nodejs main loop is stopped because it has called g_task_run_in_thread_sync (which has itself called g_cond_wait), and the thread spawn by g_task_run_in_thread_sync is itself trying to get an answer from libuv's main thread, which is waiting :/

I have trouble seeing how we're gonna get out of this one. One thing is sure, if we want to run JS from other threads, the main loop cannot be blocked by *_sync functions. They need to be moved off-thread somehow.

[sdroege]

Asynchronous callbacks (I assume you mean things like GIO async operations with GAsyncResult etc) are called from the thread that runs the main loop, not from some random other thread.