[Home]

Summary:ASTERISK-09781: Read application buffers input DTMF tones
Reporter:Sherwood McGowan (rushowr)Labels:
Date Opened:2007-06-28 15:10:58Date Closed:2007-07-23 13:27:46
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_read
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:The Read application is used to take the user's input and place it into a variable but sometimes if it does not properly receive the DTMF tone(s), it buffers the input and places it into the NEXT Read call's input buffer and prepends it to the variable there.

One major thing we've noticed is that it's always the last digit of the input.
For example, we get the uer's language selection and for some reason the server does not get the entered digit "1" as show below:

-------------
--Executing[s@select_lang:3] BackGround("SIP/[provider name removed]-08218e30", "prepaid-lang_select")
<SIP/[provider name removed]-08218e30> Playing 'prepaid-lang_select' (language 'en')
--Executing[s@select_lang:4] Read("SIP/[provider name removed]-08218e30", "lang_input||1")
Accepting a maximum of 1 digits.
User entered nothing.
-------------

Our dialpan tests for empty input and loops back to get it again. This time, the first 1 is "received"  and the new "1" is buffered:

-------------
--Executing[s@select_lang:5] GotoIf("SIP/[provider name removed]-08218e30", "1?6:13")
Goto (select_lang,s,6)
--Executing[s@select_lang:6] GotoIf("SIP/[provider name removed]-08218e30", "1?7:10")
Goto (select_lang,s,7)
--Executing[s@select_lang:7] Set("SIP/[provider name removed]-08218e30", "loop=2")
--Executing[s@select_lang:8] Goto("SIP/[provider name removed]-08218e30", "getinput")
Goto (select_lang,s,3)
--Executing[s@select_lang:3] BackGround("SIP/[provider name removed]-08218e30", "prepaid-lang_select")
<SIP/[provider name removed]-08218e30> Playing 'prepaid-lang_select' (language 'en')
--Executing[s@select_lang:4] Read("SIP/[provider name removed]-08218e30", "lang_input||1")
Accepting a maximum of 1 digits.
User entered '1'
-------------

This time, since there's a language selected, we set the language (no need to show this), and then move on to get the pin number. This is where we can really see the error, since the pin entered was 222333444555, but Read sees 122233344455:

-------------
--Executing[sw-5-callback@authentication:8] BackGround("SIP/[provider name removed]-08218e30", "prepaid-enter-pin")
<SIP/[provider name removed]-08218e30> Playing 'prepaid-enter-pin' (language 'en')
--Executing[sw-5-callback@authentication:9] Read("SIP/[provider name removed]-08218e30", "pin||14")
Accepting a maximum of 14 digits.
User entered '1222333444555'
-------------

The next executions are omitted because they pertain to the database queries used to determine if the pin is correct, which it is not. We then loop back to try again. Unfortunately, the input is ALWAYS wrong because the last digit of the previous input keeps getting prepended as shown above.



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

The executions shown above show a Background/Read pair being used, but the Read application has also been used in testing with the prompt specified in it's options only, with same effect.

We _are_ using some backported AEL and Gosub changes from Trunk, but these tests were also run against a vanilla 1.4.5 build with the same effect.
Comments:By: Joshua C. Colp (jcolp) 2007-06-29 07:07:57

Please enable dtmf logging in logger.conf and provide the output this gives. As well what is the sip.conf configuration? (minus passwords)
By: Sherwood McGowan (rushowr) 2007-06-29 07:32:39

Hey file! I thought you might be the one to get this report. This bug and report ASTERISK-9611 might be linked :)

I'll enable DTMF logging (sorry, I had forgotten that it could be done) and report  to you the results.

Here's the sip configuration, minus passwords. This is the same sip.conf from bug ASTERISK-9611. We've made some small changes.

[general]

rfc2833compensate=yes
context=deadly
bindport=5060
bindaddr=0.0.0.0
pedantic=yes
maxexpiry=3600
defaultexpiry=3600
disallow=all
allow=ilbc
allow=alaw
allow=ulaw
allow=gsm
language=en
relaxdtmf=yes
rtptimeout=60
rtpholdtimeout=300
dtmfmode = rfc2833
rfc2833compensate=yes


[provider name removed]
type=peer
username=25811
fromuser=25811
secret=**password removed**
disallow=all
allow=gsm
allow=ilbc
host=**host name removed**
By: Sherwood McGowan (rushowr) 2007-06-29 15:45:15

Updated output. Here we see that we received "1" on DTMF but READ didn't register it. Then, it says that we received 1 one when we didn't, and finally we receive 222333444555 but READ uses 122233344455

   -- Executing [s@callcard_select_lang:3] BackGround("SIP/[SIP PROVIDER]", "prepaid-lang_select") in new stack
   -- <SIP/[SIP PROVIDER]> Playing 'prepaid-lang_select' (language 'en')
