Hey, 

I have just sent a mail to your colleague (Trey).... i think ;)

I have just asked for a pcap of your registration. I suspect there are no auth vectors being returned in your MAA from HSS but I would like to confirm. We can fix from there.

p.s. sorry we missed this post in the users list. Would normally have responded far quicker.

Cheers
Jason


On Mon, Mar 18, 2013 at 4:30 PM, mrichardson <matt.richardson@interoptechnologies.com> wrote:
Date: Fri, 15 Mar 2013 08:44:13 +0100
From: Daniel-Constantin Mierla <miconda@gmail.com>
Subject: Re: [SR-Users] Problems with Mar portion of registration
        [IMS]
To: "Kamailio (SER) - Users Mailing List"
        <sr-users@lists.sip-router.org>
Message-ID: <5142D14D.7080808@gmail.com>
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;
                        }
                }
        }
}



_______________________________________________
SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list
sr-users@lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users




--
Jason Penton
Senior Manager: Applications and Services
Smile Communications
Johannesburg, South Africa
Phone: +27 83 283 7000

This email is subject to the disclaimer of Smile Communications (PTY) Ltd. at http://www.smilecoms.com/disclaimer