Re: mISDN_send: error -12 strikes again

OK, I now see the following deadlock situation (the first lock for each
thread is the lock obtained successfully, the second one is the blocking one)

thread               lockname   lock       file        function              line
0xb4cbfb70           c          0x88835b0  astobj2.c   internal_ao2_callback  657
0xb4cbfb70           chan       0xee93418  channel.c   ast_channel_cmp_cb    1691

Waiting for:                               channel.c   ast_call              5536


0xb3287b70           chan       0xee93418  channel.c   ast_call              5536
0xb3287b70           &chan_lock 0xb5c37c00 chan_lcr.c  lcr_call              2420

Waiting for:                               chan_lcr.c  lcr_request           2067


0xb4ac3b70           &chan_lock 0xb5c37c00 chan_lcr.c  lcr_request           2067
0xb4ac3b70           c          0x88835b0  astobj2.c   internal_ao2_link      493

Waiting for:                               astobj2.c   internal_ao2_callback  657


lotsofthreads        channels   0x88835b0
lotsofthreads        &chan_lock 0xb5c37c00

a classical three-way deadlock.
If someone is interested I can provide the output of "core show locks".
This contains the backtraces of all threads when obtaining the locks.
I can think of two ways to fix this:
- if lcr_call is always called with the chan lock held, we could
  do deadlock avoidance, try to get the &chan_lock and if that fails
  give up the chan lock for some time. But I don't think that's the
  right way (looking into other channel drivers for comparison).
- maybe in lcr_request we should give up the lock before calling into
  asterisk (see thread 0xb4ac3b70)?

GDB backtrace of thread 0xb4ac3b70:
#0  0xb77f6424 in __kernel_vsyscall ()
#1  0xb7508c89 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7504099 in _L_lock_839 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7503f2b in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4  0x08113001 in __ast_pthread_mutex_lock (filename=0x81b8fbc "astobj2.c", lineno=493, func=0x81b91bd "internal_ao2_link", 
    mutex_name=0x81b90b8 "c", t=0x88835b0) at lock.c:244
#5  0x080851f8 in __ao2_lock (user_data=0x88835e0, file=0x81b8fbc "astobj2.c", func=0x81b91bd "internal_ao2_link", line=493, var=0x81b90b8 "c")
    at astobj2.c:157
#6  0x080858f9 in internal_ao2_link (c=0x88835e0, user_data=0xf98bfd8, file=0x81b8fbc "astobj2.c", line=517, func=0x81b91a1 "__ao2_link")
    at astobj2.c:493
#7  0x08085a7a in __ao2_link (c=0x88835e0, user_data=0xf98bfd8) at astobj2.c:517
#8  0x080a803f in __ast_channel_alloc_ap (needqueue=1, state=1, cid_num=0x0, cid_name=0x0, acctcode=0x0, exten=0x0, context=0x0, linkedid=0x0, 
    amaflag=0, file=0xb5c3277f "chan_lcr.c", line=2089, function=0xb5c35210 "lcr_request", name_fmt=0xb5c32a53 "%s/%d", 
    ap1=0xb4ac2b54 "\214u\303\265+Z", ap2=0xb4ac2b54 "\214u\303\265+Z") at channel.c:1312
#9  0x080a82a8 in __ast_channel_alloc (needqueue=1, state=1, cid_num=0x0, cid_name=0x0, acctcode=0x0, exten=0x0, context=0x0, linkedid=0x0, 
    amaflag=0, file=0xb5c3277f "chan_lcr.c", line=2089, function=0xb5c35210 "lcr_request", name_fmt=0xb5c32a53 "%s/%d") at channel.c:1357
#10 0xb5c2c058 in lcr_request (type=0xb3cd4100 "LCR", format=8, requestor=0x0, data=0xb3cd4150, cause=0xb4ac30d4) at chan_lcr.c:2089
#11 0x080b38aa in ast_request (type=0xb3cd4100 "LCR", format=64, requestor=0x0, data=0xb3cd4150, cause=0xb4ac30d4) at channel.c:5508
#12 0x080b2d32 in __ast_request_and_dial (type=0xb3cd4100 "LCR", format=64, requestor=0x0, data=0xb3cd4150, timeout=30000, outstate=0xb4ac32bc, 
    cid_num=0xb3cd441c "0815", cid_name=0x0, oh=0xb4ac317c) at channel.c:5273
#13 0x08146685 in ast_pbx_outgoing_exten (type=0xb3cd4100 "LCR", format=64, data=0xb3cd4150, timeout=30000, context=0xb3cd446c "linecheck", 
    exten=0xb3cd44bc "1", priority=1, reason=0xb4ac32bc, synchronous=1, cid_num=0xb3cd441c "0815", cid_name=0x0, vars=0xb3451ac8, 
    account=0xb3cd455c "2880148465", channel=0xb4ac32b8) at pbx.c:8604
#14 0x08121ac2 in fast_originate (data=0xb3cd4100) at manager.c:3588
#15 0x0818a9c5 in dummy_start (data=0xb3711dd8) at utils.c:1004
#16 0xb7501955 in start_thread () from /lib/i686/cmov/libpthread.so.0
#17 0xb66d25ee in clone () from /lib/i686/cmov/libc.so.6

