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