Jun 19 14:35:44 [31807] DBG:core:parse_msg: SIP Request:
Jun 19 14:35:44 [31807] DBG:core:parse_msg:  method:  <INVITE>
Jun 19 14:35:44 [31807] DBG:core:parse_msg:  uri:     <sip:33330003@40.0.0.164;user=phone>
Jun 19 14:35:44 [31807] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=2
Jun 19 14:35:44 [31807] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4131910994-27980743>; state=16
Jun 19 14:35:44 [31807] DBG:core:parse_via: end of header reached, state=5
Jun 19 14:35:44 [31807] DBG:core:parse_headers: via found, flags=2
Jun 19 14:35:44 [31807] DBG:core:parse_headers: this is the first via
Jun 19 14:35:44 [31807] DBG:core:receive_msg: After parse_msg...
Jun 19 14:35:44 [31807] DBG:core:receive_msg: preparing to run routing scripts...
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=100
Jun 19 14:35:44 [31807] DBG:maxfwd:is_maxfwd_present: value = 70 
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=8
Jun 19 14:35:44 [31807] DBG:core:parse_to: end of header reached, state=10
Jun 19 14:35:44 [31807] DBG:core:parse_to: display={}, ruri={sip:33330003@40.0.0.164;user=phone}
Jun 19 14:35:44 [31807] DBG:core:get_hdr_field: <To> [38]; uri=[sip:33330003@40.0.0.164;user=phone] 
Jun 19 14:35:44 [31807] DBG:core:get_hdr_field: to body [<sip:33330003@40.0.0.164;user=phone>
]
Jun 19 14:35:44 [31807] DBG:uri:has_totag: no totag
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=78
Jun 19 14:35:44 [31807] DBG:core:get_hdr_field: cseq <CSeq>: <1> <INVITE>
Jun 19 14:35:44 [31807] DBG:tm:t_lookup_request: start searching: hash=11073, isACK=0
Jun 19 14:35:44 [31807] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 19 14:35:44 [31807] DBG:tm:t_lookup_request: no transaction found
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=200
Jun 19 14:35:44 [31807] DBG:rr:is_preloaded: is_preloaded: Yes
Jun 19 14:35:44 [31807] DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [40.0.0.164] == [40.0.0.164]
Jun 19 14:35:44 [31807] DBG:core:grep_sock_info: checking if port 7060 matches port 7060
Jun 19 14:35:44 [31807] DBG:rr:after_loose: Topmost route URI: 'sip:40.0.0.164:7060;lr' is me
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=200
Jun 19 14:35:44 [31807] DBG:core:get_hdr_field: content_length=168
Jun 19 14:35:44 [31807] DBG:core:get_hdr_field: found end of header
Jun 19 14:35:44 [31807] DBG:rr:find_next_route: No next Route HF found
Jun 19 14:35:44 [31807] DBG:rr:after_loose: No next URI found
Jun 19 14:35:44 [31807] DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [40.0.0.164] == [40.0.0.164]
Jun 19 14:35:44 [31807] DBG:core:grep_sock_info: checking if port 7060 matches port 5060
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_submit_query: discon reset for 135853360
Jun 19 14:35:44 [31807] DBG:core:db_do_query: SYNC-DBG - SELECT successfully executed!
Jun 19 14:35:44 [31807] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8195508
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jun 19 14:35:44 [31807] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x8195538
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x819553c)[0]=[domain]
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jun 19 14:35:44 [31807] DBG:domain:is_domain_local: Realm '40.0.0.164' is not local
Jun 19 14:35:44 [31807] DBG:core:db_free_columns: freeing result columns at 0x8195538
Jun 19 14:35:44 [31807] DBG:core:db_free_rows: freeing 0 rows
Jun 19 14:35:44 [31807] DBG:core:db_free_result: freeing result set at 0x8195508
Jun 19 14:35:44 [31807] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 19 14:35:44 [31807] DBG:core:check_self: host != me
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_submit_query: discon reset for 135853360
Jun 19 14:35:44 [31807] DBG:core:db_do_query: SYNC-DBG - SELECT successfully executed!
Jun 19 14:35:44 [31807] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8195508
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jun 19 14:35:44 [31807] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x8195538
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x819553c)[0]=[domain]
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 19 14:35:44 [31807] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jun 19 14:35:44 [31807] DBG:domain:is_domain_local: Realm '40.0.0.164' is not local
Jun 19 14:35:44 [31807] DBG:core:db_free_columns: freeing result columns at 0x8195538
Jun 19 14:35:44 [31807] DBG:core:db_free_rows: freeing 0 rows
Jun 19 14:35:44 [31807] DBG:core:db_free_result: freeing result set at 0x8195508
Jun 19 14:35:44 [31807] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 19 14:35:44 [31807] DBG:tm:t_newtran: transaction on entrance=(nil)
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=78
Jun 19 14:35:44 [31807] DBG:tm:t_lookup_request: start searching: hash=11073, isACK=0
Jun 19 14:35:44 [31807] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 19 14:35:44 [31807] DBG:tm:t_lookup_request: no transaction found
Jun 19 14:35:44 [31807] DBG:core:parse_to_param: tag=ICF_4131911754-27980744
Jun 19 14:35:44 [31807] DBG:core:parse_to: end of header reached, state=29
Jun 19 14:35:44 [31807] DBG:core:parse_to: display={"33330004"}, ruri={sip:33330004@40.0.0.164;user=phone}
Jun 19 14:35:44 [31807] DBG:tm:run_reqin_callbacks: trans=0xb60f9dd8, callback type 1, id 0 entered
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=78
Jun 19 14:35:44 [31807] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 19 14:35:44 [31807] DBG:core:check_via_address: params 40.0.0.165, 40.0.0.165, 0
Jun 19 14:35:44 [31807] DBG:core:_shm_resize: resize(0) called
Jun 19 14:35:44 [31807] DBG:tm:_reply_light: reply sent out. buf=0x8195698: SIP/2.0 1..., shmem=0xb60fb898: SIP/2.0 1
Jun 19 14:35:44 [31807] DBG:tm:_reply_light: finished
new branch at sip:33330003@40.0.0.164;user=phone
Jun 19 14:35:44 [31807] DBG:core:mk_proxy: doing DNS lookup...
Jun 19 14:35:44 [31807] DBG:core:check_via_address: params 40.0.0.165, 40.0.0.165, 0
Jun 19 14:35:44 [31807] DBG:tm:set_timer: relative timeout is 500000
Jun 19 14:35:44 [31807] DBG:tm:insert_timer_unsafe: [4]: 0xb60f9f24 (14800000)
Jun 19 14:35:44 [31807] DBG:tm:set_timer: relative timeout is 30
Jun 19 14:35:44 [31807] DBG:tm:insert_timer_unsafe: [0]: 0xb60f9f40 (44)
Jun 19 14:35:44 [31807] DBG:tm:t_relay_to: new transaction fwd'ed
Jun 19 14:35:44 [31807] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 19 14:35:44 [31807] DBG:core:destroy_avp_list: destroying list (nil)
Jun 19 14:35:44 [31807] DBG:core:receive_msg: cleaning up
Jun 19 14:35:44 [31811] DBG:tm:utimer_routine: timer routine:4,tl=0xb60f9f24 next=(nil), timeout=14800000
Jun 19 14:35:44 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:35:44 [31811] DBG:tm:set_timer: relative timeout is 1000000
Jun 19 14:35:44 [31811] DBG:tm:insert_timer_unsafe: [5]: 0xb60f9f24 (15800000)
Jun 19 14:35:44 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:35:45 [31811] DBG:tm:utimer_routine: timer routine:5,tl=0xb60f9f24 next=(nil), timeout=15800000
Jun 19 14:35:45 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:35:45 [31811] DBG:tm:set_timer: relative timeout is 2000000
Jun 19 14:35:45 [31811] DBG:tm:insert_timer_unsafe: [6]: 0xb60f9f24 (17800000)
Jun 19 14:35:45 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:35:47 [31811] DBG:tm:utimer_routine: timer routine:6,tl=0xb60f9f24 next=(nil), timeout=17800000
Jun 19 14:35:47 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:35:47 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:35:47 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (21800000)
Jun 19 14:35:47 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:35:51 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=21800000
Jun 19 14:35:51 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:35:51 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:35:51 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (25800000)
Jun 19 14:35:51 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:35:55 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=25800000
Jun 19 14:35:55 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:35:55 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:35:55 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (29800000)
Jun 19 14:35:55 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:35:59 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=29800000
Jun 19 14:35:59 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:35:59 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:35:59 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (33800000)
Jun 19 14:35:59 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:36:03 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=33800000
Jun 19 14:36:03 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:36:03 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:36:03 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (37800000)
Jun 19 14:36:03 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:36:07 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=37800000
Jun 19 14:36:07 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:36:07 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:36:07 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (41800000)
Jun 19 14:36:07 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:36:11 [31807] DBG:core:parse_msg: SIP Request:
Jun 19 14:36:11 [31807] DBG:core:parse_msg:  method:  <OPTIONS>
Jun 19 14:36:11 [31807] DBG:core:parse_msg:  uri:     <sip:40.0.0.164:7060;transport=udp>
Jun 19 14:36:11 [31807] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=2
Jun 19 14:36:11 [31807] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4158799234-27980746>; state=16
Jun 19 14:36:11 [31807] DBG:core:parse_via: end of header reached, state=5
Jun 19 14:36:11 [31807] DBG:core:parse_headers: via found, flags=2
Jun 19 14:36:11 [31807] DBG:core:parse_headers: this is the first via
Jun 19 14:36:11 [31807] DBG:core:receive_msg: After parse_msg...
Jun 19 14:36:11 [31807] DBG:core:receive_msg: preparing to run routing scripts...
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=100
Jun 19 14:36:11 [31807] DBG:maxfwd:is_maxfwd_present: value = 70 
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=8
Jun 19 14:36:11 [31807] DBG:core:parse_to: end of header reached, state=10
Jun 19 14:36:11 [31807] DBG:core:parse_to: display={}, ruri={sip:40.0.0.164:7060;transport=udp}
Jun 19 14:36:11 [31807] DBG:core:get_hdr_field: <To> [37]; uri=[sip:40.0.0.164:7060;transport=udp] 
Jun 19 14:36:11 [31807] DBG:core:get_hdr_field: to body [<sip:40.0.0.164:7060;transport=udp>
]
Jun 19 14:36:11 [31807] DBG:uri:has_totag: no totag
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=78
Jun 19 14:36:11 [31807] DBG:core:get_hdr_field: cseq <CSeq>: <1> <OPTIONS>
Jun 19 14:36:11 [31807] DBG:tm:t_lookup_request: start searching: hash=58997, isACK=0
Jun 19 14:36:11 [31807] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 19 14:36:11 [31807] DBG:tm:t_lookup_request: no transaction found
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=200
Jun 19 14:36:11 [31807] DBG:rr:is_preloaded: is_preloaded: Yes
Jun 19 14:36:11 [31807] DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [40.0.0.164] == [40.0.0.164]
Jun 19 14:36:11 [31807] DBG:core:grep_sock_info: checking if port 7060 matches port 7060
Jun 19 14:36:11 [31807] DBG:rr:after_loose: Topmost route URI: 'sip:40.0.0.164:7060;lr' is me
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=200
Jun 19 14:36:11 [31807] DBG:core:get_hdr_field: content_length=0
Jun 19 14:36:11 [31807] DBG:core:get_hdr_field: found end of header
Jun 19 14:36:11 [31807] DBG:rr:find_next_route: No next Route HF found
Jun 19 14:36:11 [31807] DBG:rr:after_loose: No next URI found
Jun 19 14:36:11 [31807] DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [40.0.0.164] == [40.0.0.164]
Jun 19 14:36:11 [31807] DBG:core:grep_sock_info: checking if port 7060 matches port 7060
Jun 19 14:36:11 [31807] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 19 14:36:11 [31807] DBG:core:check_via_address: params 40.0.0.165, 40.0.0.165, 0
Jun 19 14:36:11 [31807] DBG:core:destroy_avp_list: destroying list (nil)
Jun 19 14:36:11 [31807] DBG:core:receive_msg: cleaning up
Jun 19 14:36:11 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=41800000
Jun 19 14:36:11 [31811] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0xb60f9dd8, INVITE si ... )
Jun 19 14:36:11 [31811] DBG:tm:set_timer: relative timeout is 4000000
Jun 19 14:36:11 [31811] DBG:tm:insert_timer_unsafe: [7]: 0xb60f9f24 (45800000)
Jun 19 14:36:11 [31811] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 19 14:36:14 [31811] DBG:tm:timer_routine: timer routine:0,tl=0xb60f9f40 next=(nil), timeout=44
Jun 19 14:36:14 [31811] DBG:tm:final_response_handler: stop retr. and send CANCEL (0xb60f9dd8)
Jun 19 14:36:14 [31811] DBG:tm:t_should_relay_response: T_code=100, new_code=408
Jun 19 14:36:14 [31811] DBG:tm:t_pick_branch: picked branch 0, code 408 (prio=800)
Jun 19 14:36:14 [31811] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=408, flags=1
Jun 19 14:36:14 [31811] DBG:tm:t_should_relay_response: trying DNS-based failover
Jun 19 14:36:14 [31811] DBG:tm:relay_reply: branch=0, save=0, relay=0
Jun 19 14:36:14 [31811] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 19 14:36:14 [31811] DBG:core:check_via_address: params 40.0.0.165, 40.0.0.165, 0
Jun 19 14:36:14 [31811] DBG:tm:set_timer: relative timeout is 500000
Jun 19 14:36:14 [31811] DBG:tm:insert_timer_unsafe: [4]: 0xb60f9ea0 (44500000)
Jun 19 14:36:14 [31811] DBG:tm:set_timer: relative timeout is 30
Jun 19 14:36:14 [31811] DBG:tm:insert_timer_unsafe: [0]: 0xb60f9ebc (74)
Jun 19 14:36:14 [31811] DBG:tm:relay_reply: sent buf=0x8190bb8: SIP/2.0 4..., shmem=0xb60fb898: SIP/2.0 4
Jun 19 14:36:14 [31811] DBG:tm:run_trans_callbacks: trans=0xb60f9dd8, callback type 256, id 0 entered
Jun 19 14:36:14 [31811] DBG:tm:final_response_handler: done
Jun 19 14:36:14 [31807] DBG:core:parse_msg: SIP Request:
Jun 19 14:36:14 [31807] DBG:core:parse_msg:  method:  <ACK>
Jun 19 14:36:14 [31807] DBG:core:parse_msg:  uri:     <sip:33330003@40.0.0.164;user=phone>
Jun 19 14:36:14 [31807] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=2
Jun 19 14:36:14 [31807] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4131910994-27980743>; state=16
Jun 19 14:36:14 [31807] DBG:core:parse_via: end of header reached, state=5
Jun 19 14:36:14 [31807] DBG:core:parse_headers: via found, flags=2
Jun 19 14:36:14 [31807] DBG:core:parse_headers: this is the first via
Jun 19 14:36:14 [31807] DBG:core:receive_msg: After parse_msg...
Jun 19 14:36:14 [31807] DBG:core:receive_msg: preparing to run routing scripts...
Jun 19 14:36:14 [31807] DBG:sl:sl_filter_ACK: to late to be a local ACK!
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=100
Jun 19 14:36:14 [31807] DBG:maxfwd:is_maxfwd_present: value = 70 
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=8
Jun 19 14:36:14 [31807] DBG:core:parse_to_param: tag=d48cb5429d75d1b1bcd850e159ef351c-a3d7
Jun 19 14:36:14 [31807] DBG:core:parse_to: end of header reached, state=29
Jun 19 14:36:14 [31807] DBG:core:parse_to: display={}, ruri={sip:33330003@40.0.0.164;user=phone}
Jun 19 14:36:14 [31807] DBG:core:get_hdr_field: <To> [80]; uri=[sip:33330003@40.0.0.164;user=phone] 
Jun 19 14:36:14 [31807] DBG:core:get_hdr_field: to body [<sip:33330003@40.0.0.164;user=phone>]
Jun 19 14:36:14 [31807] DBG:uri:has_totag: totag found
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=200
Jun 19 14:36:14 [31807] DBG:rr:is_preloaded: is_preloaded: No
Jun 19 14:36:14 [31807] DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [40.0.0.164] == [40.0.0.164]
Jun 19 14:36:14 [31807] DBG:core:grep_sock_info: checking if port 7060 matches port 5060
Jun 19 14:36:14 [31807] DBG:db_mysql:db_mysql_submit_query: discon reset for 135853360
Jun 19 14:36:14 [31807] DBG:core:db_do_query: SYNC-DBG - SELECT successfully executed!
Jun 19 14:36:14 [31807] DBG:core:db_new_result: allocate 28 bytes for result set at 0x8195570
Jun 19 14:36:14 [31807] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 19 14:36:14 [31807] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jun 19 14:36:14 [31807] DBG:core:db_allocate_columns: allocate 16 bytes for result columns at 0x8195538
Jun 19 14:36:14 [31807] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x819553c)[0]=[domain]
Jun 19 14:36:14 [31807] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 19 14:36:14 [31807] DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
Jun 19 14:36:14 [31807] DBG:domain:is_domain_local: Realm '40.0.0.164' is not local
Jun 19 14:36:14 [31807] DBG:core:db_free_columns: freeing result columns at 0x8195538
Jun 19 14:36:14 [31807] DBG:core:db_free_rows: freeing 0 rows
Jun 19 14:36:14 [31807] DBG:core:db_free_result: freeing result set at 0x8195570
Jun 19 14:36:14 [31807] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 19 14:36:14 [31807] DBG:core:check_self: host != me
Jun 19 14:36:14 [31807] DBG:core:grep_sock_info: checking if host==us: 10==10 &&  [40.0.0.164] == [40.0.0.164]
Jun 19 14:36:14 [31807] DBG:core:grep_sock_info: checking if port 7060 matches port 7060
Jun 19 14:36:14 [31807] DBG:rr:after_loose: Topmost route URI: 'sip:40.0.0.164:7060;lr' is me
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=200
Jun 19 14:36:14 [31807] DBG:core:get_hdr_field: cseq <CSeq>: <1> <ACK>
Jun 19 14:36:14 [31807] DBG:core:get_hdr_field: content_length=0
Jun 19 14:36:14 [31807] DBG:core:get_hdr_field: found end of header
Jun 19 14:36:14 [31807] DBG:rr:find_next_route: No next Route HF found
Jun 19 14:36:14 [31807] DBG:rr:after_loose: No next URI found
Jun 19 14:36:14 [31807] DBG:tm:t_newtran: transaction on entrance=0xffffffff
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 19 14:36:14 [31807] DBG:core:parse_headers: flags=78
Jun 19 14:36:14 [31807] DBG:tm:t_lookup_request: start searching: hash=11073, isACK=1
Jun 19 14:36:14 [31807] DBG:tm:matching_3261: RFC3261 transaction matched, tid=4131910994-27980743
Jun 19 14:36:14 [31807] DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
Jun 19 14:36:14 [31807] DBG:tm:t_lookup_request: transaction found (T=0xb60f9dd8)
Jun 19 14:36:14 [31807] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jun 19 14:36:14 [31807] DBG:tm:insert_timer_unsafe: [2]: 0xb60f9e20 (49)
Jun 19 14:36:14 [31807] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 19 14:36:14 [31807] DBG:core:destroy_avp_list: destroying list (nil)
Jun 19 14:36:14 [31807] DBG:core:receive_msg: cleaning up
Jun 19 14:36:14 [31811] DBG:tm:utimer_routine: timer routine:4,tl=0xb60f9ea0 next=(nil), timeout=44500000
Jun 19 14:36:15 [31811] DBG:tm:utimer_routine: timer routine:7,tl=0xb60f9f24 next=(nil), timeout=45800000
Jun 19 14:36:19 [31811] DBG:tm:timer_routine: timer routine:2,tl=0xb60f9e20 next=(nil), timeout=49
Jun 19 14:36:19 [31811] DBG:tm:wait_handler: removing 0xb60f9dd8 from table 
Jun 19 14:36:19 [31811] DBG:tm:delete_cell: delete transaction 0xb60f9dd8
Jun 19 14:36:19 [31811] DBG:tm:wait_handler: done