[Asterisk-bugs] [Asterisk 0010084]: Read application buffers input DTMF tones
noreply at bugs.digium.com
noreply at bugs.digium.com
Tue Jul 10 15:04:53 CDT 2007
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=10084
======================================================================
Reported By: rushowr
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 10084
Category: Applications/app_read
Reproducibility: random
Severity: minor
Priority: normal
Status: feedback
Asterisk Version: 1.4.5
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Disclaimer on File?: No
Request Review:
======================================================================
Date Submitted: 06-28-2007 15:10 CDT
Last Modified: 07-10-2007 15:04 CDT
======================================================================
Summary: Read application buffers input DTMF tones
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 at 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 at 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 at select_lang:5] GotoIf("SIP/[provider name
removed]-08218e30", "1?6:13")
Goto (select_lang,s,6)
--Executing[s at select_lang:6] GotoIf("SIP/[provider name
removed]-08218e30", "1?7:10")
Goto (select_lang,s,7)
--Executing[s at select_lang:7] Set("SIP/[provider name removed]-08218e30",
"loop=2")
--Executing[s at select_lang:8] Goto("SIP/[provider name removed]-08218e30",
"getinput")
Goto (select_lang,s,3)
--Executing[s at 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 at 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 at 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 at 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.
======================================================================
----------------------------------------------------------------------
rushowr - 07-10-07 15:04
----------------------------------------------------------------------
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 queued 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 at 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 at authentication:28]
Set("SIP/<PROVIDER>-081f3df8", "pin=") in new stack
-- Executing [sw-5-callback at authentication:29]
Goto("SIP/<PROVIDER>-081f3df8", "sw-5-callback|getinput1") in new stack
-- Goto (authentication,sw-5-callback,4)
-- Executing [sw-5-callback at authentication:4]
Set("SIP/<PROVIDER>-081f3df8", "loop=2") in new stack
-- Executing [sw-5-callback at authentication:5]
GotoIf("SIP/<PROVIDER>-081f3df8", "0?6:7") in new stack
-- Goto (authentication,sw-5-callback,7)
-- Executing [sw-5-callback at authentication:7]
NoOp("SIP/<PROVIDER>-081f3df8", "Finish if-sw-authentication-callback-5-6")
in new stack
-- Executing [sw-5-callback at 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 at 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'
Issue History
Date Modified Username Field Change
======================================================================
07-10-07 15:04 rushowr Note Added: 0067084
======================================================================
More information about the Asterisk-bugs
mailing list