[Home]

Summary:ASTERISK-10096: Prompts can not be interrupted with DTMF when using ZAP-Channels
Reporter:Marc Heubes (worfinator)Labels:
Date Opened:2007-08-16 13:39:28Date Closed:2011-06-07 14:08:07
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Applications/app_meetme
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:I recognised the following problem:
“Please enter your conference call number followed by the…“ I think users which are familiar with the system do not necessarily need to wait for this prompt to
end. It’s just annoying for them…Is there a solution for this? So that users can interrupt the playback of the voice file by entering the number…At the moment they have to wait till the playback for the prompt ends till they can enter their conference id.

I heart this has been working in older releases. It also does not work with Web-MeetMe (cbmysql) which seems to use the same methods as app_meetme.



Comments:By: Joshua C. Colp (jcolp) 2007-08-16 19:58:12

Please enable dtmf logging in logger.conf and provide a complete console output of this happening with app_meetme. Thanks.
By: Marc Heubes (worfinator) 2007-08-17 02:40:24

Normal Call with app_meetme. In this case I waited for the prompts to end:

   -- Accepting overlap call from '' to '17902998' on channel 0/4, span 1
   -- Starting simple switch on 'Zap/4-1'
   -- Executing [17902998@external_in:1] Answer("Zap/4-1", "") in new stack
   -- Executing [17902998@external_in:2] MeetMe("Zap/4-1", "") in new stack
   -- <Zap/4-1> Playing 'conf-getconfno' (language 'en')
[Aug 17 09:56:35] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:35] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/4-1
[Aug 17 09:56:36] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/4-1
[Aug 17 09:56:38] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:38] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/4-1
[Aug 17 09:56:38] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/4-1
[Aug 17 09:56:40] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:40] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/4-1
[Aug 17 09:56:40] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/4-1
[Aug 17 09:56:41] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:41] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/4-1
[Aug 17 09:56:41] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/4-1
[Aug 17 09:56:42] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '#' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:42] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/4-1
[Aug 17 09:56:42] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '#' queued on Zap/4-1
 == Parsing '/etc/asterisk/meetme.conf': Found
   -- Created MeetMe conference 1018 for conference '5555'
   -- <Zap/4-1> Playing 'conf-getpin' (language 'en')
[Aug 17 09:56:45] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '6' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:45] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '6' with duration 100 queued on Zap/4-1
[Aug 17 09:56:45] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '6' queued on Zap/4-1
[Aug 17 09:56:46] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '6' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:46] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '6' with duration 100 queued on Zap/4-1
[Aug 17 09:56:47] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '6' queued on Zap/4-1
[Aug 17 09:56:48] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '6' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:48] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '6' with duration 100 queued on Zap/4-1
[Aug 17 09:56:48] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '6' queued on Zap/4-1
[Aug 17 09:56:49] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '6' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:49] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '6' with duration 100 queued on Zap/4-1
[Aug 17 09:56:49] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '6' queued on Zap/4-1
[Aug 17 09:56:49] DTMF[26492]: channel.c:2346 __ast_read: DTMF end '#' received on Zap/4-1, duration 0 ms
[Aug 17 09:56:49] DTMF[26492]: channel.c:2382 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/4-1
[Aug 17 09:56:50] DTMF[26492]: channel.c:2465 __ast_read: DTMF end emulation of '#' queued on Zap/4-1
   -- <Zap/4-1> Playing 'conf-onlyperson' (language 'en')
   -- Channel 0/4, span 1 got hangup request, cause 16
   -- Hungup 'Zap/pseudo-46877113'
 == Spawn extension (external_in, 17902998, 2) exited non-zero on 'Zap/4-1'
   -- Hungup 'Zap/4-1'



In this case I didn't wait und started entering the conference number when the prompt was still playing:

   -- Accepting overlap call from '' to '17902998' on channel 0/3, span 2
   -- Starting simple switch on 'Zap/34-1'
   -- Executing [17902998@external_in:1] Answer("Zap/34-1", "") in new stack
   -- Executing [17902998@external_in:2] MeetMe("Zap/34-1", "") in new stack
   -- <Zap/34-1> Playing 'conf-getconfno' (language 'en')
