Aug 31 11:17:06 [5758] DBG:core:parse_msg: SIP Request:
Aug 31 11:17:06 [5758] DBG:core:parse_msg:  method:  <REGISTER>
Aug 31 11:17:06 [5758] DBG:core:parse_msg:  uri:     <sip:192.168.0.70:5060>
Aug 31 11:17:06 [5758] DBG:core:parse_msg:  version: <SIP/2.0>
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=2
Aug 31 11:17:06 [5758] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK60ba.f9ca4da1.0>; state=16
Aug 31 11:17:06 [5758] DBG:core:parse_via: end of header reached, state=5
Aug 31 11:17:06 [5758] DBG:core:parse_headers: via found, flags=2
Aug 31 11:17:06 [5758] DBG:core:parse_headers: this is the first via
Aug 31 11:17:06 [5758] DBG:core:receive_msg: After parse_msg...
Aug 31 11:17:06 [5758] DBG:core:receive_msg: preparing to run routing scripts...
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=100
Aug 31 11:17:06 [5758] DBG:core:parse_to: end of header reached, state=9
Aug 31 11:17:06 [5758] DBG:core:parse_to: display={}, ruri={sip:titi@open-ims.test}
Aug 31 11:17:06 [5758] DBG:core:get_hdr_field: <To> [24]; uri=[sip:titi@open-ims.test] 
Aug 31 11:17:06 [5758] DBG:core:get_hdr_field: to body [sip:titi@open-ims.test
]
Aug 31 11:17:06 [5758] DBG:core:get_hdr_field: cseq <CSeq>: <10> <REGISTER>
Aug 31 11:17:06 [5758] DBG:core:get_hdr_field: content_length=0
Aug 31 11:17:06 [5758] DBG:maxfwd:is_maxfwd_present: value = 10 
Aug 31 11:17:06 [5758] DBG:uri:has_totag: no totag
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=78
Aug 31 11:17:06 [5758] DBG:tm:t_lookup_request: start searching: hash=43782, isACK=0
Aug 31 11:17:06 [5758] DBG:tm:matching_3261: RFC3261 transaction matching failed
Aug 31 11:17:06 [5758] DBG:tm:t_lookup_request: no transaction found
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=200
Aug 31 11:17:06 [5758] DBG:core:get_hdr_field: found end of header
Aug 31 11:17:06 [5758] DBG:rr:find_first_route: No Route headers found
Aug 31 11:17:06 [5758] DBG:rr:loose_route: There is no Route HF
Aug 31 11:17:06 [5758] DBG:core:grep_sock_info: checking if host==us: 12==12 &&  [192.168.0.70] == [192.168.0.70]
Aug 31 11:17:06 [5758] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=ffffffffffffffff
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=8000000
Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=ffffffffffffffff
Aug 31 11:17:06 [5758] DBG:usrloc:update_ucontact: exists callback for type= UL_CONTACT_UPDATE
Aug 31 11:17:06 [5758] DBG:registrar:build_contact: created Contact HF: Contact: <sip:scscf.open-ims.test:6060>;expires=600120

