[asterisk-users] Asterisk ZAP/DAHDI reads phantom digit on overlap PRI
Vieri
rentorbuy at yahoo.com
Mon Dec 14 14:26:28 CST 2009
--- On Mon, 12/14/09, Tzafrir Cohen <tzafrir.cohen at xorcom.com> wrote:
> On Mon, Dec 14, 2009 at 05:32:21AM
> -0800, Vieri wrote:
> > Hi,
> >
> > I've noticed that a small but meaningful quota of
> calls from my Alcatel PBX to Asterisk are failing.
> >
> > This does not always happen and it is not easily
> reproducible but on high traffic I do get a large number of
> cases.
> >
> > Example: Alcatel PBX extension 7085 calls Asterisk PBX
> extension 6145 over a PRI E1 link.
> >
> > I see this in the Asterisk log:
> >
> > Dec 14 14:10:31 VERBOSE[11378] logger.c:
> -- Accepting overlap call from '7085' to
> '6145' on channel 1/31, span 1
> > Dec 14 14:10:31 VERBOSE[5558] logger.c:
> -- Starting simple switch on 'Zap/31-1'
> > Dec 14 14:10:32 DEBUG[5558] chan_zap.c: DTMF digit: 5
> on Zap/31-1
> > Dec 14 14:10:40 DEBUG[5558] chan_zap.c: No such
> possible extension '61455' in context 'from-alcatel'
> >
> > Obviously, it's failing because Asterisk is trying to
> match destination+extra DTMF digit (ie. 6145+5).
> >
> > However, noone ever dialed that extra digit! So how
> did it get there?
> >
> > I guess I could disable "overlap" in Asterisk but that
> isn't the right way to go.
> >
> > What else can I do (where else can I look) to solve
> this issue?
>
> Please provide trace from 'pri debug' .
OK, I just grabbed a log for an Alcatel PBX extension 6166 calling an Asterisk PBX extension 6158 over a PRI E1 link:
(not omitting any lines, just in case useful info is inadvertantly removed)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Protocol Discriminator: Q.931 (8) len=39
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Call Ref: len= 2 (reference 28696/0x7018) (Originator)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Message type: SETUP (5)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [04 03 80 90 a3]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Bearer Capability (len= 5) [ Ext: 1 Q.931 Std: 0 Info transfer capability: Speech (0)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Ext: 1 Trans mode/rate: 64kbps, circuit-mode (16)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < User information layer 1: A-Law (35)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [18 03 a9 83 8e]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Channel ID (len= 5) [ Ext: 1 IntID: Implicit, PRI Spare: 0, Exclusive Dchan: 0
Dec 14 20:15:53 VERBOSE[11378] logger.c: < ChanSel: As indicated in following octets
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Ext: 1 Coding: 0 Number Specified Channel Type: 3
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Ext: 1 Channel: 14 ]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [1e 02 80 83]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Progress Indicator (len= 4) [ Ext: 1 Coding: CCITT (ITU) standard (0) 0: 0 Location: User (0)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Ext: 1 Progress Description: Calling equipment is non-ISDN. (3) ]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [6c 06 00 81 36 31 36 36]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Calling Number (len= 8) [ Ext: 0 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Presentation: Presentation permitted, user number passed network screening (1) '6166' ]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [70 05 80 36 31 35 38]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Called Number (len= 7) [ Ext: 1 TON: Unknown Number Type (0) NPI: Unknown Number Plan (0) '6158' ]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [7d 02 91 81]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < IE: High-layer Compatibility (len = 4)
Dec 14 20:15:53 VERBOSE[11378] logger.c: < [a1]
Dec 14 20:15:53 VERBOSE[11378] logger.c: < Sending Complete (len= 1)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Making new call for cr 28696
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing Q.931 Call Setup
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 4 (cs0, Bearer Capability)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 24 (cs0, Channel Identification)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 30 (cs0, Progress Indicator)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 108 (cs0, Calling Party Number)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 112 (cs0, Called Party Number)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 125 (cs0, High-layer Compatibility)
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Processing IE 161 (cs0, Sending Complete)
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Protocol Discriminator: Q.931 (8) len=11
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Call Ref: len= 2 (reference 28696/0x7018) (Terminator)
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Message type: CALL PROCEEDING (2)
Dec 14 20:15:53 VERBOSE[11378] logger.c: > [18 04 e9 81 83 8e]
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Channel ID (len= 6) [ Ext: 1 IntID: Explicit, PRI Spare: 0, Exclusive Dchan: 0
Dec 14 20:15:53 VERBOSE[11378] logger.c: > ChanSel: As indicated in following octets
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Ext: 1 DS1 Identifier: 1
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Ext: 1 Coding: 0 Number Specified Channel Type: 3
Dec 14 20:15:53 VERBOSE[11378] logger.c: > Ext: 1 Channel: 14 ]
Dec 14 20:15:53 VERBOSE[11378] logger.c: -- Accepting overlap call from '6166' to '6158' on channel 1/14, span 1
Dec 14 20:15:53 VERBOSE[15709] logger.c: -- Starting simple switch on 'Zap/14-1'
Dec 14 20:15:53 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:53 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:53 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:53 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:53 DEBUG[11374] chan_sip.c: Stopping retransmission on '26d6021811f743aa74b1483b4ac462c0 at 10.215.147.111' of Request 102: Match Found
Dec 14 20:15:54 DEBUG[15709] chan_zap.c: DTMF digit: 8 on Zap/14-1
Dec 14 20:15:54 DEBUG[11374] chan_sip.c: Auto destroying call '499086686-54077-1 at 192.168.250.7'
Dec 14 20:15:54 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:54 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:54 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:54 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:54 DEBUG[15728] manager.c: Manager received command 'login'
Dec 14 20:15:54 VERBOSE[15728] logger.c: == Parsing '/etc/asterisk/manager.conf': Dec 14 20:15:54 VERBOSE[15728] logger.c: == Parsing '/etc/asterisk/manager.conf': Found
Dec 14 20:15:54 DEBUG[15728] acl.c: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Dec 14 20:15:54 DEBUG[15728] acl.c: 127.0.0.1/255.255.255.255/255.255.255.255 appended to acl for peer
Dec 14 20:15:54 DEBUG[15728] acl.c: 10.215.147.111/255.255.255.255/255.255.255.255 appended to acl for peer
Dec 14 20:15:54 DEBUG[15728] acl.c: 10.215.147.112/255.255.255.255/255.255.255.255 appended to acl for peer
Dec 14 20:15:54 DEBUG[15728] acl.c: 192.168.250.111/255.255.255.255/255.255.255.255 appended to acl for peer
Dec 14 20:15:54 DEBUG[15728] acl.c: 192.168.250.112/255.255.255.255/255.255.255.255 appended to acl for peer
Dec 14 20:15:54 DEBUG[15728] acl.c: ##### Testing 10.215.147.111 with 0.0.0.0
Dec 14 20:15:54 DEBUG[15728] acl.c: ##### Testing 10.215.147.111 with 127.0.0.1
Dec 14 20:15:54 DEBUG[15728] acl.c: ##### Testing 10.215.147.111 with 10.215.147.111
Dec 14 20:15:54 DEBUG[15728] acl.c: ##### Testing 10.215.147.111 with 10.215.147.112
Dec 14 20:15:54 DEBUG[15728] acl.c: ##### Testing 10.215.147.111 with 192.168.250.111
Dec 14 20:15:54 DEBUG[15728] acl.c: ##### Testing 10.215.147.111 with 192.168.250.112
Dec 14 20:15:54 VERBOSE[15728] logger.c: == Manager 'inftester' logged on from 10.215.147.111
Dec 14 20:15:54 DEBUG[15728] manager.c: Manager received command 'Logoff'
Dec 14 20:15:54 VERBOSE[15728] logger.c: == Manager 'inftester' logged off from 10.215.147.111
Dec 14 20:15:54 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:54 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:54 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:54 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:55 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:55 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:56 DEBUG[11374] chan_sip.c: Auto destroying call '899767513-34417-1 at 192.168.250.32'
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.30 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:56 DEBUG[11374] acl.c: ##### Testing 192.168.250.8 with 0.0.0.0
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Auto destroying call '1171794545-29013-1 at 192.168.250.32'
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Auto destroying call '268115595-23470-1 at 192.168.250.32'
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Auto destroying call '57108573-13315-1 at 192.168.250.32'
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Auto destroying call '2067961949-32610-1 at 192.168.250.32'
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Auto destroying call '1026640341-56087-1 at 192.168.250.32'
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Auto destroying call '1029587739-27554-1 at 192.168.250.32'
Dec 14 20:15:57 DEBUG[11374] chan_sip.c: Stopping retransmission on '055d25fe7a7fd6d268c05966457b0e35 at 10.215.147.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] acl.c: ##### Testing 10.215.146.202 with 0.0.0.0
Dec 14 20:15:58 DEBUG[11374] acl.c: ##### Testing 10.215.146.202 with 0.0.0.0
Dec 14 20:15:58 DEBUG[11374] acl.c: ##### Testing 10.215.146.202 with 0.0.0.0
Dec 14 20:15:58 DEBUG[11374] acl.c: ##### Testing 10.215.146.202 with 0.0.0.0
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '6fc6b5bb25efcb074cc5cd205ebd10ca at 192.168.250.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '563978d273d799f40b17699a5a15fa5f at 192.168.250.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '1209c14465a7e9983ae008002b35de90 at 10.215.147.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '4750cd34753b75746ed4dbbb1044fe2e at 192.168.250.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '2bbe75ff5234b8340baa00b6638ed508 at 10.215.147.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '0627b0ab6ee80a12346318472096d0ff at 10.215.147.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Stopping retransmission on '099a35c745ac60ce6175164f513bcc0a at 10.215.147.111' of Request 102: Match Found
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Auto destroying call '655820725-43243-1 at 192.168.250.33'
Dec 14 20:15:58 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:58 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:58 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:58 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Auto destroying call '1300218108-26745-1 at 192.168.250.33'
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Auto destroying call '1451777419-40210-1 at 192.168.250.33'
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Auto destroying call '130829179-35800-1 at 192.168.250.33'
Dec 14 20:15:58 DEBUG[11374] chan_sip.c: Auto destroying call '302046145-5060-1 at 192.168.250.30'
Dec 14 20:15:59 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:59 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:59 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 0.0.0.0
Dec 14 20:15:59 DEBUG[11375] acl.c: ##### Testing 127.0.0.1 with 127.0.0.1
Dec 14 20:15:59 DEBUG[11374] chan_sip.c: Auto destroying call '1003985022-58132-1 at 192.168.250.33'
Dec 14 20:15:59 DEBUG[11374] chan_sip.c: Auto destroying call '2120692116-34217-1 at 192.168.250.33'
Dec 14 20:15:59 DEBUG[11374] chan_sip.c: Auto destroying call '136564176-5062-1 at 192.168.250.30'
Dec 14 20:15:59 DEBUG[11374] chan_sip.c: Auto destroying call 'DA87E117-A8EF-4A1B-B03E-8F91A5C26E22 at 10.215.144.47'
Dec 14 20:15:59 DEBUG[15293] channel.c: Got DTMF on channel (mISDN/4-1)
Dec 14 20:15:59 DEBUG[15293] channel.c: Bridge stops bridging channels mISDN/4-1 and Zap/3-1
Dec 14 20:15:59 DEBUG[15293] res_features.c: Feature interpret: chan=mISDN/4-1, peer=Zap/3-1, sense=1, features=18
Dec 14 20:16:00 DEBUG[11374] chan_sip.c: Stopping retransmission on '796c12ae04837c495e9976a8235da32e at 192.168.250.111' of Request 102: Match Found
Dec 14 20:16:00 DEBUG[15293] chan_zap.c: Exception on 31, channel 3
Dec 14 20:16:00 DEBUG[15293] chan_zap.c: Got event Dial Complete(9) on channel 3 (index 0)
Dec 14 20:16:00 DEBUG[15293] chan_zap.c: Echo cancellation already on
Dec 14 20:16:00 DEBUG[11374] chan_sip.c: Auto destroying call '189453912-26133-1 at 192.168.250.33'
Dec 14 20:16:00 DEBUG[11374] chan_sip.c: Auto destroying call '958801415-5064-1 at 192.168.250.30'
Dec 14 20:16:00 DEBUG[11374] chan_sip.c: Auto destroying call 'd7a054a090a9d1a9 at 10.215.146.196'
Dec 14 20:16:01 DEBUG[11374] chan_sip.c: Stopping retransmission on '34a4e9b75f811d3a4c4ac61b5ee1b043 at 192.168.250.111' of Request 102: Match Found
Dec 14 20:16:01 DEBUG[11374] chan_sip.c: Stopping retransmission on '7d4a598770048e657b7c853f34e336ce at 10.215.147.111' of Request 102: Match Found
Dec 14 20:16:01 DEBUG[11374] chan_sip.c: Stopping retransmission on '51bc609a061eeeaf701aa9e540ffab22 at 192.168.250.111' of Request 102: Match Found
Dec 14 20:16:01 DEBUG[11374] chan_sip.c: Stopping retransmission on '7691917d5d96e11e0fea7c1764a0c3f9 at 192.168.250.111' of Request 102: Match Found
Dec 14 20:16:01 DEBUG[11374] chan_sip.c: Stopping retransmission on '566729374d92c0491184247b34329977 at 192.168.250.111' of Request 102: Match Found
Dec 14 20:16:02 DEBUG[11374] chan_sip.c: Stopping retransmission on '6abe29ef642a3c9e68adb8e747472f8f at 192.168.250.111' of Request 102: Match Found
Dec 14 20:16:02 DEBUG[15709] chan_zap.c: No such possible extension '61588' in context 'from-alcatel'
Not sure, but I don't see libpri passing the "extra" digit... chan_zap seems to detect it out of the blue. Could it be echo?
Vieri
More information about the asterisk-users
mailing list