[Aug 17 09:48:00] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:00] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/34-1
[Aug 17 09:48:00] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/34-1
[Aug 17 09:48:00] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:00] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/34-1
[Aug 17 09:48:00] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/34-1
[Aug 17 09:48:00] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '#' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:00] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/34-1
[Aug 17 09:48:01] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '#' queued on Zap/34-1
 == Parsing '/etc/asterisk/meetme.conf': Found
   -- <Zap/34-1> Playing 'conf-invalid' (language 'en')
   -- <Zap/34-1> Playing 'conf-getconfno' (language 'en')
[Aug 17 09:48:05] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:05] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/34-1
[Aug 17 09:48:05] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/34-1
[Aug 17 09:48:05] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:05] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/34-1
[Aug 17 09:48:05] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/34-1
[Aug 17 09:48:06] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:06] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/34-1
[Aug 17 09:48:06] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/34-1
[Aug 17 09:48:06] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:06] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/34-1
[Aug 17 09:48:06] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/34-1
[Aug 17 09:48:06] DTMF[26476]: channel.c:2346 __ast_read: DTMF end '#' received on Zap/34-1, duration 0 ms
[Aug 17 09:48:06] DTMF[26476]: channel.c:2382 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/34-1
[Aug 17 09:48:06] DTMF[26476]: channel.c:2465 __ast_read: DTMF end emulation of '#' queued on Zap/34-1
 == Parsing '/etc/asterisk/meetme.conf': Found
   -- Created MeetMe conference 1020 for conference '5555'

As you can see in the first try only 2 of 4 digits were recongised.

This may have to do with overlapdial=yes in zapata.conf, I'm not sure about that.

My E1 card is a Digium Wildcard TE212P.
By: Joshua C. Colp (jcolp) 2007-08-19 20:21:45

This is definitely a chan_zap issue then, there are no DTMF frames even being queued up to the core.
By: Marc Heubes (worfinator) 2007-09-06 06:21:55

How to continue on this? It's still not working and I would like to find a solution for this issue...
By: Joshua C. Colp (jcolp) 2007-09-06 11:01:47

I've looked through the code involved and if you enable debug in logger.conf, set the debug level to 9, and attach it we can confirm whether it is overlapdial or not that is causing this.
By: Marc Heubes (worfinator) 2007-09-14 04:08:06

Sorry, for the delay.

I now did some fourther testing.

The valid conference code in this example is 5555:

   -- Accepting overlap call from '' to '17902' on channel 0/1, span 1
   -- Starting simple switch on 'Zap/1-1'
[Sep 14 11:23:08] DTMF[950]: channel.c:2346 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:08] DTMF[950]: channel.c:2382 __ast_read: DTMF begin emulation of '9' with duration 100 queued on Zap/1-1
[Sep 14 11:23:08] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '9' queued on Zap/1-1
[Sep 14 11:23:08] DTMF[950]: channel.c:2346 __ast_read: DTMF end '9' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:08] DTMF[950]: channel.c:2363 __ast_read: DTMF end '9' put into dtmf queue on Zap/1-1
[Sep 14 11:23:08] DTMF[950]: channel.c:2215 __ast_read: DTMF begin emulation of '9' with duration 100 queued on Zap/1-1
[Sep 14 11:23:08] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '9' queued on Zap/1-1
[Sep 14 11:23:08] DTMF[950]: channel.c:2346 __ast_read: DTMF end '8' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:08] DTMF[950]: channel.c:2382 __ast_read: DTMF begin emulation of '8' with duration 100 queued on Zap/1-1
[Sep 14 11:23:08] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '8' queued on Zap/1-1
   -- Executing [17902998@external_in:1] Answer("Zap/1-1", "") in new stack
   -- Executing [17902998@external_in:2] MeetMe("Zap/1-1", "") in new stack
   -- <Zap/1-1> Playing 'conf-getconfno' (language 'en')
 == Parsing '/etc/asterisk/manager.conf': Found
 == Manager 'MeetMe' logged on from 145.228.61.150
 == Manager 'MeetMe' logged off from 145.228.61.150
