[Home]

Summary:ASTERISK-11980: DTMF issues in 1.4.19 with missing digits
Reporter:Mark Gimelfarb (dawebber)Labels:
Date Opened:2008-05-06 13:41:42Date Closed:2011-06-07 14:03:24
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_zap
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) v1-12592.patch
Description:Trying to figure out an issue with DTMF recognition with 1.4.19. This  
is somewhat similar to the issue described here:  
http://bugs.digium.com/view.php?id=11740, but it might be a different  
issue altogether.

I have 1.4.19 running with TE212P on a US PRI hooked up to Time Warner Telecom. DTMF debugging enabled.

LibPRI 1.4.3
Zaptel 1.4.9

****** STEPS TO REPRODUCE ******

I'm making an inbound call and pressing digits 823229999. Sometimes the digits are making it all  
into the asterisk, and sometimes some are missing.

In the case when the digits are all caught, my DTMF log entries are  
something like this:

<snip>
[May  2 14:48:56] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '8'  
received on Zap/1-1, duration 0 ms
[May  2 14:48:56] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '8' on Zap/1-1
[May  2 14:48:56] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '8' on Zap/1-1
[May  2 14:48:57] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '2'  
received on Zap/1-1, duration 0 ms
[May  2 14:48:57] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '2' on Zap/1-1
[May  2 14:48:57] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '2' on Zap/1-1
[May  2 14:48:57] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '3'  
received on Zap/1-1, duration 0 ms
[May  2 14:48:57] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '3' on Zap/1-1
[May  2 14:48:57] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '3' on Zap/1-1
[May  2 14:48:58] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '2'  
received on Zap/1-1, duration 0 ms
[May  2 14:48:58] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '2' on Zap/1-1
[May  2 14:48:58] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '2' on Zap/1-1
[May  2 14:48:58] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '2'  
received on Zap/1-1, duration 0 ms
[May  2 14:48:58] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '2' on Zap/1-1
[May  2 14:48:58] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '2' on Zap/1-1
[May  2 14:48:59] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:48:59] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:48:59] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
[May  2 14:49:00] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:49:00] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:49:00] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
[May  2 14:49:00] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:49:00] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:49:00] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
[May  2 14:49:01] DTMF[28649]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:49:01] DTMF[28649]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:49:01] DTMF[28649]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
</snip>

In the case when digits are not fully recognized (one is missing), I get this:
<snip>
[May  2 14:36:16] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '8'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:16] DTMF[28461]: channel.c:2128 __ast_read: DTMF begin  
emulation of '8' with duration 100 queued on Zap/1-1
[May  2 14:36:16] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '2'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:16] DTMF[28461]: channel.c:2098 __ast_read: DTMF end '2'  
put into dtmf queue on Zap/1-1
[May  2 14:36:16] DTMF[28461]: channel.c:2237 __ast_read: DTMF end  
emulation of '8' queued on Zap/1-1
[May  2 14:36:16] DTMF[28461]: channel.c:1961 __ast_read: DTMF begin  
emulation of '2' with duration 100 queued on Zap/1-1
[May  2 14:36:16] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '3'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:16] DTMF[28461]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '3' on Zap/1-1
[May  2 14:36:16] DTMF[28461]: channel.c:2155 __ast_read: DTMF end  
passthrough '3' on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2237 __ast_read: DTMF end  
emulation of '2' queued on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '2'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:17] DTMF[28461]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '2' on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2155 __ast_read: DTMF end  
passthrough '2' on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:17] DTMF[28461]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:17] DTMF[28461]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:36:17] DTMF[28461]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
[May  2 14:36:18] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:18] DTMF[28461]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:36:18] DTMF[28461]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1
[May  2 14:36:18] DTMF[28461]: channel.c:2092 __ast_read: DTMF end '9'  
received on Zap/1-1, duration 0 ms
[May  2 14:36:18] DTMF[28461]: channel.c:2144 __ast_read: DTMF end  
accepted without begin '9' on Zap/1-1
[May  2 14:36:18] DTMF[28461]: channel.c:2155 __ast_read: DTMF end  
passthrough '9' on Zap/1-1

</snip>

Looks like the 2 after the 3 is not getting recognized, and the 2  
after the 8 is being queued up and then dequeued later. I don't know  
why we need to defer DTMF here, but either way the issue is that DTMF  
digits are missing in the end.

