[SR-Users] Problems with Mar portion of registration

Date: Fri, 15 Mar 2013 08:44:13 +0100 From: Daniel-Constantin Mierla &lt;miconda(a)gmail.com&gt; Subject: Re: [SR-Users] Problems with Mar portion of registration [IMS] To: "Kamailio (SER) - Users Mailing List" &lt;sr-users(a)lists.sip-router.org&gt; Message-ID: &lt;5142D14D.7080808(a)gmail.com&gt; Content-Type: text/plain; charset=ISO-8859-1; format=flowed Hello, I haven't played with IMS modules, but you said is causing scscf to die -- is that a kamailio instance? What means 'to die' -- does it crash? If yes, can you get the syslog messages and the gdb backtrace? Cheers, Daniel ============================================ *Response:* ============================================ It appears any way we force the scscf to process a mar causes a crash. Core was generated by `/usr/sbin/kamailio -P /var/run/kamailio.pid -m 64 -M 4 -u kamailio -g kamailio'. Program terminated with signal 11, Segmentation fault. #0 async_cdp_callback (is_timeout=<value optimized out>, param=0x7f641b158e70, maa=0x7f641b159040, elapsed_msecs=<value optimized out>) at cxdx_mar.c:414 414 start_reg_await_timer(avlist[0]); //start the timer to remove stale or unused Auth Vectors Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.107.el6.x86_64 libxml2-2.7.6-8.el6_3.4.x86_64 nss-pam-ldapd-0.7.5-18.el6.x86_64 pcre-7.8-6.el6.x86_64 zlib-1.2.3-29.el6.x86_64 (gdb) syslog: 7(2211) DEBUG: tm [t_lookup.c:1657]: DEBUG: t_lookup_ident: transaction found 7(2211) INFO: ims_auth [cxdx_avp.c:139]: cxdx_get_experimental_result_code: Failed finding avp 7(2211) INFO: ims_auth [cxdx_avp.c:139]: cxdx_get_sip_number_auth_items: Failed finding avp 7(2211) DEBUG: <core> [msg_translator.c:206]: check_via_address(10.12.92.191, 10.12.92.191, 0) 7(2211) DEBUG: <core> [mem/shm_mem.c:111]: WARNING:vqm_resize: resize(0) called 7(2211) DEBUG: tm [t_reply.c:1547]: DEBUG: cleanup_uac_timers: RETR/FR timers reset 7(2211) DEBUG: tm [t_reply.c:706]: DEBUG: reply sent out. buf=0x7f64e586b950: SIP/2.0 403 Forbidde..., shmem=0x7f64de66c1b0: SIP/2.0 403 Forbidde 7(2211) DEBUG: tm [t_reply.c:716]: DEBUG: _reply_light: finished 0(2204) DEBUG: <core> [parser/msg_parser.c:623]: SIP Request: 0(2204) DEBUG: <core> [parser/msg_parser.c:625]: method: <REGISTER> 0(2204) DEBUG: <core> [parser/msg_parser.c:627]: uri: <sip:scscf.somecompany.com:6060> 0(2204) DEBUG: <core> [parser/msg_parser.c:629]: version: <SIP/2.0> 0(2204) DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field: cseq <CSeq>: <5> <REGISTER> 0(2204) DEBUG: <core> [parser/parse_to.c:799]: end of header reached, state=10 0(2204) DEBUG: <core> [parser/msg_parser.c:190]: DEBUG: get_hdr_field: <To> [34]; uri=[sip:bob@somecompany.com] 0(2204) DEBUG: <core> [parser/msg_parser.c:192]: DEBUG: to body ["bob" <sip:bob@somecompany.com> ] 0(2204) DEBUG: <core> [parser/parse_via.c:1284]: Found param type 232, <branch> = <z9hG4bK1bd1.929b9c33.1>; state=16 0(2204) DEBUG: <core> [parser/parse_via.c:2672]: end of header reached, state=5 0(2204) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=2 0(2204) DEBUG: <core> [parser/msg_parser.c:515]: parse_headers: this is the first via 0(2204) DEBUG: <core> [receive.c:149]: After parse_msg... 0(2204) DEBUG: <core> [receive.c:190]: preparing to run routing scripts... 0(2204) DEBUG: maxfwd [mf_funcs.c:85]: value = 15 0(2204) DEBUG: <core> [parser/parse_via.c:1284]: Found param type 232, <branch> = <z9hG4bK1bd1.a11580a2575452ad784ca00f869952fb.0>; state=16 0(2204) DEBUG: <core> [parser/parse_via.c:2672]: end of header reached, state=5 0(2204) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=1000 0(2204) DEBUG: <core> [parser/msg_parser.c:526]: parse_headers: this is the second via 0(2204) DEBUG: <core> [parser/parse_via.c:1284]: Found param type 232, <branch> = <z9hG4bK-333530-035cb8a7773aa017e8e89aa8db3c4f01>; state=16 0(2204) DEBUG: <core> [parser/parse_via.c:2672]: end of header reached, state=5 0(2204) DEBUG: <core> [parser/msg_parser.c:513]: parse_headers: Via found, flags=1000 0(2204) DEBUG: <core> [parser/msg_parser.c:204]: DEBUG: get_hdr_body : content_length=0 0(2204) DEBUG: <core> [parser/msg_parser.c:106]: found end of header 0(2204) DEBUG: <core> [parser/parse_to.c:176]: DEBUG: add_param: tag=1f9be4d3 0(2204) DEBUG: <core> [parser/parse_to.c:799]: end of header reached, state=29 0(2204) DEBUG: sanity [mod_sanity.c:255]: sanity checks result: 1 0(2204) DEBUG: siputils [checks.c:103]: no totag 0(2204) DEBUG: <core> [select.c:425]: Calling SELECT 0x7f64e5839ea0 0(2204) DEBUG: tm [t_lookup.c:1095]: DEBUG: t_check_msg: msg id=5 global id=4 T start=0xffffffffffffffff 0(2204) DEBUG: tm [t_lookup.c:534]: t_lookup_request: start searching: hash=7601, isACK=0 0(2204) DEBUG: tm [t_lookup.c:492]: DEBUG: RFC3261 transaction matching failed 0(2204) DEBUG: tm [t_lookup.c:716]: DEBUG: t_lookup_request: no transaction found 0(2204) DEBUG: tm [t_lookup.c:1164]: DEBUG: t_check_msg: msg id=5 global id=5 T end=(nil 0(2204) ERROR: <script>: Enter register block 0(2204) DEBUG: tm [t_lookup.c:1395]: DEBUG: t_newtran: msg id=5 , global msg id=5 , T on entrance=(nil) 0(2204) DEBUG: tm [t_lookup.c:534]: t_lookup_request: start searching: hash=7601, isACK=0 0(2204) DEBUG: tm [t_lookup.c:492]: DEBUG: RFC3261 transaction matching failed 0(2204) DEBUG: tm [t_lookup.c:716]: DEBUG: t_lookup_request: no transaction found 0(2204) DEBUG: tm [t_hooks.c:374]: DBG: trans=0x7f64de66c4d0, callback type 1, id 0 entered 0(2204) DEBUG: ims_auth [authorize.c:567]: Checking if REGISTER is authorized for realm [somecompany.com]... 0(2204) DEBUG: ims_auth [authorize.c:597]: Nonce or response missing: nonce len [1910316154], response16 len[-440163170] 0(2204) INFO: ims_auth [cxdx_mar.c:81]: created AVP successfully : [maa_return_code] - [-2] 0(2204) DEBUG: ims_auth [authorize.c:298]: Need to challenge for realm [somecompany.com] 0(2204) DEBUG: ims_auth [authorize.c:305]: Checking if REGISTER is authorized for realm [somecompany.com]... 0(2204) DEBUG: ims_auth [authorize.c:435]: Suspending SIP TM transaction 0(2204) DEBUG: ims_auth [authorize.c:1271]: Sending MAR 0(2204) DEBUG: cdp [session.c:276]: adding a session with id scscf.somecompany.com;1782936534;5 0(2204) DEBUG: cdp [routing.c:80]: get_first_connected_route in list 0x7f64de63dbc0 for app_id 16777216 and vendor_id 10415 0(2204) DEBUG: cdp [routing.c:88]: The peer hss.somecompany.com state is opened 0(2204) DEBUG: cdp [routing.c:63]: Checking if peer hss.somecompany.com handles application 16777216 for vendord 10415 0(2204) DEBUG: cdp [routing.c:90]: The peer hss.somecompany.com matches - will forward there 0(2204) DEBUG: cdp [peerstatemachine.c:91]: sm_process(): Peer hss.somecompany.com State I_Open Event Send_Message 0(2204) DEBUG: cdp [peerstatemachine.c:1096]: Snd_Message called to peer [hss.somecompany.com] for request with code 303 0(2204) DEBUG: cdp [session.c:297]: called get session with id scscf.somecompany.com;1782936534;5 and hash 111 0(2204) DEBUG: cdp [session.c:306]: no session found 0(2204) DEBUG: cdp [diameter_msg.c:83]: AAABuildMsgBuffer(): len=348 0(2204) DEBUG: cdp [receiver.c:967]: peer_send_msg(): Pipe push [0x7f64de66edd0] 0(2204) DEBUG: ims_auth [cxdx_mar.c:516]: Successfully sent async diameter 0(2204) DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) 0(2204) DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) 0(2204) DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) 0(2204) DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) 0(2204) DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) 0(2204) DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil) 0(2204) DEBUG: <core> [xavp.c:447]: destroying xavp list (nil) 0(2204) DEBUG: <core> [receive.c:293]: receive_msg: cleaning up 10(2214) DEBUG: cdp [receiver.c:743]: select_recv(): There is something on the send pipe 10(2214) DEBUG: cdp [receiver.c:756]: select_recv(): Send pipe says [0x7f64de66edd0] 8 10(2214) DEBUG: cdp [diameter_msg.c:412]: AAAFreeMessage: Freeing message (0x7f64de66edd0) 303 10(2214) DEBUG: cdp [receiver.c:104]: --- Receiver [cdp_receiver_peer=hss.somecompany.com] Serviced Peers: --- 10(2214) DEBUG: cdp [receiver.c:110]: Peer: [hss.somecompany.com] TCP Socket: [15] Recv.State: [0] 10(2214) DEBUG: cdp [receiver.c:112]: -------------------------------------------------------- 10(2214) DEBUG: cdp [receiver.c:104]: --- Receiver [cdp_receiver_peer=hss.somecompany.com] Serviced Peers: --- 10(2214) DEBUG: cdp [receiver.c:110]: Peer: [hss.somecompany.com] TCP Socket: [15] Recv.State: [1] 10(2214) DEBUG: cdp [receiver.c:112]: -------------------------------------------------------- 10(2214) DEBUG: cdp [receiver.c:567]: receive_loop(): [hss.somecompany.com] Recv Version 1 Length 172 10(2214) DEBUG: cdp [receiver.c:104]: --- Receiver [cdp_receiver_peer=hss.somecompany.com] Serviced Peers: --- 10(2214) DEBUG: cdp [receiver.c:110]: Peer: [hss.somecompany.com] TCP Socket: [15] Recv.State: [2] 10(2214) DEBUG: cdp [receiver.c:112]: -------------------------------------------------------- 10(2214) DEBUG: cdp [receiver.c:1061]: receive_message(): [hss.somecompany.com] Recv msg 303 10(2214) DEBUG: cdp [peerstatemachine.c:91]: sm_process(): Peer hss.somecompany.com State I_Open Event I_Rcv_Message 10(2214) DEBUG: cdp [session.c:297]: called get session with id scscf.somecompany.com;1782936534;5 and hash 111 10(2214) DEBUG: cdp [session.c:306]: no session found 10(2214) DEBUG: cdp [receiver.c:104]: --- Receiver [cdp_receiver_peer=hss.somecompany.com] Serviced Peers: --- 10(2214) DEBUG: cdp [receiver.c:110]: Peer: [hss.somecompany.com] TCP Socket: [15] Recv.State: [0] 10(2214) DEBUG: cdp [receiver.c:112]: -------------------------------------------------------- 0(2204) ALERT: <core> [main.c:788]: child process 2212 exited by a signal 11 0(2204) ALERT: <core> [main.c:791]: core was generated 0(2204) INFO: <core> [main.c:800]: INFO: dont_fork turned on, living on 0(2204) ALERT: <core> [main.c:788]: child process 2211 exited by a signal 11 0(2204) ALERT: <core> [main.c:791]: core was generated 0(2204) INFO: <core> [main.c:800]: INFO: dont_fork turned on, living on This is the modified register block to get a 401 unauthorized to even be generated (probably broken).... route[REGISTER] { xlog("L_ERR", "Enter register block"); t_newtran(); if (!ims_www_authenticate(NETWORKNAME)) { ims_www_challenge("$td"); exit; } if ($avp(maa_return_code) != 1 ) { if (!impu_registered("location")) { save("location"); if ($avp(saa_return_code) == 1) { isc_match_filter_reg("0","location"); exit; } } else { save("location"); if($avp(saa_return_code) == 1) { isc_match_filter_reg("1","location"); exit; } } } }