[Home]

Summary:ASTERISK-11846: DTMF needed to enter long distance PIN codes not recognized by telco, DTMF duration appears to be 0 ms
Reporter:David Brillert (aragon)Labels:
Date Opened:2008-04-14 13:36:12Date Closed:2008-04-21 11:58:51
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_zap
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) 12440.diff
( 1) messages
Description:We upgraded from Asterisk 1.4.19rc4 to SVN revision 113348 (to fix bug 12296 and bug 12309) but since upgrade we cannot generate DTMF tones to long distance provider.
Call is setting up OK but we try to pass tones to make long distance calls. Tone generation appears to be 0 ms to telco and we cannot complete any long distance calls because the PIN's are rejected

Trunk is PRI NI2

****** ADDITIONAL INFORMATION ******

Zaptel 1.4.9

zapata.conf

[channels]
jbenable                  =  no
language                  =  en
resetinterval             =  never
switchtype                =  national
signalling                =  pri_cpe
pridialplan               =  national
prilocaldialplan          =  national
facilityenable            =  yes
transfer                  =  no
faxdetect                 =  both
relaxdtmf                 =  yes
echocancel                =  128
echocancelwhenbridged     =  yes
overlapdial               =  no
echotraining              =  400
rxgain                    =  0.5
txgain                    =  -1.5
amaflags                  =  default
context                   =  zap-incoming
group                     =  1
channel                   => 01-23
language                  =  en
resetinterval             =  never
switchtype                =  national
signalling                =  pri_cpe
pridialplan               =  national
prilocaldialplan          =  national
facilityenable            =  yes
transfer                  =  no
faxdetect                 =  both
relaxdtmf                 =  yes
echocancel                =  128
echocancelwhenbridged     =  yes
overlapdial               =  no
echotraining              =  400
amaflags                  =  default
context                   =  zap-incoming
group                     =  0
channel                   => 25-47

I believe the strange behavior is caused by 0ms DTMF duration found in DTMF debug logs

[Apr 14 13:26:43] DTMF[25984] channel.c: DTMF end '0' received on Zap/17-1, duration 0 ms
[Apr 14 13:26:43] DTMF[25984] channel.c: DTMF end accepted without begin '0' on Zap/17-1
[Apr 14 13:26:43] DTMF[25984] channel.c: DTMF end passthrough '0' on Zap/17-1
[Apr 14 13:27:42] DTMF[26598] channel.c: DTMF end '3' received on Zap/15-1, duration 0 ms
[Apr 14 13:27:42] DTMF[26598] channel.c: DTMF end accepted without begin '3' on Zap/15-1
[Apr 14 13:27:42] DTMF[26598] channel.c: DTMF end passthrough '3' on Zap/15-1
[Apr 14 13:27:52] DTMF[26598] channel.c: DTMF end '0' received on Zap/15-1, duration 0 ms
[Apr 14 13:27:52] DTMF[26598] channel.c: DTMF end accepted without begin '0' on Zap/15-1
[Apr 14 13:27:52] DTMF[26598] channel.c: DTMF end passthrough '0' on Zap/15-1
[Apr 14 13:27:54] WARNING[25984] file.c: Failed to write frame
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end '2' received on Zap/11-1, duration 0 ms
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end accepted without begin '2' on Zap/11-1
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end passthrough '2' on Zap/11-1
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end '7' received on Zap/11-1, duration 0 ms
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end accepted without begin '7' on Zap/11-1
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end passthrough '7' on Zap/11-1
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end '1' received on Zap/11-1, duration 0 ms
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end accepted without begin '1' on Zap/11-1
[Apr 14 13:27:58] DTMF[26693] channel.c: DTMF end passthrough '1' on Zap/11-1
[Apr 14 13:27:59] DTMF[26693] channel.c: DTMF end '1' received on Zap/11-1, duration 0 ms
[Apr 14 13:27:59] DTMF[26693] channel.c: DTMF end accepted without begin '1' on Zap/11-1
Comments:By: Joshua C. Colp (jcolp) 2008-04-14 15:34:05

We need much more information, such as the complete console output and call flow. What technologies are involved? Is it only Zap to Zap?
By: David Brillert (aragon) 2008-04-14 15:54:40

SIP>ZAP>PRI>TELCO

Could not be simpler.

Caller places call from SIP phone to PRI (Allstream is the carrier)
Carrier invokes PIN codes to track long distance usage
Call fails because the carrier does not recognize the PIN code.
Its definitely a broken revision because I just downgraded the customer to the previous Asterisk release and they are back in service.
I thought a zaptel PRI channel with a 0 ms DTMF duration was a pretty obvious problem.
Its a shame really because I need the other patches for stability...

Anyway there are over 300 phones on this server and I cannot reintroduce the bug to do more testing.

Based on the install dates I think this problem was introduced probably in
Revision 109575 - Directory Listing
Modified Tue Mar 18 17:58:11 2008 UTC (3 weeks, 6 days ago) by mmichelson

Make sure an agent doesn't try to send dtmf to a NULL channel

closes issue ASTERISK-11667
Reported by Yourname
By: David Brillert (aragon) 2008-04-14 21:35:54

I'm attaching a trimmed messages log for a failed call on another active server which failed after updating to revision 113348

I 'm sorry but I had to downgrade this customer too...
By: Joel Vandal (jvandal) 2008-04-16 21:24:52

aragon, here the log you wanted...

We turn on DTMF logging on a server and see nothing on the CLI but if we look with 'rtp debug' we received RFC2833 packet:


Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022762, ts 2002424702, len 000004, mark 1, event 00000002, end 0, duration 00000)
Sent RTP packet to      172.16.249.55:3000 (type 00, seq 024644, ts 022880, len 000160)
Got  RTP packet from    172.16.249.55:3000 (type 101, seq 022763, ts 2002424702, len 000004)
Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022763, ts 2002424702, len 000004, mark 0, event 00000002, end 0, duration 00160)
Sent RTP packet to      172.16.249.55:3000 (type 00, seq 024645, ts 023040, len 000160)
Got  RTP packet from    172.16.249.55:3000 (type 101, seq 022764, ts 2002424702, len 000004)
Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022764, ts 2002424702, len 000004, mark 0, event 00000002, end 0, duration 00320)
Sent RTP packet to      172.16.249.55:3000 (type 00, seq 024646, ts 023200, len 000160)
Got  RTP packet from    172.16.249.55:3000 (type 101, seq 022765, ts 2002424702, len 000004)
Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022765, ts 2002424702, len 000004, mark 0, event 00000002, end 0, duration 00480)
Sent RTP packet to      172.16.249.55:3000 (type 00, seq 024647, ts 023360, len 000160)
Got  RTP packet from    172.16.249.55:3000 (type 101, seq 022766, ts 2002424702, len 000004)
Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022766, ts 2002424702, len 000004, mark 0, event 00000002, end 1, duration 00640)
Got  RTP packet from    172.16.249.55:3000 (type 101, seq 022767, ts 2002424702, len 000004)
Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022767, ts 2002424702, len 000004, mark 0, event 00000002, end 1, duration 00640)
Got  RTP packet from    172.16.249.55:3000 (type 101, seq 022768, ts 2002424702, len 000004)
Got  RTP RFC2833 from   172.16.249.55:3000 (type 101, seq 022768, ts 2002424702, len 000004, mark 0, event 00000002, end 1, duration 00640)
By: David Brillert (aragon) 2008-04-16 21:34:21

Thanks jvandal

File: I reintroduced the bug into a production server to get the logs after hours.
jvandal has produced the logs

I think the attached messages log is also useful...

I downgraded the customer to fix the problem.

What next?
I am willing to test a patch
By: David Brillert (aragon) 2008-04-18 07:43:51

Why is this still in feedback status?
By: Joshua C. Colp (jcolp) 2008-04-18 14:08:53

Please try the attached patch.
By: David Brillert (aragon) 2008-04-18 14:24:28

Thanks file

I'll give her a go soon :)
By: David Brillert (aragon) 2008-04-21 09:00:45

File:
Your patch works great.
Please close ticket and commit to SVN

Good work, thank you :)
By: Digium Subversion (svnbot) 2008-04-21 09:34:25