The behavior is a bit erratic, and may occur when the digits are being  
sent while * is playing audio on the channel, even though it's not  
every time.



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

Please let me know if this is enough info to proceed on.

Regards,
Mark G.
Comments:By: Dmitry Andrianov (dimas) 2008-05-08 09:05:25

Obviosuly it is difficult to say anything from the information you provided.

I would suggest upgrading to latest zaptel - you are using somewhat old.
Then make sure DTMF logging goes to file/console (see /etc/asterisk/logger.conf)

And then create some reproducible scenario and explain what digits were pressed, what digits were read by Asterisk and provide the corresponding piece of log.
By: Mark Gimelfarb (dawebber) 2008-05-08 09:09:24

I actually have provided the exact steps to reproduce. If you click on "View Advanced" screen, you'll see what I mean.

I've done exactly what you've suggested--created a logger specifically for DTMF. The information from it is contained within the steps.
By: Dmitry Andrianov (dimas) 2008-05-08 09:11:16

my apologies - you are right, i was in basic view for some reason :(
By: snuffy (snuffy) 2008-05-08 09:52:43

could this also be related to 11679? (i say only since its relating to a zap channel)
By: Mark Gimelfarb (dawebber) 2008-05-08 12:53:57

I think it's strictly a flaw in the emulation code. The buffered digits don't get infused back into the DTMF flow at the right time, and some of them get "munged up" and never show up. It seems to be a timing issue as well as well as whether the channel is playing audio at the time DTMF digits are being entered, IMO.
By: Dmitry Andrianov (dimas) 2008-05-12 04:36:05

Ohh....
It looks like you finally hit the scenario I was alwasy afraid of but never encountered before. This is exactly why I consider the whole DTMF normalization in ast_read a bad approach.

I guess we need attract Russel's attention to this issue. I believe bad things happen because autoservice switches AST_FLAG_END_DTMF_ONLY mode back and forth on the fly. So ast_read first reads DTMF_END in "normal" mode, starts emulating BEGIN and then autoservice switches the channel to AST_FLAG_END_DTMF_ONLY mode so when next DTMF_END is read it is passed thru. So eventually, END of the third digit is read instead of the end of the second. This obviously results in missing digits.

Mark, I'm about to attach very dirty patch you can test. I warn you that I have NOT tested this patch myself and have no idea if it works at all or if it breaks anything else. Use at your own risk.
By: Mark Gimelfarb (dawebber) 2008-05-12 09:16:26

I've patched the code and rebuilt asterisk. I am doing some more testing, but I don't think the patch solved the issue. Now, it seems that the second digit is missing. DTMF log below (same sequence is entered--823229999):

<snip>
[May 12 09:19:46] DTMF[11209] channel.c: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 09:19:46] DTMF[11209] channel.c: DTMF begin emulation of '8' with duration 100 queued on Zap
/1-1
[May 12 09:19:46] DTMF[11209] channel.c: DTMF end emulation of '8' queued on Zap/1-1
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end accepted without begin '3' on Zap/1-1
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end passthrough '3' on Zap/1-1
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 09:19:47] DTMF[11209] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 09:19:48] DTMF[11209] channel.c: DTMF end passthrough '9' on Zap/1-1

</snip>
By: Dmitry Andrianov (dimas) 2008-05-12 09:30:44

Are you really sure you pressed the second "2" ?
I'm asking because regardless of emulation/normalization process, any digit should generate

   DTMF end '%c' received on %s, duration %ld ms

log line which is present for 8 and next 3 but it is missing for 2.
By: Mark Gimelfarb (dawebber) 2008-05-12 10:07:41

Yes. I have tested this several times. I will perform another test (3 sequences in a row) and present the log results here.
By: Mark Gimelfarb (dawebber) 2008-05-12 10:28:49

Just did another test--4 times in a row:

Try 1:

<snip>
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 10:29:12] DTMF[16225] channel.c: DTMF begin emulation of '8' with duration 100 queued on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end emulation of '8' queued on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end accepted without begin '3' on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end passthrough '3' on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:12] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:13] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
</snip>

try 2:

