TE420 PCI-E x1 Call hangup Help Please

Hi

We have accquired at the company a Digium TE420 Pci-e X1 card to connect on our Asterisk Server, in order to use our E1 R2 line from our Telephony Provider.

We currently have a E1 with 99 Extension numbers supplied by the telephony company.

Ok so first things first i have installed the card and it recognized ok, i have set up the dahdi trunk and all the inbound and outbound routes.

I can receive and make phone calls, but i have an odd isue, after 2 or 3 minutes or even after 1minute call hangup and i get the following error message attached on the log.

Please i kindly need some advise regarding the error as i cannot find any other tips anywhere.

And its not a telephony line problem because we have a PABX old system running on the same Line just fine no call hangups, only issue is the old PABX system cannot make IP hibrid calls neither call recordings, this was one of the reasons why we have decided to upgrade this to Asterisk.


So below is the error message i get on the call hangup.

BTW- I am using a RJ45 cable directly from the PC digium card Interface1 to my FiberOptic ISP provider Modem RJ45 port dedicated for usage of the E1 telephony.
cable is 60cm lenght, with pinouts   Side A 1,2          Side B 4,5



below the output of the log debug




[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: cdr_mysql.c:343 mysql_log: Inserting a CDR record.
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: cdr_mysql.c:346 mysql_log: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`cnum`,`cnam`,`outbound_cnum`,`outbound_cnam`) VALUES ('2017-05-19 09:09:42','\"intelbras\" <4193>','4193','020153939','from-internal','SIP/4193-00000000','DAHDI/1-1','Dial','DAHDI/g0/20153939,300,','168','151','ANSWERED','3','1495195782.0','4193','intelbras','4193','intelbras')
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: channel.c:2843 ast_hangup: Hanging up channel 'SIP/3538-00000001'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(start) result is '2017-05-19 09:09:42'
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_sip.c:6929 sip_hangup: Hangup call SIP/3538-00000001, SIP callid 36e20b207ed6556b3f3978f23136428f@177.85.198.35:5060
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_sip.c:6564 update_call_counter: Updating call counter for outgoing call
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(clid) result is '"intelbras" <4193>'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(dcontext) result is 'from-internal'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(channel) result is 'SIP/4193-00000000'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(dstchannel) result is 'DAHDI/1-1'
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: res_rtp_asterisk.c:4805 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f1bc4032e68'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(lastapp) result is 'Dial'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(lastdata) result is 'DAHDI/g0/20153939,300,'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(duration) result is '168'
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 3538
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(billsec) result is '151'
[2017-05-19 09:12:30] DEBUG[909]: chan_sip.c:30079 sip_devicestate: Checking device state for peer 3538
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(disposition) result is 'ANSWERED'
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:477 do_state_change: Changing state for SIP/3538 - state 1 (Not in use)
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(amaflags) result is 'DOCUMENTATION'
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:452 devstate_event: device 'SIP/3538' state '1'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(accountcode) result is '(null)'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(uniqueid) result is '1495195782.0'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(userfield) result is '(null)'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(test) result is '(null)'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(src) result is '4193'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:4837 pbx_substitute_variables_helper_full: Function CDR(dst) result is '020153939'
[2017-05-19 09:12:30] DEBUG[980]: app_queue.c:1924 handle_statechange: Device 'SIP/3538' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: cdr_sqlite3_custom.c:261 write_cdr: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test,src,dst) VALUES ('2017-05-19 09:09:42','"intelbras" <4193>','from-internal','SIP/4193-00000000','DAHDI/1-1','Dial','DAHDI/g0/20153939,300,','168','151','ANSWERED','DOCUMENTATION','','1495195782.0','','','4193','020153939')
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '177.99.250.245:63141' into...
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '177.99.250.245' and port '63141'.
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_sip.c:3731 __sip_xmit: Trying to put 'BYE sip:412' onto UDP socket destined for 177.99.250.245:63141
[2017-05-19 09:12:30] DEBUG[911]: app_queue.c:2026 extension_state_cb: Extension '3538@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 3538
[2017-05-19 09:12:30] DEBUG[909]: chan_sip.c:30079 sip_devicestate: Checking device state for peer 3538
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/3538-00000001
Variable: RTPAUDIOQOS
Value: ssrc=2063464198;themssrc=873731195;lp=1;rxjitter=0.000000;rxcount=7561;txjitter=0.012451;txcount=7569;rlp=2;rtt=0.002000
Uniqueid: 1495195796.3


[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:477 do_state_change: Changing state for SIP/3538 - state 1 (Not in use)
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:452 devstate_event: device 'SIP/3538' state '1'
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/3538-00000001
Variable: RTPAUDIOQOSJITTER
Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;
Uniqueid: 1495195796.3


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/3538-00000001
Variable: RTPAUDIOQOSLOSS
Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;
Uniqueid: 1495195796.3


[2017-05-19 09:12:30] DEBUG[980]: app_queue.c:1924 handle_statechange: Device 'SIP/3538' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/3538-00000001
Variable: RTPAUDIOQOSRTT
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1495195796.3


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/3538-00000001
Variable: RTPAUDIOQOS
Value: ssrc=2063464198;themssrc=873731195;lp=1;rxjitter=0.000000;rxcount=7561;txjitter=0.012451;txcount=7569;rlp=2;rtt=0.002000
Uniqueid: 1495195796.3


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: ExtensionStatus
Privilege: call,all
Exten: 3538
Context: ext-local
Hint: SIP/3538,CustomPresence:3538
Status: 0


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: Hangup
Privilege: call,all
Channel: SIP/3538-00000001
Uniqueid: 1495195796.3
CallerIDNum: 3538
CallerIDName: LG2
ConnectedLineNum: 1120153939
ConnectedLineName: 1120153939
AccountCode:
Cause: 16
Cause-txt: Normal Clearing


[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: app_dial.c:3120 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: DIALSTATUS
Value: ANSWER
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: app_macro.c:449 _macro_exec: Spawn extension (macro-dial-one,s,43) exited non-zero on 'DAHDI/7-1' in macro 'dial-one'
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: Dial
Privilege: call,all
SubEvent: End
Channel: DAHDI/7-1
UniqueID: 1495195796.2
DialStatus: ANSWER


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: MACRO_DEPTH
Value: 1
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: ARG1
Value: novm
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: ARG2
Value: 3538
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: app_macro.c:449 _macro_exec: Spawn extension (macro-exten-vm,s,9) exited non-zero on 'DAHDI/7-1' in macro 'exten-vm'
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: pbx.c:6789 __ast_pbx_run: Spawn extension (from-did-direct,3538,2) exited non-zero on 'DAHDI/7-1'
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: channel.c:2664 ast_softhangup_nolock: Soft-Hanging up channel 'DAHDI/7-1'
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: channel.c:2843 ast_hangup: Hanging up channel 'DAHDI/7-1'
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:6659 dahdi_hangup: dahdi_hangup(DAHDI/7-1)
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:6863 dahdi_hangup: Hangup: channel: 7 index = 0, normal = 18, callwait = -1, thirdcall = -1
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:6989 dahdi_hangup: disconnecting MFC/R2 call on chan 7
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 7 - Call ended
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 7 - CAS Tx >> [IDLE] 0x08
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 7 - CAS Raw Tx >> 0x09
MFC/R2 call end on channel 7
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:5414 dahdi_disable_ec: Disabled echo cancellation on channel 7
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:7309 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/7-1
[2017-05-19 09:12:30] DEBUG[1213][C-00000002]: chan_dahdi.c:5326 update_conf: Updated conferencing on 7, with 0 conference users
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for DAHDI - 7
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:477 do_state_change: Changing state for DAHDI/7 - state 0 (Unknown)
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:452 devstate_event: device 'DAHDI/7' state '0'
[2017-05-19 09:12:30] DEBUG[980]: app_queue.c:1924 handle_statechange: Device 'DAHDI/7' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: ARG3
Value: 0
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: MACRO_EXTEN
Value: 3538
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: MACRO_CONTEXT
Value: from-did-direct
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: MACRO_PRIORITY
Value: 2
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: DAHDI/7-1
Variable: MACRO_DEPTH
Value: 0
Uniqueid: 1495195796.2


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: DAHDI/7-1
Uniqueid: 1495195796.2
Cause: 16


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: Hangup
Privilege: call,all
Channel: DAHDI/7-1
Uniqueid: 1495195796.2
CallerIDNum: 1120153939
CallerIDName: 1120153939
ConnectedLineNum: 4100
ConnectedLineName: DDR-OI-IN
AccountCode:
Cause: 16
Cause-txt: Normal Clearing


[2017-05-19 09:12:30] DEBUG[919]: chan_sip.c:9076 find_call: = Looking for  Call ID: 36e20b207ed6556b3f3978f23136428f@177.85.198.35:5060 (Checking To) --From tag as78802ce2 --To-tag 29336d3d
[2017-05-19 09:12:30] DEBUG[919][C-00000002]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '36e20b207ed6556b3f3978f23136428f@177.85.198.35:5060' of Request 103: Match Found
[2017-05-19 09:12:30] DEBUG[919]: chan_sip.c:6379 sip_pvt_dtor: Destroying SIP dialog 36e20b207ed6556b3f3978f23136428f@177.85.198.35:5060
[2017-05-19 09:12:30] DEBUG[919]: rtp_engine.c:232 instance_destructor: Destroyed RTP instance '0x7f1bc4032e68'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: channel.c:2843 ast_hangup: Hanging up channel 'DAHDI/1-1'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:6659 dahdi_hangup: dahdi_hangup(DAHDI/1-1)
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:6863 dahdi_hangup: Hangup: channel: 1 index = 0, normal = 12, callwait = -1, thirdcall = -1
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:6989 dahdi_hangup: disconnecting MFC/R2 call on chan 1
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:6623 dahdi_ast_cause_to_r2_cause: ast cause 16 resulted in openr2 cause 6/Normal Clearing
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - CAS Tx >> [CLEAR FORWARD] 0x08
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - CAS Raw Tx >> 0x09
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:5414 dahdi_disable_ec: Disabled echo cancellation on channel 1
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:7309 dahdi_setoption: Set option TDD MODE, value: OFF(0) on DAHDI/1-1
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_dahdi.c:5326 update_conf: Updated conferencing on 1, with 0 conference users
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for DAHDI - 1
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: Hangup
Privilege: call,all
Channel: DAHDI/1-1
Uniqueid: 1495195782.1
CallerIDNum: 020153939
CallerIDName: CID:4193
ConnectedLineNum: 4193
ConnectedLineName: intelbras
AccountCode:
Cause: 16
Cause-txt: Normal Clearing


[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:477 do_state_change: Changing state for DAHDI/1 - state 0 (Unknown)
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:452 devstate_event: device 'DAHDI/1' state '0'
[2017-05-19 09:12:30] DEBUG[980]: app_queue.c:1924 handle_statechange: Device 'DAHDI/1' changed to state '0' (Unknown) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: app_dial.c:3120 dial_exec_full: Exiting with DIALSTATUS=ANSWER.
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: DIALSTATUS
Value: ANSWER
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: app_macro.c:449 _macro_exec: Spawn extension (macro-dialout-trunk,s,22) exited non-zero on 'SIP/4193-00000000' in macro 'dialout-trunk'
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: Dial
Privilege: call,all
SubEvent: End
Channel: SIP/4193-00000000
UniqueID: 1495195782.0
DialStatus: ANSWER


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: MACRO_DEPTH
Value: 0
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: pbx.c:6789 __ast_pbx_run: Spawn extension (from-internal,020153939,6) exited non-zero on 'SIP/4193-00000000'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: channel.c:2664 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/4193-00000000'
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: SoftHangupRequest
Privilege: call,all
Channel: SIP/4193-00000000
Uniqueid: 1495195782.0
Cause: 16


[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: channel.c:2843 ast_hangup: Hanging up channel 'SIP/4193-00000000'
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_sip.c:6929 sip_hangup: Hangup call SIP/4193-00000000, SIP callid 3840729022@172.25.0.137
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_sip.c:6564 update_call_counter: Updating call counter for incoming call
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 4193
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: res_rtp_asterisk.c:4805 ast_rtp_remote_address_set: Setting RTCP address on RTP instance '0x7f1b8003aa68'
[2017-05-19 09:12:30] DEBUG[909]: chan_sip.c:30079 sip_devicestate: Checking device state for peer 4193
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:477 do_state_change: Changing state for SIP/4193 - state 1 (Not in use)
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:452 devstate_event: device 'SIP/4193' state '1'
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: RTPAUDIOQOS
Value: ssrc=1190990024;themssrc=1092193669;lp=1;rxjitter=0.000000;rxcount=7634;txjitter=0.000196;txcount=7674;rlp=3;rtt=0.029000
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: RTPAUDIOQOSJITTER
Value: minrxjitter=0.000000;maxrxjitter=0.000000;avgrxjitter=0.000000;stdevrxjitter=0.000000;reported_minjitter=0.000000;reported_maxjitter=0.000000;reported_avgjitter=0.000000;reported_stdevjitter=0.000000;
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: RTPAUDIOQOSLOSS
Value: minrxlost=0.000000;maxrxlost=0.000000;avgrxlost=0.000000;stdevrxlost=0.000000;reported_minlost=0.000000;reported_maxlost=0.000000;reported_avglost=0.000000;reported_stdevlost=0.000000;
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[980]: app_queue.c:1924 handle_statechange: Device 'SIP/4193' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: ExtensionStatus
Privilege: call,all
Exten: 4193
Context: ext-local
Hint: SIP/4193,CustomPresence:4193
Status: 0


[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: RTPAUDIOQOSRTT
Value: minrtt=0.000000;maxrtt=0.000000;avgrtt=0.000000;stdevrtt=0.000000;
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[911]: app_queue.c:2026 extension_state_cb: Extension '4193@ext-local' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: VarSet
Privilege: dialplan,all
Channel: SIP/4193-00000000
Variable: RTPAUDIOQOS
Value: ssrc=1190990024;themssrc=1092193669;lp=1;rxjitter=0.000000;rxcount=7634;txjitter=0.000196;txcount=7674;rlp=3;rtt=0.029000
Uniqueid: 1495195782.0


[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '177.99.250.245:5062' into...
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '177.99.250.245' and port '5062'.
[2017-05-19 09:12:30] DEBUG[1205][C-00000000]: chan_sip.c:3731 __sip_xmit: Trying to put 'BYE sip:419' onto UDP socket destined for 177.99.250.245:5062
[2017-05-19 09:12:30] DEBUG[983]: manager.c:4879 match_filter: Examining event:
Event: Hangup
Privilege: call,all
Channel: SIP/4193-00000000
Uniqueid: 1495195782.0
CallerIDNum: 4193
CallerIDName: intelbras
ConnectedLineNum: 20153939
ConnectedLineName: CID:4193
AccountCode:
Cause: 16
Cause-txt: Normal Clearing


[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:345 _ast_device_state: No provider found, checking channel drivers for SIP - 4193
[2017-05-19 09:12:30] DEBUG[909]: chan_sip.c:30079 sip_devicestate: Checking device state for peer 4193
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:477 do_state_change: Changing state for SIP/4193 - state 1 (Not in use)
[2017-05-19 09:12:30] DEBUG[909]: devicestate.c:452 devstate_event: device 'SIP/4193' state '1'
[2017-05-19 09:12:30] DEBUG[980]: app_queue.c:1924 handle_statechange: Device 'SIP/4193' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
[2017-05-19 09:12:30] DEBUG[919]: chan_sip.c:9076 find_call: = Looking for  Call ID: 3840729022@172.25.0.137 (Checking To) --From tag as63172d1c --To-tag 914066215
[2017-05-19 09:12:30] DEBUG[919][C-00000000]: chan_sip.c:4429 __sip_ack: Stopping retransmission on '3840729022@172.25.0.137' of Request 102: Match Found
[2017-05-19 09:12:30] DEBUG[919]: chan_sip.c:6379 sip_pvt_dtor: Destroying SIP dialog 3840729022@172.25.0.137
[2017-05-19 09:12:30] DEBUG[919]: rtp_engine.c:232 instance_destructor: Destroyed RTP instance '0x7f1b8003aa68'
[2017-05-19 09:12:30] DEBUG[924]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 2 - Bits changed from 0x00 to 0x08
[2017-05-19 09:12:30] DEBUG[925]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 3 - Bits changed from 0x04 to 0x08
[2017-05-19 09:12:30] DEBUG[924]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 2 - CAS Rx << [CLEAR FORWARD] 0x08
[2017-05-19 09:12:30] DEBUG[925]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 3 - CAS Rx << [IDLE] 0x08
[2017-05-19 09:12:30] NOTICE[925]: chan_dahdi.c:4616 dahdi_r2_on_line_idle: Far end unblocked on chan 3
Chan 2 - Far end disconnected. Reason: Normal Clearing
MFC/R2 call disconnected on channel 2
[2017-05-19 09:12:30] DEBUG[924]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 2 - Call ended
[2017-05-19 09:12:30] DEBUG[924]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 2 - CAS Tx >> [IDLE] 0x08
[2017-05-19 09:12:30] DEBUG[924]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 2 - CAS Raw Tx >> 0x09
MFC/R2 call end on channel 2
[2017-05-19 09:12:30] DEBUG[931]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 9 - Bits changed from 0x00 to 0x08
[2017-05-19 09:12:30] DEBUG[931]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 9 - CAS Rx << [CLEAR FORWARD] 0x08
Chan 9 - Far end disconnected. Reason: Normal Clearing
MFC/R2 call disconnected on channel 9
[2017-05-19 09:12:30] DEBUG[931]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 9 - Call ended
[2017-05-19 09:12:30] DEBUG[931]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 9 - CAS Tx >> [IDLE] 0x08
[2017-05-19 09:12:30] DEBUG[931]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 9 - CAS Raw Tx >> 0x09
MFC/R2 call end on channel 9
[2017-05-19 09:12:30] DEBUG[923]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - Bits changed from 0x08 to 0x04
[2017-05-19 09:12:30] DEBUG[923]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - CAS Rx << [0x04] 0x04
[2017-05-19 09:12:30] ERROR[923]: chan_dahdi.c:4585 dahdi_r2_write_log: Chan 1 - Protocol error. Reason = Invalid CAS, R2 State = Clear Forward Transmitted, MF state = MF Engine Off, MF Group = Forward Group II, CAS = 0x04
DNIS = 20153939, ANI = 4193, MF = 0x20
[2017-05-19 09:12:30] DEBUG[923]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - CAS Tx >> [IDLE] 0x08
[2017-05-19 09:12:30] DEBUG[923]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - CAS Raw Tx >> 0x09
[2017-05-19 09:12:30] ERROR[923]: chan_dahdi.c:4345 dahdi_r2_on_protocol_error: MFC/R2 protocol error on chan 1: Invalid CAS
[2017-05-19 09:12:30] DEBUG[923]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - Bits changed from 0x04 to 0x08
[2017-05-19 09:12:30] DEBUG[923]: chan_dahdi.c:4592 dahdi_r2_write_log: Chan 1 - CAS Rx << [IDLE] 0x08
[2017-05-19 09:12:30] NOTICE[923]: chan_dahdi.c:4616 dahdi_r2_on_line_idle: Far end unblocked on chan 1
[2017-05-19 09:12:37] DEBUG[919]: chan_sip.c:4285 __sip_autodestruct: Auto destroying SIP dialog 'TM8DR9wSGABIKfte9pd4nQ..'
[2017-05-19 09:12:37] DEBUG[919]: chan_sip.c:6379 sip_pvt_dtor: Destroying SIP dialog TM8DR9wSGABIKfte9pd4nQ..




Please any help will be appreciated.

Kind regards
Infobarra