[asterisk-dev] Asterisk 1.8 Deadlock between timerfd and channel list

Sat May 21 22:55:08 CDT 2011

I don't yet have a small snippit of dialplan that can consistently 
reproduce the problem, but I have been seeing it very very often in my 
testing.

Thread 0xb5feab70 is handling SIP/callqueue_test-00000017
Thread 0xb609eb70 is handling Local/203683 at _CallQueue_Dialer-523b;2 
("GET", "FULL", "VARIABLE", "${CHANNELS()}")

Thread 0xb5feab70 has the SIP/callqueue_test-00000017 locked while 
waiting for a timertd expiration.

Thread 0xb609eb70 is traversing the channel list and locking channels to 
get the channel names.  The thread is waiting on the lock for channel 
SIP/callqueue_test-00000017, which will indefinitely block on the timer fd.

I don't really understand any of the timer but, but should the 
expiration check be made non-blocking and time out after a reasonable 
amount of time?

=======================================================================
=== Currently Held Locks ==============================================
=======================================================================
===
=== <pending> <lock#> (<file>): <lock type> <line num> <function> <lock 
name> <lock addr> (times locked)
===
=== Thread ID: -1241601168 [0xb5feab70] (pbx_thread           started at 
[ 5045] pbx.c ast_pbx_start())
=== ---> Lock #0 (channel.c): MUTEX 4025 __ast_read chan 0xeacb660 (1)
         /usr/sbin/asterisk(ast_bt_get_addresses+0x19) [0x81199f9]
         /usr/sbin/asterisk(__ast_pthread_mutex_trylock+0xae) [0x8113932]
         /usr/sbin/asterisk(__ao2_trylock+0x48) [0x8085d48]
         /usr/lib/asterisk/modules/chan_sip.so(+0x7234c) [0xb738834c]
         /usr/lib/asterisk/modules/chan_sip.so(+0x71ff1) [0xb7387ff1]
         /usr/sbin/asterisk(ast_io_wait+0x144) [0x810e1b8]
         /usr/lib/asterisk/modules/chan_sip.so(+0x73e22) [0xb7389e22]
         /usr/sbin/asterisk() [0x818a585]
         /lib/i686/cmov/libpthread.so.0(+0x5c39) [0xb7c73c39]
         /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb7e808ee]
=== -------------------------------------------------------------------
===
=== Thread ID: -1240863888 [0xb609eb70] (pbx_thread           started at 
[ 5045] pbx.c ast_pbx_start())
=== ---> Waiting for Lock #0 (func_channel.c): MUTEX 565 
func_channels_read c 0xeacb660 (1)
         /usr/sbin/asterisk(ast_bt_get_addresses+0x19) [0x81199f9]
         /usr/sbin/asterisk(__ast_pthread_mutex_lock+0xae) [0x81135ca]
         /usr/sbin/asterisk(__ao2_lock+0x48) [0x8085cb4]
         /usr/lib/asterisk/modules/func_channel.so(+0x3b7b) [0xb700cb7b]
         /usr/sbin/asterisk(ast_func_read2+0x1fd) [0x81371f0]
         /usr/sbin/asterisk(ast_str_substitute_variables_full+0x35c) 
[0x81376fe]
         /usr/sbin/asterisk(ast_str_substitute_variables+0x35) [0x8137bec]
         /usr/lib/asterisk/modules/res_agi.so(+0x94e8) [0xb77c54e8]
         /usr/lib/asterisk/modules/res_agi.so(+0xb643) [0xb77c7643]
         /usr/lib/asterisk/modules/res_agi.so(+0xbe64) [0xb77c7e64]
         /usr/lib/asterisk/modules/res_agi.so(+0xd110) [0xb77c9110]
         /usr/lib/asterisk/modules/res_agi.so(+0xd254) [0xb77c9254]
         /usr/sbin/asterisk(pbx_exec+0x1d0) [0x812fff1]
         /usr/sbin/asterisk() [0x81388df]
         /usr/sbin/asterisk(ast_spawn_extension+0x53) [0x813a132]
         /usr/sbin/asterisk() [0x813aa26]
         /usr/sbin/asterisk() [0x813c2fc]
         /usr/sbin/asterisk() [0x818a585]
         /lib/i686/cmov/libpthread.so.0(+0x5c39) [0xb7c73c39]
         /lib/i686/cmov/libc.so.6(clone+0x5e) [0xb7e808ee]