Backtrace of 0xb3287b70
[Switching to thread 23 (Thread 0xb3287b70 (LWP 1263))]#0  0xb77f6424 in __kernel_vsyscall ()
(gdb) where
#0  0xb77f6424 in __kernel_vsyscall ()
#1  0xb7508c89 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7504099 in _L_lock_839 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7503f2b in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4  0x08113001 in __ast_pthread_mutex_lock (filename=0xb5c3277f "chan_lcr.c", lineno=2420, func=0xb5c351b8 "lcr_call", 
    mutex_name=0xb5c32774 "&chan_lock", t=0xb5c37c00) at lock.c:244
#5  0xb5c28be0 in lcr_call (ast=0xee93448, dest=0xb3ff3ab8 "Ext1/1", timeout=0) at chan_lcr.c:2420
#6  0x080b3a7a in ast_call (chan=0xee93448, addr=0xb3ff3ab8 "Ext1/1", timeout=0) at channel.c:5542
#7  0x080b2f6d in __ast_request_and_dial (type=0xb3ff3a68 "LCR", format=64, requestor=0x0, data=0xb3ff3ab8, timeout=30000, outstate=0xb32872bc, 
    cid_num=0xb3ff3d84 "0815", cid_name=0x0, oh=0xb328717c) at channel.c:5309
#8  0x08146685 in ast_pbx_outgoing_exten (type=0xb3ff3a68 "LCR", format=64, data=0xb3ff3ab8, timeout=30000, context=0xb3ff3dd4 "linecheck", 
    exten=0xb3ff3e24 "1", priority=1, reason=0xb32872bc, synchronous=1, cid_num=0xb3ff3d84 "0815", cid_name=0x0, vars=0xb31042f0, 
    account=0xb3ff3ec4 "4165336598", channel=0xb32872b8) at pbx.c:8604
#9  0x08121ac2 in fast_originate (data=0xb3ff3a68) at manager.c:3588
#10 0x0818a9c5 in dummy_start (data=0xb3ff3ee8) at utils.c:1004
#11 0xb7501955 in start_thread () from /lib/i686/cmov/libpthread.so.0
#12 0xb66d25ee in clone () from /lib/i686/cmov/libc.so.6

Backtrace of
[Switching to thread 31 (Thread 0xb4cbfb70 (LWP 20501))]#0  0xb77f6424 in __kernel_vsyscall ()
#0  0xb77f6424 in __kernel_vsyscall ()
#1  0xb7508c89 in __lll_lock_wait () from /lib/i686/cmov/libpthread.so.0
#2  0xb7504099 in _L_lock_839 () from /lib/i686/cmov/libpthread.so.0
#3  0xb7503f2b in pthread_mutex_lock () from /lib/i686/cmov/libpthread.so.0
#4  0x08113001 in __ast_pthread_mutex_lock (filename=0x81bfed4 "channel.c", lineno=1691, func=0x81c4bb6 "ast_channel_cmp_cb", 
    mutex_name=0x81c1129 "chan", t=0xee93418) at lock.c:244
#5  0x080851f8 in __ao2_lock (user_data=0xee93448, file=0x81bfed4 "channel.c", func=0x81c4bb6 "ast_channel_cmp_cb", line=1691, 
    var=0x81c1129 "chan") at astobj2.c:157
#6  0x080a8ff7 in ast_channel_cmp_cb (obj=0xee93448, arg=0xb4cbdd68, flags=0) at channel.c:1691
#7  0x08085e14 in internal_ao2_callback (c=0x88835e0, flags=0, cb_fn=0x80a8fa7, arg=0xb4cbdd68, data=0x0, type=DEFAULT, tag=0x0, file=0x0, 
    line=0, funcname=0x0) at astobj2.c:669
#8  0x080861d9 in __ao2_callback (c=0x88835e0, flags=0, cb_fn=0x80a8fa7 <ast_channel_cmp_cb>, arg=0xb4cbdd68) at astobj2.c:769
#9  0x080862f5 in __ao2_find (c=0x88835e0, arg=0xb4cbdd68, flags=0) at astobj2.c:796
#10 0x080a9360 in ast_channel_get_full (name=0xb4cbea39 "lcr/23080", name_len=0, exten=0x0, context=0x0) at channel.c:1759
#11 0x080a9394 in ast_channel_get_by_name (name=0xb4cbea39 "lcr/23080") at channel.c:1765
#12 0x0811f89f in action_hangup (s=0xb4cbf134, m=0xb4cbeec8) at manager.c:3019
#13 0x08125077 in process_message (s=0xb4cbf134, m=0xb4cbeec8) at manager.c:4530
#14 0x08125876 in do_message (s=0xb4cbf134) at manager.c:4690
#15 0x08125cda in session_do (data=0xb44234d8) at manager.c:4781
#16 0x0817b377 in handle_tcptls_connection (data=0xb44234d8) at tcptls.c:233
#17 0x0818a9c5 in dummy_start (data=0xb45b35b8) at utils.c:1004
#18 0xb7501955 in start_thread () from /lib/i686/cmov/libpthread.so.0
#19 0xb66d25ee in clone () from /lib/i686/cmov/libc.so.6



Any ideas?

Ralf
-- 
Ralf Schlatterbeck             email: [email protected]