<snip>
[May 12 10:29:32] DTMF[16225] channel.c: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 10:29:32] DTMF[16225] channel.c: DTMF begin emulation of '8' with duration 100 queued on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end emulation of '8' queued on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:33] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:34] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
</snip>

try 3:

<snip>
[May 12 10:29:54] DTMF[16225] channel.c: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 10:29:54] DTMF[16225] channel.c: DTMF begin emulation of '8' with duration 100 queued on Zap/1-1
[May 12 10:29:54] DTMF[16225] channel.c: DTMF end emulation of '8' queued on Zap/1-1
[May 12 10:29:54] DTMF[16225] channel.c: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 10:29:54] DTMF[16225] channel.c: DTMF end accepted without begin '3' on Zap/1-1
[May 12 10:29:54] DTMF[16225] channel.c: DTMF end passthrough '3' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:55] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:56] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:56] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:56] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:29:56] DTMF[16225] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:29:56] DTMF[16225] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:29:56] DTMF[16225] channel.c: DTMF end passthrough '9' on Zap/1-1
</snip>

try 4: (I spaced the digits at least 0.5 sec apart):

<snip>
[May 12 10:31:05] DTMF[16356] channel.c: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 10:31:05] DTMF[16356] channel.c: DTMF begin emulation of '8' with duration 100 queued on Zap/1-1
[May 12 10:31:05] DTMF[16356] channel.c: DTMF end emulation of '8' queued on Zap/1-1
[May 12 10:31:05] DTMF[16356] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:31:05] DTMF[16356] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:31:05] DTMF[16356] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:31:06] DTMF[16356] channel.c: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 10:31:06] DTMF[16356] channel.c: DTMF end accepted without begin '3' on Zap/1-1
[May 12 10:31:06] DTMF[16356] channel.c: DTMF end passthrough '3' on Zap/1-1
[May 12 10:31:06] DTMF[16356] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:31:06] DTMF[16356] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:31:06] DTMF[16356] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:31:07] DTMF[16356] channel.c: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 10:31:07] DTMF[16356] channel.c: DTMF end accepted without begin '2' on Zap/1-1
[May 12 10:31:07] DTMF[16356] channel.c: DTMF end passthrough '2' on Zap/1-1
[May 12 10:31:08] DTMF[16356] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:31:08] DTMF[16356] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:31:08] DTMF[16356] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:31:09] DTMF[16356] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:31:09] DTMF[16356] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:31:09] DTMF[16356] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:31:09] DTMF[16356] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:31:09] DTMF[16356] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:31:09] DTMF[16356] channel.c: DTMF end passthrough '9' on Zap/1-1
[May 12 10:31:10] DTMF[16356] channel.c: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 10:31:10] DTMF[16356] channel.c: DTMF end accepted without begin '9' on Zap/1-1
[May 12 10:31:10] DTMF[16356] channel.c: DTMF end passthrough '9' on Zap/1-1

</snip>


Try 4 worked.
By: Mark Gimelfarb (dawebber) 2008-05-12 12:06:03

Discussed on #asterisk-bugs. In the course of discussion, it turned out that Cepstral might the the culprit here.

Per file's suggestion on IRC, added the following code in the Cepstral module that's using the channel:

ast_set_flag(c, AST_FLAG_END_DTMF_ONLY);
......
ast_clear_flag(c, AST_FLAG_END_DTMF_ONLY);

I also sprinkled in ast_test_flag to see that the flags are getting set in fact.

Will be doing more testing to confirm whether it made a difference.

With the new flags set:

[May 12 12:16:13] DEBUG[25442]: app_cepstraltts.c:183 swift_cb: got END callback; done generating audio
[May 12 12:16:14] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 12:16:14] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '8' on Zap/1-1
[May 12 12:16:14] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '8' on Zap/1-1
[May 12 12:16:14] NOTICE[25427]: app_cepstraltts.c:420 cepstraltts_exec: User pressed a key: 8
[May 12 12:16:14] DEBUG[25427]: app_cepstraltts.c:424 cepstraltts_exec: AST_FLAG_END_DTMF_ONLY is set
[May 12 12:16:15] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 12:16:15] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '3' on Zap/1-1
[May 12 12:16:15] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '3' on Zap/1-1
[May 12 12:16:15] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:16:15] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:16:15] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:16:15] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:16:15] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:16:15] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:16:16] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:16:16] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:16:16] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:16:17] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:16:17] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:16:17] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:16:17] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:16:17] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:16:17] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:16:18] DTMF[25427]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:16:18] DTMF[25427]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:16:18] DTMF[25427]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1


