koffee@debian-km:~$ su
Password: 
root@debian-km:/home/koffee# kamailio -f /usr/local/etc/scscf/kamailio.cfg 
loading modules under config path: /usr/local/src/kamailio-5.0/kamailio/src/modules/
 0(3143) INFO: <core> [core/sctp_core.c:75]: sctp_core_check_support(): SCTP API not enabled - if you want to use it, load sctp module
Listening on 
             udp: 192.168.99.140 [192.168.99.140]:6060
Aliases: 
             *: scscf.koffee-ims.in:*

 0(3145) INFO: rr [../outbound/api.h:52]: ob_load_api(): unable to import bind_ob - maybe module is not loaded
 0(3145) INFO: rr [rr_mod.c:175]: mod_init(): outbound module not available
 0(3145) INFO: pike [pike.c:99]: pike_init(): PIKE - initializing
 0(3145) INFO: pike [ip_tree.c:81]: init_lock_set(): probing 256 set size
 0(3145) INFO: jsonrpcs [jsonrpcs_sock.c:197]: jsonrpc_dgram_mod_init(): the socket /var/run/kamailio/kamailio_rpc.sock already exists, trying to delete it...
 0(3145) INFO: ims_usrloc_scscf [hslot.c:69]: ul_init_locks(): locks array size 512
 0(3145) INFO: ims_usrloc_scscf [contact_hslot.c:67]: init_contacts_locks(): locks array size 512
 0(3145) INFO: ims_usrloc_scscf [hslot_sp.c:70]: subs_init_locks(): locks array size 512
 0(3145) INFO: <core> [core/udp_server.c:153]: probe_max_receive_buffer(): SO_RCVBUF is initially 163840
 0(3145) INFO: <core> [core/udp_server.c:203]: probe_max_receive_buffer(): SO_RCVBUF is finally 327680
 0(3145) INFO: cdp [cdp_mod.c:242]: cdp_child_init(): CDiameterPeer child starting ...
18(3172) INFO: jsonrpcs [jsonrpcs_sock.c:429]: jsonrpc_dgram_process(): a new child 0/3172
 0(3145) INFO: cdp [cdp_mod.c:244]: cdp_child_init(): ... CDiameterPeer child started
22(3181) INFO: cdp [worker.c:332]: worker_process(): [3] Worker process started...
20(3177) INFO: cdp [worker.c:332]: worker_process(): [1] Worker process started...
23(3182) INFO: cdp [worker.c:332]: worker_process(): [4] Worker process started...
26(3186) INFO: cdp [worker.c:332]: worker_process(): [7] Worker process started...
24(3183) INFO: cdp [worker.c:332]: worker_process(): [5] Worker process started...
25(3184) INFO: cdp [worker.c:332]: worker_process(): [6] Worker process started...
28(3189) INFO: cdp [worker.c:332]: worker_process(): [9] Worker process started...
19(3173) INFO: cdp [worker.c:332]: worker_process(): [0] Worker process started...
30(3193) INFO: cdp [worker.c:332]: worker_process(): [11] Worker process started...
27(3187) INFO: cdp [worker.c:332]: worker_process(): [8] Worker process started...
29(3190) INFO: cdp [worker.c:332]: worker_process(): [10] Worker process started...
16(3168) INFO: ctl [io_listener.c:210]: io_listen_loop(): io_listen_loop: using epoll_lt as the io watch method (auto detected)
21(3180) INFO: cdp [worker.c:332]: worker_process(): [2] Worker process started...
35(3207) INFO: cdp [receiver.c:450]: receiver_process(): receiver_process(): [] Receiver process doing init on new process...
35(3207) INFO: cdp [receiver.c:455]: receiver_process(): receiver_process(): [] Receiver process starting up...
36(3208) INFO: cdp [receiver.c:450]: receiver_process(): receiver_process(): [hss.koffee-ims.in] Receiver process doing init on new process...
36(3208) INFO: cdp [receiver.c:184]: add_serviced_peer(): add_serviced_peer(): Adding serviced_peer_t to receiver for peer [hss.koffee-ims.in]
36(3208) INFO: cdp [receiver.c:455]: receiver_process(): receiver_process(): [hss.koffee-ims.in] Receiver process starting up...
33(3205) INFO: cdp [worker.c:332]: worker_process(): [14] Worker process started...
34(3206) INFO: cdp [worker.c:332]: worker_process(): [15] Worker process started...
37(3209) INFO: cdp [acceptor.c:81]: acceptor_process(): Acceptor process starting up...
37(3209) WARNING: cdp [tcp_accept.c:121]: create_socket(): create_socket(): Trying to open/bind/listen on 192.168.99.140 port 3870
37(3209) WARNING: cdp [tcp_accept.c:146]: create_socket(): create_socket(): Successful socket open/bind/listen on 192.168.99.140 port 3870
37(3209) INFO: cdp [acceptor.c:95]: acceptor_process(): Acceptor opened sockets. Entering accept loop ...
root@debian-km:/home/koffee# 38(3210) INFO: cdp [timer.c:205]: timer_process(): Timer process starting up...
31(3196) INFO: cdp [worker.c:332]: worker_process(): [12] Worker process started...
32(3204) INFO: cdp [worker.c:332]: worker_process(): [13] Worker process started...
38(3210) INFO: cdp [peerstatemachine.c:525]: I_Snd_Conn_Req(): I_Snd_Conn_Req(): Peer hss.koffee-ims.in 
38(3210) INFO: cdp [receiver.c:869]: peer_connect(): peer_connect(): Trying to connect to 192.168.99.140 port 3868
38(3210) INFO: cdp [receiver.c:937]: peer_connect(): peer_connect(): Peer hss.koffee-ims.in:3868 connected
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086847
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086847
 2(3148) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086857
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086857
 5(3152) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086867
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086867
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086877
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086877
 4(3150) ERROR: <script>: Inside route{........}
 3(3149) ERROR: <script>: Inside route{........}
 3(3149) ERROR: <script>: ALGORITHM IS [<null>] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
 3(3149) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
 3(3149) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 3(3149) DEBUG: ims_auth [authorize.c:792]: authenticate(): Nonce or response missing: nonce len [0], response16 len[0]
 3(3149) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
 3(3149) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
 3(3149) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [koffee-ims.in]
 3(3149) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 3(3149) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 3(3149) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
 3(3149) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
 3(3149) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