=== --- ---> Locked Here: channel.c line 4025 (__ast_read)
=== -------------------------------------------------------------------
===
=======================================================================

backtrace of thread 0xb5feab70
#0  0xffffe424 in __kernel_vsyscall ()
#1  0xb7c7af02 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7c763a9 in _L_lock_819 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7c7623b in __pthread_mutex_lock (mutex=0xeacb660) at 
pthread_mutex_lock.c:82
#4  0xb7e8dba6 in pthread_mutex_lock (mutex=0xeacb660) at forward.c:182
#5  0x08113635 in __ast_pthread_mutex_lock (filename=0xb700d018 
"func_channel.c", lineno=565, func=0xb700d63a "func_channels_read", 
mutex_name=0xb700d347 "c", t=0xeacb660) at lock.c:244
#6  0x08085cb4 in __ao2_lock (user_data=0xeacb690, file=0xb700d018 
"func_channel.c", func=0xb700d63a "func_channels_read", line=565, 
var=0xb700d347 "c") at astobj2.c:157
#7  0xb700cb7b in func_channels_read (chan=0xed13730, 
function=0xb6098d00 "CHANNELS", data=0xb6098d09 "", buf=0xeb56354 "", 
maxlen=4096) at func_channel.c:565
#8  0x081371f0 in ast_func_read2 (chan=0xed13730, function=0xed620e4 
"CHANNELS()", str=0xb6098da8, maxlen=0) at pbx.c:3554
#9  0x081376fe in ast_str_substitute_variables_full (buf=0xb6098e68, 
maxlen=0, c=0xed13730, headp=0x0, templ=0xb609914a "${CHANNELS()}", 
used=0xb6098e3c) at pbx.c:3680
#10 0x08137bec in ast_str_substitute_variables (buf=0xb6098e68, 
maxlen=0, chan=0xed13730, templ=0xb609914a "${CHANNELS()}") at pbx.c:3767
#11 0xb77c54e8 in handle_getvariablefull (chan=0xed13730, 
agi=0xb60999e0, argc=4, argv=0xb6098ec8) at res_agi.c:2503
#12 0xb77c7643 in agi_handle_command (chan=0xed13730, agi=0xb60999e0, 
buf=0xb6099138 "GET", dead=0) at res_agi.c:3275
#13 0xb77c7e64 in run_agi (chan=0xed13730, request=0xb60999a0 
"agi://127.0.0.1:2000", agi=0xb60999e0, pid=-1, status=0xb60999d4, 
dead=0, argc=1, argv=0xb60999f8) at res_agi.c:3435
#14 0xb77c9110 in agi_exec_full (chan=0xed13730, data=0xb609bdac 
"agi://127.0.0.1:2000", enhanced=0, dead=0) at res_agi.c:3722
#15 0xb77c9254 in agi_exec (chan=0xed13730, data=0xb609bdac 
"agi://127.0.0.1:2000") at res_agi.c:3756
#16 0x0812fff1 in pbx_exec (c=0xed13730, app=0x854c930, data=0xb609bdac 
"agi://127.0.0.1:2000") at pbx.c:1406
#17 0x081388df in pbx_extension_helper (c=0xed13730, con=0x0, 
context=0xed13a9c "_CallQueue_Dialer", exten=0xed13aec "203683", 
priority=2, label=0x0, callerid=0xed0c438 "14",
     action=E_SPAWN, found=0xb609e230, combined_find_spawn=1) at pbx.c:4085
#18 0x0813a132 in ast_spawn_extension (c=0xed13730, context=0xed13a9c 
"_CallQueue_Dialer", exten=0xed13aec "203683", priority=2, 
callerid=0xed0c438 "14", found=0xb609e230,
     combined_find_spawn=1) at pbx.c:4608
#19 0x0813aa26 in __ast_pbx_run (c=0xed13730, args=0x0) at pbx.c:4706
#20 0x0813c2fc in pbx_thread (data=0xed13730) at pbx.c:5024
#21 0x0818a585 in dummy_start (data=0xec8b440) at utils.c:973
#22 0xb7c73c39 in start_thread (arg=0xb609eb70) at pthread_create.c:304
#23 0xb7e808ee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