Repository: asterisk
Revision: 114322

U   branches/1.4/channels/chan_sip.c

------------------------------------------------------------------------
r114322 | file | 2008-04-21 09:34:25 -0500 (Mon, 21 Apr 2008) | 4 lines

Only drop audio if we receive it without a progress indication. We allow other frames through such as DTMF because they may be needed to complete the call.
(closes issue ASTERISK-11846)
Reported by: aragon

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114322
By: Digium Subversion (svnbot) 2008-04-21 09:35:20

Repository: asterisk
Revision: 114323

_U  trunk/
U   trunk/channels/chan_sip.c

------------------------------------------------------------------------
r114323 | file | 2008-04-21 09:35:20 -0500 (Mon, 21 Apr 2008) | 12 lines

Merged revisions 114322 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r114322 | file | 2008-04-21 11:39:32 -0300 (Mon, 21 Apr 2008) | 4 lines

Only drop audio if we receive it without a progress indication. We allow other frames through such as DTMF because they may be needed to complete the call.
(closes issue ASTERISK-11846)
Reported by: aragon

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114323
By: Digium Subversion (svnbot) 2008-04-21 09:36:48

Repository: asterisk
Revision: 114324

_U  branches/1.6.0/
U   branches/1.6.0/channels/chan_sip.c

------------------------------------------------------------------------
r114324 | file | 2008-04-21 09:36:47 -0500 (Mon, 21 Apr 2008) | 20 lines

Merged revisions 114323 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r114323 | file | 2008-04-21 11:40:33 -0300 (Mon, 21 Apr 2008) | 12 lines

Merged revisions 114322 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r114322 | file | 2008-04-21 11:39:32 -0300 (Mon, 21 Apr 2008) | 4 lines

Only drop audio if we receive it without a progress indication. We allow other frames through such as DTMF because they may be needed to complete the call.
(closes issue ASTERISK-11846)
Reported by: aragon

........

................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114324
By: Digium Subversion (svnbot) 2008-04-21 11:58:51

Repository: asterisk
Revision: 114334

_U  team/seanbright/resolve-shadow-warnings/
U   team/seanbright/resolve-shadow-warnings/apps/app_authenticate.c
U   team/seanbright/resolve-shadow-warnings/channels/chan_sip.c
U   team/seanbright/resolve-shadow-warnings/doc/janitor-projects.txt
U   team/seanbright/resolve-shadow-warnings/res/res_config_ldap.c

------------------------------------------------------------------------
r114334 | seanbright | 2008-04-21 11:58:49 -0500 (Mon, 21 Apr 2008) | 39 lines

Merged revisions 114320,114323,114325,114327 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

................
r114320 | file | 2008-04-21 10:34:06 -0400 (Mon, 21 Apr 2008) | 6 lines

Only print out the error message if ldap_modify_ext_s actually returns an error, and not success.
(closes issue ASTERISK-11844)
Reported by: gservat
Patches:
     res_config_ldap.c-patch-code uploaded by gservat (license 466)

................
r114323 | file | 2008-04-21 10:40:33 -0400 (Mon, 21 Apr 2008) | 12 lines

Merged revisions 114322 via svnmerge from
https://origsvn.digium.com/svn/asterisk/branches/1.4

........
r114322 | file | 2008-04-21 11:39:32 -0300 (Mon, 21 Apr 2008) | 4 lines

Only drop audio if we receive it without a progress indication. We allow other frames through such as DTMF because they may be needed to complete the call.
(closes issue ASTERISK-11846)
Reported by: aragon

........

................
r114325 | russell | 2008-04-21 11:01:04 -0400 (Mon, 21 Apr 2008) | 2 lines

Add a simple janitor project

................
r114327 | jpeeler | 2008-04-21 11:34:37 -0400 (Mon, 21 Apr 2008) | 2 lines

This removes an invalid warning message for an incorrectly entered pin, but more importantly removes an inapplicable check. If the first argument passed to app_authenticate does not contain a '/', the argument should be treated as the sole fixed "password" to match against and that is all. (Previous behavior was attempting to open a file based on the pin.)

................

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=114334