22(3181) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
22(3181) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
22(3181) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
22(3181) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
22(3181) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
22(3181) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:alice@koffee-ims.in / IMPI alice@koffee-ims.in (Hash 181)
22(3181) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
22(3181) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
22(3181) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
11(3161) ERROR: <script>: Inside route{........}
11(3161) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
11(3161) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
11(3161) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
11(3161) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [koffee-ims.in]
11(3161) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [koffee-ims.in]
11(3161) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0xb6e4ab4c
11(3161) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
11(3161) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <koffee-ims.in> and <koffee-ims.in>
11(3161) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
11(3161) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [alice@koffee-ims.in] and IMPU: [sip:alice@koffee-ims.in]
11(3161) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
11(3161) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
11(3161) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for alice@koffee-ims.in
11(3161) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
11(3161) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
11(3161) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 1 and were looking for 1
11(3161) DEBUG: ims_auth [authorize.c:1072]: get_auth_vector(): Found result
11(3161) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:koffee-ims.in nonce=cd77bdb3c75d390135f9b1b85a3323fb response=0fce8aa0593a5c5cfbdfbc0d99b8adf6 qop=auth-int nc=00000001 cnonce=ba4a8eba6cca0e92df35824f36dac6e1 hbody=d41d8cd98f00b204e9800998ecf8427e
11(3161) DEBUG: ims_auth [authorize.c:865]: authenticate(): nc is 00000001, expected: 00000001
11(3161) DEBUG: ims_auth [rfc2617.c:144]: calc_response(): calc_response(_ha1=4802e13f2db32d20d287f397ba099aa6, _nonce=cd77bdb3c75d390135f9b1b85a3323fb, _nc=00000001,_cnonce=ba4a8eba6cca0e92df35824f36dac6e1, _qop=auth-int, _auth_int=1,_method=REGISTER,_uri=sip:koffee-ims.in,_hentity=d41d8cd98f00b204e9800998ecf8427e)
11(3161) DEBUG: ims_auth [rfc2617.c:186]: calc_response(): H(A1) = 4802e13f2db32d20d287f397ba099aa6, H(A2) = 73b9fcf5220c7f9a7e9460a5e50e1172, rspauth = 0fce8aa0593a5c5cfbdfbc0d99b8adf6
11(3161) INFO: ims_auth [authorize.c:892]: authenticate(): UE said: 0fce8aa0593a5c5cfbdfbc0d99b8adf6 and we expect 0fce8aa0593a5c5cfbdfbc0d99b8adf6 ha1 4802e13f2db32d20d287f397ba099aa6 (REGISTER)
11(3161) DEBUG: ims_auth [authorize.c:927]: authenticate(): vector 0xb2060d10 successfully used 1 time(s)
11(3161) DEBUG: ims_auth [authorize.c:930]: authenticate(): vector 0xb2060d10 isn't fresh anymore, recycle it with a new nonce
 8(3158) ERROR: <script>: Inside route{........}
 8(3158) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
 8(3158) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
 8(3158) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 8(3158) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [koffee-ims.in]
 8(3158) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [koffee-ims.in]
 8(3158) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0xb6e4ab4c
 8(3158) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
 8(3158) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <koffee-ims.in> and <koffee-ims.in>
 8(3158) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
 8(3158) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [alice@koffee-ims.in] and IMPU: [sip:alice@koffee-ims.in]
 8(3158) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 8(3158) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 8(3158) DEBUG: ims_auth [authorize.c:820]: authenticate(): vector 0xb2060d10 is marked for deletion
 8(3158) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for alice@koffee-ims.in
 8(3158) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 8(3158) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 8(3158) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 1
 8(3158) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:koffee-ims.in nonce=cd77bdb3c75d390135f9b1b85a3323fb response=0fce8aa0593a5c5cfbdfbc0d99b8adf6 qop=auth-int nc=00000001 cnonce=ba4a8eba6cca0e92df35824f36dac6e1 hbody=d41d8cd98f00b204e9800998ecf8427e
 8(3158) DEBUG: ims_auth [authorize.c:843]: authenticate(): no matching auth vector found - maybe timer expired
 8(3158) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
 8(3158) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
 8(3158) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [koffee-ims.in]
 8(3158) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 8(3158) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 8(3158) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 8(3158) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
 8(3158) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
 8(3158) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
 8(3158) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
