Skip to content

Instantly share code, notes, and snippets.

/hangup_bug.log

Created February 25, 2013 14:10
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save anonymous/5030013 to your computer and use it in GitHub Desktop.
Save anonymous/5030013 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
hangup_bug.log
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_msg: method: <INVITE>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_msg: uri: <sip:8665551212@63.246.156.XX:5060>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=2
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK35f48720>; state=6
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:20 sip1 opensips[13959]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=100
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_to: end of header reached, state=10
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_to: display={}, ruri={sip:8665551212@63.246.156.XX:5060}
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:get_hdr_field: <To> [37]; uri=[sip:8665551212@63.246.156.XX:5060]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:get_hdr_field: to body [<sip:8665551212@63.246.156.XX:5060>#015#012]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 25 08:49:20 sip1 opensips[13959]: DBG:uri:has_totag: no totag
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_to_param: tag=as76076dfc
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@64.2.142.28}
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:build_new_dlg: new dialog 0x7fc563376aa8 (c=0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28,f=sip:7278516359@64.2.142.28,t=sip:8665551212@63.246.156.XX:5060,ft=as76076dfc) on hash 873
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:get_hdr_field: content_length=332
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:init_leg_info: route_set , contact sip:7278516359@64.2.142.28, cseq 102 and bind_addr udp:63.246.156.XX:5060
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0x7fc563376aa8: tag=<as76076dfc> rcseq=<0>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:link_dlg: ref dlg 0x7fc563376aa8 with 3 -> 3
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rr:add_rr_param: adding (;did=963.825d2b42) (nil)
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rr:add_rr_param: rr_param_buf=<;did=963.825d2b42>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:sip_trace: sip_trace called
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=893; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=78
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_lookup_request: start searching: hash=4665, isACK=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=200
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rr:find_first_route: No Route headers found
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rr:loose_route: There is no Route HF
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13959]: DBG:permissions:get_source_group: Looking for <1c8e0240, 5060> in address table
Feb 25 08:49:20 sip1 opensips[13959]: DBG:permissions:get_source_group: Found <1>
Feb 25 08:49:20 sip1 opensips[13959]: GROIUP: 1
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <FACII> and param2 <none>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=root 21562 21562 IN IP4 64.2.142.28#015#012s=session#015#012c=IN IP4 64.2.142.28#015#012t=0 0#015#012m=audio 18870 RTP/AVP 0 8 3 18 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:8 PCMA/8000#015#012a=rtpmap:3 GSM/8000#015#012a=rtpmap:18 G729/8000#015#012a=fmtp:18 annexb=no#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=silenceSupp:off - - - -#015#012a=ptime:20#015#012a=sendrecv#015#012]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 16486 63.246.156.MM#012
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:comp_scriptvar: int 20 : 1 / -1
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:comp_scriptvar: int 20 : 1 / 3
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:comp_scriptvar: int 20 : 1 / 4
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:comp_scriptvar: int 20 : 1 / 2
Feb 25 08:49:20 sip1 opensips[13959]: DBG:permissions:check_src_addr_3: Looking for : <1, 64.2.142.28, 5060, 1> in tables
Feb 25 08:49:20 sip1 opensips[13959]: DBG:permissions:hash_match: no pattern to match
Feb 25 08:49:20 sip1 opensips[13959]: DBG:permissions:hash_match: match found in the hash table
Feb 25 08:49:20 sip1 opensips[13959]: Looking for DID 8665551212 in didtable...
Feb 25 08:49:20 sip1 opensips[13959]: Looking for DID 8665551212 in didtable...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:avpops:ops_dbquery_avps: query [SELECT 1 setid,null prefix,null postfix, 1 enabled, '' description FROM vcs_dev.pbx_DIDs WHERE number='8665551212' and status='A']
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_new_result: allocate 48 bytes for result set at 0x7fc56fa788e0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: 5 columns returned from the query
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_allocate_columns: allocate 140 bytes for result columns at 0x7fc56fa78928
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fc56fa78950)[0]=[setid]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: use DB_BIGINT result type
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fc56fa78960)[1]=[prefix]
Feb 25 08:49:20 sip1 opensips[13959]: WARNING:db_mysql:db_mysql_get_columns: unhandled data type column (prefix) type id (6), use DB_STRING as default
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fc56fa78970)[2]=[postfix]
Feb 25 08:49:20 sip1 opensips[13959]: WARNING:db_mysql:db_mysql_get_columns: unhandled data type column (postfix) type id (6), use DB_STRING as default
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fc56fa78980)[3]=[enabled]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: use DB_BIGINT result type
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x7fc56fa78990)[4]=[description]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_allocate_rows: allocate 176 bytes for result rows and values at 0x7fc56fa789d0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_str2val: converting INT BIG[1]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_str2val: converting INT BIG[1]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_str2val: converting STRING []
Feb 25 08:49:20 sip1 opensips[13959]: DBG:avpops:db_query_avp: rows [1]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:avpops:db_query_avp: row [0]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:avpops:db_close_query: close avp query
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_free_columns: freeing result columns at 0x7fc56fa78928
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_free_rows: freeing 1 rows
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_free_row: freeing row values at 0x7fc56fa789e0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_free_rows: freeing rows at 0x7fc56fa789d0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:db_free_result: freeing result set at 0x7fc56fa788e0
Feb 25 08:49:20 sip1 opensips[13959]: Found DID:8665551212 Type:1 Prefix: Postfix: Enabled:1 Description: <null>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:comp_scriptvar: int 20 : 1 / 0
Feb 25 08:49:20 sip1 opensips[13959]: Going to rewrite rU: Method:INVITE rU:8665551212 Prefix: Postfix:
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dispatcher:ds_select_dst: set [1]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dispatcher:ds_select_dst: alg hash [0], id [0]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dispatcher:ds_select_dst: selected [4-1/0] <sip:192.168.1.21:5060>
Feb 25 08:49:20 sip1 opensips[13959]: DBG:uri:has_totag: no totag
Feb 25 08:49:20 sip1 opensips[13959]: Engaging Media Proxy...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_newtran: transaction on entrance=(nil)
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=78
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_lookup_request: start searching: hash=4665, isACK=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 2 entered
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:trace_onreq_in: trace on req in
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 1 entered
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:dlg_onreq: t hash_index = 4665, t label = 655686091
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 0 entered
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=78
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:_reply_light: reply sent out. buf=0x7fc56fa78a98: SIP/2.0 1..., shmem=0x7fc563380590: SIP/2.0 1
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:_reply_light: finished
Feb 25 08:49:20 sip1 opensips[13959]: new branch at sip:8665551212@192.168.1.21:5060
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:get_out_socket: socket determined: 0x7fc56fa6b720
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:clen_builder: content-length: 352 (352)
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:set_timer: relative timeout is 500000
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:insert_timer_unsafe: [4]: 0x7fc56337cb58 (511400000)
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:set_timer: relative timeout is 5
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:insert_timer_unsafe: [0]: 0x7fc56337cb88 (515)
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 1024, id 1 entered
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:trace_onreq_out: trace on req out
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:trace_msg_out: trace msg out
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:trace_msg_out: dest [udp:192.168.1.21:5060]
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13959]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=1237; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_msg: status: <100>
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_msg: reason: <Trying>
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: flags=2
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK9321.bc9f4172.0>; state=6
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.22>; state=6
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: flags=22
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 234, <received> = <64.2.142.28>; state=6
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK35f48720>; state=6
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_to: end of header reached, state=10
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_to: display={}, ruri={sip:8665551212@63.246.156.XX:5060}
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:get_hdr_field: <To> [37]; uri=[sip:8665551212@63.246.156.XX:5060]
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:get_hdr_field: to body [<sip:8665551212@63.246.156.XX:5060>#015#012]
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: flags=8
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_reply_matching: hash 4665 label 655686091 branch 0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337c938] after is 2
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337c938)!
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 4 entered
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 2 entered
Feb 25 08:49:20 sip1 opensips[13956]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_to_param: tag=as76076dfc
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@64.2.142.28}
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13956]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13956]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=745; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_relay_to: new transaction fwd'ed
Feb 25 08:49:20 sip1 opensips[13959]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 1
Feb 25 08:49:20 sip1 opensips[13959]: DBG:dialog:unref_dlg: unref dlg 0x7fc563376aa8 with 1 -> 2
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:20 sip1 opensips[13959]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_msg: status: <200>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_msg: reason: <OK>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=2
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK9321.bc9f4172.0>; state=6
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.22>; state=6
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=22
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 234, <received> = <64.2.142.28>; state=6
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK35f48720>; state=6
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_to_param: tag=as40fedff8
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_to: display={}, ruri={sip:8665551212@63.246.156.XX:5060}
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:get_hdr_field: <To> [52]; uri=[sip:8665551212@63.246.156.XX:5060]
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:get_hdr_field: to body [<sip:8665551212@63.246.156.XX:5060>]
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=8
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_reply_matching: hash 4665 label 655686091 branch 0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337c938] after is 2
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337c938)!
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=8
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 4 entered
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=8
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 2 entered
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_check: end=0x7fc56337c938
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_to_param: tag=as76076dfc
Feb 25 08:49:20 sip1 opensips[13956]: incoming reply
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_should_relay_response: T_code=100, new_code=100
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@64.2.142.28}
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:relay_reply: branch=0, save=0, relay=-1
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:set_timer: relative timeout is 30
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:insert_timer_unsafe: [1]: 0x7fc56337cb88 (540)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13956]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 1
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13956]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=1024; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_check: end=0x7fc56337c938
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Feb 25 08:49:20 sip1 opensips[13954]: incoming reply
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:get_hdr_field: content_length=235
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Feb 25 08:49:20 sip1 opensips[13954]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <FACII> and param2 <none>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13954]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=root 148720142 148720142 IN IP4 192.168.1.21#015#012s=Asterisk PBX 1.8.19.0#015#012c=IN IP4 192.168.1.21#015#012t=0 0#015#012m=audio 13458 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012a=sendrecv#015#012]
Feb 25 08:49:20 sip1 opensips[13954]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 18240 63.246.156.MM#012
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_should_relay_response: T_code=100, new_code=200
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 8, id 0 entered
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:push_reply_in_dialog: 0x7fc563376aa8 totag in rpl is <as40fedff8> (10)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:push_reply_in_dialog: new branch with tag <as40fedff8>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:init_leg_info: route_set , contact , cseq 102 and bind_addr udp:192.168.1.22:5060
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0x7fc563376aa8: tag=<as40fedff8> rcseq=<102>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:print_rr_body: current rr is <sip:192.168.1.22;r2=on;lr;ftag=as76076dfc;did=963.825d2b42>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:print_rr_body: current rr is <sip:63.246.156.XX;r2=on;lr;ftag=as76076dfc;did=963.825d2b42>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:print_rr_body: skipping 2 route records
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:print_rr_body: out rr []
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:print_rr_body: we have 2 records
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:dlg_update_routing: dialog 0x7fc563376aa8[1]: rr=<> contact=<sip:8665551212@192.168.1.21:5060>
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:clen_builder: content-length: 254 (254)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:build_res_buf_from_sip_res: old size: 1024, new size: 949
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:build_res_buf_from_sip_res: copied size: orig:1024, new: 949, rest: 0 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 64.2.142.28:5060;received=64.2.142.28;branch=z9hG4bK35f48720;rport=5060#015#012Record-Route: <sip:192.168.1.22;r2=on;lr;ftag=as76076dfc;did=963.825d2b42>#015#012Record-Route: <sip:63.246.156.XX;r2=on;lr;ftag=as76076dfc;did=963.825d2b42>#015#012From: "+17278516359" <sip:7278516359@64.2.142.28>;tag=as76076dfc#015#012To: <sip:8665551212@63.246.156.XX:5060>;tag=as40fedff8#015#012Call-ID: 0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28#015#012CSeq: 102 INVITE#015#012Server: Asterisk PBX 1.8.19.0#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH#015#012Supported: replaces, timer#015#012Contact: <sip:8665551212@192.168.1.21:5060>#015#012Content-Type: application/sdp#015#012Content-Length: 254#015#012#015#012v=0#015#012o=root 148720142 148720142 IN IP4 192.168.1.21#015#012s=Asterisk PBX 1.8.19.0#015#012c=IN IP4 63.246.156.MM#015#012t=0 0#015#012m=audio 18240 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012a=sendrecv#015#012a=nortpproxy:yes#015#012
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:update_totag_set: new totag
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:insert_timer_unsafe: [2]: 0x7fc56337c9b8 (515)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 64, id 0 entered
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:next_state_dlg: dialog 0x7fc563376aa8 changed from state 1 to state 3, due event 3
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:dlg_onreply: dialog 0x7fc563376aa8 confirmed
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0x7fc563376ae8 for 43710
Feb 25 08:49:20 sip1 opensips[13954]: DBG:dialog:ref_dlg: ref dlg 0x7fc563376aa8 with 1 -> 3
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:relay_reply: sent buf=0x7fc56fa79a88: SIP/2.0 2..., shmem=0x7fc56337b990: SIP/2.0 2
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 128, id 4 entered
Feb 25 08:49:20 sip1 opensips[13954]: ACC: transaction answered: timestamp=1361800160;method=INVITE;from_tag=as76076dfc;to_tag=as40fedff8;call_id=0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28;code=200;reason=OK
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:has_stmt_ctx: ctx found for acc
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74490 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=7; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=11; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=12; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 128, id 3 entered
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:trace_onreply_out: trace onreply out
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:trace_onreply_out: dest [udp:64.2.142.28:5060]
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13954]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=949; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=20; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 25 08:49:20 sip1 opensips[13954]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 0
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:20 sip1 opensips[13954]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_msg: method: <ACK>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_msg: uri: <sip:8665551212@192.168.1.21:5060>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=2
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK6426f973>; state=6
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:sl:sl_filter_ACK: to late to be a local ACK!
Feb 25 08:49:20 sip1 opensips[13960]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=100
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_to_param: tag=as40fedff8
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_to: display={}, ruri={sip:8665551212@63.246.156.XX:5060}
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:get_hdr_field: <To> [52]; uri=[sip:8665551212@63.246.156.XX:5060]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:get_hdr_field: to body [<sip:8665551212@63.246.156.XX:5060>]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <ACK>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 25 08:49:20 sip1 opensips[13960]: DBG:uri:has_totag: totag found
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=200
Feb 25 08:49:20 sip1 opensips[13960]: DBG:rr:is_preloaded: is_preloaded: No
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.21] == [127.0.0.1]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.21] == [192.168.1.22]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 12==13 && [192.168.1.21] == [63.246.156.XX]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:check_self: host != me
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:rr:after_loose: Topmost route URI: 'sip:63.246.156.XX;r2=on;lr;ftag=as76076dfc;did=963.825d2b42' is me
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=200
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:20 sip1 opensips[13960]: DBG:rr:find_next_route: No next Route HF found
Feb 25 08:49:20 sip1 opensips[13960]: DBG:rr:after_loose: no next URI found
Feb 25 08:49:20 sip1 opensips[13960]: DBG:rr:run_rr_callbacks: callback id 1 entered with <r2=on;lr;ftag=as76076dfc;did=963.825d2b42>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:dlg_onroute: route param is '963.825d2b42' (len=12)
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:lookup_dlg: ref dlg 0x7fc563376aa8 with 1 -> 4
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:lookup_dlg: dialog id=615699752 found on entry 873
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=58
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_to_param: tag=as76076dfc
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@64.2.142.28}
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:next_state_dlg: dialog 0x7fc563376aa8 changed from state 3 to state 4, due event 6
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1)
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:run_dlg_callbacks: dialog=0x7fc563376aa8, type=16
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:fetch_dlg_value: looking for <trace_x00>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:fetch_dlg_value: var NOT found!
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:sip_trace: sip_trace called
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=535; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=20; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:rr:run_rr_callbacks: callback id 2 entered with <r2=on;lr;ftag=as76076dfc;did=963.825d2b42>
Feb 25 08:49:20 sip1 opensips[13960]: DBG:uac:restore_uri: getting 'vsf' Route param
Feb 25 08:49:20 sip1 opensips[13960]: DBG:uac:restore_uri: route param 'vsf' not found
Feb 25 08:49:20 sip1 opensips[13960]: DBG:uac:restore_uri: getting 'vst' Route param
Feb 25 08:49:20 sip1 opensips[13960]: DBG:uac:restore_uri: route param 'vst' not found
Feb 25 08:49:20 sip1 opensips[13960]: LOOSE ROUTE || MATCH DIALOG****************************************
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=78
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_lookup_request: start searching: hash=4665, isACK=1
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=38
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7fc56337c938] after is 1
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_lookup_request: e2e proxy ACK found
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_newtran: building branch for end2end ACK - flags=1
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_relay_to: forwarding ACK
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:forward_request: sending:#012ACK sip:8665551212@192.168.1.21:5060 SIP/2.0#015#012Via: SIP/2.0/UDP 192.168.1.22;branch=z9hG4bK9321.bc9f4172.2#015#012Via: SIP/2.0/UDP 64.2.142.28:5060;received=64.2.142.28;branch=z9hG4bK6426f973;rport=5060#015#012From: "+17278516359" <sip:7278516359@64.2.142.28>;tag=as76076dfc#015#012To: <sip:8665551212@63.246.156.XX:5060>;tag=as40fedff8#015#012Contact: <sip:7278516359@64.2.142.28>#015#012Call-ID: 0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28#015#012CSeq: 102 ACK#015#012User-Agent: packetrino#015#012Max-Forwards: 69#015#012Content-Length: 0#015#012#015#012.
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:forward_request: orig. len=535, new_len=491, proto=1
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:run_fwd_callbacks: FWD callback entered
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:parse_headers: flags=40
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:trace_msg_out: trace msg out
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:trace_msg_out: dest [udp:192.168.1.21:5060]
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:20 sip1 opensips[13960]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=491; type=252; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:20 sip1 opensips[13960]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7fc56337c938] after is 0
Feb 25 08:49:20 sip1 opensips[13960]: DBG:dialog:unref_dlg: unref dlg 0x7fc563376aa8 with 1 -> 3
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:20 sip1 opensips[13960]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:21 sip1 opensips[13963]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fc56337cb58 next=(nil), timeout=511400000
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_msg: method: <INVITE>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_msg: uri: <sip:17275551212@192.168.1.22>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=2
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4e0f1aee>; state=6
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:22 sip1 opensips[13957]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=100
Feb 25 08:49:22 sip1 opensips[13957]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=8
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_to: end of header reached, state=10
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:get_hdr_field: <To> [32]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>#015#012]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:uri:has_totag: no totag
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:22 sip1 opensips[13957]: DBG:dialog:build_new_dlg: new dialog 0x7fc56337b208 (c=445c30514321387a6edfd124044f2226@192.168.1.21:5060,f=sip:7278516359@192.168.1.21,t=sip:17275551212@192.168.1.22,ft=as5fe6f9f1) on hash 2901
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=20
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:get_hdr_field: content_length=235
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:22 sip1 opensips[13957]: DBG:dialog:init_leg_info: route_set , contact sip:7278516359@192.168.1.21:5060, cseq 102 and bind_addr udp:192.168.1.22:5060
Feb 25 08:49:22 sip1 opensips[13957]: DBG:dialog:dlg_add_leg_info: set leg 0 for 0x7fc56337b208: tag=<as5fe6f9f1> rcseq=<0>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:dialog:link_dlg: ref dlg 0x7fc56337b208 with 3 -> 3
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rr:add_rr_param: adding (;did=55b.59ef7b13) (nil)
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rr:add_rr_param: rr_param_buf=<;did=55b.59ef7b13>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:sip_trace: sip_trace called
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=827; type=252; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=78
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:t_lookup_request: start searching: hash=14885, isACK=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=200
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rr:find_first_route: No Route headers found
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rr:loose_route: There is no Route HF
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:22 sip1 opensips[13957]: DBG:permissions:get_source_group: Looking for <1501a8c0, 5060> in address table
Feb 25 08:49:22 sip1 opensips[13957]: DBG:permissions:get_source_group: Found <2>
Feb 25 08:49:22 sip1 opensips[13957]: GROIUP: 2
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <FACII> and param2 <none>
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=root 534048843 534048843 IN IP4 192.168.1.21#015#012s=Asterisk PBX 1.8.19.0#015#012c=IN IP4 192.168.1.21#015#012t=0 0#015#012m=audio 15316 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=ptime:20#015#012a=sendrecv#015#012]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 16018 63.246.156.MM#012
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:comp_scriptvar: int 20 : 2 / -1
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:comp_scriptvar: int 20 : 2 / 3
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:comp_scriptvar: int 20 : 2 / 4
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:comp_scriptvar: int 20 : 2 / 2
Feb 25 08:49:22 sip1 opensips[13957]: DBG:drouting:do_routing_123: unknown flag : [1] . Skipping
Feb 25 08:49:22 sip1 opensips[13957]: DBG:drouting:do_routing: using dr group 10, rule_idx 0, username 17275551212
Feb 25 08:49:22 sip1 opensips[13957]: DBG:drouting:internal_check_rt: found rgid 10 (rule list 0x7fc563376a28)
Feb 25 08:49:22 sip1 opensips[13957]: DBG:drouting:push_gw_for_usage: adding gw [2] as "sip:17275551212@64.2.142.93" in order 0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:drouting:push_gw_for_usage: setting GW id [2] as avp
Feb 25 08:49:22 sip1 opensips[13957]: DBG:drouting:push_gw_for_usage: setting GW attr [] as avp
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:t_newtran: transaction on entrance=(nil)
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=78
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:t_lookup_request: start searching: hash=14885, isACK=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337e480, callback type 1, id 2 entered
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:trace_onreq_in: trace on req in
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337e480, callback type 1, id 1 entered
Feb 25 08:49:22 sip1 opensips[13957]: DBG:dialog:dlg_onreq: t hash_index = 14885, t label = 884373854
Feb 25 08:49:22 sip1 opensips[13957]: DBG:dialog:get_dlg_timeout: invalid AVP value, use default timeout
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337e480, callback type 1, id 0 entered
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=78
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:_reply_light: reply sent out. buf=0x7fc56fa792d0: SIP/2.0 1..., shmem=0x7fc563380590: SIP/2.0 1
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:_reply_light: finished
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:get_out_socket: socket determined: 0x7fc56fa6b850
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:clen_builder: content-length: 254 (254)
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:set_timer: relative timeout is 500000
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:insert_timer_unsafe: [4]: 0x7fc56337e6a0 (513800000)
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:set_timer: relative timeout is 5
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:insert_timer_unsafe: [0]: 0x7fc56337e6d0 (518)
Feb 25 08:49:22 sip1 opensips[13957]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 1024, id 1 entered
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:trace_onreq_out: trace on req out
Feb 25 08:49:22 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:trace_msg_out: trace msg out
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:trace_msg_out: dest [udp:64.2.142.93:5060]
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:22 sip1 opensips[13957]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=1171; type=252; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=20; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:22 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:23 sip1 opensips[13957]: DBG:tm:t_relay_to: new transaction fwd'ed
Feb 25 08:49:23 sip1 opensips[13957]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337e480] after is 0
Feb 25 08:49:23 sip1 opensips[13957]: DBG:dialog:unref_dlg: unref dlg 0x7fc56337b208 with 1 -> 2
Feb 25 08:49:23 sip1 opensips[13957]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:23 sip1 opensips[13957]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_msg: status: <100>
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_msg: reason: <Giving a try>
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: flags=2
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.e5976b43.0>; state=6
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: flags=22
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.21>; state=6
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4e0f1aee>; state=6
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_to: end of header reached, state=10
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:get_hdr_field: <To> [32]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>#015#012]
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: flags=8
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_reply_matching: hash 14885 label 884373854 branch 0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337e480] after is 1
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337e480)!
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 2, id 4 entered
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 2, id 2 entered
Feb 25 08:49:23 sip1 opensips[13961]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:parse_headers: flags=40
Feb 25 08:49:23 sip1 opensips[13961]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:23 sip1 opensips[13961]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=443; type=252; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_check: end=0x7fc56337e480
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Feb 25 08:49:23 sip1 opensips[13961]: incoming reply
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_should_relay_response: T_code=100, new_code=100
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:relay_reply: branch=0, save=0, relay=-1
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:set_timer: relative timeout is 30
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:insert_timer_unsafe: [1]: 0x7fc56337e6d0 (543)
Feb 25 08:49:23 sip1 opensips[13961]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337e480] after is 0
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:23 sip1 opensips[13961]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:23 sip1 opensips[13963]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fc56337e6a0 next=(nil), timeout=513800000
Feb 25 08:49:25 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:2,tl=0x7fc56337c9b8 next=(nil), timeout=515
Feb 25 08:49:25 sip1 opensips[13963]: DBG:tm:wait_handler: removing 0x7fc56337c938 from table
Feb 25 08:49:25 sip1 opensips[13963]: DBG:tm:delete_cell: delete transaction 0x7fc56337c938
Feb 25 08:49:25 sip1 opensips[13963]: DBG:dialog:next_state_dlg: unref dlg 0x7fc563376aa8 with 1 -> 2
Feb 25 08:49:25 sip1 opensips[13963]: DBG:dialog:next_state_dlg: dialog 0x7fc563376aa8 changed from state 4 to state 4, due event 1
Feb 25 08:49:25 sip1 opensips[13963]: DBG:tm:wait_handler: done
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_msg: status: <183>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_msg: reason: <Session Progress>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=2
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 234, <received> = <63.246.156.XX>; state=6
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.e5976b43.0>; state=16
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=22
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.21>; state=6
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4e0f1aee>; state=6
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>]
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=8
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_reply_matching: hash 14885 label 884373854 branch 0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337e480] after is 1
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337e480)!
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 2, id 4 entered
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 2, id 2 entered
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=40
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=1064; type=252; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_check: end=0x7fc56337e480
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:reply_received: org. status uas=100, uac[0]=100 local=0 is_invite=1)
Feb 25 08:49:25 sip1 opensips[13958]: incoming reply
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:get_hdr_field: content_length=242
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Feb 25 08:49:25 sip1 opensips[13958]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <FACII> and param2 <none>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=40
Feb 25 08:49:25 sip1 opensips[13958]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=root 24219 24219 IN IP4 66.241.97.173#015#012s=session#015#012c=IN IP4 66.241.97.173#015#012t=0 0#015#012m=audio 13264 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=silenceSupp:off - - - -#015#012a=ptime:20#015#012a=sendrecv#015#012]
Feb 25 08:49:25 sip1 opensips[13958]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 13672 63.246.156.MM#012
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_should_relay_response: T_code=100, new_code=183
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 8, id 0 entered
Feb 25 08:49:25 sip1 opensips[13958]: DBG:dialog:push_reply_in_dialog: 0x7fc56337b208 totag in rpl is <as3ed8aad2> (10)
Feb 25 08:49:25 sip1 opensips[13958]: DBG:dialog:push_reply_in_dialog: new branch with tag <as3ed8aad2>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:dialog:init_leg_info: route_set , contact , cseq 102 and bind_addr udp:63.246.156.XX:5060
Feb 25 08:49:25 sip1 opensips[13958]: DBG:dialog:dlg_add_leg_info: set leg 1 for 0x7fc56337b208: tag=<as3ed8aad2> rcseq=<102>
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:clen_builder: content-length: 260 (260)
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:build_res_buf_from_sip_res: old size: 1064, new size: 986
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:build_res_buf_from_sip_res: copied size: orig:1064, new: 986, rest: 0 msg=#012SIP/2.0 183 Session Progress#015#012Via: SIP/2.0/UDP 192.168.1.21:5060;received=192.168.1.21;branch=z9hG4bK4e0f1aee;rport=5060#015#012Record-Route: <sip:64.2.142.93;lr=on>#015#012Record-Route: <sip:63.246.156.XX;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>#015#012Record-Route: <sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>#015#012From: "+17278516359" <sip:7278516359@192.168.1.21>;tag=as5fe6f9f1#015#012To: <sip:17275551212@192.168.1.22>;tag=as3ed8aad2#015#012Call-ID: 445c30514321387a6edfd124044f2226@192.168.1.21:5060#015#012CSeq: 102 INVITE#015#012User-Agent: packetrino#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO#015#012Supported: replaces#015#012Contact: <sip:17275551212@66.241.97.173>#015#012Content-Type: application/sdp#015#012Content-Length: 260#015#012#015#012v=0#015#012o=root 24219 24219 IN IP4 66.241.97.173#015#012s=session#015#012c=IN IP4 63.246.156.MM#015#012t=0 0#015#012m=audio 13672 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=silenceSupp:off - - - -#015#012a=ptime:20#015#012a=sendrecv#015#012a=nortpproxy:yes#015#012
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 64, id 0 entered
Feb 25 08:49:25 sip1 opensips[13958]: DBG:dialog:next_state_dlg: dialog 0x7fc56337b208 changed from state 1 to state 2, due event 2
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:relay_reply: sent buf=0x7fc56fa78d90: SIP/2.0 1..., shmem=0x7fc56337bd60: SIP/2.0 1
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 128, id 4 entered
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 128, id 3 entered
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:trace_onreply_out: trace onreply out
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:parse_headers: flags=40
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:trace_onreply_out: dest [udp:192.168.1.21:5060]
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:25 sip1 opensips[13958]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=986; type=252; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:set_timer: relative timeout is 30
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:insert_timer_unsafe: [1]: 0x7fc56337e6d0 (545)
Feb 25 08:49:25 sip1 opensips[13958]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337e480] after is 0
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:25 sip1 opensips[13958]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_msg: status: <200>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_msg: reason: <OK>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=2
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 234, <received> = <63.246.156.XX>; state=6
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.e5976b43.0>; state=16
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=22
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.21>; state=6
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK4e0f1aee>; state=6
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=8
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_reply_matching: hash 14885 label 884373854 branch 0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337e480] after is 1
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337e480)!
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=8
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 2, id 4 entered
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=8
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 2, id 2 entered
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=1050; type=252; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_check: end=0x7fc56337e480
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:reply_received: org. status uas=183, uac[0]=183 local=0 is_invite=1)
Feb 25 08:49:27 sip1 opensips[13959]: incoming reply
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:get_hdr_field: content_length=242
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:decode_mime_type: Decoding MIME type for:[application/sdp]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:rtpproxy:force_rtp_proxy: force rtp proxy with param1 <FACII> and param2 <none>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:27 sip1 opensips[13959]: DBG:rtpproxy:force_rtp_proxy: Forcing body:#012[v=0#015#012o=root 24219 24220 IN IP4 66.241.97.173#015#012s=session#015#012c=IN IP4 66.241.97.173#015#012t=0 0#015#012m=audio 13264 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=silenceSupp:off - - - -#015#012a=ptime:20#015#012a=sendrecv#015#012]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:rtpproxy:force_rtp_proxy_body: proxy reply: 13672 63.246.156.MM#012
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_should_relay_response: T_code=183, new_code=200
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 8, id 0 entered
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:push_reply_in_dialog: 0x7fc56337b208 totag in rpl is <as3ed8aad2> (10)
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:push_reply_in_dialog: branch with tag <as3ed8aad2> already exists
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:print_rr_body: current rr is <sip:64.2.142.93;lr=on>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:print_rr_body: current rr is <sip:63.246.156.XX;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:print_rr_body: current rr is <sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:print_rr_body: skipping 2 route records
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:print_rr_body: out rr [<sip:64.2.142.93;lr=on>]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:print_rr_body: we have 3 records
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:dlg_update_routing: dialog 0x7fc56337b208[1]: rr=<<sip:64.2.142.93;lr=on>> contact=<sip:17275551212@66.241.97.173>
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=2000
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:clen_builder: content-length: 260 (260)
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:build_res_buf_from_sip_res: old size: 1050, new size: 972
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:build_res_buf_from_sip_res: copied size: orig:1050, new: 972, rest: 0 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 192.168.1.21:5060;received=192.168.1.21;branch=z9hG4bK4e0f1aee;rport=5060#015#012Record-Route: <sip:64.2.142.93;lr=on>#015#012Record-Route: <sip:63.246.156.XX;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>#015#012Record-Route: <sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>#015#012From: "+17278516359" <sip:7278516359@192.168.1.21>;tag=as5fe6f9f1#015#012To: <sip:17275551212@192.168.1.22>;tag=as3ed8aad2#015#012Call-ID: 445c30514321387a6edfd124044f2226@192.168.1.21:5060#015#012CSeq: 102 INVITE#015#012User-Agent: packetrino#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO#015#012Supported: replaces#015#012Contact: <sip:17275551212@66.241.97.173>#015#012Content-Type: application/sdp#015#012Content-Length: 260#015#012#015#012v=0#015#012o=root 24219 24220 IN IP4 66.241.97.173#015#012s=session#015#012c=IN IP4 63.246.156.MM#015#012t=0 0#015#012m=audio 13672 RTP/AVP 0 101#015#012a=rtpmap:0 PCMU/8000#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-16#015#012a=silenceSupp:off - - - -#015#012a=ptime:20#015#012a=sendrecv#015#012a=nortpproxy:yes#015#012
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:update_totag_set: new totag
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:insert_timer_unsafe: [2]: 0x7fc56337e500 (523)
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 64, id 0 entered
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:next_state_dlg: dialog 0x7fc56337b208 changed from state 2 to state 3, due event 3
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:dlg_onreply: dialog 0x7fc56337b208 confirmed
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0x7fc56337b248 for 43718
Feb 25 08:49:27 sip1 opensips[13959]: DBG:dialog:ref_dlg: ref dlg 0x7fc56337b208 with 1 -> 3
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:relay_reply: sent buf=0x7fc56fa792c8: SIP/2.0 2..., shmem=0x7fc56337bd60: SIP/2.0 2
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 128, id 4 entered
Feb 25 08:49:27 sip1 opensips[13959]: ACC: transaction answered: timestamp=1361800167;method=INVITE;from_tag=as5fe6f9f1;to_tag=as3ed8aad2;call_id=445c30514321387a6edfd124044f2226@192.168.1.21:5060;code=200;reason=OK
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74490 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time,from_did,to_did,carrier,direction,src_ip,dst_ip ) values (?,?,?,?,?,?,?,?,?,?,?,?,?)|
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:re_init_statement: query is <insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time,from_did,to_did,carrier,direction,src_ip,dst_ip ) values (?,?,?,?,?,?,?,?,?,?,?,?,?)>, ptr=(nil)
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_msg: method: <ACK>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_msg: uri: <sip:17275551212@66.241.97.173>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=2
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK77a375d9>; state=6
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:sl:sl_filter_ACK: to late to be a local ACK!
Feb 25 08:49:27 sip1 opensips[13955]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0x7fc56fa796b0) on connection: (0x7fc56fa74490) 0x7fc56fa74608
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=100
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:27 sip1 opensips[13955]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=8
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=50; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:uri:has_totag: totag found
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=200
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=11; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:rr:is_preloaded: is_preloaded: No
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [66.241.97.173] == [127.0.0.1]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=8; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=12; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [66.241.97.173] == [192.168.1.22]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=11; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [66.241.97.173] == [63.246.156.XX]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:check_self: host != me
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13955]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13' is me
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:27 sip1 opensips[13955]: DBG:rr:after_loose: URI to be processed: 'sip:64.2.142.93;lr=on'
Feb 25 08:49:27 sip1 opensips[13955]: DBG:rr:after_loose: Next URI is a loose router
Feb 25 08:49:27 sip1 opensips[13955]: DBG:rr:run_rr_callbacks: callback id 1 entered with <r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:dlg_onroute: route param is '55b.59ef7b13' (len=12)
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:lookup_dlg: ref dlg 0x7fc56337b208 with 1 -> 4
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:lookup_dlg: dialog id=834141845 found on entry 2901
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=58
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:next_state_dlg: dialog 0x7fc56337b208 changed from state 3 to state 4, due event 6
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:dlg_onroute: sequential request successfully processed (dst_leg=1)
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:run_dlg_callbacks: dialog=0x7fc56337b208, type=16
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:fetch_dlg_value: looking for <trace_x00>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:fetch_dlg_value: var NOT found!
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=40
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:sip_trace: sip_trace called
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=576; type=252; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc56337e480, callback type 128, id 3 entered
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:trace_onreply_out: trace onreply out
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:parse_headers: flags=40
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:trace_onreply_out: dest [udp:192.168.1.21:5060]
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:27 sip1 opensips[13959]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=972; type=252; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=6; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:rr:run_rr_callbacks: callback id 2 entered with <r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:uac:restore_uri: getting 'vsf' Route param
Feb 25 08:49:27 sip1 opensips[13955]: DBG:uac:restore_uri: route param 'vsf' not found
Feb 25 08:49:27 sip1 opensips[13955]: DBG:uac:restore_uri: getting 'vst' Route param
Feb 25 08:49:27 sip1 opensips[13955]: DBG:uac:restore_uri: route param 'vst' not found
Feb 25 08:49:27 sip1 opensips[13955]: LOOSE ROUTE || MATCH DIALOG****************************************
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <ACK>
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=78
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_lookup_request: start searching: hash=14885, isACK=1
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=38
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_lookup_request: REF_UNSAFE:[0x7fc56337e480] after is 2
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_lookup_request: e2e proxy ACK found
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_newtran: building branch for end2end ACK - flags=1
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_relay_to: forwarding ACK
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:forward_request: sending:#012ACK sip:17275551212@66.241.97.173 SIP/2.0#015#012Via: SIP/2.0/UDP 63.246.156.XX;branch=z9hG4bK52a3.e5976b43.2#015#012Via: SIP/2.0/UDP 192.168.1.21:5060;received=192.168.1.21;branch=z9hG4bK77a375d9;rport=5060#015#012Route: <sip:64.2.142.93;lr=on>#015#012Max-Forwards: 69#015#012From: "+17278516359" <sip:7278516359@192.168.1.21>;tag=as5fe6f9f1#015#012To: <sip:17275551212@192.168.1.22>;tag=as3ed8aad2#015#012Contact: <sip:7278516359@192.168.1.21:5060>#015#012Call-ID: 445c30514321387a6edfd124044f2226@192.168.1.21:5060#015#012CSeq: 102 ACK#015#012User-Agent: Asterisk PBX 1.8.19.0#015#012Content-Length: 0#015#012#015#012.
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:forward_request: orig. len=576, new_len=542, proto=1
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:run_fwd_callbacks: FWD callback entered
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:parse_headers: flags=40
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:trace_msg_out: trace msg out
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:trace_msg_out: dest [udp:64.2.142.93:5060]
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:27 sip1 opensips[13955]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=542; type=252; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=20; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 25 08:49:27 sip1 opensips[13959]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337e480] after is 1
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:27 sip1 opensips[13959]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:27 sip1 opensips[13955]: DBG:tm:t_unref_cell: UNREF_UNSAFE: [0x7fc56337e480] after is 0
Feb 25 08:49:27 sip1 opensips[13955]: DBG:dialog:unref_dlg: unref dlg 0x7fc56337b208 with 1 -> 3
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:27 sip1 opensips[13955]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:33 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:2,tl=0x7fc56337e500 next=(nil), timeout=523
Feb 25 08:49:33 sip1 opensips[13963]: DBG:tm:wait_handler: removing 0x7fc56337e480 from table
Feb 25 08:49:33 sip1 opensips[13963]: DBG:tm:delete_cell: delete transaction 0x7fc56337e480
Feb 25 08:49:33 sip1 opensips[13963]: DBG:dialog:next_state_dlg: unref dlg 0x7fc56337b208 with 1 -> 2
Feb 25 08:49:33 sip1 opensips[13963]: DBG:dialog:next_state_dlg: dialog 0x7fc56337b208 changed from state 4 to state 4, due event 1
Feb 25 08:49:33 sip1 opensips[13963]: DBG:tm:wait_handler: done
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_msg: method: <BYE>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_msg: uri: <sip:7278516359@63.246.156.XX:5060>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=2
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.fb1fc0d7.0>; state=16
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:33 sip1 opensips[13960]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=100
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_via_param: found param type 234, <received> = <66.241.97.173>; state=6
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK14c6843b>; state=6
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: via found, flags=100
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:get_hdr_field: <To> [61]; uri=[sip:7278516359@192.168.1.21]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:get_hdr_field: to body ["+17278516359" <sip:7278516359@192.168.1.21>]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <BYE>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:maxfwd:is_maxfwd_present: value = 69
Feb 25 08:49:33 sip1 opensips[13960]: DBG:uri:has_totag: totag found
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=200
Feb 25 08:49:33 sip1 opensips[13960]: DBG:rr:is_preloaded: is_preloaded: No
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13960]: DBG:rr:after_strict: Next hop: 'sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13' is loose router
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:33 sip1 opensips[13960]: DBG:rr:after_strict: The last route URI: 'sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13'
Feb 25 08:49:33 sip1 opensips[13960]: DBG:rr:run_rr_callbacks: callback id 1 entered with <>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:dialog:dlg_onroute: Route param 'did' not found
Feb 25 08:49:33 sip1 opensips[13960]: DBG:rr:run_rr_callbacks: callback id 2 entered with <>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:uac:restore_uri: getting 'vsf' Route param
Feb 25 08:49:33 sip1 opensips[13960]: DBG:uac:restore_uri: route param 'vsf' not found
Feb 25 08:49:33 sip1 opensips[13960]: DBG:uac:restore_uri: getting 'vst' Route param
Feb 25 08:49:33 sip1 opensips[13960]: DBG:uac:restore_uri: route param 'vst' not found
Feb 25 08:49:33 sip1 opensips[13960]: LOOSE ROUTE || MATCH DIALOG****************************************
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=78
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:t_lookup_request: start searching: hash=14885, isACK=0
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 2 entered
Feb 25 08:49:33 sip1 opensips[13960]: DBG:siptrace:trace_onreq_in: trace on req in
Feb 25 08:49:33 sip1 opensips[13960]: DBG:siptrace:trace_onreq_in: nothing to trace...
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 1 entered
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 0 entered
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_headers: flags=78
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:check_ip_address: params 64.2.142.93, 64.2.142.93, 0
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:set_timer: relative timeout is 500000
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:insert_timer_unsafe: [4]: 0x7fc56337cb58 (524300000)
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_msg: method: <BYE>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:set_timer: relative timeout is 5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_msg: uri: <sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:insert_timer_unsafe: [0]: 0x7fc56337cb88 (528)
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:t_relay_to: new transaction fwd'ed
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=2
Feb 25 08:49:33 sip1 opensips[13960]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.f5976b43.0>; state=16
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13960]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:33 sip1 opensips[13956]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=100
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.fb1fc0d7.0>; state=16
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: via found, flags=100
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 234, <received> = <66.241.97.173>; state=6
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK14c6843b>; state=6
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: via found, flags=100
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:get_hdr_field: <To> [61]; uri=[sip:7278516359@192.168.1.21]
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:get_hdr_field: to body ["+17278516359" <sip:7278516359@192.168.1.21>]
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <BYE>
Feb 25 08:49:33 sip1 opensips[13956]: DBG:maxfwd:is_maxfwd_present: value = 68
Feb 25 08:49:33 sip1 opensips[13956]: DBG:uri:has_totag: totag found
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=200
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:33 sip1 opensips[13956]: DBG:rr:find_first_route: No Route headers found
Feb 25 08:49:33 sip1 opensips[13956]: DBG:rr:loose_route: There is no Route HF
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=200
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:w_match_dialog: We found DID param in R-URI with value of 55b.59ef7b13
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:dlg_onroute: route param is '55b.59ef7b13' (len=12)
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:lookup_dlg: ref dlg 0x7fc56337b208 with 1 -> 3
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:lookup_dlg: dialog id=834141845 found on entry 2901
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=58
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:next_state_dlg: dialog 0x7fc56337b208 changed from state 4 to state 5, due event 7
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:dlg_onroute: BYE successfully processed - dst_leg = 0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:run_dlg_callbacks: dialog=0x7fc56337b208, type=32
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:fetch_dlg_value: looking for <trace_x00>
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:fetch_dlg_value: var NOT found!
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=40
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:sip_trace: sip_trace called
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=618; type=252; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:unref_dlg: unref dlg 0x7fc56337b208 with 2 -> 1
Feb 25 08:49:33 sip1 opensips[13956]: LOOSE ROUTE || MATCH DIALOG****************************************
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=78
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:t_lookup_request: start searching: hash=14885, isACK=0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:run_reqin_callbacks: trans=0x7fc563380848, callback type 1, id 2 entered
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:run_reqin_callbacks: trans=0x7fc563380848, callback type 1, id 1 entered
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:ref_dlg: ref dlg 0x7fc56337b208 with 1 -> 2
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:run_reqin_callbacks: trans=0x7fc563380848, callback type 1, id 0 entered
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=78
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:get_out_socket: socket determined: 0x7fc56fa6b720
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:check_ip_address: params 63.246.156.XX, 63.246.156.XX, 0
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:set_timer: relative timeout is 500000
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:insert_timer_unsafe: [4]: 0x7fc563380a68 (524300000)
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_msg: method: <BYE>
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:set_timer: relative timeout is 5
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_msg: uri: <sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:insert_timer_unsafe: [0]: 0x7fc563380a98 (528)
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 1024, id 0 entered
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: flags=2
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:trace_onreq_out: trace on req out
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.06976b43.0>; state=16
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:parse_headers: flags=40
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:trace_msg_out: trace msg out
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:trace_msg_out: dest [udp:192.168.1.22:5060]
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:33 sip1 opensips[13954]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: flags=100
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.f5976b43.0>; state=16
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=679; type=252; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=100
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.fb1fc0d7.0>; state=16
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=100
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 234, <received> = <66.241.97.173>; state=6
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK14c6843b>; state=6
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13956]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=100
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:get_hdr_field: <To> [61]; uri=[sip:7278516359@192.168.1.21]
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:get_hdr_field: to body ["+17278516359" <sip:7278516359@192.168.1.21>]
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <BYE>
Feb 25 08:49:33 sip1 opensips[13954]: DBG:maxfwd:is_maxfwd_present: value = 67
Feb 25 08:49:33 sip1 opensips[13954]: DBG:uri:has_totag: totag found
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: flags=200
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:33 sip1 opensips[13954]: DBG:rr:find_first_route: No Route headers found
Feb 25 08:49:33 sip1 opensips[13954]: DBG:rr:loose_route: There is no Route HF
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: flags=200
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:w_match_dialog: We found DID param in R-URI with value of 55b.59ef7b13
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:dlg_onroute: route param is '55b.59ef7b13' (len=12)
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:lookup_dlg: no dialog id=834141845 found on entry 2901
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:dlg_onroute: unable to find dialog for BYE with route param '55b.59ef7b13'
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: flags=58
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:get_dlg: input ci=<445c30514321387a6edfd124044f2226@192.168.1.21:5060>(50), tt=<as3ed8aad2>(10), ft=<as5fe6f9f1>(10)
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:get_dlg: no dialog callid='445c30514321387a6edfd124044f2226@192.168.1.21:5060' found
Feb 25 08:49:33 sip1 opensips[13954]: DBG:dialog:dlg_onroute: Callid '445c30514321387a6edfd124044f2226@192.168.1.21:5060' not found
Feb 25 08:49:33 sip1 opensips[13954]: NOT A LOOSE ROUTE****************************************
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:check_ip_address: params 192.168.1.22, 192.168.1.22, 0
Feb 25 08:49:33 sip1 opensips[13954]: DBG:sl:run_sl_callbacks: callback id 0 entered
Feb 25 08:49:33 sip1 opensips[13954]: DBG:siptrace:trace_sl_onreply_out: trace slonreply out
Feb 25 08:49:33 sip1 opensips[13954]: DBG:siptrace:trace_sl_onreply_out: nothing to trace...
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:33 sip1 opensips[13954]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_msg: status: <404>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_msg: reason: <Not here>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: flags=2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.06976b43.0>; state=16
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: flags=22
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.f5976b43.0>; state=16
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.fb1fc0d7.0>; state=16
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 234, <received> = <66.241.97.173>; state=6
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK14c6843b>; state=6
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:get_hdr_field: <To> [61]; uri=[sip:7278516359@192.168.1.21]
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:get_hdr_field: to body ["+17278516359" <sip:7278516359@192.168.1.21>]
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <BYE>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_reply_matching: hash 14885 label 884373856 branch 0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc563380848] after is 2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_reply_matching: reply matched (T=0x7fc563380848)!
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 2, id 4 entered
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: flags=8
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 2, id 1 entered
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=561; type=252; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:t_relay_to: new transaction fwd'ed
Feb 25 08:49:33 sip1 opensips[13956]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc563380848] after is 1
Feb 25 08:49:33 sip1 opensips[13956]: DBG:dialog:unref_dlg: unref dlg 0x7fc56337b208 with 1 -> 1
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:33 sip1 opensips[13956]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_check: end=0x7fc563380848
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_should_relay_response: T_code=0, new_code=404
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_pick_branch: picked branch 0, code 404 (prio=604)
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=404, flags=2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:build_res_buf_from_sip_res: old size: 561, new size: 500
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:build_res_buf_from_sip_res: copied size: orig:83, new: 22, rest: 478 msg=#012SIP/2.0 404 Not here#015#012Via: SIP/2.0/UDP 63.246.156.XX;branch=z9hG4bK52a3.f5976b43.0#015#012Via: SIP/2.0/UDP 64.2.142.93;branch=z9hG4bK52a3.fb1fc0d7.0#015#012Via: SIP/2.0/UDP 66.241.97.173:5060;received=66.241.97.173;branch=z9hG4bK14c6843b;rport=5060#015#012From: <sip:17275551212@192.168.1.22>;tag=as3ed8aad2#015#012To: "+17278516359" <sip:7278516359@192.168.1.21>;tag=as5fe6f9f1#015#012Call-ID: 445c30514321387a6edfd124044f2226@192.168.1.21:5060#015#012CSeq: 102 BYE#015#012Server: OpenSIPS (1.8.2-notls (x86_64/linux))#015#012Content-Length: 0#015#012#015#012
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:insert_timer_unsafe: [2]: 0x7fc5633808c8 (528)
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:relay_reply: sent buf=0x7fc56fa79940: SIP/2.0 4..., shmem=0x7fc56337b420: SIP/2.0 4
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 128, id 4 entered
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:33 sip1 opensips[13957]: ACC: transaction answered: timestamp=1361800173;method=BYE;from_tag=as3ed8aad2;to_tag=as5fe6f9f1;call_id=445c30514321387a6edfd124044f2226@192.168.1.21:5060;code=404;reason=Not here
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:has_stmt_ctx: ctx found for acc
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_msg: status: <404>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74490 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_msg: reason: <Not here>
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: flags=2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.f5976b43.0>; state=16
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=50; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=8; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: flags=22
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK52a3.fb1fc0d7.0>; state=16
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=13; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=12; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 234, <received> = <66.241.97.173>; state=6
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK14c6843b>; state=6
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:get_hdr_field: <To> [61]; uri=[sip:7278516359@192.168.1.21]
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:get_hdr_field: to body ["+17278516359" <sip:7278516359@192.168.1.21>]
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:get_hdr_field: cseq <CSeq>: <102> <BYE>
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_reply_matching: hash 14885 label 884373855 branch 0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337c938] after is 1
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337c938)!
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 0 entered
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:parse_headers: flags=8
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_check: end=0x7fc56337c938
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_should_relay_response: T_code=0, new_code=404
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_pick_branch: picked branch 0, code 404 (prio=604)
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=404, flags=2
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:build_res_buf_from_sip_res: old size: 500, new size: 438
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:build_res_buf_from_sip_res: copied size: orig:84, new: 22, rest: 416 msg=#012SIP/2.0 404 Not here#015#012Via: SIP/2.0/UDP 64.2.142.93;branch=z9hG4bK52a3.fb1fc0d7.0#015#012Via: SIP/2.0/UDP 66.241.97.173:5060;received=66.241.97.173;branch=z9hG4bK14c6843b;rport=5060#015#012From: <sip:17275551212@192.168.1.22>;tag=as3ed8aad2#015#012To: "+17278516359" <sip:7278516359@192.168.1.21>;tag=as5fe6f9f1#015#012Call-ID: 445c30514321387a6edfd124044f2226@192.168.1.21:5060#015#012CSeq: 102 BYE#015#012Server: OpenSIPS (1.8.2-notls (x86_64/linux))#015#012Content-Length: 0#015#012#015#012
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:insert_timer_unsafe: [2]: 0x7fc56337c9b8 (528)
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:relay_reply: sent buf=0x7fc56fa78298: SIP/2.0 4..., shmem=0x7fc563380398: SIP/2.0 4
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 128, id 0 entered
Feb 25 08:49:33 sip1 opensips[13961]: ACC: transaction answered: timestamp=1361800173;method=BYE;from_tag=as3ed8aad2;to_tag=as5fe6f9f1;call_id=445c30514321387a6edfd124044f2226@192.168.1.21:5060;code=404;reason=Not here
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74490 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: new query=|insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time,from_did,to_did,carrier,direction,src_ip,dst_ip ) values (?,?,?,?,?,?,?,?,?,?,?,?,?)|
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:re_init_statement: query is <insert into acc (method,from_tag,to_tag,callid,sip_code,sip_reason,time,from_did,to_did,carrier,direction,src_ip,dst_ip ) values (?,?,?,?,?,?,?,?,?,?,?,?,?)>, ptr=(nil)
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: new statement(0x7fc56fa78690) on connection: (0x7fc56fa74490) 0x7fc56fa74608
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=50; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=8; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=11; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=12; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 128, id 2 entered
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:trace_onreply_out: trace onreply out
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:parse_headers: flags=40
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:trace_onreply_out: dest [udp:63.246.156.XX:5060]
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:33 sip1 opensips[13957]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=500; type=252; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=50; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 25 08:49:33 sip1 opensips[13961]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 0
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:33 sip1 opensips[13961]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 25 08:49:33 sip1 opensips[13957]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc563380848] after is 0
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:33 sip1 opensips[13957]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:34 sip1 opensips[13963]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fc56337cb58 next=0x7fc563380a68, timeout=524300000
Feb 25 08:49:34 sip1 opensips[13963]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fc563380a68 next=(nil), timeout=524300000
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:0,tl=0x7fc56337cb88 next=0x7fc563380a98, timeout=528
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:0,tl=0x7fc563380a98 next=(nil), timeout=528
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:2,tl=0x7fc5633808c8 next=0x7fc56337c9b8, timeout=528
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:wait_handler: removing 0x7fc563380848 from table
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:delete_cell: delete transaction 0x7fc563380848
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 4096, id 3 entered
Feb 25 08:49:39 sip1 opensips[13963]: DBG:dialog:unref_dlg: unref dlg 0x7fc56337b208 with 1 -> 0
Feb 25 08:49:39 sip1 opensips[13963]: DBG:dialog:unref_dlg: ref <=0 for dialog 0x7fc56337b208
Feb 25 08:49:39 sip1 opensips[13963]: DBG:dialog:destroy_dlg: destroing dialog 0x7fc56337b208
Feb 25 08:49:39 sip1 opensips[13963]: DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x7fc56337b208 [2901:834141845] with clid '445c30514321387a6edfd124044f2226@192.168.1.21:5060' and tags 'as5fe6f9f1' 'as3ed8aad2'
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:wait_handler: done
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:2,tl=0x7fc56337c9b8 next=(nil), timeout=528
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:wait_handler: removing 0x7fc56337c938 from table
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:delete_cell: delete transaction 0x7fc56337c938
Feb 25 08:49:39 sip1 opensips[13963]: DBG:tm:wait_handler: done
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_msg: method: <BYE>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_msg: uri: <sip:8665551212@192.168.1.21:5060>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=2
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK47ccbf12>; state=6
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:40 sip1 opensips[13958]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=100
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_to_param: tag=as40fedff8
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_to: display={}, ruri={sip:8665551212@63.246.156.XX:5060}
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:get_hdr_field: <To> [52]; uri=[sip:8665551212@63.246.156.XX:5060]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:get_hdr_field: to body [<sip:8665551212@63.246.156.XX:5060>]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:get_hdr_field: cseq <CSeq>: <103> <BYE>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 25 08:49:40 sip1 opensips[13958]: DBG:uri:has_totag: totag found
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=200
Feb 25 08:49:40 sip1 opensips[13958]: DBG:rr:is_preloaded: is_preloaded: No
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.21] == [127.0.0.1]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.21] == [192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 12==13 && [192.168.1.21] == [63.246.156.XX]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:check_self: host != me
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:rr:after_loose: Topmost route URI: 'sip:63.246.156.XX;r2=on;lr;ftag=as76076dfc;did=963.825d2b42' is me
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=200
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:40 sip1 opensips[13958]: DBG:rr:find_next_route: No next Route HF found
Feb 25 08:49:40 sip1 opensips[13958]: DBG:rr:after_loose: no next URI found
Feb 25 08:49:40 sip1 opensips[13958]: DBG:rr:run_rr_callbacks: callback id 1 entered with <r2=on;lr;ftag=as76076dfc;did=963.825d2b42>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:dlg_onroute: route param is '963.825d2b42' (len=12)
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:lookup_dlg: ref dlg 0x7fc563376aa8 with 1 -> 3
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:lookup_dlg: dialog id=615699752 found on entry 873
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=58
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_to_param: tag=as76076dfc
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@64.2.142.28}
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:next_state_dlg: dialog 0x7fc563376aa8 changed from state 4 to state 5, due event 7
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:dlg_onroute: BYE successfully processed - dst_leg = 1
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:run_dlg_callbacks: dialog=0x7fc563376aa8, type=32
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:fetch_dlg_value: looking for <trace_x00>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:fetch_dlg_value: var NOT found!
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=40
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:sip_trace: sip_trace called
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=569; type=252; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=22; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:unref_dlg: unref dlg 0x7fc563376aa8 with 2 -> 1
Feb 25 08:49:40 sip1 opensips[13958]: DBG:rr:run_rr_callbacks: callback id 2 entered with <r2=on;lr;ftag=as76076dfc;did=963.825d2b42>
Feb 25 08:49:40 sip1 opensips[13958]: DBG:uac:restore_uri: getting 'vsf' Route param
Feb 25 08:49:40 sip1 opensips[13958]: DBG:uac:restore_uri: route param 'vsf' not found
Feb 25 08:49:40 sip1 opensips[13958]: DBG:uac:restore_uri: getting 'vst' Route param
Feb 25 08:49:40 sip1 opensips[13958]: DBG:uac:restore_uri: route param 'vst' not found
Feb 25 08:49:40 sip1 opensips[13958]: LOOSE ROUTE || MATCH DIALOG****************************************
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=78
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:t_lookup_request: start searching: hash=4666, isACK=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 2 entered
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 1 entered
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:ref_dlg: ref dlg 0x7fc563376aa8 with 1 -> 2
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:run_reqin_callbacks: trans=0x7fc56337c938, callback type 1, id 0 entered
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=78
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:set_timer: relative timeout is 500000
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:insert_timer_unsafe: [4]: 0x7fc56337cb58 (530900000)
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:set_timer: relative timeout is 5
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:insert_timer_unsafe: [0]: 0x7fc56337cb88 (535)
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 1024, id 0 entered
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:trace_onreq_out: trace on req out
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:parse_headers: flags=40
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:trace_msg_out: trace msg out
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:trace_msg_out: dest [udp:192.168.1.21:5060]
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:40 sip1 opensips[13958]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=525; type=252; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=21; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13958]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_msg: status: <200>
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_msg: reason: <OK>
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: flags=2
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bKa321.cc345046.0>; state=6
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.22>; state=6
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: flags=22
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 234, <received> = <64.2.142.28>; state=6
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK47ccbf12>; state=6
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_to_param: tag=as40fedff8
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_to: display={}, ruri={sip:8665551212@63.246.156.XX:5060}
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:get_hdr_field: <To> [52]; uri=[sip:8665551212@63.246.156.XX:5060]
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:get_hdr_field: to body [<sip:8665551212@63.246.156.XX:5060>]
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:get_hdr_field: cseq <CSeq>: <103> <BYE>
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_reply_matching: hash 4666 label 1678066636 branch 0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc56337c938] after is 2
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_reply_matching: reply matched (T=0x7fc56337c938)!
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 4 entered
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: flags=8
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 2, id 1 entered
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:trace_onreply_in: trace onreply in
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_to_param: tag=as76076dfc
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@64.2.142.28}
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: flags=40
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=555; type=252; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=21; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=2; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:t_relay_to: new transaction fwd'ed
Feb 25 08:49:40 sip1 opensips[13958]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 1
Feb 25 08:49:40 sip1 opensips[13958]: DBG:dialog:unref_dlg: unref dlg 0x7fc563376aa8 with 1 -> 1
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:40 sip1 opensips[13958]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_check: end=0x7fc56337c938
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_should_relay_response: T_code=0, new_code=200
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:build_res_buf_from_sip_res: old size: 555, new size: 461
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:build_res_buf_from_sip_res: copied size: orig:110, new: 16, rest: 445 msg=#012SIP/2.0 200 OK#015#012Via: SIP/2.0/UDP 64.2.142.28:5060;received=64.2.142.28;branch=z9hG4bK47ccbf12;rport=5060#015#012From: "+17278516359" <sip:7278516359@64.2.142.28>;tag=as76076dfc#015#012To: <sip:8665551212@63.246.156.XX:5060>;tag=as40fedff8#015#012Call-ID: 0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28#015#012CSeq: 103 BYE#015#012Server: Asterisk PBX 1.8.19.0#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH#015#012Supported: replaces, timer#015#012Content-Length: 0#015#012#015#012
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:insert_timer_unsafe: [2]: 0x7fc56337c9b8 (535)
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:relay_reply: sent buf=0x7fc56fa78188: SIP/2.0 2..., shmem=0x7fc563380398: SIP/2.0 2
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 128, id 4 entered
Feb 25 08:49:40 sip1 opensips[13955]: ACC: transaction answered: timestamp=1361800180;method=BYE;from_tag=as76076dfc;to_tag=as40fedff8;call_id=0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28;code=200;reason=OK
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:has_stmt_ctx: ctx found for acc
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74490 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=44; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=11; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=12; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_msg: SIP Request:
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_msg: method: <BYE>
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_msg: uri: <sip:17275551212@66.241.97.173>
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=2
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK303e48bc>; state=6
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 25 08:49:40 sip1 opensips[13954]: ===============================BEGINNING ROUTE=================================
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=100
Feb 25 08:49:40 sip1 opensips[13954]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=8
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:uri:has_totag: totag found
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=200
Feb 25 08:49:40 sip1 opensips[13954]: DBG:rr:is_preloaded: is_preloaded: No
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [66.241.97.173] == [127.0.0.1]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [66.241.97.173] == [192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [66.241.97.173] == [63.246.156.XX]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:check_self: host != me
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 12==9 && [192.168.1.22] == [127.0.0.1]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 12==12 && [192.168.1.22] == [192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:rr:after_loose: Topmost route URI: 'sip:192.168.1.22;r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13' is me
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 13==9 && [63.246.156.XX] == [127.0.0.1]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 13==12 && [63.246.156.XX] == [192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if host==us: 13==13 && [63.246.156.XX] == [63.246.156.XX]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 25 08:49:40 sip1 opensips[13954]: DBG:rr:after_loose: URI to be processed: 'sip:64.2.142.93;lr=on'
Feb 25 08:49:40 sip1 opensips[13954]: DBG:rr:after_loose: Next URI is a loose router
Feb 25 08:49:40 sip1 opensips[13954]: DBG:rr:run_rr_callbacks: callback id 1 entered with <r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:40 sip1 opensips[13954]: DBG:dialog:dlg_onroute: route param is '55b.59ef7b13' (len=12)
Feb 25 08:49:40 sip1 opensips[13954]: DBG:dialog:lookup_dlg: no dialog id=834141845 found on entry 2901
Feb 25 08:49:40 sip1 opensips[13954]: DBG:dialog:dlg_onroute: unable to find dialog for BYE with route param '55b.59ef7b13'
Feb 25 08:49:40 sip1 opensips[13954]: DBG:rr:run_rr_callbacks: callback id 2 entered with <r2=on;lr;ftag=as5fe6f9f1;did=55b.59ef7b13>
Feb 25 08:49:40 sip1 opensips[13954]: DBG:uac:restore_uri: getting 'vsf' Route param
Feb 25 08:49:40 sip1 opensips[13954]: DBG:uac:restore_uri: route param 'vsf' not found
Feb 25 08:49:40 sip1 opensips[13954]: DBG:uac:restore_uri: getting 'vst' Route param
Feb 25 08:49:40 sip1 opensips[13954]: DBG:uac:restore_uri: route param 'vst' not found
Feb 25 08:49:40 sip1 opensips[13954]: LOOSE ROUTE || MATCH DIALOG****************************************
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:get_hdr_field: cseq <CSeq>: <103> <BYE>
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:get_hdr_field: content_length=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:get_hdr_field: found end of header
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=78
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:t_lookup_request: start searching: hash=14886, isACK=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:matching_3261: RFC3261 transaction matching failed
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:t_lookup_request: no transaction found
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:run_reqin_callbacks: trans=0x7fc563380848, callback type 1, id 2 entered
Feb 25 08:49:40 sip1 opensips[13954]: DBG:siptrace:trace_onreq_in: trace on req in
Feb 25 08:49:40 sip1 opensips[13954]: DBG:siptrace:trace_onreq_in: nothing to trace...
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:run_reqin_callbacks: trans=0x7fc563380848, callback type 1, id 1 entered
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:run_reqin_callbacks: trans=0x7fc563380848, callback type 1, id 0 entered
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 128, id 2 entered
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_headers: flags=78
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:trace_onreply_out: trace onreply out
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_to_param: tag=as5fe6f9f1
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:parse_headers: flags=40
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:trace_onreply_out: dest [udp:64.2.142.28:5060]
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:parse_to: display={"+17278516359"}, ruri={sip:7278516359@192.168.1.21}
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:save_siptrace: saving siptrace
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:40 sip1 opensips[13955]: DBG:siptrace:insert_siptrace_flag: storing info 1...
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:mk_proxy: doing DNS lookup...
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:has_stmt_ctx: ctx found for sip_trace
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:set_timer: relative timeout is 500000
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74d40 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:insert_timer_unsafe: [4]: 0x7fc563380a68 (530900000)
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:set_timer: relative timeout is 5
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=461; type=252; is_null=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:insert_timer_unsafe: [0]: 0x7fc563380a98 (535)
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=44; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:t_relay_to: new transaction fwd'ed
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc563380848] after is 0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=22; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13954]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=20; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 25 08:49:40 sip1 opensips[13955]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc56337c938] after is 0
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:40 sip1 opensips[13955]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_msg: SIP Reply (status):
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_msg: version: <SIP/2.0>
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_msg: status: <481>
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_msg: reason: <Call leg/transaction does not exist>
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: flags=2
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=6
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 234, <received> = <63.246.156.XX>; state=6
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK62a3.e72c7c97.0>; state=16
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: via found, flags=2
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: this is the first via
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:receive_msg: After parse_msg...
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:forward_reply: found module tm, passing reply to it
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_check: start=0xffffffffffffffff
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: flags=22
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 234, <received> = <192.168.1.21>; state=6
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK303e48bc>; state=6
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_via: end of header reached, state=5
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: via found, flags=22
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: parse_headers: this is the second via
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_to_param: tag=as3ed8aad2
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_to: end of header reached, state=29
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_to: display={}, ruri={sip:17275551212@192.168.1.22}
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:get_hdr_field: <To> [47]; uri=[sip:17275551212@192.168.1.22]
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:get_hdr_field: to body [<sip:17275551212@192.168.1.22>]
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:get_hdr_field: cseq <CSeq>: <103> <BYE>
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_reply_matching: hash 14886 label 2043134590 branch 0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_reply_matching: REF_UNSAFE:[0x7fc563380848] after is 1
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_reply_matching: reply matched (T=0x7fc563380848)!
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 2, id 0 entered
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:parse_headers: flags=8
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_check: end=0x7fc563380848
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:reply_received: org. status uas=0, uac[0]=0 local=0 is_invite=0)
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_should_relay_response: T_code=0, new_code=481
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_pick_branch: picked branch 0, code 481 (prio=681)
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=481, flags=2
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:relay_reply: branch=0, save=0, relay=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:build_res_buf_from_sip_res: old size: 571, new size: 475
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:build_res_buf_from_sip_res: copied size: orig:145, new: 49, rest: 426 msg=#012SIP/2.0 481 Call leg/transaction does not exist#015#012Via: SIP/2.0/UDP 192.168.1.21:5060;received=192.168.1.21;branch=z9hG4bK303e48bc;rport=5060#015#012From: "+17278516359" <sip:7278516359@192.168.1.21>;tag=as5fe6f9f1#015#012To: <sip:17275551212@192.168.1.22>;tag=as3ed8aad2#015#012Call-ID: 445c30514321387a6edfd124044f2226@192.168.1.21:5060#015#012CSeq: 103 BYE#015#012User-Agent: packetrino#015#012Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO#015#012Supported: replaces#015#012Content-Length: 0#015#012#015#012
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:_shm_resize: resize(0) called
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:insert_timer_unsafe: [2]: 0x7fc5633808c8 (535)
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:relay_reply: sent buf=0x7fc56fa792c8: SIP/2.0 4..., shmem=0x7fc56337b420: SIP/2.0 4
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:run_trans_callbacks: trans=0x7fc563380848, callback type 128, id 0 entered
Feb 25 08:49:40 sip1 opensips[13959]: ACC: transaction answered: timestamp=1361800180;method=BYE;from_tag=as5fe6f9f1;to_tag=as3ed8aad2;call_id=445c30514321387a6edfd124044f2226@192.168.1.21:5060;code=481;reason=Call leg/transaction does not exist
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:has_stmt_ctx: ctx found for acc
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: conn=0x7fc56fa74490 (tail=140485958518280) MC=0x7fc56fa74668
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (0): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (2): len=10; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (3): len=50; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (5): len=35; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (7): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (8): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (9): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (10): len=0; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (11): len=12; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_val2bind: added val (12): len=13; type=254; is_null=0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 25 08:49:40 sip1 opensips[13959]: DBG:tm:t_unref: UNREF_UNSAFE: [0x7fc563380848] after is 0
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 25 08:49:40 sip1 opensips[13959]: DBG:core:receive_msg: cleaning up
Feb 25 08:49:41 sip1 opensips[13963]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fc56337cb58 next=0x7fc563380a68, timeout=530900000
Feb 25 08:49:41 sip1 opensips[13963]: DBG:tm:utimer_routine: timer routine:4,tl=0x7fc563380a68 next=(nil), timeout=530900000
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:0,tl=0x7fc56337cb88 next=0x7fc563380a98, timeout=535
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:0,tl=0x7fc563380a98 next=(nil), timeout=535
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:2,tl=0x7fc56337c9b8 next=0x7fc5633808c8, timeout=535
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:wait_handler: removing 0x7fc56337c938 from table
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:delete_cell: delete transaction 0x7fc56337c938
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:run_trans_callbacks: trans=0x7fc56337c938, callback type 4096, id 3 entered
Feb 25 08:49:46 sip1 opensips[13963]: DBG:dialog:unref_dlg: unref dlg 0x7fc563376aa8 with 1 -> 0
Feb 25 08:49:46 sip1 opensips[13963]: DBG:dialog:unref_dlg: ref <=0 for dialog 0x7fc563376aa8
Feb 25 08:49:46 sip1 opensips[13963]: DBG:dialog:destroy_dlg: destroing dialog 0x7fc563376aa8
Feb 25 08:49:46 sip1 opensips[13963]: DBG:dialog:destroy_dlg: dlg expired or not in list - dlg 0x7fc563376aa8 [873:615699752] with clid '0ba9bee746d44a7d4c587d4c4a8d4c9e@64.2.142.28' and tags 'as76076dfc' 'as40fedff8'
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:wait_handler: done
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:timer_routine: timer routine:2,tl=0x7fc5633808c8 next=(nil), timeout=535
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:wait_handler: removing 0x7fc563380848 from table
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:delete_cell: delete transaction 0x7fc563380848
Feb 25 08:49:46 sip1 opensips[13963]: DBG:tm:wait_handler: done
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment