[asterisk-r2] Problems with an Asterisk PBX connected with a NEC PBX via E1-R2

Oscar Rocha orochamty at hotmail.com
Thu Jul 4 12:52:03 CDT 2013 

Hi, 

Attach the call log file, not attached in previous mail, my mistake.


 I found in internet a similar error posted in 2008 in asterisk-r2 forum
 but not have any solution for this problem, this is the link:

http://web.archiveorange.com/archive/v/MvSDXH27p4PVICQ9kfeU

I put the content for file, the list send to me an error when attach files.

[17:51:50:796] [Thread: 3073014672] [Chan 5] - Call started at Wed Jun 26 17:51:50 2013 on chan 5 [openr2 version 1.3.1, revision exported]
[17:51:50:796] [Thread: 3073014672] [Chan 5] - Initialized R2 MF detector
[17:51:50:796] [Thread: 3073014672] [Chan 5] - CAS Tx >> [SEIZE ACK] 0x0C
[17:51:50:796] [Thread: 3073014672] [Chan 5] - CAS Raw Tx >> 0x0D
[17:51:51:487] [Thread: 3073014672] [Chan 5] - MF Rx << 0 [ON]
[17:51:51:487] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 0
[17:51:51:487] [Thread: 3073014672] [Chan 5] - Cannot cancel timer 0
[17:51:51:487] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 0
[17:51:51:487] [Thread: 3073014672] [Chan 5] - DNIS so far: 0, expected length: 13
[17:51:51:487] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:51:487] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:51:487] [Thread: 3073014672] [Chan 5] - scheduled timer id 2 (mf_back_cycle)
[17:51:51:587] [Thread: 3073014672] [Chan 5] - MF Rx << 0 [OFF]
[17:51:51:587] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:51:687] [Thread: 3073014672] [Chan 5] - MF Rx << 1 [ON]
[17:51:51:687] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 2
[17:51:51:687] [Thread: 3073014672] [Chan 5] - timer id 2 found, cancelling it now
[17:51:51:687] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 1
[17:51:51:687] [Thread: 3073014672] [Chan 5] - DNIS so far: 01, expected length: 13
[17:51:51:687] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:51:687] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:51:687] [Thread: 3073014672] [Chan 5] - scheduled timer id 3 (mf_back_cycle)
[17:51:51:767] [Thread: 3073014672] [Chan 5] - MF Rx << 1 [OFF]
[17:51:51:767] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:51:867] [Thread: 3073014672] [Chan 5] - MF Rx << 7 [ON]
[17:51:51:867] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 3
[17:51:51:867] [Thread: 3073014672] [Chan 5] - timer id 3 found, cancelling it now
[17:51:51:867] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 7
[17:51:51:867] [Thread: 3073014672] [Chan 5] - DNIS so far: 017, expected length: 13
[17:51:51:867] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:51:867] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:51:867] [Thread: 3073014672] [Chan 5] - scheduled timer id 4 (mf_back_cycle)
[17:51:51:947] [Thread: 3073014672] [Chan 5] - MF Rx << 7 [OFF]
[17:51:51:947] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:52:047] [Thread: 3073014672] [Chan 5] - MF Rx << 7 [ON]
[17:51:52:047] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 4
[17:51:52:047] [Thread: 3073014672] [Chan 5] - timer id 4 found, cancelling it now
[17:51:52:047] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 7
[17:51:52:047] [Thread: 3073014672] [Chan 5] - DNIS so far: 0177, expected length: 13
[17:51:52:047] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:52:047] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:52:047] [Thread: 3073014672] [Chan 5] - scheduled timer id 5 (mf_back_cycle)
[17:51:52:147] [Thread: 3073014672] [Chan 5] - MF Rx << 7 [OFF]
[17:51:52:147] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:52:247] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [ON]
[17:51:52:247] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 5
[17:51:52:247] [Thread: 3073014672] [Chan 5] - timer id 5 found, cancelling it now
[17:51:52:247] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 9
[17:51:52:247] [Thread: 3073014672] [Chan 5] - DNIS so far: 01779, expected length: 13
[17:51:52:247] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:52:247] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:52:247] [Thread: 3073014672] [Chan 5] - scheduled timer id 6 (mf_back_cycle)
[17:51:52:327] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [OFF]
[17:51:52:327] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:52:427] [Thread: 3073014672] [Chan 5] - MF Rx << 7 [ON]
[17:51:52:427] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 6
[17:51:52:427] [Thread: 3073014672] [Chan 5] - timer id 6 found, cancelling it now
[17:51:52:427] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 7
[17:51:52:427] [Thread: 3073014672] [Chan 5] - DNIS so far: 017797, expected length: 13
[17:51:52:427] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:52:427] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:52:427] [Thread: 3073014672] [Chan 5] - scheduled timer id 7 (mf_back_cycle)
[17:51:52:527] [Thread: 3073014672] [Chan 5] - MF Rx << 7 [OFF]
[17:51:52:527] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:52:627] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [ON]
[17:51:52:627] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 7
[17:51:52:627] [Thread: 3073014672] [Chan 5] - timer id 7 found, cancelling it now
[17:51:52:627] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 9
[17:51:52:627] [Thread: 3073014672] [Chan 5] - DNIS so far: 0177979, expected length: 13
[17:51:52:627] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:52:627] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:52:627] [Thread: 3073014672] [Chan 5] - scheduled timer id 8 (mf_back_cycle)
[17:51:52:707] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [OFF]
[17:51:52:707] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:52:807] [Thread: 3073014672] [Chan 5] - MF Rx << 6 [ON]
[17:51:52:807] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 8
[17:51:52:807] [Thread: 3073014672] [Chan 5] - timer id 8 found, cancelling it now
[17:51:52:807] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 6
[17:51:52:807] [Thread: 3073014672] [Chan 5] - DNIS so far: 01779796, expected length: 13
[17:51:52:807] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:52:807] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:52:807] [Thread: 3073014672] [Chan 5] - scheduled timer id 9 (mf_back_cycle)
[17:51:52:887] [Thread: 3073014672] [Chan 5] - MF Rx << 6 [OFF]
[17:51:52:887] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:52:967] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [ON]
[17:51:52:967] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 9
[17:51:52:967] [Thread: 3073014672] [Chan 5] - timer id 9 found, cancelling it now
[17:51:52:967] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 9
[17:51:52:967] [Thread: 3073014672] [Chan 5] - DNIS so far: 017797969, expected length: 13
[17:51:52:967] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:52:967] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:52:967] [Thread: 3073014672] [Chan 5] - scheduled timer id 10 (mf_back_cycle)
[17:51:52:987] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [OFF]
[17:51:52:987] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:53:007] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [ON]
[17:51:53:007] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 10
[17:51:53:007] [Thread: 3073014672] [Chan 5] - timer id 10 found, cancelling it now
[17:51:53:007] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 9
[17:51:53:007] [Thread: 3073014672] [Chan 5] - DNIS so far: 0177979699, expected length: 13
[17:51:53:007] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:53:007] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:53:007] [Thread: 3073014672] [Chan 5] - scheduled timer id 11 (mf_back_cycle)
[17:51:53:087] [Thread: 3073014672] [Chan 5] - MF Rx << 9 [OFF]
[17:51:53:087] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:53:187] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [ON]
[17:51:53:187] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 11
[17:51:53:187] [Thread: 3073014672] [Chan 5] - timer id 11 found, cancelling it now
[17:51:53:187] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 2
[17:51:53:187] [Thread: 3073014672] [Chan 5] - DNIS so far: 01779796992, expected length: 13
[17:51:53:187] [Thread: 3073014672] [Chan 5] - Requesting next DNIS with signal 0x31.
[17:51:53:187] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:53:187] [Thread: 3073014672] [Chan 5] - scheduled timer id 12 (mf_back_cycle)
[17:51:53:247] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [OFF]
[17:51:53:247] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:53:347] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [ON]
[17:51:53:347] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 12
[17:51:53:347] [Thread: 3073014672] [Chan 5] - timer id 12 found, cancelling it now
[17:51:53:347] [Thread: 3073014672] [Chan 5] - Getting DNIS digit 2
[17:51:53:347] [Thread: 3073014672] [Chan 5] - DNIS so far: 017797969922, expected length: 13
[17:51:53:347] [Thread: 3073014672] [Chan 5] - User requested us to stop getting DNIS!
[17:51:53:347] [Thread: 3073014672] [Chan 5] - MF Tx >> 6 [ON]
[17:51:53:347] [Thread: 3073014672] [Chan 5] - scheduled timer id 13 (mf_back_cycle)
[17:51:53:427] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [OFF]
[17:51:53:427] [Thread: 3073014672] [Chan 5] - MF Tx >> 6 [OFF]
[17:51:53:527] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [ON]
[17:51:53:527] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 13
[17:51:53:527] [Thread: 3073014672] [Chan 5] - timer id 13 found, cancelling it now
[17:51:53:527] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:53:527] [Thread: 3073014672] [Chan 5] - scheduled timer id 14 (mf_back_cycle)
[17:51:53:627] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [OFF]
[17:51:53:627] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:53:747] [Thread: 3073014672] [Chan 5] - MF Rx << F [ON]
[17:51:53:747] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 14
[17:51:53:747] [Thread: 3073014672] [Chan 5] - timer id 14 found, cancelling it now
[17:51:53:747] [Thread: 3073014672] [Chan 5] - Got end of ANI
[17:51:53:747] [Thread: 3073014672] [Chan 5] - Requesting change to Group II with signal 0x33
[17:51:53:747] [Thread: 3073014672] [Chan 5] - MF Tx >> 3 [ON]
[17:51:53:747] [Thread: 3073014672] [Chan 5] - scheduled timer id 15 (mf_back_cycle)
[17:51:53:847] [Thread: 3073014672] [Chan 5] - MF Rx << F [OFF]
[17:51:53:847] [Thread: 3073014672] [Chan 5] - MF Tx >> 3 [OFF]
[17:51:53:947] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [ON]
[17:51:53:947] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 15
[17:51:53:947] [Thread: 3073014672] [Chan 5] - timer id 15 found, cancelling it now
[17:51:53:947] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [ON]
[17:51:53:947] [Thread: 3073014672] [Chan 5] - scheduled timer id 16 (mf_back_cycle)
[17:51:54:047] [Thread: 3073014672] [Chan 5] - MF Rx << 2 [OFF]
[17:51:54:047] [Thread: 3073014672] [Chan 5] - MF Tx >> 1 [OFF]
[17:51:54:047] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 16
[17:51:54:047] [Thread: 3073014672] [Chan 5] - timer id 16 found, cancelling it now
[17:51:54:047] [Thread: 3073014672] [Chan 5] - scheduled timer id 17 (r2_answer_delay)
[17:51:54:207] [Thread: 3073014672] [Chan 5] - Attempting to cancel timer timer 17
[17:51:54:207] [Thread: 3073014672] [Chan 5] - timer id 17 found, cancelling it now
[17:51:54:207] [Thread: 3073014672] [Chan 5] - calling timer 17 (r2_answer_delay) callback
[17:52:04:222] [Thread: 3068345232] [Chan 5] - CAS Tx >> [ANSWER] 0x04
[17:52:04:222] [Thread: 3068345232] [Chan 5] - CAS Raw Tx >> 0x05
[17:52:22:731] [Thread: 3068345232] [Chan 5] - Bits changed from 0x00 to 0x08
[17:52:22:731] [Thread: 3068345232] [Chan 5] - CAS Rx << [CLEAR FORWARD] 0x08
[17:52:22:731] [Thread: 3068345232] [Chan 5] - Far end disconnected. Reason: Normal Clearing
[17:52:22:750] [Thread: 3068345232] [Chan 5] - Call ended
[17:52:22:750] [Thread: 3068345232] [Chan 5] - Attempting to cancel timer timer 0
[17:52:22:750] [Thread: 3068345232] [Chan 5] - Cannot cancel timer 0

Oscar Rocha.





From: orochamty at hotmail.com
To: asterisk-r2 at lists.digium.com
Date: Thu, 4 Jul 2013 11:49:58 -0500
Subject: Re: [asterisk-r2] Problems with an Asterisk PBX connected with a NEC PBX via E1-R2




Hi Melcon, thanks for your reply. As you say, apparently everything is fine, the PBX NEC seems send the repeated digit but I saw that the user dials the number correctly (from NEC) and the NEC not send repeated digits to Xorcom (I saw in protocol analizer), just "delay" to respond when Xorcom sends "1" and then Xorcom "gets" the previous digit, the question is: from where did it get? Or why "decide" to take the previous  digit received when not receives a response (ACK) from NEC?

For example, in this call, Xorcom receive 9
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Rx << 9 [ON]
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - Getting DNIS digit 9
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - DNIS so far: 017797969, expected length: 13

Then sends tone 1 requesting next DNIS
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - Requesting next DNIS with signal 0x31.
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Tx >> 1 [ON]

NEC receives tone 1 and sends tone 9 (stop)
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Rx << 9 [OFF]

Xorcom stops to send tone 1
[Jun 26 17:51:52] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Tx >> 1 [OFF]

NEC sends tone 9 (repeated), but really not sends this tone, in previous step (saw in protocol analizer) Xorcom not receives a response from NEC, then appears as if Xorcom receives tone 9, but really did not send by NEC
[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Rx << 9 [ON]

[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - Getting DNIS digit 9
[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - DNIS so far: 0177979699, expected length: 13
[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - Requesting next DNIS with signal 0x31.
[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Tx >> 1 [ON]
[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Rx << 9 [OFF]
[Jun 26 17:51:53] DEBUG[25685]: chan_dahdi.c:4109 dahdi_r2_write_log: Chan 5 - MF Tx >> 1 [OFF]

Attach the call log, I don´t have the output from the protocol analyzer,
 I´ll try make some tests and "copy" that the protocol analyzer show.

Oscar Rocha.


From: melcon at gmail.com
Date: Wed, 3 Jul 2013 08:00:36 -0300
To: asterisk-r2 at lists.digium.com
Subject: Re: [asterisk-r2] Problems with an Asterisk PBX connected with a NEC PBX via E1-R2

How can you tell about the slow ACK? From the console you paste it, it all seems normal to me and I find very odd that the OpenR2 would repeat a digit at will.


Can you provide the call file for this call? According to the logs and config, it should be in /var/log/asterisk/mfcr2/span1 and has a name similar to chan-5-backward-111-20130626175150.call


Also, can you provide the output from the protocol analyzer for the very same call? I would like to see how the analyzer is reading those signals.



-MM




--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

asterisk-r2 mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-r2 		 	   		  

--
_____________________________________________________________________
-- Bandwidth and Colocation Provided by http://www.api-digital.com --

asterisk-r2 mailing list
To UNSUBSCRIBE or update options visit:
   http://lists.digium.com/mailman/listinfo/asterisk-r2 		 	   		  
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-r2/attachments/20130704/2d2a1c6a/attachment-0001.htm>

More information about the asterisk-r2 mailing list