[sr-dev] git:master:9c3ea838: dialog: re-entrant mutex for dialogs hash table slots

Daniel-Constantin Mierla miconda at gmail.com
Mon Aug 10 12:08:57 CEST 2015 

The first 6 frames of the backtrace are missing the debugging symbols --
no file name and line -- do you get the same for all traces?

Also, some more details if you have them: can it be reproduced? how
quick is ending up in deadlock? do you get any error messages in the
syslog printed by dialog module? any event_route from dialog module?

Cheers,
Daniel

On 10/08/15 10:14, Pawel Kuzak wrote:
> No, we are not using any other module on top of dialog, also not cnxcc.
>
> Here 3 backtraces out of 12 deadlocked processes (if you need all of
> them please tell :-) ):
>
>> (gdb) bt
>> #0  0x00007f7e98cfd8e9 in syscall () from /lib/libc.so.6
>> #1  0x00007f7e9359146a in ?? () from /usr/lib/kamailio/modules/dialog.so
>> #2  0x00007f7e9359616d in ?? () from /usr/lib/kamailio/modules/dialog.so
>> #3  0x00007f7e93596947 in get_dlg () from
>> /usr/lib/kamailio/modules/dialog.so
>> #4  0x00007f7e9358d8a2 in dlg_get_msg_dialog () from
>> /usr/lib/kamailio/modules/dialog.so
>> #5  0x00007f7e935ac77f in pv_get_dlg_variable () from
>> /usr/lib/kamailio/modules/dialog.so
>> #6  0x00000000004a046c in pv_get_spec_value (msg=0x7f7e98346208,
>> sp=0x7f7e97fb30d0, value=0x7fffb0805630) at pvapi.c:1266
>> #7  0x00000000004d063a in rv_defined (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rv=0x7f7e97fb30c8, cache=0x0)
>> at rvalue.c:1859
>> #8  0x00000000004d06ed in int_rve_defined (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rve=0x7f7e97fb30c0) at
>> rvalue.c:1895
>> #9  0x00000000004d14e5 in rval_expr_eval_int (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rve=0x7f7e97fb3fe0) at
>> rvalue.c:2117
>> #10 0x00000000004d0adc in rval_expr_eval_int (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805dd8, rve=0x7f7e97fb4e20) at
>> rvalue.c:1960
>> #11 0x000000000041c912 in do_action (h=0x7fffb0806510,
>> a=0x7f7e97fc1418, msg=0x7f7e98346208) at action.c:1075
>> #12 0x0000000000425b01 in run_actions (h=0x7fffb0806510,
>> a=0x7f7e97fc1418, msg=0x7f7e98346208) at action.c:1599
>> #13 0x000000000041a9cc in do_action (h=0x7fffb0806510,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:715
>> #14 0x0000000000425b01 in run_actions (h=0x7fffb0806510,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:1599
>> #15 0x00000000004261fb in run_actions_safe (h=0x7fffb0807520,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:1664
>> #16 0x00000000004cd997 in rval_get_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, i=0x7fffb0806978, rv=0x7f7e97d20500, cache=0x0)
>> at rvalue.c:924
>> #17 0x00000000004d078b in rval_expr_eval_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, res=0x7fffb0806978, rve=0x7f7e97d204f8) at
>> rvalue.c:1918
>> #18 0x00000000004d09a2 in rval_expr_eval_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, res=0x7fffb0806de8, rve=0x7f7e97d20c18) at
>> rvalue.c:1926
>> #19 0x000000000041c912 in do_action (h=0x7fffb0807520,
>> a=0x7f7e97d23890, msg=0x7f7e98346208) at action.c:1075
>> #20 0x0000000000425b01 in run_actions (h=0x7fffb0807520,
>> a=0x7f7e97d20198, msg=0x7f7e98346208) at action.c:1599
>> #21 0x000000000041cb82 in do_action (h=0x7fffb0807520,
>> a=0x7f7e97dce4a8, msg=0x7f7e98346208) at action.c:1090
>> #22 0x0000000000425b01 in run_actions (h=0x7fffb0807520,
>> a=0x7f7e97cb6bb8, msg=0x7f7e98346208) at action.c:1599
>> #23 0x00000000004262c3 in run_top_route (a=0x7f7e97cb6bb8,
>> msg=0x7f7e98346208, c=0x0) at action.c:1685
>> #24 0x00000000004ac5d5 in receive_msg (
>>     buf=0x937360 "INVITE sip:49789654123 at XXX.XXX.XXX.XXX:5060
>> SIP/2.0\r\nRecord-Route: <sip:XXX.XXX.XXX.XXX;lr=on>\r\nVia:
>> SIP/2.0/UDP
>> XXX.XXX.XXX.XXX;branch=z9hG4bK8081.1d9a97b13c3c42328b572ca0ddd297aa."...,
>> len=1542, rcv_info=0x7fffb08077e0) at receive.c:212
>> #25 0x000000000054808d in udp_rcv_loop () at udp_server.c:536
>> #26 0x0000000000472f6d in main_loop () at main.c:1620
>> #27 0x000000000047692e in main (argc=13, argv=0x7fffb0807b28) at
>> main.c:2566
>
>> (gdb) bt
>> #0  0x00007f7e98cfd8e9 in syscall () from /lib/libc.so.6
>> #1  0x00007f7e9359146a in ?? () from /usr/lib/kamailio/modules/dialog.so
>> #2  0x00007f7e9359616d in ?? () from /usr/lib/kamailio/modules/dialog.so
>> #3  0x00007f7e93596947 in get_dlg () from
>> /usr/lib/kamailio/modules/dialog.so
>> #4  0x00007f7e9358d8a2 in dlg_get_msg_dialog () from
>> /usr/lib/kamailio/modules/dialog.so
>> #5  0x00007f7e935ac77f in pv_get_dlg_variable () from
>> /usr/lib/kamailio/modules/dialog.so
>> #6  0x00000000004a046c in pv_get_spec_value (msg=0x7f7e98346208,
>> sp=0x7f7e97fb30d0, value=0x7fffb0805630) at pvapi.c:1266
>> #7  0x00000000004d063a in rv_defined (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rv=0x7f7e97fb30c8, cache=0x0)
>> at rvalue.c:1859
>> #8  0x00000000004d06ed in int_rve_defined (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rve=0x7f7e97fb30c0) at
>> rvalue.c:1895
>> #9  0x00000000004d14e5 in rval_expr_eval_int (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rve=0x7f7e97fb3fe0) at
>> rvalue.c:2117
>> #10 0x00000000004d0adc in rval_expr_eval_int (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805dd8, rve=0x7f7e97fb4e20) at
>> rvalue.c:1960
>> #11 0x000000000041c912 in do_action (h=0x7fffb0806510,
>> a=0x7f7e97fc1418, msg=0x7f7e98346208) at action.c:1075
>> #12 0x0000000000425b01 in run_actions (h=0x7fffb0806510,
>> a=0x7f7e97fc1418, msg=0x7f7e98346208) at action.c:1599
>> #13 0x000000000041a9cc in do_action (h=0x7fffb0806510,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:715
>> #14 0x0000000000425b01 in run_actions (h=0x7fffb0806510,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:1599
>> #15 0x00000000004261fb in run_actions_safe (h=0x7fffb0807520,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:1664
>> #16 0x00000000004cd997 in rval_get_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, i=0x7fffb0806978, rv=0x7f7e97d20500, cache=0x0)
>> at rvalue.c:924
>> #17 0x00000000004d078b in rval_expr_eval_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, res=0x7fffb0806978, rve=0x7f7e97d204f8) at
>> rvalue.c:1918
>> #18 0x00000000004d09a2 in rval_expr_eval_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, res=0x7fffb0806de8, rve=0x7f7e97d20c18) at
>> rvalue.c:1926
>> #19 0x000000000041c912 in do_action (h=0x7fffb0807520,
>> a=0x7f7e97d23890, msg=0x7f7e98346208) at action.c:1075
>> #20 0x0000000000425b01 in run_actions (h=0x7fffb0807520,
>> a=0x7f7e97d20198, msg=0x7f7e98346208) at action.c:1599
>> #21 0x000000000041cb82 in do_action (h=0x7fffb0807520,
>> a=0x7f7e97dce4a8, msg=0x7f7e98346208) at action.c:1090
>> #22 0x0000000000425b01 in run_actions (h=0x7fffb0807520,
>> a=0x7f7e97cb6bb8, msg=0x7f7e98346208) at action.c:1599
>> #23 0x00000000004262c3 in run_top_route (a=0x7f7e97cb6bb8,
>> msg=0x7f7e98346208, c=0x0) at action.c:1685
>> #24 0x00000000004ac5d5 in receive_msg (
>>     buf=0x937360 "INVITE sip:49321654987 at XXX.XXX.XXX.XXX:5060
>> SIP/2.0\r\nRecord-Route: <sip:XXX.XXX.XXX.XXX;lr=on>\r\nVia:
>> SIP/2.0/UDP
>> XXX.XXX.XXX.XXX;branch=z9hG4bKa2d3.8d04ff9e19f9b1e4e9cbcb9bbae4cf41"...,
>> len=1555, rcv_info=0x7fffb08077e0) at receive.c:212
>> #25 0x000000000054808d in udp_rcv_loop () at udp_server.c:536
>> #26 0x0000000000472f6d in main_loop () at main.c:1620
>> #27 0x000000000047692e in main (argc=13, argv=0x7fffb0807b28) at
>> main.c:2566
>
>> (gdb) bt
>> #0  0x00007f7e98cfd8e9 in syscall () from /lib/libc.so.6
>> #1  0x00007f7e9359146a in ?? () from /usr/lib/kamailio/modules/dialog.so
>> #2  0x00007f7e9359616d in ?? () from /usr/lib/kamailio/modules/dialog.so
>> #3  0x00007f7e93596767 in get_dlg () from
>> /usr/lib/kamailio/modules/dialog.so
>> #4  0x00007f7e9358d8a2 in dlg_get_msg_dialog () from
>> /usr/lib/kamailio/modules/dialog.so
>> #5  0x00007f7e935ac77f in pv_get_dlg_variable () from
>> /usr/lib/kamailio/modules/dialog.so
>> #6  0x00000000004a046c in pv_get_spec_value (msg=0x7f7e98346208,
>> sp=0x7f7e97fb30d0, value=0x7fffb0805630) at pvapi.c:1266
>> #7  0x00000000004d063a in rv_defined (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rv=0x7f7e97fb30c8, cache=0x0)
>> at rvalue.c:1859
>> #8  0x00000000004d06ed in int_rve_defined (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rve=0x7f7e97fb30c0) at
>> rvalue.c:1895
>> #9  0x00000000004d14e5 in rval_expr_eval_int (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805968, rve=0x7f7e97fb3fe0) at
>> rvalue.c:2117
>> #10 0x00000000004d0adc in rval_expr_eval_int (h=0x7fffb0806510,
>> msg=0x7f7e98346208, res=0x7fffb0805dd8, rve=0x7f7e97fb4e20) at
>> rvalue.c:1960
>> #11 0x000000000041c912 in do_action (h=0x7fffb0806510,
>> a=0x7f7e97fc1418, msg=0x7f7e98346208) at action.c:1075
>> #12 0x0000000000425b01 in run_actions (h=0x7fffb0806510,
>> a=0x7f7e97fc1418, msg=0x7f7e98346208) at action.c:1599
>> #13 0x000000000041a9cc in do_action (h=0x7fffb0806510,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:715
>> #14 0x0000000000425b01 in run_actions (h=0x7fffb0806510,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:1599
>> #15 0x00000000004261fb in run_actions_safe (h=0x7fffb0807520,
>> a=0x7f7e97d203b8, msg=0x7f7e98346208) at action.c:1664
>> #16 0x00000000004cd997 in rval_get_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, i=0x7fffb0806978, rv=0x7f7e97d20500, cache=0x0)
>> at rvalue.c:924
>> #17 0x00000000004d078b in rval_expr_eval_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, res=0x7fffb0806978, rve=0x7f7e97d204f8) at
>> rvalue.c:1918
>> #18 0x00000000004d09a2 in rval_expr_eval_int (h=0x7fffb0807520,
>> msg=0x7f7e98346208, res=0x7fffb0806de8, rve=0x7f7e97d20c18) at
>> rvalue.c:1926
>> #19 0x000000000041c912 in do_action (h=0x7fffb0807520,
>> a=0x7f7e97d23890, msg=0x7f7e98346208) at action.c:1075
>> #20 0x0000000000425b01 in run_actions (h=0x7fffb0807520,
>> a=0x7f7e97d20198, msg=0x7f7e98346208) at action.c:1599
>> #21 0x000000000041cb82 in do_action (h=0x7fffb0807520,
>> a=0x7f7e97dce4a8, msg=0x7f7e98346208) at action.c:1090
>> #22 0x0000000000425b01 in run_actions (h=0x7fffb0807520,
>> a=0x7f7e97cb6bb8, msg=0x7f7e98346208) at action.c:1599
>> #23 0x00000000004262c3 in run_top_route (a=0x7f7e97cb6bb8,
>> msg=0x7f7e98346208, c=0x0) at action.c:1685
>> #24 0x00000000004ac5d5 in receive_msg (
>>     buf=0x937360 "INVITE sip:491234567 at XXX.XXX.XXX.XXX:5060
>> SIP/2.0\r\nRecord-Route: <sip:XXX.XXX.XXX.XXX;lr=on>\r\nVia:
>> SIP/2.0/UDP
>> XXX.XXX.XXX.XXX;branch=z9hG4bK41dd.793c6bda464296fb439170efecc7c405."...,
>> len=1542, rcv_info=0x7fffb08077e0) at receive.c:212
>> #25 0x000000000054808d in udp_rcv_loop () at udp_server.c:536
>> #26 0x0000000000472f6d in main_loop () at main.c:1620
>> #27 0x000000000047692e in main (argc=13, argv=0x7fffb0807b28) at
>> main.c:2566
>
> Thank you for you help.
>
> Paul
>
>
> On 07.08.2015 14:12, Daniel-Constantin Mierla wrote:
>> Hello,
>>
>> are you using cnxcc or other module on top of dialog?
>>
>> The reason was cnxcc, as it apparently does some lower level dialog ops
>> that involve locking in case of a dialog being already locked.
>>
>> Have you got the backtrace in case of the lock you encountered to see
>> what situations ended there?
>>
>> Cheers,
>> Daniel
>>
>> On 07/08/15 13:14, Pawel Kuzak wrote:
>>> Hi Daniel,
>>>
>>> We are testing Kamailio 4.1.8 and we are running into a deadlock in
>>> the dialog module. I therefore searched the git commits if something
>>> has been done to the locking in dialog module and I found this commit.
>>> I wanted to ask you if there was a specific motivation for you to
>>> change this. I mean in the previous locking (e.g. like it is still in
>>> 4.1.8), do you see potential scenarios which could lead to a deadlock?
>>> Obviously there is one, but at a first glance checking the code
>>> acquiring and releasing locks looks fine.
>>> Of course we will now give 4.2 a try. I am just curious, that's why I
>>> am asking :-) .
>>>
>>> Regards,
>>> Paul
>>>
>>> On 16.06.2015 15:18, Daniel-Constantin Mierla wrote:
>>>> Module: kamailio
>>>> Branch: master
>>>> Commit: 9c3ea838b31039ac067e17d519df67b64b0dada1
>>>> URL:
>>>> https://github.com/kamailio/kamailio/commit/9c3ea838b31039ac067e17d519df67b64b0dada1
>>>>
>>>>
>>>> Author: Daniel-Constantin Mierla <miconda at gmail.com>
>>>> Committer: Daniel-Constantin Mierla <miconda at gmail.com>
>>>> Date: 2015-06-16T15:18:27+02:00
>>>>
>>>> dialog: re-entrant mutex for dialogs hash table slots
>>>>
>>>> - changed from a lock set usage to per slot lock field
>>>>
>>>> ---
>>>>
>>>> Modified: modules/dialog/dlg_hash.c
>>>> Modified: modules/dialog/dlg_hash.h
>>>>
>>>> ---
>>>>
>>>> Diff:
>>>> https://github.com/kamailio/kamailio/commit/9c3ea838b31039ac067e17d519df67b64b0dada1.diff
>>>>
>>>> Patch:
>>>> https://github.com/kamailio/kamailio/commit/9c3ea838b31039ac067e17d519df67b64b0dada1.patch
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> sr-dev mailing list
>>>> sr-dev at lists.sip-router.org
>>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>>>
>>> _______________________________________________
>>> sr-dev mailing list
>>> sr-dev at lists.sip-router.org
>>> http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
>

-- 
Daniel-Constantin Mierla
http://twitter.com/#!/miconda - http://www.linkedin.com/in/miconda
Book: SIP Routing With Kamailio - http://www.asipto.com

More information about the sr-dev mailing list