./opensips[28089]: DBG:core:parse_msg: SIP Request:
./opensips[28089]: DBG:core:parse_msg:method:<INVITE>
./opensips[28089]: DBG:core:parse_msg:uri: <sip:185511@10.250.5.3:5080>
./opensips[28089]: DBG:core:parse_msg:version: <SIP/2.0>
./opensips[28089]: DBG:core:parse_headers: flags=2
./opensips[28089]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
./opensips[28089]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1ytH5t8ZyF3aH>; state=16
./opensips[28089]: DBG:core:parse_via: end of header reached, state=5
./opensips[28089]: DBG:core:parse_headers: via found, flags=2
./opensips[28089]: DBG:core:parse_headers: this is the first via
./opensips[28089]: DBG:core:receive_msg: After parse_msg...
./opensips[28089]: DBG:core:receive_msg: preparing to run routing scripts...
./opensips[28089]: DBG:core:parse_headers: flags=100
./opensips[28089]: DBG:maxfwd:is_maxfwd_present: value = 69
./opensips[28089]: DBG:core:parse_headers: flags=8
./opensips[28089]: DBG:core:parse_to: end of header reached, state=10
./opensips[28089]: DBG:core:parse_to: display={}, ruri={sip:185511@10.250.5.3:5080}
./opensips[28089]: DBG:core:get_hdr_field: <To> [30]; uri=[sip:185511@10.250.5.3:5080]
./opensips[28089]: DBG:core:get_hdr_field: to body [<sip:185511@10.250.5.3:5080>#015#012]
./opensips[28089]: DBG:uri:has_totag: no totag
./opensips[28089]: DBG:core:parse_headers: flags=78
./opensips[28089]: DBG:core:get_hdr_field: cseq <CSeq>: <88641991> <INVITE>
./opensips[28089]: DBG:tm:t_lookup_request: start searching: hash=30020, isACK=0
./opensips[28089]: DBG:tm:matching_3261: RFC3261 transaction matching failed
./opensips[28089]: DBG:tm:t_lookup_request: no transaction found
./opensips[28089]: DBG:core:parse_headers: flags=200
./opensips[28089]: DBG:core:get_hdr_field: content_length=218
./opensips[28089]: DBG:core:get_hdr_field: found end of header
./opensips[28089]: DBG:rr:find_first_route: No Route headers found
./opensips[28089]: DBG:rr:loose_route: There is no Route HF
./opensips[28089]: DBG:core:parse_to_param: tag=m05SKryceZQ7F
./opensips[28089]: DBG:core:parse_to: end of header reached, state=29
./opensips[28089]: DBG:core:parse_to: display={"1001"}, ruri={sip:1001@[10.250.5.50:5090]}
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 16==13 &&[10.250.5.50:5090] == [192.168.1.150]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 16==10 &&[10.250.5.50:5090] == [10.250.5.3]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5080 matches port 5060
./opensips[28089]: DBG:core:check_self: host != me
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 10==13 &&[10.250.5.3] == [192.168.1.150]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5060 matches port 5080
./opensips[28089]: DBG:core:grep_sock_info: checking if host==us: 10==10 &&[10.250.5.3] == [10.250.5.3]
./opensips[28089]: DBG:core:grep_sock_info: checking if port 5080 matches port 5080
./opensips[28089]: DBG:core:buf_init: initializing...
./opensips[28089]: Into invite method.
./opensips[28089]: DBG:dialog:w_create_dialog2: bye on timeout activated
./opensips[28089]: DBG:dialog:build_new_dlg: new dialog 0x7fb36ea18a18 (c=83c45345-647d-1234-e187-000c295a647b,f=sip:1001@[10.250.5.50:5090],t=sip:185511@10.250.5.3:5080,ft=m05SKryceZQ7F) on hash 1723
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:dialog:init_leg_info: route_set , contact sip:gw+osips@10.250.5.50:5090;transport=udp;gw=osips, cseq 88641991 and bind_addr udp:10.250.5.3:5080
./opensips[28089]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0x7fb36ea18a18: tag=<m05SKryceZQ7F> rcseq=<0>
./opensips[28089]: DBG:dialog:link_dlg: ref dlg 0x7fb36ea18a18 with 4 -> 4 in h_entry 0x7fb36e9f43d8 - 1723
./opensips[28089]: DBG:rr:add_rr_param: adding (;did=bb6.b255faa3)
./opensips[28089]: DBG:rr:add_rr_param: second RR lump found
./opensips[28089]: DBG:rr:add_rr_param: second RR lump found
./opensips[28089]: DBG:db_mysql:mysql_raise_event: MySQL status has not changed: connected
./opensips[28089]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fb3b2ef0970
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
./opensips[28089]: DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x7fb3b2ef09b8
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fb3b2ef09c8)[0]=[username]
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fb3b2ef09d8)[1]=[domain]
./opensips[28089]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
./opensips[28089]: DBG:db_mysql:db_mysql_convert_rows: no rows returned from the query
./opensips[28089]: DBG:alias_db:alias_db_query: no alias found for R-URI
./opensips[28089]: DBG:core:db_free_columns: freeing result columns at 0x7fb3b2ef09b8
./opensips[28089]: DBG:core:db_free_rows: freeing 0 rows
./opensips[28089]: DBG:core:db_free_result: freeing result set at 0x7fb3b2ef0970
./opensips[28089]: 185511@10.250.5.3
./opensips[28089]: Jumped to Outbound.
./opensips[28089]: FS tries to call PBX! 185511@10.250.5.3:5080 via 10.250.5.50
./opensips[28089]: FS tries to call PBX! 185511@192.168.1.30:5060 via 10.250.5.50
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
./opensips[28089]: DBG:core:comp_scriptvar: str 20 : 10.250.5.50
./opensips[28089]: Offer rtpp Outbound.
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <rie> and param2 <none>
./opensips[28089]: DBG:core:parse_headers: flags=40
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=FreeSWITCH 1457938126 1457938127 IN IP4 10.250.5.50#015#012s=FreeSWITCH#015#012c=IN IP4 10.250.5.50#015#012t=0 0#015#012m=audio 17984 RTP/AVP 8 101#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012]
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy_body: trying new rtpproxy node localhost:5006
./opensips[28089]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 35022 192.168.1.150
./opensips[28089]: DBG:tm:t_newtran: transaction on entrance=(nil)
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:parse_headers: flags=78
./opensips[28089]: DBG:tm:t_lookup_request: start searching: hash=30020, isACK=0
./opensips[28089]: DBG:tm:matching_3261: RFC3261 transaction matching failed
./opensips[28089]: DBG:tm:t_lookup_request: no transaction found
./opensips[28089]: DBG:tm:run_reqin_callbacks: trans=0x7fb36ea19510, callback type 1, id 1 entered
./opensips[28089]: DBG:dialog:dlg_onreq: t hash_index = 30020, t label = 223596535
./opensips[28089]: DBG:tm:run_reqin_callbacks: trans=0x7fb36ea19510, callback type 1, id 0 entered
./opensips[28089]: DBG:core:parse_headers: flags=78
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:_shm_resize: resize(0) called
./opensips[28089]: DBG:tm:_reply_light: reply sent out. buf=0x7fb3b2ef1238: SIP/2.0 1..., shmem=0x7fb36ea1ce18: SIP/2.0 1
./opensips[28089]: DBG:tm:_reply_light: finished
./opensips[28089]: new branch at sip:185511@192.168.1.30:5060
./opensips[28089]: DBG:core:mk_proxy: doing DNS lookup...
./opensips[28089]: DBG:core:parse_headers: flags=2000
./opensips[28089]: DBG:core:parse_headers: flags=ffffffffffffffff
./opensips[28089]: DBG:core:clen_builder: content-length: 238 (238)
./opensips[28089]: DBG:tm:set_timer: relative timeout is 500000
./opensips[28089]: DBG:tm:insert_timer_unsafe: [4]: 0x7fb36ea19730 (24100000)
./opensips[28089]: DBG:tm:insert_timer_unsafe: [0]: 0x7fb36ea19760 (28)
./opensips[28089]: DBG:tm:t_relay_to: new transaction fwd'ed
./opensips[28089]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fb36ea19510] after is 0
./opensips[28089]: DBG:dialog:unref_dlg: unref dlg 0x7fb36ea18a18 with 1 -> 3 in entry 0x7fb36e9f43d8
./opensips[28089]: DBG:core:destroy_avp_list: destroying list (nil)
./opensips[28089]: DBG:core:receive_msg: cleaning up
./opensips[28080]: DBG:core:parse_msg: SIP Reply(status):
./opensips[28080]: DBG:core:parse_msg:version: <SIP/2.0>
./opensips[28080]: DBG:core:parse_msg:status:<400>
./opensips[28080]: DBG:core:parse_msg:reason:<Bad Request>
./opensips[28080]: DBG:core:parse_headers: flags=2
./opensips[28080]: DBG:core:parse_to_param: tag=73249f74b80225097691065c86c67aec
./opensips[28080]: DBG:core:parse_to: end of header reached, state=29
./opensips[28080]: DBG:core:parse_to: display={}, ruri={sip:185511@10.250.5.3:5080}
./opensips[28080]: DBG:core:get_hdr_field: <To> [67]; uri=[sip:185511@10.250.5.3:5080]
./opensips[28080]: DBG:core:get_hdr_field: to body [<sip:185511@10.250.5.3:5080>]
./opensips[28080]: DBG:core:get_hdr_field: cseq <CSeq>: <88641991> <INVITE>
./opensips[28080]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4457.7ffc35d.0>; state=16
./opensips[28080]: DBG:core:parse_via: end of header reached, state=5
./opensips[28080]: DBG:core:parse_headers: via found, flags=2
./opensips[28080]: DBG:core:parse_headers: this is the first via
./opensips[28080]: DBG:core:receive_msg: After parse_msg...
./opensips[28080]: DBG:core:forward_reply: found module nathelper, passing reply to it
./opensips[28080]: DBG:core:parse_headers: flags=4
./opensips[28080]: DBG:core:parse_via_param: found param type 234, <received> = <10.250.5.50>; state=6
./opensips[28080]: DBG:core:parse_via_param: found param type 235, <rport> = <5090>; state=6
./opensips[28080]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1ytH5t8ZyF3aH>; state=16
./opensips[28080]: DBG:core:parse_via: end of header reached, state=5
./opensips[28080]: DBG:core:parse_headers: via found, flags=4
./opensips[28080]: DBG:core:parse_headers: parse_headers: this is the second via
./opensips[28080]: DBG:core:forward_reply: found module tm, passing reply to it
./opensips[28080]: DBG:tm:t_check: start=0xffffffffffffffff
./opensips[28080]: DBG:core:parse_headers: flags=22
./opensips[28080]: DBG:core:parse_headers: flags=8
./opensips[28080]: DBG:tm:t_reply_matching: hash 30020 label 223596535 branch 0
./opensips[28080]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fb36ea19510] after is 1
./opensips[28080]: DBG:tm:t_reply_matching: reply matched (T=0x7fb36ea19510)!
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback type 2, id 1 entered
./opensips[28080]: DBG:tm:t_check: end=0x7fb36ea19510
./opensips[28080]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
./opensips[28080]: DBG:core:parse_headers: flags=18
./opensips[28080]: DBG:core:get_hdr_field: content_length=0
./opensips[28080]: DBG:core:get_hdr_field: found end of header
./opensips[28080]: ERROR:tm:send_ack: failed to generate a HBH ACK if key HFs in reply missing
./opensips[28080]: ERROR:tm:reply_received: failed to send ACK (local=no)
./opensips[28080]: DBG:core:parse_headers: flags=20
./opensips[28080]: DBG:sipmsgops:has_body_f: content length is zero
./opensips[28080]: DBG:core:buf_init: initializing...
./opensips[28080]: incoming reply
./opensips[28080]: DBG:tm:t_should_relay_response: T_code=100, new_code=400
./opensips[28080]: DBG:tm:t_pick_branch: picked branch 0, code 400 (prio=600)
./opensips[28080]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=400, flags=2
./opensips[28080]: DBG:tm:relay_reply: branch=0, save=0, relay=0
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback type 8, id 0 entered
./opensips[28080]: DBG:dialog:push_reply_in_dialog: 0x7fb36ea18a18 totag in rpl is <73249f74b80225097691065c86c67aec> (32)
./opensips[28080]: DBG:dialog:push_reply_in_dialog: new branch with tag <73249f74b80225097691065c86c67aec>
./opensips[28080]: DBG:dialog:init_leg_info: route_set , contact , cseq 88641991 and bind_addr udp:192.168.1.150:5060
./opensips[28080]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0x7fb36ea18a18: tag=<73249f74b80225097691065c86c67aec> rcseq=<88641991>
./opensips[28080]: DBG:core:build_res_buf_from_sip_res:old size: 403, new size: 337
./opensips[28080]: DBG:core:build_res_buf_from_sip_res: copied size: orig:287, new: 221, rest: 116 msg=#012SIP/2.0 400 Bad Request#015#012Warning: 399 192.168.1.30 "Malformed headers : From "#015#012To: <sip:185511@10.250.5.3:5080>;tag=73249f74b80225097691065c86c67aec#015#012Call-ID: 83c45345-647d-1234-e187-000c295a647b#015#012CSeq: 88641991 INVITE#015#012Via: SIP/2.0/UDP 10.250.5.50:5090;received=10.250.5.50;rport=5090;branch=z9hG4bK1ytH5t8ZyF3aH#015#012Content-Length: 0
./opensips[28080]: DBG:tm:set_timer: relative timeout is 500000
./opensips[28080]: DBG:tm:insert_timer_unsafe: [4]: 0x7fb36ea19658 (24100000)
./opensips[28080]: DBG:tm:insert_timer_unsafe: [0]: 0x7fb36ea19688 (28)
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback type 64, id 0 entered
./opensips[28080]: DBG:core:evi_param_set: adding string param
./opensips[28080]: DBG:core:evi_param_set: adding string param
./opensips[28080]: DBG:core:evi_param_set: adding int param
./opensips[28080]: DBG:core:evi_param_set: adding int param
./opensips[28080]: DBG:core:destroy_avp_list: destroying list (nil)
./opensips[28080]: DBG:dialog:next_state_dlg: dialog 0x7fb36ea18a18 changed from state 1 to state 5, due event 4
./opensips[28080]: DBG:dialog:dlg_onreply: dialog 0x7fb36ea18a18 failed (negative reply)
./opensips[28080]: DBG:dialog:unref_dlg: unref dlg 0x7fb36ea18a18 with 1 -> 2 in entry 0x7fb36e9f43d8
./opensips[28080]: DBG:tm:relay_reply: sent buf=0x7fb3b2eefc90: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
./opensips[28080]: DBG:tm:run_trans_callbacks: trans=0x7fb36ea19510, callback type 128, id 1 entered
./opensips[28080]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
./opensips[28080]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fb36ea19510] after is 0
./opensips[28080]: DBG:core:destroy_avp_list: destroying list (nil)
./opensips[28080]: DBG:core:receive_msg: cleaning up
./opensips[28090]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fb36ea19730 next=0x7fb36ea19658, timeout=24100000
./opensips[28090]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fb36ea19658 next=(nil), timeout=24100000
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0x7fb36ea19510, SIP/2.0 4 ... )
./opensips[28090]: DBG:tm:t_retransmit_reply: buf=0x7fb3b2a9dfc0: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
./opensips[28090]: DBG:tm:set_timer: relative timeout is 1000000
./opensips[28090]: DBG:tm:insert_timer_unsafe: [5]: 0x7fb36ea19658 (25100000)
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler : done
./opensips[28090]: DBG:tm:utimer_routine: timer routine:5,tl=0x7fb36ea19658 next=(nil), timeout=25100000
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler : reply resending (t=0x7fb36ea19510, SIP/2.0 4 ... )
./opensips[28090]: DBG:tm:t_retransmit_reply: buf=0x7fb3b2a9dfc0: SIP/2.0 4..., shmem=0x7fb36ea1ce18: SIP/2.0 4
./opensips[28090]: DBG:tm:set_timer: relative timeout is 2000000
./opensips[28090]: DBG:tm:insert_timer_unsafe: [6]: 0x7fb36ea19658 (27100000)
./opensips[28090]: DBG:tm:retransmission_handler: retransmission_handler : done
./opensips[28090]: DBG:core:parse_msg: SIP Request:
./opensips[28090]: DBG:core:parse_msg:method:<CANCEL>
./opensips[28090]: DBG:core:parse_msg:uri: <sip:185511@10.250.5.3:5080>
./opensips[28090]: DBG:core:parse_msg:version: <SIP/2.0>
./opensips[28090]: DBG:core:parse_headers: flags=2
./opensips[28090]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=6
./opensips[28090]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK1ytH5t8ZyF3aH>; state=16
./opensips[28090]: DBG:core:parse_via: end of header reached, state=5
./opensips[28090]: DBG:core:parse_headers: via found, flags=2
./opensips[28090]: DBG:core:parse_headers: this is the first via
./opensips[28090]: DBG:core:receive_msg: After parse_msg...
./opensips[28090]: DBG:core:receive_msg: preparing to run routing scripts...
./opensips[28090]: DBG:core:parse_headers: flags=100
./opensips[28090]: DBG:maxfwd:is_maxfwd_present: value = 69
./opensips[28090]: DBG:core:parse_headers: flags=8
./opensips[28090]: DBG:core:parse_to: end of header reached, state=10
./opensips[28090]: DBG:core:parse_to: display={}, ruri={sip:185511@10.250.5.3:5080}
./opensips[28090]: DBG:core:get_hdr_field: <To> [30]; uri=[sip:185511@10.250.5.3:5080]
./opensips[28090]: DBG:core:get_hdr_field: to body [<sip:185511@10.250.5.3:5080>#015#012]