2 possible bugs - Modules Dialog and ACC

2012-11-24
2013-05-09
  • Daniel Zanutti
    Daniel Zanutti
    2012-11-24

    Hi everyone

    I have 2 critical situations that I need help to figure out the real problem. Please, someone help :)

    My opensips is 1.8.2, MySQL 5.1.63, installed from APT on Debian Squeeze X64.

    1) Some times a day, my opensips is crashing on dialog module. How to identify  where the problem is hapenning and also how to report the bug?
    This appears on syslog:

    kernel: [400285.244331] opensips[5086]: segfault at 20 ip 00007f0051cd7725 sp 00007fff12e41220 error 4 in dialog.so[7f0051ca0000+4b000]
    /sbin/opensips[5038]: INFO:core:handle_sigs: child process 5086 exited by a signal 11
    /sbin/opensips[5038]: INFO:core:handle_sigs: core was not generated
    /sbin/opensips[5038]: INFO:core:handle_sigs: terminating due to SIGCHLD
    


    2) Second problem is with ACC module. I have 2 opensips running, sending and receiving calls each other… I checked that SOME calls, randomic, don't record the BYE request on ACC.

    On a normal call, i can check on syslog the INVITE:

    /sbin/opensips[12015]: ACC: transaction answered: timestamp=1353662114;method=INVITE;from_tag=as3315fe8a;to_tag=as2fe8f86b;call_id=2aefdeeb5837524a50a878c85210db19@x.x.x.x:5060;code=200;reason=OK
    

    and BYE:

    /sbin/opensips[12004]: ACC: transaction answered: timestamp=1353662118;method=BYE;from_tag=as3315fe8a;to_tag=as2fe8f86b;call_id=2aefdeeb5837524a50a878c85210db19@x.x.x.x:5060;code=200;reason=OK
    

    But on some calls, just the INVITE:

    sbin/opensips[2024]: ACC: transaction answered: timestamp=1353582441;method=INVITE;from_tag=as6c53d5bd;to_tag=1c431879610;call_id=c1434b259b666c921e0c67752f09c01@189.20.204.170:5060;code=200;reason=OK
    

    How to debug this? Is happening randomly, not for specific calls.

    I didn't check if happens the opposite, ACC logging BYE and not INVITE.

    Any help is appreciated.

     
  • Daniel Zanutti
    Daniel Zanutti
    2012-11-24

    When i mean ACC is not logging, it is also not writing to DB… so, maybe a bug.

    Thanks

     
  • Daniel Zanutti
    Daniel Zanutti
    2012-11-25

    I could get a new call on a dev machine. See detailed log:

    Nov 25 14:29:54 s05 /sbin/opensips[9352]: INVITE AUTENTICADO - 1005@sip.domain.com (Si=46.182.2.2) - Dest: sip:22223333@sip.domain.com:5060 (1205-17251@46.182.2.2)
    Nov 25 14:29:54 s05 /sbin/opensips[9352]: DBG:dialog:build_new_dlg: new dialog 0x7f5b61498e80 (c=1205-17251@46.182.2.2,f=sip:1005@sip.domain.com:5060,t=sip:22223333@sip.domain.com:5060,ft=17251SIPpTag001205) on hash 3434
    Nov 25 14:29:54 s05 /sbin/opensips[9352]: Using mediaproxy 1005@sip.domain.com (46.182.2.2) - sip:22223333@sip.domain.com:5060 - 1205-17251@46.182.2.2
    Nov 25 14:29:54 s05 /sbin/opensips[9352]: Calling: sip:551122223333@206.217.3.3:5082 - (gw=12) - Tent: 1 - Prio: 1 - Route: 5511 - User: 1005@sip.domain.com (46.182.2.2) - Billinguser: 1005@sip.domain.com - 1205-17251@46.182.2.2
    Nov 25 14:29:54 s05 /sbin/opensips[9362]: incoming reply Ringing - 180 - ru=sip:551122223333@sip.domain.com:5060 - 1205-17251@46.182.2.2 - ip:206.217.3.3
    Nov 25 14:29:54 s05 /sbin/opensips[9362]: DBG:core:build_res_buf_from_sip_res: copied size: orig:106, new: 21, rest: 542 msg=#012SIP/2.0 180 Ringing#015#012Via: SIP/2.0/UDP 46.182.2.2:5060;branch=z9hG4bK-17251-1205-6#015#012Record-Route: <sip:46.182.109.24;lr;ftag=17251SIPpTag001205;did=a6d.5a26a9a4>#015#012From: 1005 <sip:1005@sip.domain.com:5060>;tag=17251SIPpTag001205#015#012To: <sip:22223333@sip.domain.com:5060>;tag=as671b4406#015#012Call-ID: 1205-17251@46.182.2.2#015#012CSeq: 1 INVITE#015#012Server: Asterisk PBX 1.6.2.9-2+squeeze5#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO#015#012Supported: replaces, timer#015#012Contact: <sip:551122223333@206.217.3.3:5082>#015#012Content-Length: 0#015#012#015#012
    Nov 25 14:29:54 s05 /sbin/opensips[9369]: incoming reply Trying - 100 - ru=sip:551122223333@sip.domain.com:5060 - 1205-17251@46.182.2.2 - ip:206.217.3.3
    Nov 25 14:29:56 s05 /sbin/opensips[9366]: incoming reply OK - 200 - ru=sip:551122223333@sip.domain.com:5060 - 1205-17251@46.182.2.2 - ip:206.217.3.3
    Nov 25 14:29:56 s05 /sbin/opensips[9366]: DBG:core:build_res_buf_from_sip_res: copied size: orig:813, new: 726, rest: 58 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 46.182.2.2:5060;branch=z9hG4bK-17251-1205-6#015#012Record-Route: <sip:46.182.109.24;lr;ftag=17251SIPpTag001205;did=a6d.5a26a9a4>#015#012From: 1005 <sip:1005@sip.domain.com:5060>;tag=17251SIPpTag001205#015#012To: <sip:22223333@sip.domain.com:5060>;tag=as671b4406#015#012Call-ID: 1205-17251@46.182.2.2#015#012CSeq: 1 INVITE#015#012Server: Asterisk PBX 1.6.2.9-2+squeeze5#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO#015#012Supported: replaces, timer#015#012Contact: <sip:551122223333@206.217.3.3:5082>#015#012Content-Type: application/sdp#015#012Content-Length: 193#015#012#015#012v=0#015#012o=root 507224764 507224764 IN IP4 206.217.3.3#015#012s=Asterisk PBX 1.6.2.9-2+squeeze5#015#012c=IN IP4 46.182.2.2#015#012t=0 0#015#012m=audio 55006 RTP/AVP 8#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:20#015#012a=sendrecv#015#012
    Nov 25 14:29:56 s05 /sbin/opensips[9366]: ACC: transaction answered: timestamp=1353860996;method=INVITE;from_tag=17251SIPpTag001205;to_tag=as671b4406;call_id=1205-17251@46.182.2.2;code=200;reason=OK
    Nov 25 14:29:56 s05 /sbin/opensips[9379]: ACK - sip:551122223333@206.217.3.3:5082 - 1005@sip.domain.com (46.182.2.2) - 1205-17251@46.182.2.2
    Nov 25 14:29:56 s05 /sbin/opensips[9379]: DBG:core:forward_request: sending:#012ACK sip:551122223333@206.217.3.3:5082 SIP/2.0#015#012Via: SIP/2.0/UDP 46.182.109.24;branch=z9hG4bK1ad5.8f665b07.2#015#012Via: SIP/2.0/UDP 46.182.2.2:5060;branch=z9hG4bK-17251-1205-6#015#012From: <sip:1005@sip.domain.com:5060>;tag=17251SIPpTag001205#015#012To: <sip:22223333@sip.domain.com:5060>;tag=as671b4406#015#012Call-ID: 1205-17251@46.182.2.2#015#012CSeq: 1 ACK#015#012Contact: sip:1005@46.182.2.2:5060#015#012Max-Forwards: 69#015#012Subject: Performance Test#015#012Content-Length: 0#015#012#015#012.
    Nov 25 14:30:02 s05 /sbin/opensips[9359]: BYE - sip:551122223333@206.217.3.3:5082 - 1005@sip.domain.com (46.182.2.2) - 1205-17251@46.182.2.2
    Nov 25 14:30:02 s05 /sbin/opensips[9376]: DBG:core:build_res_buf_from_sip_res: copied size: orig:134, new: 49, rest: 406 msg=#012SIP/2.0 481 Call leg/transaction does not exist#015#012Via: SIP/2.0/UDP 46.182.2.2:5060;branch=z9hG4bK-17251-1205-13#015#012From: <sip:1005@sip.domain.com:5060>;tag=17251SIPpTag001205#015#012To: <sip:22223333@sip.domain.com:5060>;tag=as671b4406#015#012Call-ID: 1205-17251@46.182.2.2#015#012CSeq: 2 BYE#015#012Server: Asterisk PBX 1.6.2.9-2+squeeze5#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO#015#012Supported: replaces, timer#015#012Content-Length: 0#015#012#015#012
    Nov 25 14:30:08 s05 /sbin/opensips[9385]: DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x7f5b61498e80 [3434:1251631781] with clid '1205-17251@46.182.2.2' and tags '17251SIPpTag001205' 'as671b4406'
    

    On my Opensips, i have this configured:

    modparam("acc", "log_flag", 1)
    modparam("acc", "log_missed_flag", 1)
    modparam("acc", "db_flag", 1)
    ...
            if (has_totag()) {
                    if (loose_route()) {
                            if (is_method("BYE")) {
                                    setflag(1); 
    ...
    

    Before call leave the proxy, on first INVITE, also setflag(1)

    Any help is appreciated, this is a really urgent matter.

    Thanks

     
  • Daniel Zanutti
    Daniel Zanutti
    2012-11-25

    O checked that in Dev machine (very overloaded), the problem is happening around 1500 for 10k calls… So i believe that this is related to the load of the machine… But i don't see and error from ACC, informing that it couldn't write do DB or syslog.

     
  • Daniel Zanutti
    Daniel Zanutti
    2012-11-28

    I confirmed the bug and opened a bug report. Please, close this topic.

     
  • Hi Daniel,

    Please open the bug report on the tracker with all relevant data - we will take care of it asap !

    Thanks and regards,
    Bogdan