[OpenSIPS-Devel] [ opensips-Bugs-2892636 ] Opensips crash

Mon Nov 9 10:11:19 CET 2009

Bugs item #2892636, was opened at 2009-11-05 17:28
Message generated for change (Comment added) made by kuznetsov82
You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=2892636&group_id=232389

Please note that this message will contain a full copy of the comment thread,
including the initial issue submission, for this request,
not just the latest update.
Category: modules
Group: 1.5.x
Status: Open
Resolution: None
Priority: 5
Private: No
Submitted By: Vladimir Kuznetsov (kuznetsov82)
Assigned to: Anca Vamanu (anca_vamanu)
Summary: Opensips crash

Initial Comment:
server version 1.5.3
callstack:
#0  search_shtable (htable=0x2adf94a1e2e0, callid=
      {s = 0x74212e "55525-14278 at 10.2.176.220\r\nCSeq: 3 SUBSCRIBE\r\nContact: sip:andrey11 at 10.2.176.220:5061\r\nMax-Forwards: 68\r\nExpires: 5\r\nEvent: presence\r\nSubject: Performance Test\r\nContent-Type: application/sdp\r\nContent-L"..., len = 24}, to_tag=
      {s = 0x2adf9d2b118e "70a5b204a9409a36294d5c67c6ad5ef1-2fc8\r\nCall-ID: 55525-14278 at 10.2.176.220\r\nCSeq: 3 SUBSCRIBE\r\nExpires: 5\r\nContact: <sip:94.25.209.130:5060>\r\nServer: Yota voip server 1.5.3-1.2.0-800\r\nContent-Length: 0\r"..., len = 37}, from_tag=
      {s = 0x7420f0 "14278SIPpTag0055525\r\nTo: sut <sip:andrey11 at yota.ru>\r\nCall-ID: 55525-14278 at 10.2.176.220\r\nCSeq: 3 SUBSCRIBE\r\nContact: sip:andrey11 at 10.2.176.220:5061\r\nMax-Forwards: 68\r\nExpires: 5\r\nEvent: presence\r\nSubje"..., len = 19}, hash_code=1280) at hash.c:110
#1  0x00002adf913a1ab2 in update_shtable (htable=0x2adf94a1e2e0, hash_code=80, subs=0x7fff1b4271a0, type=4) at hash.c:342
#2  0x00002adf913b09dc in notify (subs=0x7fff1b4271a0, watcher_subs=0x0, n_body=0x0, force_null_body=0) at notify.c:1776
#3  0x00002adf913c3dc9 in update_subscription (msg=<value optimized out>, subs=0x7fff1b4271a0, init_req=<value optimized out>) at subscribe.c:418
#4  0x00002adf913cae4c in handle_subscribe (msg=0x7dd0a0, str1=<value optimized out>, str2=<value optimized out>) at subscribe.c:697
#5  0x000000000040ddfc in do_action (a=0x79f3c0, msg=0x7dd0a0) at action.c:962
#6  0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#7  0x000000000040ec40 in do_action (a=0x79f710, msg=0x7dd0a0) at action.c:706
#8  0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#9  0x000000000040ec40 in do_action (a=0x79fdb0, msg=0x7dd0a0) at action.c:706
#10 0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#11 0x000000000040fc27 in do_action (a=0x79fe80, msg=0x7dd0a0) at action.c:712
#12 0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#13 0x000000000040fc27 in do_action (a=0x79ff50, msg=0x7dd0a0) at action.c:712
#14 0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#15 0x000000000040ebac in do_action (a=0x7824c0, msg=0x7dd0a0) at action.c:119
#16 0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#17 0x000000000040ec40 in do_action (a=0x782590, msg=0x7dd0a0) at action.c:706
#18 0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#19 0x000000000040ec40 in do_action (a=0x784180, msg=0x7dd0a0) at action.c:706
#20 0x000000000041089e in run_action_list (a=<value optimized out>, msg=0x7dd0a0) at action.c:139
#21 0x0000000000410bf9 in run_top_route (a=0x773bb8, msg=0x7dd0a0) at action.c:119
#22 0x000000000044f4df in receive_msg (
    buf=0x741fe0 "SUBSCRIBE sip:94.25.209.130:5060 SIP/2.0\r\nRecord-Route: <sip:94.25.209.132;lr=on;ftag=14278SIPpTag0055525>\r\nVia: SIP/2.0/UDP 94.25.209.132;branch=z9hG4bK6236.7f93e02.0\r\nVia: SIP/2.0/UDP 10.2.176.220:5"..., len=546, rcv_info=0x7fff1b4293a0) at receive.c:165
#23 0x000000000048efce in udp_rcv_loop () at udp_server.c:449
#24 0x0000000000427a8a in main (argc=7, argv=0x7fff1b4295a8) at main.c:779

In core dump I can see that variable 's' has not valid value. 'hash_code' value is 1280. I think in some place in the code 1280-record in htable was deleted without lock in the same time with search_shtable was called. I can see only this reason for crash in this situation. I trying to resolve this bug now, but I need help from this module developer...

----------------------------------------------------------------------

>Comment By: Vladimir Kuznetsov (kuznetsov82)
Date: 2009-11-09 12:11

Message:
I can reproduce this crash with SUBSCRIBE requests- -about 20 requests per
second during 30-40 minutes.

----------------------------------------------------------------------

Comment By: Vladimir Kuznetsov (kuznetsov82)
Date: 2009-11-05 18:17

Message:
I see((( No, this parameter has default value = 512. 
GDB is crazy now(( On frame #2 hash_code == 37, on frame 1 hash_code ==
80, on frame 0 hash_code == 1280. Now I trying to crash opensips server
with valgrind and memcheck utilities...

----------------------------------------------------------------------

Comment By: Anca Vamanu (anca_vamanu)
Date: 2009-11-05 18:09

Message:
Hi Vladimir,

Have you set the subs_htable_size module parameter? By default the maximum
value for hash code is 512.

Regards,
Anca 

----------------------------------------------------------------------

Comment By: Vladimir Kuznetsov (kuznetsov82)
Date: 2009-11-05 17:47

Message:
just forgot...
htable[hash_code].entries == 0 in the core dump.

----------------------------------------------------------------------

You can respond by visiting: 
https://sourceforge.net/tracker/?func=detail&atid=1086410&aid=2892636&group_id=232389