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