Aug 31 11:17:06 [5758] DBG:core:parse_headers: flags=ffffffffffffffff
Aug 31 11:17:06 [5758] DBG:core:check_ip_address: params 192.168.0.72, 192.168.0.72, 0
Aug 31 11:17:06 [5758] DBG:core:destroy_avp_list: destroying list (nil)
Aug 31 11:17:06 [5758] DBG:core:receive_msg: cleaning up
Aug 31 11:17:12 [5758] DBG:core:parse_msg: SIP Request:
Aug 31 11:17:12 [5758] DBG:core:parse_msg:  method:  <INVITE>
Aug 31 11:17:12 [5758] DBG:core:parse_msg:  uri:     <sip:yassine@open-ims.test>
Aug 31 11:17:12 [5758] DBG:core:parse_msg:  version: <SIP/2.0>
Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=2
Aug 31 11:17:12 [5758] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0723.a9bf0797.0>; state=16
Aug 31 11:17:12 [5758] DBG:core:parse_via: end of header reached, state=5
Aug 31 11:17:12 [5758] DBG:core:parse_headers: via found, flags=2
Aug 31 11:17:12 [5758] DBG:core:parse_headers: this is the first via
Aug 31 11:17:12 [5758] DBG:core:receive_msg: After parse_msg...
Aug 31 11:17:12 [5758] DBG:core:receive_msg: preparing to run routing scripts...
Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=100
Aug 31 11:17:12 [5758] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0723.e4626a26.0>; state=16
Aug 31 11:17:12 [5758] DBG:core:parse_via: end of header reached, state=5
Aug 31 11:17:12 [5758] DBG:core:parse_headers: via found, flags=100
Aug 31 11:17:12 [5758] DBG:core:parse_headers: parse_headers: this is the second via
Aug 31 11:17:12 [5758] DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Aug 31 11:17:12 [5758] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1612509901>; state=16
Aug 31 11:17:12 [5758] DBG:core:parse_via: end of header reached, state=5
Aug 31 11:17:12 [5758] DBG:core:parse_headers: via found, flags=100
Aug 31 11:17:12 [5758] DBG:core:parse_to: end of header reached, state=10
Aug 31 11:17:12 [5758] DBG:core:parse_to: display={}, ruri={sip:yassine@open-ims.test}
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: <To> [29]; uri=[sip:yassine@open-ims.test] 
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: to body [<sip:yassine@open-ims.test>
]
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: cseq <CSeq>: <20> <INVITE>
Aug 31 11:17:12 [5758] DBG:maxfwd:is_maxfwd_present: value = 15 
Aug 31 11:17:12 [5758] DBG:uri:has_totag: no totag
Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=78
Aug 31 11:17:12 [5758] DBG:tm:t_lookup_request: start searching: hash=12912, isACK=0
Aug 31 11:17:12 [5758] DBG:tm:matching_3261: RFC3261 transaction matching failed
Aug 31 11:17:12 [5758] DBG:tm:t_lookup_request: no transaction found
Aug 31 11:17:12 [5758] DBG:core:parse_to_param: tag=95842272
Aug 31 11:17:12 [5758] DBG:core:parse_to: end of header reached, state=29
Aug 31 11:17:12 [5758] DBG:core:parse_to: display={"titi"}, ruri={sip:titi@open-ims.test}
Aug 31 11:17:12 [5758] DBG:core:grep_sock_info: checking if host==us: 13==12 &&  [open-ims.test] == [192.168.0.70]
Aug 31 11:17:12 [5758] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=200
Aug 31 11:17:12 [5758] DBG:rr:is_preloaded: is_preloaded: Yes
Aug 31 11:17:12 [5758] DBG:core:grep_sock_info: checking if host==us: 12==12 &&  [192.168.0.70] == [192.168.0.70]
Aug 31 11:17:12 [5758] DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Aug 31 11:17:12 [5758] DBG:rr:after_loose: Topmost route URI: 'sip:192.168.0.70:5060;lr' is me
Aug 31 11:17:12 [5758] DBG:rr:after_loose: URI to be processed: 'sip:iscmark@scscf.open-ims.test:6060;lr;s=1;h=0;d=0;a=7369703a74697469406f70656e2d696d732e74657374'
Aug 31 11:17:12 [5758] DBG:rr:after_loose: Next URI is a loose router
Attempt to route with preloaded Route's [sip:titi@open-ims.test/sip:yassine@open-ims.test/sip:yassine@open-ims.test/1349680262]Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=ffffffffffffffff
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: content_length=334
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: found end of header
Aug 31 11:17:12 [5758] DBG:core:check_ip_address: params 192.168.0.72, 192.168.0.72, 0
Aug 31 11:17:12 [5758] DBG:core:destroy_avp_list: destroying list (nil)
Aug 31 11:17:12 [5758] DBG:core:receive_msg: cleaning up
Aug 31 11:17:12 [5758] DBG:core:parse_msg: SIP Request:
Aug 31 11:17:12 [5758] DBG:core:parse_msg:  method:  <ACK>
Aug 31 11:17:12 [5758] DBG:core:parse_msg:  uri:     <sip:yassine@open-ims.test>
Aug 31 11:17:12 [5758] DBG:core:parse_msg:  version: <SIP/2.0>
Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=2
Aug 31 11:17:12 [5758] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK0723.a9bf0797.0>; state=16
Aug 31 11:17:12 [5758] DBG:core:parse_via: end of header reached, state=5
Aug 31 11:17:12 [5758] DBG:core:parse_headers: via found, flags=2
Aug 31 11:17:12 [5758] DBG:core:parse_headers: this is the first via
Aug 31 11:17:12 [5758] DBG:core:receive_msg: After parse_msg...
Aug 31 11:17:12 [5758] DBG:core:receive_msg: preparing to run routing scripts...
Aug 31 11:17:12 [5758] DBG:core:parse_headers: flags=8
Aug 31 11:17:12 [5758] DBG:core:parse_to_param: tag=d9d72f9546b6b56e4e4be7c5ecbf45ae.ad3d
Aug 31 11:17:12 [5758] DBG:core:parse_to: end of header reached, state=29
Aug 31 11:17:12 [5758] DBG:core:parse_to: display={}, ruri={sip:yassine@open-ims.test}
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: <To> [71]; uri=[sip:yassine@open-ims.test] 
Aug 31 11:17:12 [5758] DBG:core:get_hdr_field: to body [<sip:yassine@open-ims.test>]
Aug 31 11:17:12 [5758] DBG:sl:sl_filter_ACK: local ACK found -> dropping it!
Aug 31 11:17:12 [5758] DBG:core:destroy_avp_list: destroying list (nil)
Aug 31 11:17:12 [5758] DBG:core:receive_msg: cleaning up
Aug 31 11:17:22 [5761] DBG:db_mysql:has_stmt_ctx: ctx found for location
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_do_prepared_query: conn=0xb7193e98 (tail=-1223083064) MC=0xb7194220
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (0): len=36; type=12; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (1): len=8; type=5; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (2): len=4; type=3; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (3): len=4; type=3; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (4): len=4; type=3; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (5): len=55; type=254; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (8): len=21; type=254; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (10): len=36; type=12; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (11): len=4; type=254; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (12): len=28; type=254; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_val2bind: added val (13): len=26; type=254; is_null=0
Aug 31 11:17:22 [5761] DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...