[Jun 29 22:32:12] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '1' received on SIP/[SIP PROVIDER], duration 0 ms
   -- Executing [s@callcard_select_lang:4] Read("SIP/[SIP PROVIDER]", "lang_input||1||1") in new stack
   -- Accepting a maximum of 1 digits.
   -- User entered nothing.
   -- Executing [s@callcard_select_lang:5] GotoIf("SIP/[SIP PROVIDER]", "1?6:13") in new stack
   -- Goto (callcard_select_lang,s,6)
   -- Executing [s@callcard_select_lang:6] GotoIf("SIP/[SIP PROVIDER]", "1?7:10") in new stack
   -- Goto (callcard_select_lang,s,7)
   -- Executing [s@callcard_select_lang:7] Set("SIP/[SIP PROVIDER]", "loop=2") in new stack
   -- Executing [s@callcard_select_lang:8] Goto("SIP/[SIP PROVIDER]", "getinput") in new stack
   -- Goto (callcard_select_lang,s,3)
   -- Executing [s@callcard_select_lang:3] BackGround("SIP/[SIP PROVIDER]", "prepaid-lang_select") in new stack
   -- <SIP/[SIP PROVIDER]> Playing 'prepaid-lang_select' (language 'en')
   -- Executing [s@callcard_select_lang:4] Read("SIP/[SIP PROVIDER]", "lang_input||1||1") in new stack
   -- Accepting a maximum of 1 digits.
   -- User entered '1'
   -- Executing [s@callcard_select_lang:5] GotoIf("SIP/[SIP PROVIDER]", "0?6:13") in new stack
   -- Goto (callcard_select_lang,s,13)
   -- Executing [s@callcard_select_lang:13] NoOp("SIP/[SIP PROVIDER]", "Finish if-callcard_select_lang-63") in new stack
   -- Executing [s@callcard_select_lang:14] Wait("SIP/[SIP PROVIDER]", "1") in new stack
[Jun 29 22:32:25] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '1' received on SIP/[SIP PROVIDER], duration 0 ms
   -- Executing [s@callcard_select_lang:15] GotoIf("SIP/[SIP PROVIDER]", "0?16:20") in new stack
   -- Goto (callcard_select_lang,s,20)
   -- Executing [s@callcard_select_lang:20] Goto("SIP/[SIP PROVIDER]", "sw-66-1|1") in new stack
   -- Goto (callcard_select_lang,sw-66-1,1)
   -- Executing [sw-66-1@callcard_select_lang:1] Set("SIP/[SIP PROVIDER]", "LANGUAGE()=en") in new stack
   -- Executing [sw-66-1@callcard_select_lang:2] Set("SIP/[SIP PROVIDER]", "__LANGSET=y") in new stack
   -- Executing [sw-66-1@callcard_select_lang:3] Goto("SIP/[SIP PROVIDER]", "s|21") in new stack
   -- Goto (callcard_select_lang,s,21)
   -- Executing [s@callcard_select_lang:21] NoOp("SIP/[SIP PROVIDER]", "Finish switch-if-callcard_select_lang-65-66") in new stack
   -- Executing [s@callcard_select_lang:22] NoOp("SIP/[SIP PROVIDER]", "Finish if-callcard_select_lang-65") in new stack
   -- Executing [s@callcard_select_lang:23] Set("SIP/[SIP PROVIDER]", "announce_status=on") in new stack
   -- Executing [s@callcard_select_lang:24] Return("SIP/[SIP PROVIDER]", "") in new stack
   -- Executing [sw-5-callback@authentication:2] Wait("SIP/[SIP PROVIDER]", "1") in new stack
   -- Executing [sw-5-callback@authentication:3] Set("SIP/[SIP PROVIDER]", "loop=0") in new stack
   -- Executing [sw-5-callback@authentication:4] Set("SIP/[SIP PROVIDER]", "loop=1") in new stack
   -- Executing [sw-5-callback@authentication:5] GotoIf("SIP/[SIP PROVIDER]", "0?6:7") in new stack
   -- Goto (authentication,sw-5-callback,7)
   -- Executing [sw-5-callback@authentication:7] NoOp("SIP/[SIP PROVIDER]", "Finish if-sw-authentication-callback-5-6") in new stack
   -- Executing [sw-5-callback@authentication:8] BackGround("SIP/[SIP PROVIDER]", "prepaid-enter-pin") in new stack
   -- <SIP/[SIP PROVIDER]> Playing 'prepaid-enter-pin' (language 'en')
   -- Executing [sw-5-callback@authentication:9] Read("SIP/[SIP PROVIDER]", "pin||14||1") in new stack
   -- Accepting a maximum of 14 digits.
[Jun 29 22:32:30] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '2' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:31] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '2' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:31] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '2' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:32] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '3' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:33] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '3' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:33] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '3' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:34] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '4' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:35] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '4' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:35] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '4' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:36] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '5' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:37] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '5' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:38] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '5' received on SIP/[SIP PROVIDER], duration 0 ms
[Jun 29 22:32:38] DTMF[2766]: channel.c:2297 __ast_read: DTMF end '#' received on SIP/[SIP PROVIDER], duration 0 ms
   -- User entered '1222333444555'
By: Joshua C. Colp (jcolp) 2007-07-02 09:24:13

I have added additional DTMF logging in 1.4 as of revision 72888. Can you please check out a copy and attach the output? It should give much more information. Thanks!
By: Sherwood McGowan (rushowr) 2007-07-10 15:04:53

Ok, the improved DTMF logging has improved our understanding greatly. We know see that we get 3 lines of dtmf logging: "received, begin, queued". Unfortunately, the [edited, previously said "queued"] end log doesn't show up until AFTER more executions in the Dialplan happen, which makes Read think it's getting new data instead of data from BEFORE the command.

Output follows:

  -- Executing [sw-5-callback@authentication:27] Playback("SIP/<PROVIDER>-081f3df8", "pin-invalid") in new stack
   -- <SIP/<PROVIDER>-081f3df8> Playing 'pin-invalid' (language 'en')
[Jul 10 21:41:02] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '5' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:02] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '5' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:02] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '5' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:02] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '5' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:02] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '5' with duration 100 queued on SIP/<PROVIDER>-081f3df8
   -- Executing [sw-5-callback@authentication:28] Set("SIP/<PROVIDER>-081f3df8", "pin=") in new stack
   -- Executing [sw-5-callback@authentication:29] Goto("SIP/<PROVIDER>-081f3df8", "sw-5-callback|getinput1") in new stack
   -- Goto (authentication,sw-5-callback,4)
   -- Executing [sw-5-callback@authentication:4] Set("SIP/<PROVIDER>-081f3df8", "loop=2") in new stack
   -- Executing [sw-5-callback@authentication:5] GotoIf("SIP/<PROVIDER>-081f3df8", "0?6:7") in new stack
   -- Goto (authentication,sw-5-callback,7)
   -- Executing [sw-5-callback@authentication:7] NoOp("SIP/<PROVIDER>-081f3df8", "Finish if-sw-authentication-callback-5-6") in new stack
   -- Executing [sw-5-callback@authentication:8] BackGround("SIP/<PROVIDER>-081f3df8", "prepaid-enter-pin") in new stack
   -- <SIP/<PROVIDER>-081f3df8> Playing 'prepaid-enter-pin' (language 'en')
   -- Executing [sw-5-callback@authentication:9] Read("SIP/<PROVIDER>-081f3df8", "pin||14||1") in new stack
   -- Accepting a maximum of 14 digits.
[Jul 10 21:41:06] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '5' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:06] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '2' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:06] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:06] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '2' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:07] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '2' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:07] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:07] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '2' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:07] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '2' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:07] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:08] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '2' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:08] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '3' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:08] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '3' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:08] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '3' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:09] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '3' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:09] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '3' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:09] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '3' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:10] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '3' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:10] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '3' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:10] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '3' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:11] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '4' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:11] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '4' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:11] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '4' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:12] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '4' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:12] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '4' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:12] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '4' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:12] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '4' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:12] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '4' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:12] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '4' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:13] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '5' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:13] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '5' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:13] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '5' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:14] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '5' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:14] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '5' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:14] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '5' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:14] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '5' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:14] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '5' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:14] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '5' queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:16] DTMF[14172]: channel.c:2332 __ast_read: DTMF end '#' received on SIP/<PROVIDER>-081f3df8, duration 0 ms
[Jul 10 21:41:16] DTMF[14172]: channel.c:2366 __ast_read: DTMF begin emulation of '#' with duration 100 queued on SIP/<PROVIDER>-081f3df8
[Jul 10 21:41:17] DTMF[14172]: channel.c:2438 __ast_read: DTMF end emulation of '#' queued on SIP/<PROVIDER>-081f3df8
   -- User entered '5222333444555'


By: Sherwood McGowan (rushowr) 2007-07-11 14:32:43

Any thoughts?
By: Sherwood McGowan (rushowr) 2007-07-11 14:39:47