backtrace of thread 0xb609eb70
#0  0xffffe424 in __kernel_vsyscall ()
#1  0xb7c7af02 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7c763a9 in _L_lock_819 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7c7623b in __pthread_mutex_lock (mutex=0xeacb660) at 
pthread_mutex_lock.c:82
#4  0xb7e8dba6 in pthread_mutex_lock (mutex=0xeacb660) at forward.c:182
#5  0x08113635 in __ast_pthread_mutex_lock (filename=0xb700d018 
"func_channel.c", lineno=565, func=0xb700d63a "func_channels_read", 
mutex_name=0xb700d347 "c", t=0xeacb660) at lock.c:244
#6  0x08085cb4 in __ao2_lock (user_data=0xeacb690, file=0xb700d018 
"func_channel.c", func=0xb700d63a "func_channels_read", line=565, 
var=0xb700d347 "c") at astobj2.c:157
#7  0xb700cb7b in func_channels_read (chan=0xed13730, 
function=0xb6098d00 "CHANNELS", data=0xb6098d09 "", buf=0xeb56354 "", 
maxlen=4096) at func_channel.c:565
#8  0x081371f0 in ast_func_read2 (chan=0xed13730, function=0xed620e4 
"CHANNELS()", str=0xb6098da8, maxlen=0) at pbx.c:3554
#9  0x081376fe in ast_str_substitute_variables_full (buf=0xb6098e68, 
maxlen=0, c=0xed13730, headp=0x0, templ=0xb609914a "${CHANNELS()}", 
used=0xb6098e3c) at pbx.c:3680
#10 0x08137bec in ast_str_substitute_variables (buf=0xb6098e68, 
maxlen=0, chan=0xed13730, templ=0xb609914a "${CHANNELS()}") at pbx.c:3767
#11 0xb77c54e8 in handle_getvariablefull (chan=0xed13730, 
agi=0xb60999e0, argc=4, argv=0xb6098ec8) at res_agi.c:2503
#12 0xb77c7643 in agi_handle_command (chan=0xed13730, agi=0xb60999e0, 
buf=0xb6099138 "GET", dead=0) at res_agi.c:3275
#13 0xb77c7e64 in run_agi (chan=0xed13730, request=0xb60999a0 
"agi://127.0.0.1:2000", agi=0xb60999e0, pid=-1, status=0xb60999d4, 
dead=0, argc=1, argv=0xb60999f8) at res_agi.c:3435
#14 0xb77c9110 in agi_exec_full (chan=0xed13730, data=0xb609bdac 
"agi://127.0.0.1:2000", enhanced=0, dead=0) at res_agi.c:3722
#15 0xb77c9254 in agi_exec (chan=0xed13730, data=0xb609bdac 
"agi://127.0.0.1:2000") at res_agi.c:3756
#16 0x0812fff1 in pbx_exec (c=0xed13730, app=0x854c930, data=0xb609bdac 
"agi://127.0.0.1:2000") at pbx.c:1406
#17 0x081388df in pbx_extension_helper (c=0xed13730, con=0x0, 
context=0xed13a9c "_CallQueue_Dialer", exten=0xed13aec "203683", 
priority=2, label=0x0, callerid=0xed0c438 "14",
     action=E_SPAWN, found=0xb609e230, combined_find_spawn=1) at pbx.c:4085
#18 0x0813a132 in ast_spawn_extension (c=0xed13730, context=0xed13a9c 
"_CallQueue_Dialer", exten=0xed13aec "203683", priority=2, 
callerid=0xed0c438 "14", found=0xb609e230,
     combined_find_spawn=1) at pbx.c:4608
#19 0x0813aa26 in __ast_pbx_run (c=0xed13730, args=0x0) at pbx.c:4706
#20 0x0813c2fc in pbx_thread (data=0xed13730) at pbx.c:5024
#21 0x0818a585 in dummy_start (data=0xec8b440) at utils.c:973
#22 0xb7c73c39 in start_thread (arg=0xb609eb70) at pthread_create.c:304
#23 0xb7e808ee in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130