Jun 21 02:32:35 [3155] DBG:core:parse_msg: SIP Request:
Jun 21 02:32:35 [3155] DBG:core:parse_msg:  method:  <INVITE>
Jun 21 02:32:35 [3155] DBG:core:parse_msg:  uri:     <sip:556139659184@pabx1:5090>
Jun 21 02:32:35 [3155] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=2
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2233e439>; state=6
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jun 21 02:32:35 [3155] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:35 [3155] DBG:core:parse_headers: via found, flags=2
Jun 21 02:32:35 [3155] DBG:core:parse_headers: this is the first via
Jun 21 02:32:35 [3155] DBG:core:receive_msg: After parse_msg...
Jun 21 02:32:35 [3155] DBG:core:receive_msg: preparing to run routing scripts...
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=100
Jun 21 02:32:35 [3155] DBG:core:parse_to: end of header reached, state=10
Jun 21 02:32:35 [3155] DBG:core:parse_to: display={}, ruri={sip:556139659184@pabx1:5090}
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: <To> [31]; uri=[sip:556139659184@pabx1:5090] 
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: to body [<sip:556139659184@pabx1:5090>
]
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Jun 21 02:32:35 [3155] DBG:maxfwd:is_maxfwd_present: value = 70 
Jun 21 02:32:35 [3155] DBG:uri:has_totag: no totag
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=78
Jun 21 02:32:35 [3155] DBG:tm:t_lookup_request: start searching: hash=19206, isACK=0
Jun 21 02:32:35 [3155] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 21 02:32:35 [3155] DBG:tm:t_lookup_request: no transaction found
Jun 21 02:32:35 [3155] DBG:core:parse_to_param: tag=as13631b36
Jun 21 02:32:35 [3155] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:35 [3155] DBG:core:parse_to: display={"tronco2"}, ruri={sip:tronco2@pabx1}
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_submit_query: discon reset for 7893920
Jun 21 02:32:35 [3155] DBG:core:db_do_query: SYNC-DBG - SELECT successfully executed!
Jun 21 02:32:35 [3155] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78b338
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jun 21 02:32:35 [3155] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x78b378
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78b380)[0]=[domain]
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3155] DBG:core:db_allocate_rows: allocate 48 bytes for result rows and values at 0x78b3a8
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_str2val: converting STRING [pabx1]
Jun 21 02:32:35 [3155] DBG:domain:is_domain_local: Realm 'pabx1' is local
Jun 21 02:32:35 [3155] DBG:core:db_free_columns: freeing result columns at 0x78b378
Jun 21 02:32:35 [3155] DBG:core:db_free_rows: freeing 1 rows
Jun 21 02:32:35 [3155] DBG:core:db_free_row: freeing row values at 0x78b3b8
Jun 21 02:32:35 [3155] DBG:core:db_free_rows: freeing rows at 0x78b3a8
Jun 21 02:32:35 [3155] DBG:core:db_free_result: freeing result set at 0x78b338
Jun 21 02:32:35 [3155] DBG:core:db_free_result: SYNC-DBG - freeing result!
Mensagem pertence aos dominios servidos pelo opensipsJun 21 02:32:35 [3155] DBG:core:parse_headers: flags=200
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: content_length=269
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: found end of header
Jun 21 02:32:35 [3155] DBG:rr:find_first_route: No Route headers found
Jun 21 02:32:35 [3155] DBG:rr:loose_route: There is no Route HF
Processando record_routevai executar do_routingJun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_submit_query: discon reset for 7893920
Jun 21 02:32:35 [3155] DBG:core:db_do_query: SYNC-DBG - SELECT successfully executed!
Jun 21 02:32:35 [3155] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78bb40
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: 1 columns returned from the query
Jun 21 02:32:35 [3155] DBG:core:db_allocate_columns: allocate 28 bytes for result columns at 0x78bb80
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78bb88)[0]=[groupid]
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: use DB_INT result type
Jun 21 02:32:35 [3155] DBG:core:db_allocate_rows: allocate 48 bytes for result rows and values at 0x78bbb0
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_str2val: converting INT [2]
Jun 21 02:32:35 [3155] DBG:core:db_free_columns: freeing result columns at 0x78bb80
Jun 21 02:32:35 [3155] DBG:core:db_free_rows: freeing 1 rows
Jun 21 02:32:35 [3155] DBG:core:db_free_row: freeing row values at 0x78bbc0
Jun 21 02:32:35 [3155] DBG:core:db_free_rows: freeing rows at 0x78bbb0
Jun 21 02:32:35 [3155] DBG:core:db_free_result: freeing result set at 0x78bb40
Jun 21 02:32:35 [3155] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 21 02:32:35 [3155] DBG:drouting:do_routing: using dr group 2
Jun 21 02:32:35 [3155] DBG:drouting:internal_check_rt: found rgid 2 (rule list 0x2afe45b59448)
Jun 21 02:32:35 [3155] DBG:drouting:do_routing: setting attr [] as for ruri
Jun 21 02:32:35 [3155] DBG:drouting:do_routing: setting the gw [0] as ruri "sip:6139659184@nheen.net.br:5090"
Executando route_1, de envioEntrando na route_1, de envioSetando flags de accouting para os INVITESe eh INVITE, pode setar t_on_reply e t_on_failureTransmitindo do sip:tronco2@pabx1 para uri sip:6139659184@nheen.net.br:5090 e com o to sip:556139659184@pabx1:5090Jun 21 02:32:35 [3155] DBG:tm:t_newtran: transaction on entrance=(nil)
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=78
Jun 21 02:32:35 [3155] DBG:tm:t_lookup_request: start searching: hash=19206, isACK=0
Jun 21 02:32:35 [3155] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 21 02:32:35 [3155] DBG:tm:t_lookup_request: no transaction found
Jun 21 02:32:35 [3155] DBG:tm:run_reqin_callbacks: trans=0x2afe45ea9150, callback type 1, id 0 entered
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=78
Jun 21 02:32:35 [3155] DBG:rr:is_direction: param ftag not found
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:35 [3155] DBG:core:check_via_address: params 192.168.200.243, 192.168.200.243, 0
Jun 21 02:32:35 [3155] DBG:core:_shm_resize: resize(0) called
Jun 21 02:32:35 [3155] DBG:tm:_reply_light: reply sent out. buf=0x78bbf0: SIP/2.0 1..., shmem=0x2afe45eabe80: SIP/2.0 1
Jun 21 02:32:35 [3155] DBG:tm:_reply_light: finished
Entrou na branch route 1: sip:6139659184@nheen.net.br:5090
tronco=tronco2 and pabx=pabx1 and dominio=nheen.net.brJun 21 02:32:35 [3155] DBG:avpops:ops_dbquery_avps: query [SELECT usuario,dominio FROM providers_trunks where tronco='tronco2' and pabx='pabx1' and dominio='nheen.net.br';]
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_submit_query: discon reset for 7893920
Jun 21 02:32:35 [3155] DBG:core:db_do_raw_query: SYNC-DBG - raw query succesfully executed!
Jun 21 02:32:35 [3155] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78bbb0
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Jun 21 02:32:35 [3155] DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x78bbf0
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78bc00)[0]=[usuario]
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78bc10)[1]=[dominio]
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3155] DBG:core:db_allocate_rows: allocate 80 bytes for result rows and values at 0x78bc38
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_str2val: converting STRING [617056557]
Jun 21 02:32:35 [3155] DBG:db_mysql:db_mysql_str2val: converting STRING [nheen.net.br]
Jun 21 02:32:35 [3155] DBG:core:db_do_raw_query: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3155] DBG:avpops:db_query_avp: rows [1]
Jun 21 02:32:35 [3155] DBG:avpops:db_query_avp: row [0]
Jun 21 02:32:35 [3155] DBG:avpops:db_close_query: close avp query
Jun 21 02:32:35 [3155] DBG:core:db_free_columns: freeing result columns at 0x78bbf0
Jun 21 02:32:35 [3155] DBG:core:db_free_rows: freeing 1 rows
Jun 21 02:32:35 [3155] DBG:core:db_free_row: freeing row values at 0x78bc48
Jun 21 02:32:35 [3155] DBG:core:db_free_rows: freeing rows at 0x78bc38
Jun 21 02:32:35 [3155] DBG:core:db_free_result: freeing result set at 0x78bbb0
Jun 21 02:32:35 [3155] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 21 02:32:35 [3155] DBG:uac:replace_from: uri to replace [sip:tronco2@pabx1]
Jun 21 02:32:35 [3155] DBG:uac:replace_from: replacement uri is [sip:617056557@nheen.net.br]
Jun 21 02:32:35 [3155] DBG:uac:replace_from: encode is=<AAAAAEJDWF5WWQd1RyEMEFRlbi5uZXQuYnI-> len=36
Jun 21 02:32:35 [3155] DBG:rr:add_rr_param: adding (;vsf=AAAAAEJDWF5WWQd1RyEMEFRlbi5uZXQuYnI-) 0x78b7f0
Jun 21 02:32:35 [3155] DBG:core:mk_proxy: doing DNS lookup...
Jun 21 02:32:35 [3155] DBG:core:sip_resolvehost: has port -> do A record lookup!
Jun 21 02:32:35 [3155] DBG:tm:set_timer: relative timeout is 500000
Jun 21 02:32:35 [3155] DBG:tm:insert_timer_unsafe: [4]: 0x2afe45ea9370 (8200000)
Jun 21 02:32:35 [3155] DBG:tm:set_timer: relative timeout is 30
Jun 21 02:32:35 [3155] DBG:tm:insert_timer_unsafe: [0]: 0x2afe45ea93a0 (37)
Jun 21 02:32:35 [3155] DBG:tm:t_relay_to: new transaction fwd'ed
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=78
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:35 [3155] DBG:core:pv_get_xto_attr: no Display name
ACC: request accounted: timestamp=1245562355;method=INVITE;from_tag=as13631b36;to_tag=;call_id=5416a1206742cb8a6b157c21352ab0e0@pabx1;code=;reason=inicio de conexao;via=SIP/2.0/UDP 192.168.200.243:5060;branch=z9hG4bK2233e439;rport;cseq=102;origruriuser=556139659184;origruridomn=pabx1;origruriport=5090;origruriproto=UDP;ruriuser=6139659184;ruridomn=nheen.net.br;ruriport=5090;ruriproto=UDP;Acontact=<sip:tronco2@192.168.200.243>;Aiporigem=192.168.200.243;Aportorigem=5060;Aipinterf=192.168.200.246;Aportinterf=5090;Afromdisplay=pabx1;Afromuser=tronco2;Afromdomn=pabx1;Atodisplay=;Atouser=556139659184;Atodomn=pabx1;Auagent=Asterisk PBX;Bcontact=;Bportorigem=;Bipinterf=;Bportinterf=;Bfromdisplay=;Bfromuser=;Bfromdomn=;Btodisplay=;Btouser=;Btodomn=;Buagent=
Jun 21 02:32:35 [3155] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 21 02:32:35 [3155] DBG:core:destroy_avp_list: destroying list (nil)
Jun 21 02:32:35 [3155] DBG:core:receive_msg: cleaning up
Jun 21 02:32:35 [3171] DBG:core:parse_msg: SIP Reply  (status):
Jun 21 02:32:35 [3171] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 21 02:32:35 [3171] DBG:core:parse_msg:  status:  <407>
Jun 21 02:32:35 [3171] DBG:core:parse_msg:  reason:  <Proxy Authentication Required>
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=2
Jun 21 02:32:35 [3171] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK60b4.7d029da2.0>; state=6
Jun 21 02:32:35 [3171] DBG:core:parse_via_param: found param type 235, <rport> = <5090>; state=6
Jun 21 02:32:35 [3171] DBG:core:parse_via_param: found param type 234, <received> = <xxx.xxx.xxx.xxx>; state=16
Jun 21 02:32:35 [3171] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:35 [3171] DBG:core:parse_headers: via found, flags=2
Jun 21 02:32:35 [3171] DBG:core:parse_headers: this is the first via
Jun 21 02:32:35 [3171] DBG:core:receive_msg: After parse_msg...
Jun 21 02:32:35 [3171] DBG:core:forward_reply: found module tm, passing reply to it
Jun 21 02:32:35 [3171] DBG:tm:t_check: start=0xffffffffffffffff
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=22
Jun 21 02:32:35 [3171] DBG:core:parse_via_param: found param type 234, <received> = <192.168.200.243>; state=6
Jun 21 02:32:35 [3171] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2233e439>; state=6
Jun 21 02:32:35 [3171] DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Jun 21 02:32:35 [3171] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:35 [3171] DBG:core:parse_headers: via found, flags=22
Jun 21 02:32:35 [3171] DBG:core:parse_headers: parse_headers: this is the second via
Jun 21 02:32:35 [3171] DBG:core:parse_to_param: tag=9054a870c6f8064552c9ed55619cbd62.3ba9
Jun 21 02:32:35 [3171] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:35 [3171] DBG:core:parse_to: display={}, ruri={sip:556139659184@pabx1:5090}
Jun 21 02:32:35 [3171] DBG:core:get_hdr_field: <To> [73]; uri=[sip:556139659184@pabx1:5090] 
Jun 21 02:32:35 [3171] DBG:core:get_hdr_field: to body [<sip:556139659184@pabx1:5090>]
Jun 21 02:32:35 [3171] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=8
Jun 21 02:32:35 [3171] DBG:tm:t_reply_matching: hash 19206 label 718872791 branch 0
Jun 21 02:32:35 [3171] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Jun 21 02:32:35 [3171] DBG:tm:t_reply_matching: reply matched (T=0x2afe45ea9150)!
Jun 21 02:32:35 [3171] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 1 entered
Jun 21 02:32:35 [3171] DBG:core:parse_to_param: tag=as13631b36
Jun 21 02:32:35 [3171] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:35 [3171] DBG:core:parse_to: display={"tronco2"}, ruri={sip:617056557@nheen.net.br}
Jun 21 02:32:35 [3171] DBG:uac:restore_from_reply: removing <From: "tronco2" <sip:617056557@nheen.net.br>;tag=as13631b36
>
Jun 21 02:32:35 [3171] DBG:uac:restore_from_reply: inserting <From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>
Jun 21 02:32:35 [3171] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 0 entered
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=8
Jun 21 02:32:35 [3171] DBG:tm:t_check: end=0x2afe45ea9150
Jun 21 02:32:35 [3171] DBG:tm:reply_received: org. status uas=100, uac[0]=0 local=0 is_invite=1)
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=8
Jun 21 02:32:35 [3171] DBG:tm:build_local: using FROM=<From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>, TO=<To: <sip:556139659184@pabx1:5090>;tag=9054a870c6f8064552c9ed55619cbd62.3ba9
>, CSEQ_N=<CSeq: 102>
incoming reply
Jun 21 02:32:35 [3171] DBG:tm:t_check_status: checked status is <407>
Jun 21 02:32:35 [3171] DBG:tm:t_should_relay_response: T_code=100, new_code=407
Jun 21 02:32:35 [3171] DBG:tm:t_pick_branch: picked branch 0, code 407 (prio=501)
Jun 21 02:32:35 [3171] DBG:tm:is_3263_failure: dns-failover test: branch=0, last_recv=407, flags=2
Jun 21 02:32:35 [3171] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 64, id 0 entered
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:35 [3171] DBG:core:pv_get_xto_attr: no Display name
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=80
Jun 21 02:32:35 [3171] DBG:core:get_hdr_field: content_length=0
Jun 21 02:32:35 [3171] DBG:core:get_hdr_field: found end of header
Jun 21 02:32:35 [3171] DBG:core:pv_get_contact: no contact header!
Jun 21 02:32:35 [3171] DBG:core:pv_get_xto_attr: no Display name
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=8000000
Jun 21 02:32:35 [3171] DBG:core:pv_get_useragent: no User-Agent header
ACC: call missed: timestamp=1245562355;method=INVITE;from_tag=as13631b36;to_tag=9054a870c6f8064552c9ed55619cbd62.3ba9;call_id=5416a1206742cb8a6b157c21352ab0e0@pabx1;code=407;reason=Proxy Authentication Required;via=SIP/2.0/UDP 192.168.200.243:5060;branch=z9hG4bK2233e439;rport;cseq=102;origruriuser=556139659184;origruridomn=pabx1;origruriport=5090;origruriproto=UDP;ruriuser=6139659184;ruridomn=nheen.net.br;ruriport=5090;ruriproto=UDP;Acontact=<sip:tronco2@192.168.200.243>;Aiporigem=192.168.200.243;Aportorigem=5060;Aipinterf=192.168.200.246;Aportinterf=5090;Afromdisplay=pabx1;Afromuser=tronco2;Afromdomn=pabx1;Atodisplay=;Atouser=556139659184;Atodomn=pabx1;Auagent=Asterisk PBX;Bcontact=;Bportorigem=5090;Bipinterf=192.168.200.246;Bportinterf=5090;Bfromdisplay=nheen.net.br;Bfromuser=617056557;Bfromdomn=nheen.net.br;Btodisplay=;Btouser=556139659184;Btodomn=pabx1;Buagent=
Jun 21 02:32:35 [3171] DBG:core:pv_get_xto_attr: no Display name
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=80
Jun 21 02:32:35 [3171] DBG:core:pv_get_contact: no contact header!
Jun 21 02:32:35 [3171] DBG:core:pv_get_xto_attr: no Display name
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=8000000
Jun 21 02:32:35 [3171] DBG:core:pv_get_useragent: no User-Agent header
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: conn=0x789f00 (tail=7893920) MC=0x7873f8
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: new query=|insert into missed_calls (method,from_tag,to_tag,callid,sip_code,sip_reason,time,cseq,origruriuser,origruridomn,origruriport,origruriproto,ruriuser,ruridomn,ruriport,ruriproto,Acontact,Aiporigem,Aportorigem,Aipinterf,Aportinterf,Afromdisplay,Afromuser,Afromdomn,Atodisplay,Atouser,Atodomn,Auagent,Bcontact,Biporigem,Bportorigem,Bipinterf,Bportinterf,Bfromdisplay,Bfromuser,Bfromdomn,Btodisplay,Btouser,Btodomn,Buagent ) values (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)|
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: prepared statement successfully set...
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: discon is 0 for 7893920
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (2): len=37; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (3): len=38; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (5): len=29; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (8): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (9): len=5; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (10): len=4; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (11): len=3; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (12): len=10; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (13): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (14): len=4; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (15): len=3; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (16): len=29; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (17): len=15; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (18): len=4; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (19): len=15; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (20): len=4; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (21): len=5; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (22): len=7; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (23): len=5; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (24): len=0; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (25): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (26): len=5; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (27): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (28): len=0; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (29): len=15; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (30): len=4; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (31): len=15; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (32): len=4; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (33): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (34): len=9; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (35): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (36): len=0; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (37): len=12; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (38): len=5; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_val2bind: added val (39): len=0; type=254; is_null=0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_do_prepared_query: discon reset for 7893920
Entrando na failure route 1Jun 21 02:32:35 [3171] DBG:tm:t_check_status: checked status is <407>
Detectou pedido para autorizar. Usando uac_authJun 21 02:32:35 [3171] DBG:avpops:ops_dbquery_avps: query [SELECT usuario,dominio,senha FROM providers_trunks where tronco='tronco2' and pabx='pabx1' and dominio='nheen.net.br';]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_submit_query: discon reset for 7893920
Jun 21 02:32:35 [3171] DBG:core:db_do_raw_query: SYNC-DBG - raw query succesfully executed!
Jun 21 02:32:35 [3171] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78b798
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: 3 columns returned from the query
Jun 21 02:32:35 [3171] DBG:core:db_allocate_columns: allocate 84 bytes for result columns at 0x78ceb8
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78ced0)[0]=[usuario]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78cee0)[1]=[dominio]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78cef0)[2]=[senha]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3171] DBG:core:db_allocate_rows: allocate 112 bytes for result rows and values at 0x78cf20
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_str2val: converting STRING [617056557]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_str2val: converting STRING [nheen.net.br]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_str2val: converting STRING [password]
Jun 21 02:32:35 [3171] DBG:core:db_do_raw_query: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3171] DBG:avpops:db_query_avp: rows [1]
Jun 21 02:32:35 [3171] DBG:avpops:db_query_avp: row [0]
Jun 21 02:32:35 [3171] DBG:avpops:db_close_query: close avp query
Jun 21 02:32:35 [3171] DBG:core:db_free_columns: freeing result columns at 0x78ceb8
Jun 21 02:32:35 [3171] DBG:core:db_free_rows: freeing 1 rows
Jun 21 02:32:35 [3171] DBG:core:db_free_row: freeing row values at 0x78cf30
Jun 21 02:32:35 [3171] DBG:core:db_free_rows: freeing rows at 0x78cf20
Jun 21 02:32:35 [3171] DBG:core:db_free_result: freeing result set at 0x78b798
Jun 21 02:32:35 [3171] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 21 02:32:35 [3171] DBG:uac:uac_auth: picked reply is 0x78a560, code 407
Jun 21 02:32:35 [3171] DBG:uac:get_autenticate_hdr: looking for header "Proxy-Authenticate"
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:35 [3171] DBG:uac:uac_auth: header found; body=<Digest realm="nheen.net.br", nonce="4a3dc6a1e0519fb7e8a6176b49b5ef843aae2c27", qop="auth">
Jun 21 02:32:35 [3171] DBG:uac:parse_authenticate_body: <realm>="nheen.net.br" state=2
Jun 21 02:32:35 [3171] DBG:uac:parse_authenticate_body: <nonce>="4a3dc6a1e0519fb7e8a6176b49b5ef843aae2c27" state=3
Jun 21 02:32:35 [3171] DBG:uac:parse_authenticate_body: <qop>="auth" state=1
Jun 21 02:32:35 [3171] DBG:uac:build_authorization_hdr: hdr is <Proxy-Authorization: Digest username="617056557", realm="nheen.net.br", nonce="4a3dc6a1e0519fb7e8a6176b49b5ef843aae2c27", uri="sip:6139659184@nheen.net.br:5090", qop=auth, nc=00000001, cnonce="4038814349", response="77e79b157b6d003f581eca19f0ac18d2", algorithm=MD5
>
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Executando route_1, de envioEntrando na route_1, de envioSetando flags de accouting para os INVITESe eh INVITE, pode setar t_on_reply e t_on_failureTransmitindo do sip:tronco2@pabx1 para uri sip:6139659184@nheen.net.br:5090 e com o to sip:556139659184@pabx1:5090Entrou na branch route 1: sip:6139659184@nheen.net.br:5090
tronco=tronco2 and pabx=pabx1 and dominio=nheen.net.brJun 21 02:32:35 [3171] DBG:avpops:ops_dbquery_avps: query [SELECT usuario,dominio FROM providers_trunks where tronco='tronco2' and pabx='pabx1' and dominio='nheen.net.br';]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_submit_query: discon reset for 7893920
Jun 21 02:32:35 [3171] DBG:core:db_do_raw_query: SYNC-DBG - raw query succesfully executed!
Jun 21 02:32:35 [3171] DBG:core:db_new_result: allocate 48 bytes for result set at 0x78cf50
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_store_result: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: 2 columns returned from the query
Jun 21 02:32:35 [3171] DBG:core:db_allocate_columns: allocate 56 bytes for result columns at 0x78d0c0
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78d0d0)[0]=[usuario]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: RES_NAMES(0x78d0e0)[1]=[dominio]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_get_columns: use DB_STRING result type
Jun 21 02:32:35 [3171] DBG:core:db_allocate_rows: allocate 80 bytes for result rows and values at 0x78d108
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_str2val: converting STRING [617056557]
Jun 21 02:32:35 [3171] DBG:db_mysql:db_mysql_str2val: converting STRING [nheen.net.br]
Jun 21 02:32:35 [3171] DBG:core:db_do_raw_query: SYNC-DBG - SELECT result was stored!
Jun 21 02:32:35 [3171] DBG:avpops:db_query_avp: rows [1]
Jun 21 02:32:35 [3171] DBG:avpops:db_query_avp: row [0]
Jun 21 02:32:35 [3171] DBG:avpops:db_close_query: close avp query
Jun 21 02:32:35 [3171] DBG:core:db_free_columns: freeing result columns at 0x78d0c0
Jun 21 02:32:35 [3171] DBG:core:db_free_rows: freeing 1 rows
Jun 21 02:32:35 [3171] DBG:core:db_free_row: freeing row values at 0x78d118
Jun 21 02:32:35 [3171] DBG:core:db_free_rows: freeing rows at 0x78d108
Jun 21 02:32:35 [3171] DBG:core:db_free_result: freeing result set at 0x78cf50
Jun 21 02:32:35 [3171] DBG:core:db_free_result: SYNC-DBG - freeing result!
Jun 21 02:32:35 [3171] DBG:uac:replace_from: uri to replace [sip:tronco2@pabx1]
Jun 21 02:32:35 [3171] DBG:uac:replace_from: replacement uri is [sip:617056557@nheen.net.br]
Jun 21 02:32:35 [3171] DBG:uac:replace_from: encode is=<AAAAAEJDWF5WWQd1RyEMEFRlbi5uZXQuYnI-> len=36
Jun 21 02:32:35 [3171] DBG:rr:add_rr_param: adding (;vsf=AAAAAEJDWF5WWQd1RyEMEFRlbi5uZXQuYnI-) 0x2afe45eabbe0
Jun 21 02:32:35 [3171] DBG:core:mk_proxy: doing DNS lookup...
Jun 21 02:32:35 [3171] DBG:core:sip_resolvehost: has port -> do A record lookup!
Jun 21 02:32:35 [3171] DBG:tm:set_timer: relative timeout is 500000
Jun 21 02:32:35 [3171] DBG:tm:insert_timer_unsafe: [4]: 0x2afe45ea9530 (8300000)
Jun 21 02:32:35 [3171] DBG:tm:set_timer: relative timeout is 30
Jun 21 02:32:35 [3171] DBG:tm:insert_timer_unsafe: [0]: 0x2afe45ea9560 (37)
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=78
Jun 21 02:32:35 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:35 [3171] DBG:core:pv_get_xto_attr: no Display name
ACC: request accounted: timestamp=1245562355;method=INVITE;from_tag=as13631b36;to_tag=;call_id=5416a1206742cb8a6b157c21352ab0e0@pabx1;code=;reason=inicio de conexao;via=SIP/2.0/UDP 192.168.200.243:5060;branch=z9hG4bK2233e439;rport;cseq=102;origruriuser=556139659184;origruridomn=pabx1;origruriport=5090;origruriproto=UDP;ruriuser=6139659184;ruridomn=nheen.net.br;ruriport=5090;ruriproto=UDP;Acontact=<sip:tronco2@192.168.200.243>;Aiporigem=192.168.200.243;Aportorigem=5060;Aipinterf=192.168.200.246;Aportinterf=5090;Afromdisplay=pabx1;Afromuser=tronco2;Afromdomn=pabx1;Atodisplay=;Atouser=556139659184;Atodomn=pabx1;Auagent=Asterisk PBX;Bcontact=;Bportorigem=;Bipinterf=;Bportinterf=;Bfromdisplay=;Bfromuser=;Bfromdomn=;Btodisplay=;Btouser=;Btodomn=;Buagent=
Jun 21 02:32:35 [3171] DBG:tm:relay_reply: branch=0, save=1, relay=-1
Jun 21 02:32:35 [3171] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 21 02:32:35 [3171] DBG:core:destroy_avp_list: destroying list (nil)
Jun 21 02:32:35 [3171] DBG:core:receive_msg: cleaning up
Jun 21 02:32:35 [3155] DBG:core:parse_msg: SIP Reply  (status):
Jun 21 02:32:35 [3155] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 21 02:32:35 [3155] DBG:core:parse_msg:  status:  <100>
Jun 21 02:32:35 [3155] DBG:core:parse_msg:  reason:  <trying -- your call is important to us>
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=2
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK60b4.7d029da2.1>; state=6
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 235, <rport> = <5090>; state=6
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 234, <received> = <xxx.xxx.xxx.xxx>; state=16
Jun 21 02:32:35 [3155] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:35 [3155] DBG:core:parse_headers: via found, flags=2
Jun 21 02:32:35 [3155] DBG:core:parse_headers: this is the first via
Jun 21 02:32:35 [3155] DBG:core:receive_msg: After parse_msg...
Jun 21 02:32:35 [3155] DBG:core:forward_reply: found module tm, passing reply to it
Jun 21 02:32:35 [3155] DBG:tm:t_check: start=0xffffffffffffffff
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=22
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 234, <received> = <192.168.200.243>; state=6
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2233e439>; state=6
Jun 21 02:32:35 [3155] DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Jun 21 02:32:35 [3155] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:35 [3155] DBG:core:parse_headers: via found, flags=22
Jun 21 02:32:35 [3155] DBG:core:parse_headers: parse_headers: this is the second via
Jun 21 02:32:35 [3155] DBG:core:parse_to: end of header reached, state=10
Jun 21 02:32:35 [3155] DBG:core:parse_to: display={}, ruri={sip:556139659184@pabx1:5090}
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: <To> [31]; uri=[sip:556139659184@pabx1:5090] 
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: to body [<sip:556139659184@pabx1:5090>
]
Jun 21 02:32:35 [3155] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Jun 21 02:32:35 [3155] DBG:core:parse_headers: flags=8
Jun 21 02:32:35 [3155] DBG:tm:t_reply_matching: hash 19206 label 718872791 branch 1
Jun 21 02:32:35 [3155] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Jun 21 02:32:35 [3155] DBG:tm:t_reply_matching: reply matched (T=0x2afe45ea9150)!
Jun 21 02:32:35 [3155] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 2 entered
Jun 21 02:32:35 [3155] DBG:core:parse_to_param: tag=as13631b36
Jun 21 02:32:35 [3155] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:35 [3155] DBG:core:parse_to: display={"tronco2"}, ruri={sip:617056557@nheen.net.br}
Jun 21 02:32:35 [3155] DBG:uac:restore_from_reply: removing <From: "tronco2" <sip:617056557@nheen.net.br>;tag=as13631b36
>
Jun 21 02:32:35 [3155] DBG:uac:restore_from_reply: inserting <From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>
Jun 21 02:32:35 [3155] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 1 entered
Jun 21 02:32:35 [3155] DBG:uac:restore_from_reply: removing <From: "tronco2" <sip:617056557@nheen.net.br>;tag=as13631b36
>
Jun 21 02:32:35 [3155] DBG:uac:restore_from_reply: inserting <From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>
Jun 21 02:32:35 [3155] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 0 entered
Jun 21 02:32:35 [3155] DBG:tm:t_check: end=0x2afe45ea9150
Jun 21 02:32:35 [3155] DBG:tm:reply_received: org. status uas=100, uac[1]=0 local=0 is_invite=1)
incoming reply
Jun 21 02:32:35 [3155] DBG:tm:t_check_status: checked status is <100>
Jun 21 02:32:35 [3155] DBG:tm:t_should_relay_response: T_code=100, new_code=100
Jun 21 02:32:35 [3155] DBG:tm:relay_reply: branch=1, save=0, relay=-1
Jun 21 02:32:35 [3155] DBG:tm:set_timer: relative timeout is 120
Jun 21 02:32:35 [3155] DBG:tm:insert_timer_unsafe: [1]: 0x2afe45ea9560 (127)
Jun 21 02:32:35 [3155] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 21 02:32:35 [3155] DBG:core:destroy_avp_list: destroying list (nil)
Jun 21 02:32:35 [3155] DBG:core:receive_msg: cleaning up
Jun 21 02:32:36 [3191] DBG:tm:utimer_routine: timer routine:4,tl=0x2afe45ea9370 next=(nil), timeout=8200000
Jun 21 02:32:36 [3191] DBG:tm:utimer_routine: timer routine:4,tl=0x2afe45ea9530 next=(nil), timeout=8300000
Jun 21 02:32:36 [3158] DBG:core:parse_msg: SIP Reply  (status):
Jun 21 02:32:36 [3158] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 21 02:32:36 [3158] DBG:core:parse_msg:  status:  <183>
Jun 21 02:32:36 [3158] DBG:core:parse_msg:  reason:  <Session Progress>
Jun 21 02:32:36 [3158] DBG:core:parse_headers: flags=2
Jun 21 02:32:36 [3158] DBG:core:parse_via_param: found param type 235, <rport> = <5090>; state=6
Jun 21 02:32:36 [3158] DBG:core:parse_via_param: found param type 234, <received> = <xxx.xxx.xxx.xxx>; state=6
Jun 21 02:32:36 [3158] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK60b4.7d029da2.1>; state=16
Jun 21 02:32:36 [3158] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:36 [3158] DBG:core:parse_headers: via found, flags=2
Jun 21 02:32:36 [3158] DBG:core:parse_headers: this is the first via
Jun 21 02:32:36 [3158] DBG:core:receive_msg: After parse_msg...
Jun 21 02:32:36 [3158] DBG:core:forward_reply: found module tm, passing reply to it
Jun 21 02:32:36 [3158] DBG:tm:t_check: start=0xffffffffffffffff
Jun 21 02:32:36 [3158] DBG:core:parse_headers: flags=22
Jun 21 02:32:36 [3158] DBG:core:parse_via_param: found param type 234, <received> = <192.168.200.243>; state=6
Jun 21 02:32:36 [3158] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2233e439>; state=6
Jun 21 02:32:36 [3158] DBG:core:parse_via_param: found param type 235, <rport> = <5060>; state=16
Jun 21 02:32:36 [3158] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:36 [3158] DBG:core:parse_headers: via found, flags=22
Jun 21 02:32:36 [3158] DBG:core:parse_headers: parse_headers: this is the second via
Jun 21 02:32:36 [3158] DBG:core:parse_to_param: tag=as7705788f
Jun 21 02:32:36 [3158] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:36 [3158] DBG:core:parse_to: display={}, ruri={sip:556139659184@pabx1:5090}
Jun 21 02:32:36 [3158] DBG:core:get_hdr_field: <To> [46]; uri=[sip:556139659184@pabx1:5090] 
Jun 21 02:32:36 [3158] DBG:core:get_hdr_field: to body [<sip:556139659184@pabx1:5090>]
Jun 21 02:32:36 [3158] DBG:core:get_hdr_field: cseq <CSeq>: <102> <INVITE>
Jun 21 02:32:36 [3158] DBG:core:parse_headers: flags=8
Jun 21 02:32:36 [3158] DBG:tm:t_reply_matching: hash 19206 label 718872791 branch 1
Jun 21 02:32:36 [3158] DBG:tm:t_reply_matching: REF_UNSAFE: after is 1
Jun 21 02:32:36 [3158] DBG:tm:t_reply_matching: reply matched (T=0x2afe45ea9150)!
Jun 21 02:32:36 [3158] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 2 entered
Jun 21 02:32:36 [3158] DBG:core:parse_to_param: tag=as13631b36
Jun 21 02:32:36 [3158] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:36 [3158] DBG:core:parse_to: display={"tronco2"}, ruri={sip:617056557@nheen.net.br}
Jun 21 02:32:36 [3158] DBG:uac:restore_from_reply: removing <From: "tronco2" <sip:617056557@nheen.net.br>;tag=as13631b36
>
Jun 21 02:32:36 [3158] DBG:uac:restore_from_reply: inserting <From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>
Jun 21 02:32:36 [3158] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 1 entered
Jun 21 02:32:36 [3158] DBG:uac:restore_from_reply: removing <From: "tronco2" <sip:617056557@nheen.net.br>;tag=as13631b36
>
Jun 21 02:32:36 [3158] DBG:uac:restore_from_reply: inserting <From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>
Jun 21 02:32:36 [3158] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 2, id 0 entered
Jun 21 02:32:36 [3158] DBG:tm:t_check: end=0x2afe45ea9150
Jun 21 02:32:36 [3158] DBG:tm:reply_received: org. status uas=100, uac[1]=100 local=0 is_invite=1)
incoming reply
Jun 21 02:32:36 [3158] DBG:tm:t_check_status: checked status is <183>
Achou 180-ring ou 183-session-progress. Fazer acc via xlog.Jun 21 02:32:36 [3158] DBG:core:parse_headers: flags=80
Jun 21 02:32:36 [3158] DBG:core:pv_get_xto_attr: no Display name
Jun 21 02:32:36 [3158] DBG:core:pv_get_xto_attr: no Display name
timestamp=1245562356;modulo=xlog;method=INVITE;from_tag=as13631b36;to_tag=as7705788f;call_id=5416a1206742cb8a6b157c21352ab0e0@pabx1;code=Session Progress;reason=183;cseq=102;origruriuser=<null>;origruridomn=<null>;origruriport=<null>;origruriproto=<null>;ruriuser=<null>;ruridomn=<null>;ruriport=<null>;ruriproto=<null>;Acontact=<sip:556139659184@200.170.210.226>;Aiporigem=200.170.210.226;Aportorigem=5090;Aipinterf=192.168.200.246;Aportinterf=5090;Afromdisplay=nheen.net.br;Afromuser=617056557;Afromdomn=nheen.net.br;Atodisplay=<null>;Atouser=556139659184;Atodomn=pabx1;Auagent=Nheen Voip engine (Asterisk PBX Based);Bcontact=<sip:556139659184@200.170.210.226>/reply;Bportorigem=5090/reply;Bipinterf=192.168.200.246/reply;Bportinterf=5090/reply;Bfromdisplay=nheen.net.br/reply;Bfromuser=617056557/reply;Bfromdomn=nheen.net.br/reply;Btodisplay=<null>/reply;Btouser=556139659184/reply;Btodomn=pabx1/reply;Buagent=Nheen Voip engine (Asterisk PBX Based)/replyJun 21 02:32:36 [3158] DBG:tm:t_should_relay_response: T_code=100, new_code=183
Jun 21 02:32:36 [3158] DBG:tm:relay_reply: branch=1, save=0, relay=1
Jun 21 02:32:36 [3158] DBG:core:build_res_buf_from_sip_res:  old size: 1085, new size: 1025
Jun 21 02:32:36 [3158] DBG:core:build_res_buf_from_sip_res: copied size: orig:461, new: 401, rest: 624 msg=
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 192.168.200.243:5060;received=192.168.200.243;branch=z9hG4bK2233e439;rport=5060
Record-Route: <sip:200.170.210.226:5090;ftag=as13631b36;lr=on>
Record-Route: <sip:192.168.200.246:5090;lr=on;ftag=as13631b36;vsf=AAAAAEJDWF5WWQd1RyEMEFRlbi5uZXQuYnI->
From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
To: <sip:556139659184@pabx1:5090>;tag=as7705788f
Call-ID: 5416a1206742cb8a6b157c21352ab0e0@pabx1
CSeq: 102 INVITE
User-Agent: Nheen Voip engine (Asterisk PBX Based)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Contact: <sip:556139659184@200.170.210.226>
Content-Type: application/sdp
Content-Length: 267