By: Dmitry Andrianov (dimas) 2008-05-12 12:27:08

I'm not familar with Cepstral/ However, again, to me it looks like DTMF_END somtimes aren't just read from Zap channel. This can happen when Zap channel is not read for a long time (200ms is long enough) and NOT autoserviced at that time.

If it is an issue, then Cepstral should put channel to autoservice and back before and after doing long operation (external lookups etc). Just setting DTMF_END_ONLY flag won't cure the issue...
By: Mark Gimelfarb (dawebber) 2008-05-12 12:30:51

Per suggestion on IRC, added a step to use Read() instead of Cepstral module.

The following relevant steps are in the dialplan:

exten => xxxxxxx,n,Read(DGTS,,9,,,5)
exten => xxxxxxx,n,NoOp(${DGTS})

Here are the results:

<snip>
[May 12 12:35:20] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 12:35:20] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '8' on Zap/1-1
[May 12 12:35:20] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '8' on Zap/1-1
   -- Executing [xxxxxxx@default:5] Read("Zap/1-1", "DGTS||9|||5") in new stack
   -- Accepting a maximum of 9 digits.
[May 12 12:35:20] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:35:20] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:35:20] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:35:21] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 12:35:21] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '3' on Zap/1-1
[May 12 12:35:21] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '3' on Zap/1-1
[May 12 12:35:21] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:35:21] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:35:21] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:35:21] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:35:21] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:35:21] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:35:22] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:35:22] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:35:22] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:35:22] DTMF[27699]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:35:22] DTMF[27699]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
   -- User entered '23229999'
   -- Executing [xxxxxxx@default:6] NoOp("Zap/1-1", "23229999") in new stack
</snip>


Looks like the Read() application doesn't get the first digit.

It was suggested that I wasn't waiting till Read() got a hold of the channel.

Did another test, making sure to wait long enough. Seems to have captured all the digits.

<snip>
   -- Executing [xxxxxxx@default:5] Read("Zap/1-1", "DGTS||9|||5") in new stack
   -- Accepting a maximum of 9 digits.
[May 12 12:38:37] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '8' received on Zap/1-1, duration 0 ms
[May 12 12:38:37] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '8' on Zap/1-1
[May 12 12:38:37] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '8' on Zap/1-1
[May 12 12:38:37] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:38:37] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:38:37] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:38:37] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '3' received on Zap/1-1, duration 0 ms
[May 12 12:38:37] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '3' on Zap/1-1
[May 12 12:38:37] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '3' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:38:38] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '2' received on Zap/1-1, duration 0 ms
[May 12 12:38:38] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '2' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '2' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:38:38] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:38:38] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:38:38] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:38:39] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:38:39] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:38:39] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
[May 12 12:38:39] DTMF[28096]: channel.c:2092 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[May 12 12:38:39] DTMF[28096]: channel.c:2143 __ast_read: DTMF end accepted without begin '9' on Zap/1-1
[May 12 12:38:39] DTMF[28096]: channel.c:2154 __ast_read: DTMF end passthrough '9' on Zap/1-1
   -- User entered '823229999'

</snip>


By: Dmitry Andrianov (dimas) 2008-05-13 04:10:26

Just for records: the problem reported AFTER the patch caused by the impoper behavior of 3rd party application, not the Asterisk itself.

However I still believe that log present in the "Steps to Reproduce" (in Advanced View) demonstrate a bug in the Asterisk DTMF emulation code.
By: Dmitry Andrianov (dimas) 2008-05-20 10:14:00

The issue 12658 contains a patch for the initial problem reported in this issue.
Also, 12656 has important fix too.
By: Mark Gimelfarb (dawebber) 2008-05-20 13:47:06

As far as I am concerned, we can go ahead and close this bug report. The application was corrected adding the autoservice behavior, and the problems seems to have gone away. Thank you for everyone's help on this.
By: Tilghman Lesher (tilghman) 2008-07-16 10:43:09

Closed on request of reporter.