[Sep 14 11:23:13] DTMF[950]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:13] DTMF[950]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/1-1
[Sep 14 11:23:13] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/1-1
[Sep 14 11:23:13] DTMF[950]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:13] DTMF[950]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/1-1
[Sep 14 11:23:14] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/1-1
[Sep 14 11:23:14] DTMF[950]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:14] DTMF[950]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/1-1
[Sep 14 11:23:14] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/1-1
[Sep 14 11:23:14] DTMF[950]: channel.c:2346 __ast_read: DTMF end '#' received on Zap/1-1, duration 0 ms
[Sep 14 11:23:14] DTMF[950]: channel.c:2382 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/1-1
[Sep 14 11:23:14] DTMF[950]: channel.c:2465 __ast_read: DTMF end emulation of '#' queued on Zap/1-1
 == Parsing '/etc/asterisk/meetme.conf': Found
[Sep 14 11:23:14] DEBUG[950]: app_meetme.c:2413 find_conf: 555 isn't a valid conference
   -- <Zap/1-1> Playing 'conf-invalid' (language 'en')
   -- <Zap/1-1> Playing 'conf-getconfno' (language 'en')
   -- <Zap/1-1> Playing 'conf-getconfno' (language 'en')
   -- Channel 0/1, span 1 got hangup request, cause 16
 == Spawn extension (external_in, 17902998, 2) exited non-zero on 'Zap/1-1'
[Sep 14 11:23:34] DEBUG[950]: chan_zap.c:2964 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[Sep 14 11:23:34] DEBUG[950]: chan_zap.c:2603 zt_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Sep 14 11:23:34] DEBUG[950]: chan_zap.c:2960 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
   -- Hungup 'Zap/1-1'