Here's another instance that shows weird behavior:

   -- Executing [s@callcard_select_lang:3] Read("PROVIDER REMOVED", "lang_input|prepaid-lang_select|1||1") in new stack
   -- Accepting a maximum of 1 digits.
   -- <PROVIDER REMOVED> Playing 'prepaid-lang_select' (language 'en')
[Jul 11 21:34:48] DTMF[2712]: channel.c:2332 __ast_read: DTMF end '1' received on PROVIDER_REMOVED, duration 0 ms
[Jul 11 21:34:48] DTMF[2712]: channel.c:2366 __ast_read: DTMF begin emulation of '1' with duration 100 queued on PROVIDER_REMOVED
   -- User entered nothing.

This shows further problems with Asterisk putting DTMF tones into the Read application's input variable even though it's been entered.
By: Digium Subversion (svnbot) 2007-07-12 11:59:41

Repository: asterisk
Revision: 74888

------------------------------------------------------------------------
r74888 | file | 2007-07-12 11:59:40 -0500 (Thu, 12 Jul 2007) | 2 lines

When waiting for a digit ensure that a begin frame was received with it, not just an end frame. (issue ASTERISK-9781 reported by rushowr)

------------------------------------------------------------------------
By: Digium Subversion (svnbot) 2007-07-12 12:01:07

Repository: asterisk
Revision: 74891

------------------------------------------------------------------------
r74891 | file | 2007-07-12 12:01:06 -0500 (Thu, 12 Jul 2007) | 10 lines

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

........
r74888 | file | 2007-07-12 14:16:28 -0300 (Thu, 12 Jul 2007) | 2 lines

When waiting for a digit ensure that a begin frame was received with it, not just an end frame. (issue ASTERISK-9781 reported by rushowr)

........

------------------------------------------------------------------------
By: Joshua C. Colp (jcolp) 2007-07-12 12:01:19

Give the above a try.
By: Sherwood McGowan (rushowr) 2007-07-12 13:27:30

Excellent, I'll do so during our testing session this afternoon. Thanks for the work so far, I've got my fingers crossed.
By: Sherwood McGowan (rushowr) 2007-07-12 13:56:00

Ok, I updated my source tree and recompiled and installed. Unfortunately, Asterisk now shows that DTMF is being received but the READ application does not register any input.

Here's the output:

   -- Executing [sw-5-callback@authentication:8] Read("SIP/[PROVIDER REMOVED]", "pin|prepaid-enter-pin|14||1") in new stack
   -- Accepting a maximum of 14 digits.
   -- <SIP/[PROVIDER REMOVED]> Playing 'prepaid-enter-pin' (language '')
[Jul 12 20:56:26] DTMF[10669]: channel.c:2443 __ast_read: DTMF end emulation of '1' queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:26] DTMF[10669]: channel.c:2337 __ast_read: DTMF end '2' received on SIP/[PROVIDER REMOVED], duration 0 ms
[Jul 12 20:56:26] DTMF[10669]: channel.c:2371 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:26] DTMF[10669]: channel.c:2443 __ast_read: DTMF end emulation of '2' queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:27] DTMF[10669]: channel.c:2337 __ast_read: DTMF end '2' received on SIP/[PROVIDER REMOVED], duration 0 ms
[Jul 12 20:56:27] DTMF[10669]: channel.c:2371 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:27] DTMF[10669]: channel.c:2443 __ast_read: DTMF end emulation of '2' queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:27] DTMF[10669]: channel.c:2337 __ast_read: DTMF end '2' received on SIP/[PROVIDER REMOVED], duration 0 ms
[Jul 12 20:56:27] DTMF[10669]: channel.c:2371 __ast_read: DTMF begin emulation of '2' with duration 100 queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:29] DTMF[10669]: channel.c:2443 __ast_read: DTMF end emulation of '2' queued on SIP/[PROVIDER REMOVED]
[Jul 12 20:56:29] DTMF[10669]: channel.c:2337 __ast_read: DTMF end '3' received on SIP/[PROVIDER REMOVED], duration 0 ms
[Jul 12 20:56:29] DTMF[10669]: channel.c:2371 __ast_read: DTMF begin emulation of '3' with duration 100 queued on SIP/[PROVIDER REMOVED]
   -- User entered nothing.
By: Joshua C. Colp (jcolp) 2007-07-12 14:02:59

Fixed! Go for it again.
By: Sherwood McGowan (rushowr) 2007-07-18 10:55:19

Looks like the issue _may_ be resolved, but please leave this bug open for a little while. We're finalizing all testing on our app which uses READ a lot so there's definitely stress testing going on. :)
By: Joshua C. Colp (jcolp) 2007-07-23 13:27:45

Alrighty, I've left this open for 5 days and there have been no negative comments... so if this is still an issue please feel free to reopen.