v=0
o=root 3430 3430 IN IP4 200.170.210.226
s=session
c=IN IP4 200.170.210.226
t=0 0
m=audio 18562 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

Jun 21 02:32:36 [3158] DBG:tm:relay_reply: sent buf=0x78b910: SIP/2.0 1..., shmem=0x2afe45eae078: SIP/2.0 1
Jun 21 02:32:36 [3158] DBG:tm:run_trans_callbacks: trans=0x2afe45ea9150, callback type 256, id 0 entered
Jun 21 02:32:36 [3158] DBG:tm:set_timer: relative timeout is 120
Jun 21 02:32:36 [3158] DBG:tm:insert_timer_unsafe: [1]: 0x2afe45ea9560 (128)
Jun 21 02:32:36 [3158] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 21 02:32:36 [3158] DBG:core:destroy_avp_list: destroying list (nil)
Jun 21 02:32:36 [3158] DBG:core:receive_msg: cleaning up
Jun 21 02:32:51 [3171] DBG:core:parse_msg: SIP Request:
Jun 21 02:32:51 [3171] DBG:core:parse_msg:  method:  <CANCEL>
Jun 21 02:32:51 [3171] DBG:core:parse_msg:  uri:     <sip:556139659184@pabx1:5090>
Jun 21 02:32:51 [3171] DBG:core:parse_msg:  version: <SIP/2.0>
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=2
Jun 21 02:32:51 [3171] DBG:core:parse_via_param: found param type 232, <branch> = <z9hG4bK2233e439>; state=6
Jun 21 02:32:51 [3171] DBG:core:parse_via_param: found param type 235, <rport> = <n/a>; state=17
Jun 21 02:32:51 [3171] DBG:core:parse_via: end of header reached, state=5
Jun 21 02:32:51 [3171] DBG:core:parse_headers: via found, flags=2
Jun 21 02:32:51 [3171] DBG:core:parse_headers: this is the first via
Jun 21 02:32:51 [3171] DBG:core:receive_msg: After parse_msg...
Jun 21 02:32:51 [3171] DBG:core:receive_msg: preparing to run routing scripts...
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=100
Jun 21 02:32:51 [3171] DBG:core:parse_to: end of header reached, state=10
Jun 21 02:32:51 [3171] DBG:core:parse_to: display={}, ruri={sip:556139659184@pabx1:5090}
Jun 21 02:32:51 [3171] DBG:core:get_hdr_field: <To> [31]; uri=[sip:556139659184@pabx1:5090] 
Jun 21 02:32:51 [3171] DBG:core:get_hdr_field: to body [<sip:556139659184@pabx1:5090>
]
Jun 21 02:32:51 [3171] DBG:core:get_hdr_field: cseq <CSeq>: <102> <CANCEL>
Jun 21 02:32:51 [3171] DBG:maxfwd:is_maxfwd_present: value = 70 
Jun 21 02:32:51 [3171] DBG:uri:has_totag: no totag
Processando CANCELJun 21 02:32:51 [3171] DBG:core:parse_headers: flags=78
Jun 21 02:32:51 [3171] DBG:tm:t_lookupOriginalT: searching on hash entry 19206
Jun 21 02:32:51 [3171] DBG:tm:matching_3261: RFC3261 transaction matched, tid=2233e439
Jun 21 02:32:51 [3171] DBG:tm:t_lookupOriginalT: canceled transaction found (0x2afe45ea9150)! 
Jun 21 02:32:51 [3171] DBG:tm:t_lookupOriginalT: REF_UNSAFE: after is 1
Jun 21 02:32:51 [3171] DBG:tm:t_lookupOriginalT: t_lookupOriginalT completed
Jun 21 02:32:51 [3171] DBG:tm:t_newtran: transaction on entrance=0xffffffffffffffff
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:51 [3171] DBG:core:get_hdr_field: content_length=0
Jun 21 02:32:51 [3171] DBG:core:get_hdr_field: found end of header
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=78
Jun 21 02:32:51 [3171] DBG:tm:t_lookup_request: start searching: hash=19206, isACK=0
Jun 21 02:32:51 [3171] DBG:tm:matching_3261: RFC3261 transaction matching failed
Jun 21 02:32:51 [3171] DBG:tm:t_lookup_request: no transaction found
Jun 21 02:32:51 [3171] DBG:tm:run_reqin_callbacks: trans=0x2afe45eae530, callback type 1, id 0 entered
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=78
Jun 21 02:32:51 [3171] DBG:core:parse_to_param: tag=as13631b36
Jun 21 02:32:51 [3171] DBG:core:parse_to: end of header reached, state=29
Jun 21 02:32:51 [3171] DBG:core:parse_to: display={"tronco2"}, ruri={sip:tronco2@pabx1}
Jun 21 02:32:51 [3171] DBG:rr:is_direction: param ftag not found
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:51 [3171] DBG:core:check_via_address: params 192.168.200.243, 192.168.200.243, 0
Jun 21 02:32:51 [3171] DBG:core:_shm_resize: resize(0) called
Jun 21 02:32:51 [3171] DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Jun 21 02:32:51 [3171] DBG:tm:insert_timer_unsafe: [2]: 0x2afe45eae5b0 (28)
Jun 21 02:32:51 [3171] DBG:tm:_reply_light: reply sent out. buf=0x78d5c0: SIP/2.0 2..., shmem=0x2afe45eb0a98: SIP/2.0 2
Jun 21 02:32:51 [3171] DBG:tm:run_trans_callbacks: trans=0x2afe45eae530, callback type 256, id 0 entered
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=ffffffffffffffff
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=80
Jun 21 02:32:51 [3171] DBG:core:pv_get_contact: no contact header!
Jun 21 02:32:51 [3171] DBG:core:pv_get_xto_attr: no Display name
ACC: transaction answered: timestamp=1245562371;method=CANCEL;from_tag=as13631b36;to_tag=;call_id=5416a1206742cb8a6b157c21352ab0e0@pabx1;code=200;reason=OK;via=SIP/2.0/UDP 192.168.200.243:5060;branch=z9hG4bK2233e439;rport;cseq=102;origruriuser=556139659184;origruridomn=pabx1;origruriport=5090;origruriproto=UDP;ruriuser=556139659184;ruridomn=pabx1;ruriport=5090;ruriproto=UDP;Acontact=;Aiporigem=192.168.200.243;Aportorigem=5060;Aipinterf=192.168.200.246;Aportinterf=5090;Afromdisplay=pabx1;Afromuser=tronco2;Afromdomn=pabx1;Atodisplay=;Atouser=556139659184;Atodomn=pabx1;Auagent=Asterisk PBX;Bcontact=;Bportorigem=;Bipinterf=;Bportinterf=;Bfromdisplay=;Bfromuser=;Bfromdomn=;Btodisplay=;Btouser=;Btodomn=;Buagent=
Jun 21 02:32:51 [3171] DBG:core:parse_headers: flags=80
Jun 21 02:32:51 [3171] DBG:core:pv_get_contact: no contact header!
Jun 21 02:32:51 [3171] DBG:core:pv_get_xto_attr: no Display name
Jun 21 02:32:51 [3171] DBG:db_mysql:has_stmt_ctx: ctx not found for acc
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_do_prepared_query: conn=0x789f00 (tail=7893920) MC=0x7873f8
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_do_prepared_query: discon is 0 for 7893920
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_do_prepared_query: set values for the statement run
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (0): len=6; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (1): len=10; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (2): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (3): len=38; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (4): len=3; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (5): len=2; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (6): len=40; type=12; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (7): len=3; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (8): len=12; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (9): len=5; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (10): len=4; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (11): len=3; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (12): len=12; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (13): len=5; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (14): len=4; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (15): len=3; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (16): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (17): len=15; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (18): len=4; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (19): len=15; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (20): len=4; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (21): len=5; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (22): len=7; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (23): len=5; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (24): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (25): len=12; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (26): len=5; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (27): len=12; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (28): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (29): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (30): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (31): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (32): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (33): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (34): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (35): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (36): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (37): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (38): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_val2bind: added val (39): len=0; type=254; is_null=0
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_do_prepared_query: doing BIND_PARAM in...
Jun 21 02:32:51 [3171] DBG:db_mysql:db_mysql_do_prepared_query: discon reset for 7893920
Jun 21 02:32:51 [3171] DBG:tm:_reply_light: finished
Jun 21 02:32:51 [3171] DBG:tm:build_local: using FROM=<From: "tronco2" <sip:tronco2@pabx1>;tag=as13631b36
>, TO=<To: <sip:556139659184@pabx1:5090>
>, CSEQ_N=<CSeq: 102>
Jun 21 02:32:51 [3171] DBG:tm:cancel_branch: sending cancel...
Jun 21 02:32:51 [3171] DBG:tm:set_timer: relative timeout is 500000
Jun 21 02:32:51 [3171] DBG:tm:insert_timer_unsafe: [4]: 0x2afe45ea95f8 (24200000)
Jun 21 02:32:51 [3171] DBG:tm:set_timer: relative timeout is 30
Jun 21 02:32:51 [3171] DBG:tm:insert_timer_unsafe: [0]: 0x2afe45ea9628 (53)
Jun 21 02:32:51 [3171] DBG:tm:t_relay_to: new transaction fwd'ed
Jun 21 02:32:51 [3171] DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 0
Jun 21 02:32:51 [3171] DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Jun 21 02:32:51 [3171] DBG:core:destroy_avp_list: destroying list (nil)
Jun 21 02:32:51 [3171] DBG:core:receive_msg: cleaning up
Jun 21 02:32:52 [3191] DBG:tm:utimer_routine: timer routine:4,tl=0x2afe45ea95f8 next=(nil), timeout=24200000
Jun 21 02:32:52 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:32:52 [3191] DBG:tm:set_timer: relative timeout is 1000000
Jun 21 02:32:52 [3191] DBG:tm:insert_timer_unsafe: [5]: 0x2afe45ea95f8 (25200000)
Jun 21 02:32:52 [3191] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 21 02:32:53 [3191] DBG:tm:utimer_routine: timer routine:5,tl=0x2afe45ea95f8 next=(nil), timeout=25200000
Jun 21 02:32:53 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:32:53 [3191] DBG:tm:set_timer: relative timeout is 2000000
Jun 21 02:32:53 [3191] DBG:tm:insert_timer_unsafe: [6]: 0x2afe45ea95f8 (27200000)
Jun 21 02:32:53 [3191] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 21 02:32:55 [3191] DBG:tm:utimer_routine: timer routine:6,tl=0x2afe45ea95f8 next=(nil), timeout=27200000
Jun 21 02:32:55 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:32:55 [3191] DBG:tm:set_timer: relative timeout is 4000000
Jun 21 02:32:55 [3191] DBG:tm:insert_timer_unsafe: [7]: 0x2afe45ea95f8 (31200000)
Jun 21 02:32:55 [3191] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 21 02:32:56 [3191] DBG:tm:timer_routine: timer routine:2,tl=0x2afe45eae5b0 next=(nil), timeout=28
Jun 21 02:32:56 [3191] DBG:tm:wait_handler: removing 0x2afe45eae530 from table 
Jun 21 02:32:56 [3191] DBG:tm:delete_cell: delete transaction 0x2afe45eae530
Jun 21 02:32:56 [3191] DBG:tm:wait_handler: done
Jun 21 02:32:59 [3191] DBG:tm:utimer_routine: timer routine:7,tl=0x2afe45ea95f8 next=(nil), timeout=31200000
Jun 21 02:32:59 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:32:59 [3191] DBG:tm:set_timer: relative timeout is 4000000
Jun 21 02:32:59 [3191] DBG:tm:insert_timer_unsafe: [7]: 0x2afe45ea95f8 (35200000)
Jun 21 02:32:59 [3191] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 21 02:33:03 [3191] DBG:tm:utimer_routine: timer routine:7,tl=0x2afe45ea95f8 next=(nil), timeout=35200000
Jun 21 02:33:03 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:33:03 [3191] DBG:tm:set_timer: relative timeout is 4000000
Jun 21 02:33:03 [3191] DBG:tm:insert_timer_unsafe: [7]: 0x2afe45ea95f8 (39200000)
Jun 21 02:33:03 [3191] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 21 02:33:05 [3191] DBG:tm:timer_routine: timer routine:0,tl=0x2afe45ea93a0 next=(nil), timeout=37
Jun 21 02:33:07 [3191] DBG:tm:utimer_routine: timer routine:7,tl=0x2afe45ea95f8 next=(nil), timeout=39200000
Jun 21 02:33:07 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:33:07 [3191] DBG:tm:set_timer: relative timeout is 4000000
Jun 21 02:33:07 [3191] DBG:tm:insert_timer_unsafe: [7]: 0x2afe45ea95f8 (43200000)
Jun 21 02:33:07 [3191] DBG:tm:retransmission_handler: retransmission_handler : done
Jun 21 02:33:11 [3191] DBG:tm:utimer_routine: timer routine:7,tl=0x2afe45ea95f8 next=(nil), timeout=43200000
Jun 21 02:33:11 [3191] DBG:tm:retransmission_handler: retransmission_handler : request resending (t=0x2afe45ea9150, CANCEL si ... )
Jun 21 02:33:11 [3191] DBG:tm:set_timer: relative timeout is 4000000
Jun 21 02:33:11 [3191] DBG:tm:insert_timer_unsafe: [7]: 0x2afe45ea95f8 (47200000)
Jun 21 02:33:11 [3191] DBG:tm:retransmission_handler: retransmission_handler : done