20(3177) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
20(3177) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
20(3177) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
20(3177) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
20(3177) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
20(3177) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:alice@koffee-ims.in / IMPI alice@koffee-ims.in (Hash 181)
20(3177) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
20(3177) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
20(3177) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
 6(3153) ERROR: <script>: Inside route{........}
 6(3153) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
 6(3153) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
 6(3153) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 6(3153) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [koffee-ims.in]
 6(3153) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [koffee-ims.in]
 6(3153) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0xb6e4ab4c
 6(3153) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
 6(3153) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <koffee-ims.in> and <koffee-ims.in>
 6(3153) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
 6(3153) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [alice@koffee-ims.in] and IMPU: [sip:alice@koffee-ims.in]
 6(3153) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 6(3153) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 6(3153) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for alice@koffee-ims.in
 6(3153) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 6(3153) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 6(3153) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 1 and were looking for 1
 6(3153) DEBUG: ims_auth [authorize.c:1072]: get_auth_vector(): Found result
 6(3153) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:koffee-ims.in nonce=c01a3b0a33ce724b273e859778a9170e response=255d289e9f2eb2afb1b9c661388753b8 qop=auth-int nc=00000001 cnonce=e0d8727444e65aeec91b45f690b908ab hbody=d41d8cd98f00b204e9800998ecf8427e
 6(3153) DEBUG: ims_auth [authorize.c:865]: authenticate(): nc is 00000001, expected: 00000001
 6(3153) DEBUG: ims_auth [rfc2617.c:144]: calc_response(): calc_response(_ha1=4802e13f2db32d20d287f397ba099aa6, _nonce=c01a3b0a33ce724b273e859778a9170e, _nc=00000001,_cnonce=e0d8727444e65aeec91b45f690b908ab, _qop=auth-int, _auth_int=1,_method=REGISTER,_uri=sip:koffee-ims.in,_hentity=d41d8cd98f00b204e9800998ecf8427e)
 6(3153) DEBUG: ims_auth [rfc2617.c:186]: calc_response(): H(A1) = 4802e13f2db32d20d287f397ba099aa6, H(A2) = 73b9fcf5220c7f9a7e9460a5e50e1172, rspauth = 255d289e9f2eb2afb1b9c661388753b8
 6(3153) INFO: ims_auth [authorize.c:892]: authenticate(): UE said: 255d289e9f2eb2afb1b9c661388753b8 and we expect 255d289e9f2eb2afb1b9c661388753b8 ha1 4802e13f2db32d20d287f397ba099aa6 (REGISTER)
 6(3153) DEBUG: ims_auth [authorize.c:927]: authenticate(): vector 0xb20649c4 successfully used 1 time(s)
 6(3153) DEBUG: ims_auth [authorize.c:930]: authenticate(): vector 0xb20649c4 isn't fresh anymore, recycle it with a new nonce
