Resque forks while resolving DNS, causing deadlock in child
resque (1.27.4)
I'm seeing a (somewhat rare) deadlock in a forked child process. This deadlock occurs inside the rb_thread_atfork callback -- in this case, the callback is being used to re-initialize database connections to work around known bugs with sharing handles across forked ruby processes.
The deadlock is in name resolution -- in the lock libc/nss uses to serialize access to its own state. It's not possible for the child process to have created this deadlock as it's not multithreaded (save for the internal ruby timer thread). I believe the only way for this to occur is for the nss lock to have been acquired in the parent -- meaning a DNS lookup was in-flight in a parent thread, with the lock held, at the same time that this child process was forked.
I am not a resque developer or even a user and am mostly unfamiliar with the codebase, but I poked around briefly and I see threads created for @@all_heartbeat_threads, and I see that these threads can resolve DNS to interact with Redis.
I suggest not allowing these threads to run while forking a child process. I apologize for not sending a PR along with this issue report but I don't have enough time to ramp up fully on resque and attempt a PR at the moment.
Here's a stack trace showing the deadlock. The key points to note are rb_f_fork, rb_protect, then dropping out of ruby into mysql then into glibc/nss.
(gdb) bt
#0 0x00007f346d9ca334 in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007f346d9c55d8 in _L_lock_854 () from /lib64/libpthread.so.0
#2 0x00007f346d9c54a7 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x00007f3467b798fa in _nss_files_gethostbyname4_r () from /lib64/libnss_files.so.2
#4 0x00007f346ce30f7b in gaih_inet () from /lib64/libc.so.6
#5 0x00007f346ce33fbf in getaddrinfo () from /lib64/libc.so.6
#6 0x00007f34682cd39b in mysql_real_connect (mysql=0xa3fab40, host=0x891a150 "<redacted-our-mysql-db>", user=0x7176e10 "<redacted>", passwd=0x7f346832f27a "",
db=0x7176f50 "<redacted>", port=3306, unix_socket=0x0, client_flag=3222282759) at /project/mysql-5.7.14/sql-common/client.c:4492
#7 0x00007f346885b011 in nogvl_connect (ptr=<value optimized out>) at client.c:203
#8 0x00007f346dd86017 in call_without_gvl (func=0x7f346885afe0 <nogvl_connect>, data1=0x7ffd591460e0, ubf=<value optimized out>, data2=<value optimized out>, fail_if_interrupted=0) at thread.c:1321
#9 0x00007f346885cd1a in rb_mysql_connect (self=165676040, user=118976000, pass=8, host=118975840, port=8, database=118976320, socket=8, flags=6444565519, conn_attrs=165658480) at client.c:438
#10 0x00007f346dda68df in call_cfunc_8 (func=<value optimized out>, recv=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>) at vm_insnhelper.c:1644
#11 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c2770, calling=<value optimized out>, ci=0x478a040, cc=<value optimized out>) at vm_insnhelper.c:1769
#12 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c2770, calling=<value optimized out>, ci=0x478a040, cc=<value optimized out>) at vm_insnhelper.c:1864
#13 0x00007f346ddc4559 in vm_call_method_each_type (th=0x25646d0, cfp=0x7f346e2c2770, calling=0x7ffd59146390, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2163
#14 0x00007f346ddc4d6b in vm_call_method (th=0x25646d0, cfp=0x7f346e2c2770, calling=<value optimized out>, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2313
#15 0x00007f346ddbc9fb in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:1066
#16 0x00007f346ddc205b in vm_exec (th=0x25646d0) at vm.c:1775
#17 0x00007f346ddb5986 in vm_call0 (recv=165676040, mid=3105, argc=1, argv=0x7f346e1c3718, scope=CALL_FCALL, self=63768160) at vm_eval.c:62
#18 rb_call0 (recv=165676040, mid=3105, argc=1, argv=0x7f346e1c3718, scope=CALL_FCALL, self=63768160) at vm_eval.c:343
#19 0x00007f346dcd3a80 in rb_class_new_instance (argc=1, argv=0x7f346e1c3718, klass=<value optimized out>) at object.c:1896
#20 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c27d0, calling=<value optimized out>, ci=0x9173eb0, cc=<value optimized out>) at vm_insnhelper.c:1769
#21 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c27d0, calling=<value optimized out>, ci=0x9173eb0, cc=<value optimized out>) at vm_insnhelper.c:1864
#22 0x00007f346ddc4559 in vm_call_method_each_type (th=0x25646d0, cfp=0x7f346e2c27d0, calling=0x7ffd59146880, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2163
#23 0x00007f346ddc4d6b in vm_call_method (th=0x25646d0, cfp=0x7f346e2c27d0, calling=<value optimized out>, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2313
#24 0x00007f346ddbc9fb in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:1066
#25 0x00007f346ddc205b in vm_exec (th=0x25646d0) at vm.c:1775
#26 0x00007f346ddc30f1 in invoke_block (th=0x25646d0, captured=<value optimized out>, self=131617520, argc=<value optimized out>, argv=<value optimized out>, passed_block_handler=<value optimized out>,
cref=0x0, splattable=0, is_lambda=0) at vm.c:973
#27 invoke_iseq_block_from_c (th=0x25646d0, captured=<value optimized out>, self=131617520, argc=<value optimized out>, argv=<value optimized out>, passed_block_handler=<value optimized out>, cref=0x0,
splattable=0, is_lambda=0) at vm.c:1019
#28 0x00007f346ddc3cd1 in invoke_block_from_c_splattable (val=<value optimized out>) at vm.c:1037
#29 vm_yield (val=<value optimized out>) at vm.c:1079
#30 rb_yield_0 (val=<value optimized out>) at vm_eval.c:1010
#31 rb_yield (val=<value optimized out>) at vm_eval.c:1023
#32 0x00007f346dc711c0 in rb_protect (proc=0x7f346ddc3bc0 <rb_yield>, data=52, state=0x7ffd59146f4c) at eval.c:906
#33 0x00007f346dd020ab in rb_f_fork (obj=<value optimized out>) at process.c:3715
#34 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c2b90, calling=<value optimized out>, ci=0x7f13230, cc=<value optimized out>) at vm_insnhelper.c:1769
#35 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c2b90, calling=<value optimized out>, ci=0x7f13230, cc=<value optimized out>) at vm_insnhelper.c:1864
#36 0x00007f346ddbd24c in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:967
#37 0x00007f346ddc205b in vm_exec (th=0x25646d0) at vm.c:1775
#38 0x00007f346ddc9544 in invoke_block () at vm.c:973
#39 invoke_iseq_block_from_c () at vm.c:1019
#40 invoke_block_from_c_splattable () at vm.c:1037
#41 vm_yield () at vm.c:1079
#42 rb_yield_0 () at vm_eval.c:1010
#43 loop_i () at vm_eval.c:1088
#44 0x00007f346dc712a4 in rb_rescue2 (b_proc=0x7f346ddc91f0 <loop_i>, data1=0, r_proc=0x7f346dda8260 <loop_stop>, data2=0) at eval.c:838
#45 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c2c50, calling=<value optimized out>, ci=0x478d0f0, cc=<value optimized out>) at vm_insnhelper.c:1769
#46 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c2c50, calling=<value optimized out>, ci=0x478d0f0, cc=<value optimized out>) at vm_insnhelper.c:1864
#47 0x00007f346ddc4559 in vm_call_method_each_type (th=0x25646d0, cfp=0x7f346e2c2c50, calling=0x7ffd59147710, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2163
#48 0x00007f346ddc4d6b in vm_call_method (th=0x25646d0, cfp=0x7f346e2c2c50, calling=<value optimized
#7 0x00007f346885b011 in nogvl_connect (ptr=<value optimized out>) at client.c:203
#8 0x00007f346dd86017 in call_without_gvl (func=0x7f346885afe0 <nogvl_connect>, data1=0x7ffd591460e0, ubf=<value optimized out>, data2=<value optimized out>, fail_if_interrupted=0) at thread.c:1321
#9 0x00007f346885cd1a in rb_mysql_connect (self=165676040, user=118976000, pass=8, host=118975840, port=8, database=118976320, socket=8, flags=6444565519, conn_attrs=165658480) at client.c:438
#10 0x00007f346dda68df in call_cfunc_8 (func=<value optimized out>, recv=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>) at vm_insnhelper.c:1644
#11 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c2770, calling=<value optimized out>, ci=0x478a040, cc=<value optimized out>) at vm_insnhelper.c:1769
#12 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c2770, calling=<value optimized out>, ci=0x478a040, cc=<value optimized out>) at vm_insnhelper.c:1864
#13 0x00007f346ddc4559 in vm_call_method_each_type (th=0x25646d0, cfp=0x7f346e2c2770, calling=0x7ffd59146390, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2163
#14 0x00007f346ddc4d6b in vm_call_method (th=0x25646d0, cfp=0x7f346e2c2770, calling=<value optimized out>, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2313
#15 0x00007f346ddbc9fb in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:1066
#16 0x00007f346ddc205b in vm_exec (th=0x25646d0) at vm.c:1775
#17 0x00007f346ddb5986 in vm_call0 (recv=165676040, mid=3105, argc=1, argv=0x7f346e1c3718, scope=CALL_FCALL, self=63768160) at vm_eval.c:62
#18 rb_call0 (recv=165676040, mid=3105, argc=1, argv=0x7f346e1c3718, scope=CALL_FCALL, self=63768160) at vm_eval.c:343
#19 0x00007f346dcd3a80 in rb_class_new_instance (argc=1, argv=0x7f346e1c3718, klass=<value optimized out>) at object.c:1896
#20 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c27d0, calling=<value optimized out>, ci=0x9173eb0, cc=<value optimized out>) at vm_insnhelper.c:1769
#21 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c27d0, calling=<value optimized out>, ci=0x9173eb0, cc=<value optimized out>) at vm_insnhelper.c:1864
#22 0x00007f346ddc4559 in vm_call_method_each_type (th=0x25646d0, cfp=0x7f346e2c27d0, calling=0x7ffd59146880, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2163
#23 0x00007f346ddc4d6b in vm_call_method (th=0x25646d0, cfp=0x7f346e2c27d0, calling=<value optimized out>, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2313
#24 0x00007f346ddbc9fb in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:1066
#25 0x00007f346ddc205b in vm_exec (th=0x25646d0) at vm.c:1775
#26 0x00007f346ddc30f1 in invoke_block (th=0x25646d0, captured=<value optimized out>, self=131617520, argc=<value optimized out>, argv=<value optimized out>, passed_block_handler=<value optimized out>,
cref=0x0, splattable=0, is_lambda=0) at vm.c:973
#27 invoke_iseq_block_from_c (th=0x25646d0, captured=<value optimized out>, self=131617520, argc=<value optimized out>, argv=<value optimized out>, passed_block_handler=<value optimized out>, cref=0x0,
splattable=0, is_lambda=0) at vm.c:1019
#28 0x00007f346ddc3cd1 in invoke_block_from_c_splattable (val=<value optimized out>) at vm.c:1037
#29 vm_yield (val=<value optimized out>) at vm.c:1079
#30 rb_yield_0 (val=<value optimized out>) at vm_eval.c:1010
#31 rb_yield (val=<value optimized out>) at vm_eval.c:1023
#32 0x00007f346dc711c0 in rb_protect (proc=0x7f346ddc3bc0 <rb_yield>, data=52, state=0x7ffd59146f4c) at eval.c:906
#33 0x00007f346dd020ab in rb_f_fork (obj=<value optimized out>) at process.c:3715
#34 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c2b90, calling=<value optimized out>, ci=0x7f13230, cc=<value optimized out>) at vm_insnhelper.c:1769
#35 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c2b90, calling=<value optimized out>, ci=0x7f13230, cc=<value optimized out>) at vm_insnhelper.c:1864
#36 0x00007f346ddbd24c in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:967
#37 0x00007f346ddc205b in vm_exec (th=0x25646d0) at vm.c:1775
#38 0x00007f346ddc9544 in invoke_block () at vm.c:973
#39 invoke_iseq_block_from_c () at vm.c:1019
#40 invoke_block_from_c_splattable () at vm.c:1037
#41 vm_yield () at vm.c:1079
#42 rb_yield_0 () at vm_eval.c:1010
#43 loop_i () at vm_eval.c:1088
#44 0x00007f346dc712a4 in rb_rescue2 (b_proc=0x7f346ddc91f0 <loop_i>, data1=0, r_proc=0x7f346dda8260 <loop_stop>, data2=0) at eval.c:838
#45 0x00007f346ddadb9a in vm_call_cfunc_with_frame (th=0x25646d0, reg_cfp=0x7f346e2c2c50, calling=<value optimized out>, ci=0x478d0f0, cc=<value optimized out>) at vm_insnhelper.c:1769
#46 vm_call_cfunc (th=0x25646d0, reg_cfp=0x7f346e2c2c50, calling=<value optimized out>, ci=0x478d0f0, cc=<value optimized out>) at vm_insnhelper.c:1864
#47 0x00007f346ddc4559 in vm_call_method_each_type (th=0x25646d0, cfp=0x7f346e2c2c50, calling=0x7ffd59147710, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2163
#48 0x00007f346ddc4d6b in vm_call_method (th=0x25646d0, cfp=0x7f346e2c2c50, calling=<value optimized out>, ci=<value optimized out>, cc=<value optimized out>) at vm_insnhelper.c:2313Source: resque/resque