[Sep 14 11:23:34] DEBUG[950]: cdr_addon_mysql.c:211 mysql_log: cdr_mysql: inserting a CDR record.
[Sep 14 11:23:34] DEBUG[950]: cdr_addon_mysql.c:227 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr_asterisk (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-09-14 11:23:07','','','17902998','external_in', 'Zap/1-1','','MeetMe','',27,23,'ANSWERED',3,'','1189761787.2','')

As you can see the first 5 is missing. The extension for reachin meetme is 17902998

And another try, in this case only two of the 4 digits arrive:
   -- Accepting overlap call from '' to '17902' on channel 0/1, span 2
   -- Starting simple switch on 'Zap/32-1'
[Sep 14 11:24:54] DTMF[962]: channel.c:2346 __ast_read: DTMF end '9' received on Zap/32-1, duration 0 ms
[Sep 14 11:24:54] DTMF[962]: channel.c:2382 __ast_read: DTMF begin emulation of '9' with duration 100 queued on Zap/32-1
[Sep 14 11:24:54] DTMF[962]: channel.c:2465 __ast_read: DTMF end emulation of '9' queued on Zap/32-1
[Sep 14 11:24:54] DTMF[962]: channel.c:2346 __ast_read: DTMF end '9' received on Zap/32-1, duration 0 ms
[Sep 14 11:24:54] DTMF[962]: channel.c:2363 __ast_read: DTMF end '9' put into dtmf queue on Zap/32-1
[Sep 14 11:24:54] DTMF[962]: channel.c:2215 __ast_read: DTMF begin emulation of '9' with duration 100 queued on Zap/32-1
[Sep 14 11:24:54] DTMF[962]: channel.c:2465 __ast_read: DTMF end emulation of '9' queued on Zap/32-1
[Sep 14 11:24:54] DTMF[962]: channel.c:2346 __ast_read: DTMF end '8' received on Zap/32-1, duration 0 ms
[Sep 14 11:24:54] DTMF[962]: channel.c:2382 __ast_read: DTMF begin emulation of '8' with duration 100 queued on Zap/32-1
[Sep 14 11:24:54] DTMF[962]: channel.c:2465 __ast_read: DTMF end emulation of '8' queued on Zap/32-1
   -- Executing [17902998@external_in:1] Answer("Zap/32-1", "") in new stack
   -- Executing [17902998@external_in:2] MeetMe("Zap/32-1", "") in new stack
   -- <Zap/32-1> Playing 'conf-getconfno' (language 'en')
[Sep 14 11:24:59] DTMF[962]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/32-1, duration 0 ms
[Sep 14 11:24:59] DTMF[962]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/32-1
[Sep 14 11:24:59] DTMF[962]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/32-1
[Sep 14 11:24:59] DTMF[962]: channel.c:2346 __ast_read: DTMF end '5' received on Zap/32-1, duration 0 ms
[Sep 14 11:24:59] DTMF[962]: channel.c:2382 __ast_read: DTMF begin emulation of '5' with duration 100 queued on Zap/32-1
[Sep 14 11:24:59] DTMF[962]: channel.c:2465 __ast_read: DTMF end emulation of '5' queued on Zap/32-1
[Sep 14 11:24:59] DTMF[962]: channel.c:2346 __ast_read: DTMF end '#' received on Zap/32-1, duration 0 ms
[Sep 14 11:24:59] DTMF[962]: channel.c:2382 __ast_read: DTMF begin emulation of '#' with duration 100 queued on Zap/32-1
[Sep 14 11:24:59] DTMF[962]: channel.c:2465 __ast_read: DTMF end emulation of '#' queued on Zap/32-1
 == Parsing '/etc/asterisk/meetme.conf': Found
[Sep 14 11:24:59] DEBUG[962]: app_meetme.c:2413 find_conf: 55 isn't a valid conference
   -- <Zap/32-1> Playing 'conf-invalid' (language 'en')
   -- Channel 0/1, span 2 got hangup request, cause 16
[Sep 14 11:25:02] WARNING[962]: file.c:626 ast_readaudio_callback: Failed to write frame
   -- <Zap/32-1> Playing 'conf-getconfno' (language 'en')
 == Spawn extension (external_in, 17902998, 2) exited non-zero on 'Zap/32-1'
[Sep 14 11:25:02] DEBUG[962]: chan_zap.c:2964 zt_setoption: Set option AUDIO MODE, value: ON(1) on Zap/32-1
[Sep 14 11:25:02] DEBUG[962]: chan_zap.c:2603 zt_hangup: Not yet hungup...  Calling hangup once with icause, and clearing call
[Sep 14 11:25:02] DEBUG[962]: chan_zap.c:2960 zt_setoption: Set option AUDIO MODE, value: OFF(0) on Zap/32-1
   -- Hungup 'Zap/32-1'
[Sep 14 11:25:02] DEBUG[962]: cdr_addon_mysql.c:211 mysql_log: cdr_mysql: inserting a CDR record.
[Sep 14 11:25:02] DEBUG[962]: cdr_addon_mysql.c:227 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr_asterisk (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-09-14 11:24:54','','','17902998','external_in', 'Zap/32-1','','MeetMe','',8,5,'ANSWERED',3,'','1189761894.3','')
By: Marc Heubes (worfinator) 2007-09-17 04:03:30

How to continue on this? Is there a way tu debug the zap driver/modul?

Regards,
Marc.
By: Marc Heubes (worfinator) 2007-09-18 08:17:35

I did some further testing. The problem seems to be that prompts can't be interrupted correctly in general - not only at the beginning of calls as I thought initially.
By: Russell Bryant (russell) 2008-04-22 10:44:56

Unfortunately, we were never able to reproduce this issue.  However, there have been a _lot_ of DTMF realted fixes since this issue was reported.  If you still have a problem with the latest release, feel free to reopen this issue, or create a new one.