11(3161) ERROR: ims_registrar_scscf [save.c:1033]: update_contacts(): Unable to remove contact <sip:alice@192.168.99.145:56841;transport=udp>
11(3161) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [-2]
11(3161) ERROR: ims_registrar_scscf [save.c:1432]: save(): failed to suspend the TM processing
11(3161) ERROR: tm [t_reply.c:482]: _reply_light(): can't generate 500 reply when a final 401 was sent out
11(3161) ERROR: sl [sl.c:271]: send_reply(): failed to reply stateful (tm)
11(3161) ERROR: ims_registrar_scscf [reply.c:820]: reg_send_reply(): failed to send 500 Server Internal Error
12(3162) ERROR: <script>: Inside route{........}
12(3162) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
12(3162) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
12(3162) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
12(3162) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [koffee-ims.in]
12(3162) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [koffee-ims.in]
12(3162) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0xb6e4ab4c
12(3162) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
12(3162) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <koffee-ims.in> and <koffee-ims.in>
12(3162) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
12(3162) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [alice@koffee-ims.in] and IMPU: [sip:alice@koffee-ims.in]
12(3162) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
12(3162) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
12(3162) DEBUG: ims_auth [authorize.c:820]: authenticate(): vector 0xb20649c4 is marked for deletion
12(3162) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for alice@koffee-ims.in
12(3162) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
12(3162) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
12(3162) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 1
12(3162) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 1
12(3162) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:koffee-ims.in nonce=c01a3b0a33ce724b273e859778a9170e response=255d289e9f2eb2afb1b9c661388753b8 qop=auth-int nc=00000001 cnonce=e0d8727444e65aeec91b45f690b908ab hbody=d41d8cd98f00b204e9800998ecf8427e
12(3162) DEBUG: ims_auth [authorize.c:843]: authenticate(): no matching auth vector found - maybe timer expired
12(3162) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
12(3162) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
12(3162) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [koffee-ims.in]
12(3162) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
12(3162) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
12(3162) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
12(3162) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
12(3162) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
12(3162) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
12(3162) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
12(3162) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
23(3182) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
23(3182) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
23(3182) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
23(3182) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
23(3182) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
23(3182) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:alice@koffee-ims.in / IMPI alice@koffee-ims.in (Hash 181)
23(3182) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
23(3182) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
23(3182) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
10(3160) ERROR: <script>: Inside route{........}
10(3160) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
10(3160) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
10(3160) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
10(3160) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [koffee-ims.in]
10(3160) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [koffee-ims.in]
10(3160) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0xb6e4ab4c
10(3160) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
10(3160) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <koffee-ims.in> and <koffee-ims.in>
10(3160) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
10(3160) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [alice@koffee-ims.in] and IMPU: [sip:alice@koffee-ims.in]
10(3160) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
10(3160) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
10(3160) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for alice@koffee-ims.in
10(3160) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
10(3160) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
10(3160) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 1 and were looking for 1
10(3160) DEBUG: ims_auth [authorize.c:1072]: get_auth_vector(): Found result
10(3160) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:koffee-ims.in nonce=4b3a0b4fd6679bf885d6676af202fe9a response=a11c6c5d46f54c772e15bc4fe695a180 qop=auth-int nc=00000001 cnonce=0c32e9989498e1351d5a937afcb92298 hbody=d41d8cd98f00b204e9800998ecf8427e
10(3160) DEBUG: ims_auth [authorize.c:865]: authenticate(): nc is 00000001, expected: 00000001
10(3160) DEBUG: ims_auth [rfc2617.c:144]: calc_response(): calc_response(_ha1=4802e13f2db32d20d287f397ba099aa6, _nonce=4b3a0b4fd6679bf885d6676af202fe9a, _nc=00000001,_cnonce=0c32e9989498e1351d5a937afcb92298, _qop=auth-int, _auth_int=1,_method=REGISTER,_uri=sip:koffee-ims.in,_hentity=d41d8cd98f00b204e9800998ecf8427e)
10(3160) DEBUG: ims_auth [rfc2617.c:186]: calc_response(): H(A1) = 4802e13f2db32d20d287f397ba099aa6, H(A2) = 73b9fcf5220c7f9a7e9460a5e50e1172, rspauth = a11c6c5d46f54c772e15bc4fe695a180
10(3160) INFO: ims_auth [authorize.c:892]: authenticate(): UE said: a11c6c5d46f54c772e15bc4fe695a180 and we expect a11c6c5d46f54c772e15bc4fe695a180 ha1 4802e13f2db32d20d287f397ba099aa6 (REGISTER)
10(3160) DEBUG: ims_auth [authorize.c:927]: authenticate(): vector 0xb206d884 successfully used 1 time(s)
10(3160) DEBUG: ims_auth [authorize.c:930]: authenticate(): vector 0xb206d884 isn't fresh anymore, recycle it with a new nonce
 7(3156) ERROR: <script>: Inside route{........}
 7(3156) ERROR: <script>: ALGORITHM IS [MD5] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
 7(3156) DEBUG: ims_auth [authorize.c:734]: authenticate(): Running authenticate, is_proxy_auth=0
 7(3156) DEBUG: ims_auth [authorize.c:754]: authenticate(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 7(3156) DEBUG: ims_auth [utils.c:168]: get_nonce_response(): Calling find_credentials with realm [koffee-ims.in]
 7(3156) DEBUG: ims_auth [utils.c:57]: ims_find_credentials(): Searching credentials in realm [koffee-ims.in]
 7(3156) DEBUG: ims_auth [utils.c:92]: ims_find_credentials(): *hook = 0xb6e4ab4c
 7(3156) DEBUG: ims_auth [utils.c:103]: ims_find_credentials(): Credential parsed successfully
 7(3156) DEBUG: ims_auth [utils.c:106]: ims_find_credentials(): Comparing realm <koffee-ims.in> and <koffee-ims.in>
 7(3156) DEBUG: ims_auth [utils.c:195]: get_nonce_response(): Found nonce response
 7(3156) DEBUG: ims_auth [authorize.c:812]: authenticate(): Looking for auth vector based on IMPI: [alice@koffee-ims.in] and IMPU: [sip:alice@koffee-ims.in]
 7(3156) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 7(3156) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 7(3156) DEBUG: ims_auth [authorize.c:820]: authenticate(): vector 0xb206d884 is marked for deletion
 7(3156) DEBUG: ims_auth [authorize.c:829]: authenticate(): look for a fresh vector for alice@koffee-ims.in
 7(3156) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 7(3156) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 7(3156) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 1
 7(3156) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 1
 7(3156) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 1
 7(3156) INFO: ims_auth [authorize.c:840]: authenticate(): uri=sip:koffee-ims.in nonce=4b3a0b4fd6679bf885d6676af202fe9a response=a11c6c5d46f54c772e15bc4fe695a180 qop=auth-int nc=00000001 cnonce=0c32e9989498e1351d5a937afcb92298 hbody=d41d8cd98f00b204e9800998ecf8427e
 7(3156) DEBUG: ims_auth [authorize.c:843]: authenticate(): no matching auth vector found - maybe timer expired
 7(3156) DEBUG: ims_auth [authorize.c:299]: challenge(): Looking for route block [REG_MAR_REPLY]
 7(3156) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [-2]
 7(3156) DEBUG: ims_auth [authorize.c:323]: challenge(): Need to challenge for realm [koffee-ims.in]
 7(3156) DEBUG: ims_auth [authorize.c:330]: challenge(): Checking if REGISTER is authorized for realm [koffee-ims.in]...
 7(3156) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
 7(3156) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
 7(3156) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
 7(3156) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
 7(3156) DEBUG: ims_auth [authorize.c:1070]: get_auth_vector(): looping through AV status is 2 and were looking for 0
 7(3156) DEBUG: ims_auth [authorize.c:466]: challenge(): Suspending SIP TM transaction
 7(3156) DEBUG: ims_auth [authorize.c:1534]: multimedia_auth_request(): Sending MAR
 7(3156) DEBUG: ims_auth [cxdx_mar.c:549]: cxdx_send_mar(): Successfully sent async diameter
26(3186) INFO: ims_auth [cxdx_avp.c:137]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp (avp_code = 297, vendor_id = 0)
26(3186) DEBUG: ims_auth [authorize.c:1565]: pack_challenge(): setting QOP str used is [, qop="auth,auth-int"]
26(3186) DEBUG: ims_auth [authorize.c:1567]: pack_challenge(): QOP str used is [, qop="auth,auth-int"]
26(3186) DEBUG: ims_auth [authorize.c:1454]: get_auth_userdata(): Searching auth_userdata for IMPU sip:alice@koffee-ims.in (Hash 181)
26(3186) DEBUG: ims_auth [authorize.c:1463]: get_auth_userdata(): Found auth_userdata
26(3186) DEBUG: ims_auth [authorize.c:1689]: add_auth_vector(): Adding auth_vector (status 1) for IMPU sip:alice@koffee-ims.in / IMPI alice@koffee-ims.in (Hash 181)
26(3186) DEBUG: ims_auth [cxdx_mar.c:464]: async_cdp_callback(): DBG:UAR Async CDP callback: ... Done resuming transaction
26(3186) INFO: ims_auth [cxdx_mar.c:79]: create_return_code(): created AVP successfully : [maa_return_code] - [1]
26(3186) DEBUG: ims_auth [cxdx_mar.c:87]: free_saved_transaction_data(): Freeing saved transaction data: async
 6(3153) ERROR: ims_registrar_scscf [save.c:1033]: update_contacts(): Unable to remove contact <sip:alice@192.168.99.145:56841;transport=udp>
 6(3153) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [-2]
 6(3153) ERROR: ims_registrar_scscf [save.c:1432]: save(): failed to suspend the TM processing
 6(3153) ERROR: tm [t_reply.c:482]: _reply_light(): can't generate 500 reply when a final 401 was sent out
 6(3153) ERROR: sl [sl.c:271]: send_reply(): failed to reply stateful (tm)
 6(3153) ERROR: ims_registrar_scscf [reply.c:820]: reg_send_reply(): failed to send 500 Server Internal Error
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086887
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 2 Exp 64087186  0xb206d884
13(3163) DEBUG: ims_auth [authorize.c:210]: reg_await_timer(): ... dropping av 1 - 2
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 2 Exp 64087185  0xb20649c4
13(3163) DEBUG: ims_auth [authorize.c:210]: reg_await_timer(): ... dropping av 1 - 2
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 2 Exp 64087185  0xb2060d10
13(3163) DEBUG: ims_auth [authorize.c:210]: reg_await_timer(): ... dropping av 1 - 2
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086887
10(3160) ERROR: ims_registrar_scscf [save.c:1033]: update_contacts(): Unable to remove contact <sip:alice@192.168.99.145:56841;transport=udp>
10(3160) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [-2]
10(3160) ERROR: ims_registrar_scscf [save.c:1432]: save(): failed to suspend the TM processing
10(3160) ERROR: tm [t_reply.c:482]: _reply_light(): can't generate 500 reply when a final 401 was sent out
10(3160) ERROR: sl [sl.c:271]: send_reply(): failed to reply stateful (tm)
10(3160) ERROR: ims_registrar_scscf [reply.c:820]: reg_send_reply(): failed to send 500 Server Internal Error
12(3162) ERROR: <script>: Inside route{........}
12(3162) ERROR: <script>: ALGORITHM IS [] and User-Agent is [IM-client/OMA1.0 Boghe-Win32/v2.0.153.836]
12(3162) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [-2]
24(3183) INFO: ims_registrar_scscf [cxdx_avp.c:138]: cxdx_get_avp(): cxdx_get_experimental_result_code: Failed finding avp
24(3183) ERROR: db_mysql [km_dbase.c:128]: db_mysql_submit_query(): driver error on query: Query was empty (1065)
24(3183) ERROR: <core> [db_query.c:181]: db_do_raw_query(): error while submitting query
24(3183) ERROR: ims_usrloc_scscf [usrloc_db.c:1086]: db_link_contact_to_impu(): Unable to link impu-contact in DB - impu [sip:alice@koffee-ims.in], contact [sip:alice@192.168.99.145:60101;transport=udp]
24(3183) ERROR: ims_usrloc_scscf [impurecord.c:1227]: link_contact_to_impu(): Failed to update DB linking contact [sip:alice@192.168.99.145:60101;transport=udp] to IMPU [sip:alice@koffee-ims.in]...continuing but db will be out of sync!
 4(3150) ERROR: <script>: Inside route{........}
24(3183) INFO: ims_registrar_scscf [cxdx_sar.c:84]: create_return_code(): created AVP successfully : [saa_return_code] - [1]
 7(3156) ERROR: <script>: Inside route{........}
12(3162) ERROR: <script>: Inside route{........}
 6(3153) ERROR: <script>: Inside route{........}
12(3162) DEBUG: ims_dialog [dlg_handlers.c:826]: dlg_onroute(): No to tag header found --- ignoring... MESSAGE [SUBSCRIBE
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:826]: dlg_onroute(): No to tag header found --- ignoring... MESSAGE [SUBSCRIBE
12(3162) ERROR: <script>: No=1 Before checking sip:orig@.*
 6(3153) ERROR: <script>: No=1 Before checking sip:orig@.*
 6(3153) ERROR: <script>: Orig
 6(3153) ERROR: <script>: No=2 Inside checking sip:orig@.*
 6(3153) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='bb9e6572-6788-77c7-3288-ed897ffe9ccc' found
 6(3153) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='bb9e6572-6788-77c7-3288-ed897ffe9ccc' found
12(3162) ERROR: <script>: Orig
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid 'bb9e6572-6788-77c7-3288-ed897ffe9ccc' not found
12(3162) ERROR: <script>: No=2 Inside checking sip:orig@.*
12(3162) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='33164750-32dd-aa1a-9822-12767ffec999' found
12(3162) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='33164750-32dd-aa1a-9822-12767ffec999' found
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid '33164750-32dd-aa1a-9822-12767ffec999' not found
12(3162) INFO: ims_isc [ims_isc_mod.c:233]: isc_match_filter(): Checking triggers
 6(3153) INFO: ims_isc [ims_isc_mod.c:233]: isc_match_filter(): Checking triggers
11(3161) ERROR: <script>: Inside route{........}
 6(3153) ERROR: <script>: No=3 Inside checking sip:After route
12(3162) ERROR: <script>: No=3 Inside checking sip:After route
 8(3158) ERROR: <script>: Inside route{........}
 8(3158) ERROR: <script>: No=1 Before checking sip:orig@.*
 8(3158) DEBUG: ims_dialog [dlg_profile.c:596]: is_dlg_in_profile(): Getting current dialog 8(3158) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='bb9e6572-6788-77c7-3288-ed897ffe9ccc' found
 8(3158) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='bb9e6572-6788-77c7-3288-ed897ffe9ccc' found
 8(3158) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid 'bb9e6572-6788-77c7-3288-ed897ffe9ccc' not found
 8(3158) DEBUG: ims_dialog [dlg_profile.c:601]: is_dlg_in_profile(): Error: Current dlg is null 8(3158) DEBUG: ims_dialog [dlg_profile.c:596]: is_dlg_in_profile(): Getting current dialog 8(3158) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='bb9e6572-6788-77c7-3288-ed897ffe9ccc' found
 8(3158) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='bb9e6572-6788-77c7-3288-ed897ffe9ccc' found
 8(3158) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid 'bb9e6572-6788-77c7-3288-ed897ffe9ccc' not found
 8(3158) DEBUG: ims_dialog [dlg_profile.c:601]: is_dlg_in_profile(): Error: Current dlg is null 8(3158) ERROR: <script>: No=9 Terminating ---403  Forbidden - Domain not served 
 5(3152) ERROR: <script>: Inside route{........}
 5(3152) ERROR: <script>: No=1 Before checking sip:orig@.*
 5(3152) DEBUG: ims_dialog [dlg_profile.c:596]: is_dlg_in_profile(): Getting current dialog 5(3152) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='33164750-32dd-aa1a-9822-12767ffec999' found
 5(3152) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='33164750-32dd-aa1a-9822-12767ffec999' found
 5(3152) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid '33164750-32dd-aa1a-9822-12767ffec999' not found
 5(3152) DEBUG: ims_dialog [dlg_profile.c:601]: is_dlg_in_profile(): Error: Current dlg is null 5(3152) DEBUG: ims_dialog [dlg_profile.c:596]: is_dlg_in_profile(): Getting current dialog 5(3152) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='33164750-32dd-aa1a-9822-12767ffec999' found
 5(3152) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='33164750-32dd-aa1a-9822-12767ffec999' found
 5(3152) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid '33164750-32dd-aa1a-9822-12767ffec999' not found
 5(3152) DEBUG: ims_dialog [dlg_profile.c:601]: is_dlg_in_profile(): Error: Current dlg is null 5(3152) ERROR: <script>: No=9 Terminating ---403  Forbidden - Domain not served 
 2(3148) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086897
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086897
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086907
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086907
 1(3147) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086917
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086917
 4(3150) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086927
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086927
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086937
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086937
 6(3153) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086947
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:204]: reg_await_timer(): .. AV    1 - 1 Exp 64086946  0xb2064b88
13(3163) DEBUG: ims_auth [authorize.c:210]: reg_await_timer(): ... dropping av 1 - 1
13(3163) DEBUG: ims_auth [authorize.c:221]: reg_await_timer(): ... started empty aud drop timer
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086947
 2(3148) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086957
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086957
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086967
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086967
11(3161) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086977
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086977
10(3160) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086987
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086987
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64086997
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64086997
 7(3156) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64087007
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64087007
 9(3159) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64087017
13(3163) DEBUG: ims_auth [authorize.c:199]: reg_await_timer(): Slot  181 <alice@koffee-ims.in>
13(3163) DEBUG: ims_auth [authorize.c:225]: reg_await_timer(): ... dropping aud 
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64087017
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64087027
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64087027
 5(3152) ERROR: <script>: Inside route{........}
12(3162) ERROR: <script>: Inside route{........}
12(3162) DEBUG: ims_dialog [dlg_handlers.c:826]: dlg_onroute(): No to tag header found --- ignoring... MESSAGE [INVITE
12(3162) ERROR: <script>: No=1 Before checking sip:orig@.*
12(3162) ERROR: <script>: Orig
12(3162) ERROR: <script>: No=2 Inside checking sip:orig@.*
12(3162) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='74178fce-d298-0315-ecfe-5537f7dfb7c9' found
12(3162) DEBUG: ims_dialog [dlg_hash.c:954]: get_dlg(): no dialog callid='74178fce-d298-0315-ecfe-5537f7dfb7c9' found
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1951]: dlg_get_msg_dialog(): dlg with callid '74178fce-d298-0315-ecfe-5537f7dfb7c9' not found
12(3162) DEBUG: ims_dialog [dlg_handlers.c:775]: dlg_onreq(): dialog creation on config flag
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1554]: dlg_new_dialog(): starting dlg_new_dialog and method is [INVITE]
12(3162) DEBUG: ims_dialog [dlg_hash.c:924]: internal_get_dlg(): no dialog callid='74178fce-d298-0315-ecfe-5537f7dfb7c9' found
12(3162) DEBUG: ims_dialog [dlg_hash.c:1788]: search_dlg(): dialog with callid='74178fce-d298-0315-ecfe-5537f7dfb7c9' not found
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1615]: dlg_new_dialog(): Building new Dialog for call-id 74178fce-d298-0315-ecfe-5537f7dfb7c9
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1616]: dlg_new_dialog(): SIP Method: INVITE  
12(3162) DEBUG: ims_dialog [dlg_hash.c:342]: build_new_dlg(): new dialog on hash 3165
12(3162) DEBUG: ims_dialog [dlg_handlers.c:240]: populate_leg_info(): route_set <sip:mo@192.168.99.140;lr=on;ftag=19054650;rm=8>, contact sip:alice@192.168.99.145:60101;transport=udp, cseq 31553 and bind_addr udp:192.168.99.140:6060 [0xb6da4e88]
12(3162) DEBUG: ims_dialog [dlg_hash.c:1006]: link_dlg(): linking dialog [3165:2638]
12(3162) DEBUG: ims_dialog [dlg_hash.c:1015]: link_dlg(): ref dlg 0xb20619f4 with 1 -> 1
12(3162) DEBUG: ims_dialog [dlg_cb.c:237]: run_create_callbacks(): Running DLG_CREATED callbacks
12(3162) DEBUG: ims_dialog [dlg_cb.c:251]: run_create_callbacks(): dialog=0xb20619f4
12(3162) DEBUG: ims_dialog [dlg_handlers.c:512]: get_dlg_timeout(): invalid AVP value, using default timeout
12(3162) DEBUG: ims_dialog [dlg_profile.c:419]: set_current_dialog(): setting current dialog [3165:2638]
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1672]: dlg_new_dialog(): New dialog created
12(3162) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
12(3162) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
12(3162) DEBUG: ims_dialog [dlg_handlers.c:784]: dlg_onreq(): dialog [0xb20619f4] added to tm callbacks
12(3162) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
12(3162) INFO: ims_isc [ims_isc_mod.c:233]: isc_match_filter(): Checking triggers
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1172]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [256] = [TMCB_REQUEST_OUT]
12(3162) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
12(3162) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1188]: dlg_onreply(): DLG dialogid is entry:id [3165:2638]
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1196]: dlg_onreply(): Received Request out for request [INVITE sip:bob@koffee-ims.in SIP/2.0
Record-Route: <sip:mo@192.168.99.140:6060;lr=on;ftag=19054650;did=d5c.e4a>
Record-Route: <sip:mo@192.168.99.140;lr=on;ftag=19054650;rm=8>
Via: SIP/2.0/UDP 192.168.99.140:6060;branch=z9hG4bKb26e.4f95ab7c27413f23c522be9aa43dd326.0
Via: SIP/2.0/UDP 192.168.99.140;branch=z9hG4bKb26e.5f4e6fb5bd7a2bc208cc932f7a828e2a.0
Via: SIP/2.0/UDP 192.168.99.145:60101;received=192.168.99.145;branch=z9hG4bK19067030;rport=60101
From: <sip:alice@koffee-ims.in>;tag=19054650
To: <sip:bob@koffee-ims.in>
Contact: <sip:alice@192.168.99.145:60101;transport=udp>;+g.oma.sip-im;language="en,fr";+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"
Call-ID: 74178fce-d298-0315-ecfe-5537f7dfb7c9
CSeq: 31553 INVITE
Content-Type: application/sdp
Content-Length: 531
Max-Forwards: 68
Accept-Contact: *;+g.3gpp.icsi-ref="urn%3Aurn-7%3A3gpp-service.ims.icsi.mmtel"
P-Preferred-Service: urn:urn-7:3gpp-service.ims.icsi.mmtel
Allow: INVITE, ACK, CANCEL, BYE, MESSAGE, OPTIONS, NOTIFY, PRACK, UPDATE, REFER
Privacy: none
P-Access-Network-Info: ADSL;utran-cell-id-3gpp=00000000
User-Agent: IM-client/OMA1.0 Boghe-Win32/v2.0.153.836
Supported: 100rel
P-Charging-Vector: icid-value=4956537F000101980B0000D401000000; icid-generated-at=192.168.99.140
P-Visited-Network-ID: koffee-ims.in
P-Asserted-Identity: <sip:alice@koffee-ims.in>

v=0
o=doubango 1983 678901 IN IP4 192.168.99.140
s=-
c=IN IP4 192.168.99.140
t=0 0
a=tcap:1 RTP/AVPF
m=audio 30000 RTP/AVP 0 3 8 97 101
a=ptime:20
a=silenceSupp:off - - - -
a=rtpmap:0 PCMU/8000/1
a=rtpmap:3 GSM/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:97 SPEEX/8000/1
a=rtpmap:101 telephone-event/8000/1
a=fmtp:101 0-16
a=pcfg:1 t=1
a=ssrc:1056905624 cname:ldjWoB60jbyQlR6e
a=ssrc:1056905624 mslabel:6994f7d1-6ce9-4fbd-acfd-84e5131ca2e2
a=ssrc:1056905624 label:Doubango.Audio
a=sendrecv
a=rtcp:30001
a=rtcp-mux
]
12(3162) DEBUG: ims_dialog [dlg_handlers.c:1202]: dlg_onreply(): Ignoring request out as it's not a CANCEL
12(3162) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
12(3162) ERROR: <script>: No=3 Inside checking sip:After route
 3(3149) DEBUG: ims_dialog [dlg_handlers.c:1172]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [2] = [TMCB_RESPONSE_IN]
 3(3149) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 3(3149) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
 3(3149) DEBUG: ims_dialog [dlg_handlers.c:1188]: dlg_onreply(): DLG dialogid is entry:id [3165:2638]
 3(3149) DEBUG: ims_dialog [dlg_profile.c:419]: set_current_dialog(): setting current dialog [3165:2638]
 3(3149) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 8(3158) DEBUG: ims_dialog [dlg_handlers.c:1172]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [2] = [TMCB_RESPONSE_IN]
 8(3158) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 8(3158) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
 8(3158) DEBUG: ims_dialog [dlg_handlers.c:1188]: dlg_onreply(): DLG dialogid is entry:id [3165:2638]
 8(3158) DEBUG: ims_dialog [dlg_profile.c:419]: set_current_dialog(): setting current dialog [3165:2638]
 8(3158) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 1(3147) ERROR: <script>: Inside route{........}
 1(3147) ERROR: <script>: No=1 Before checking sip:orig@.*
 1(3147) DEBUG: ims_dialog [dlg_profile.c:596]: is_dlg_in_profile(): Getting current dialog 1(3147) DEBUG: ims_dialog [dlg_hash.h:414]: match_dialog(): No dlg outs yet...
 1(3147) DEBUG: ims_dialog [dlg_hash.c:915]: internal_get_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 1(3147) DEBUG: ims_dialog [dlg_hash.c:918]: internal_get_dlg(): dialog callid='74178fce-d298-0315-ecfe-5537f7dfb7c9' found on entry 3165, dir=1
 1(3147) DEBUG: ims_dialog [dlg_profile.c:605]: is_dlg_in_profile(): Current dlg found 1(3147) DEBUG: ims_dialog [dlg_profile.c:612]: is_dlg_in_profile(): Running through linkers 1(3147) DEBUG: ims_dialog [dlg_profile.c:614]: is_dlg_in_profile(): Profile matches 1(3147) DEBUG: ims_dialog [dlg_profile.c:616]: is_dlg_in_profile(): Profile has value is zero returning true 1(3147) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 1(3147) DEBUG: ims_dialog [dlg_profile.c:596]: is_dlg_in_profile(): Getting current dialog 1(3147) DEBUG: ims_dialog [dlg_hash.h:414]: match_dialog(): No dlg outs yet...
 1(3147) DEBUG: ims_dialog [dlg_hash.c:915]: internal_get_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 1(3147) DEBUG: ims_dialog [dlg_hash.c:918]: internal_get_dlg(): dialog callid='74178fce-d298-0315-ecfe-5537f7dfb7c9' found on entry 3165, dir=1
 1(3147) DEBUG: ims_dialog [dlg_profile.c:605]: is_dlg_in_profile(): Current dlg found 1(3147) DEBUG: ims_dialog [dlg_profile.c:612]: is_dlg_in_profile(): Running through linkers 1(3147) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 1(3147) ERROR: <script>: No=9 Terminating ---403  Forbidden - Domain not served 
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1172]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [2] = [TMCB_RESPONSE_IN]
 6(3153) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 6(3153) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1188]: dlg_onreply(): DLG dialogid is entry:id [3165:2638]
 6(3153) DEBUG: ims_dialog [dlg_profile.c:419]: set_current_dialog(): setting current dialog [3165:2638]
 6(3153) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1172]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [128] = [TMCB_ON_FAILURE]
 6(3153) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 6(3153) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1188]: dlg_onreply(): DLG dialogid is entry:id [3165:2638]
 6(3153) DEBUG: ims_dialog [dlg_profile.c:419]: set_current_dialog(): setting current dialog [3165:2638]
 6(3153) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1172]: dlg_onreply(): ONREPLY CALL_BACK from TM received and type is [1048576] = [TMCB_RESPONSE_READY]
 6(3153) DEBUG: ims_dialog [dlg_hash.c:879]: lookup_dlg(): ref dlg 0xb20619f4 with 1 -> 2
 6(3153) DEBUG: ims_dialog [dlg_hash.c:881]: lookup_dlg(): dialog id=2638 found on entry 3165
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1188]: dlg_onreply(): DLG dialogid is entry:id [3165:2638]
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1230]: dlg_onreply(): Extracting to-tag from reply 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1250]: dlg_onreply(): Got to-tag from response: 84772552fab76e8916cf9e5dd5027417.9b14 
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1270]: dlg_onreply(): Calling next_state_dlg and event is 4 = DLG_EVENT_RPL3xx
 6(3153) DEBUG: ims_dialog [dlg_hash.c:1283]: next_state_dlg(): dialog 0xb20619f4 changed from state 1 to state 6, due event 4
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1274]: dlg_onreply(): Checking if there is an existing dialog_out entry with same to-tag 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1295]: dlg_onreply(): Extracting to-tag from reply 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1326]: dlg_onreply(): Got to-tag from response: 84772552fab76e8916cf9e5dd5027417.9b14 
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1333]: dlg_onreply(): Scanning dlg_entry_out list for dlg_out 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1404]: dlg_onreply(): new state is 6 and old state is 1
 6(3153) DEBUG: ims_dialog [dlg_handlers.c:1484]: dlg_onreply(): dialog 0xb20619f4 failed (negative reply)
 6(3153) DEBUG: ims_dialog [dlg_cb.c:277]: run_dlg_callbacks(): dialog=0xb20619f4, type=4
 6(3153) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 1
 6(3153) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): unref dlg 0xb20619f4 with 1 -> 0
 6(3153) DEBUG: ims_dialog [dlg_hash.c:1056]: unref_dlg(): ref <=0 for dialog 0xb20619f4
 6(3153) DEBUG: ims_dialog [dlg_hash.c:194]: destroy_dlg(): destroying dialog 0xb20619f4
 6(3153) DEBUG: ims_dialog [dlg_hash.c:209]: destroy_dlg(): removed timer for dlg 0xb20619f4 [3165:2638] with clid '74178fce-d298-0315-ecfe-5537f7dfb7c9' and tags '19054650' 
 6(3153) DEBUG: ims_dialog [dlg_hash.c:216]: destroy_dlg(): About to run dlg callback for destroy
 6(3153) DEBUG: ims_dialog [dlg_cb.c:277]: run_dlg_callbacks(): dialog=0xb20619f4, type=8192
 6(3153) DEBUG: ims_dialog [dlg_hash.c:218]: destroy_dlg(): DONE: About to run dlg callback for destroy
 6(3153) DEBUG: ims_dialog [dlg_hash.c:154]: destroy_entry_out(): Destroy dialog entry out
 2(3148) ERROR: <script>: Inside route{........}
 2(3148) WARNING: tm [t_lookup.c:1465]: t_unref(): script writer didn't release transaction
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64087037
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64087037
14(3164) DEBUG: ims_dialog [dlg_handlers.c:284]: dlg_iuid_sfree(): freeing dlg iuid [3165:2638] (0xb2061e1c)
11(3161) ERROR: <script>: Inside route{........}
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64087047
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64087047
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1918]: print_all_dlgs(): ********************13(3163) DEBUG: ims_dialog [dlg_handlers.c:1919]: print_all_dlgs(): printing 4096 dialogs
13(3163) DEBUG: ims_dialog [dlg_handlers.c:1929]: print_all_dlgs(): ********************13(3163) DEBUG: ims_auth [authorize.c:193]: reg_await_timer(): Looking for expired/useless at 64087057
13(3163) DEBUG: ims_auth [authorize.c:238]: reg_await_timer(): [DONE] Looking for expired/useless at 64087057
10(3160) ERROR: <script>: Inside route{........}