[asterisk-users] 4 sec delay in voice menu (asterisk)

Eric Wieling EWieling at nyigc.com
Mon Nov 7 08:35:55 CST 2011 

Asterisk does not know if the user is dialing "2" or dialing "2666", so it must wait for a timeout.   Rewrite your dialplan so there are no ambiguous extensions in the context and it will work as expected.

-----Original Message-----
From: asterisk-users-bounces at lists.digium.com [mailto:asterisk-users-bounces at lists.digium.com] On Behalf Of Albert
Sent: Monday, November 07, 2011 9:29 AM
To: Asterisk Users Mailing List - Non-Commercial Discussion
Subject: [asterisk-users] 4 sec delay in voice menu (asterisk)

Hi guys, 

I have very weird case, which i dont understand. I have voice menu where customer is choosing language, and all works fine apart from this that after pressing 1 applications related to 1-ext are being processed immediatly and after pressinf 2, there is 4-5 sec delay betweek 1st application is being processed related to that extension 2.

Difference which i am seeing in this log files is that in 2nd case, there is "  == CDR updated on ...", but why in 1st case it isnt and in 2nd is ? Could that be my source of problem ?

Thanks for your help, any hint will do

Regards
Robert
---------------------------------------

Below you can find part of menu from and log files....


*** menu ***
[voiceservices_menu]
exten => 2666,1,Background(custom/l_stories/swelcome)
exten => 2666,n,WaitExten(15)  ;wait 15 sec

exten => 1,1,Verbose(Customer pressed key 1) exten => 1,n,Goto(storiesmenu-lu,2666,1) ;if customer choosed 1 jump to LU lang

exten => 2,1,Verbose(Customer pressed key 2) exten => 2,n,Goto(storiesmenu-en,2666,1) ;if customer choosed 1 jump to EN lang

exten => i,1,Playback(invalid)
exten => i,n,Goto(voiceservices_menu,2666,1)

exten => t,1,Playback(vm-goodbye)
exten => t,n,Goto(voiceservices_menu,2666,1)

*** console log, without delay after pressing 1 *** voice*CLI> [Nov  7 17:01:24] DTMF[12808]: channel.c:3960 __ast_read: DTMF begin '1' received on IAX2/spiderman-6887 [Nov  7 17:01:24] DTMF[12808]: channel.c:3964 __ast_read: DTMF begin ignored '1' on IAX2/spiderman-6887 [Nov  7 17:01:24] DTMF[12808]: channel.c:3875 __ast_read: DTMF end '1' received on IAX2/spiderman-6887, duration 0 ms [Nov  7 17:01:24] DTMF[12808]: channel.c:3933 __ast_read: DTMF end accepted without begin '1' on IAX2/spiderman-6887 [Nov  7 17:01:24] DTMF[12808]: channel.c:3944 __ast_read: DTMF end passthrough '1' on IAX2/spiderman-6887 [Nov  7 17:01:24] DEBUG[12808]: channel.c:3402 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov  7 17:01:24] DEBUG[12808]: channel.c:3402 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov  7 17:01:24] DEBUG[12808]: channel.c:5018 set_format: Set channel IAX2/spiderman-6887 to write format ulaw [Nov  7 17:01:24] DEBUG[12808]: pbx.c:4067 pbx_extension_helper: Launching 'Verbose'
    -- Executing [1 at incoming-from-spiderman:1] Verbose("IAX2/spiderman-6887", "Customer pressed key 1") in new stack Customer pressed key 1 [Nov  7 17:01:24] DEBUG[12808]: pbx.c:4067 pbx_extension_helper: Launching 'Goto'
    -- Executing [1 at incoming-from-spiderman:2] Goto("IAX2/spiderman-6887", "storiesmenu-lu,2666,1") in new stack
    -- Goto (storiesmenu-lu,2666,1)
[Nov  7 17:01:24] DEBUG[12808]: pbx.c:4067 pbx_extension_helper: Launching 'BackGround'
    -- Executing [2666 at storiesmenu-lu:1] BackGround("IAX2/spiderman-6887", "custom/l_stories/lu_service_menu") in new stack [Nov  7 17:01:24] DEBUG[12808]: channel.c:5018 set_format: Set channel IAX2/spiderman-6887 to write format gsm [Nov  7 17:01:24] DEBUG[12808]: channel.c:3402 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <IAX2/spiderman-6887> Playing 'custom/l_stories/lu_service_menu.gsm' (language 'en') [Nov  7 17:01:25] DEBUG[28034]: chan_iax2.c:10631 socket_process: Immediately destroying 6887, having received hangup [Nov  7 17:01:25] DEBUG[12808]: channel.c:3402 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov  7 17:01:25] DEBUG[12808]: channel.c:3402 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Nov  7 17:01:25] DEBUG[12808]: channel.c:5018 set_format: Set channel IAX2/spiderman-6887 to write format ulaw



*** console log, 4 sec delay after pressing 2 ***
[Nov  7 17:19:42] DTMF[13309]: channel.c:3875 __ast_read: DTMF end '2' received on IAX2/spiderman-7784, duration 0 ms
[Nov  7 17:19:42] DTMF[13309]: channel.c:3933 __ast_read: DTMF end accepted without begin '2' on IAX2/spiderman-7784
[Nov  7 17:19:42] DTMF[13309]: channel.c:3944 __ast_read: DTMF end passthrough '2' on IAX2/spiderman-7784
[Nov  7 17:19:42] DEBUG[13309]: channel.c:3402 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov  7 17:19:42] DEBUG[13309]: channel.c:3402 ast_settimeout: Scheduling timer at (0 requested / 0 actual) timer ticks per second
[Nov  7 17:19:42] DEBUG[13309]: channel.c:5018 set_format: Set channel IAX2/spiderman-7784 to write format ulaw
[Nov  7 17:19:42] DEBUG[13309]: pbx.c:4734 __ast_pbx_run: Oooh, got something to jump out with ('2')!
[Nov  7 17:19:46] DEBUG[28037]: chan_iax2.c:2366 peercnt_add: ip callno count incremented to 4 for 62.233.208.241
[Nov  7 17:19:46] DEBUG[28022]: chan_iax2.c:13889 iax2_devicestate: Checking device state for device spiderman
[Nov  7 17:19:46] DEBUG[28022]: chan_iax2.c:13897 iax2_devicestate: iax2_devicestate: Found peer. What's device state of spiderman? addr=1055510769, defaddr=0 maxms=0, lastms=0
[Nov  7 17:19:46] DEBUG[28022]: devicestate.c:458 do_state_change: Changing state for IAX2/spiderman - state 2 (In use)
[Nov  7 17:19:46] DEBUG[28022]: devicestate.c:438 devstate_event: device 'IAX2/spiderman' state '2'
[Nov  7 17:19:46] DEBUG[28052]: app_queue.c:1330 handle_statechange: Device 'IAX2/spiderman' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov  7 17:19:46] DEBUG[28022]: chan_iax2.c:13889 iax2_devicestate: Checking device state for device spiderman
[Nov  7 17:19:46] DEBUG[28022]: chan_iax2.c:13897 iax2_devicestate: iax2_devicestate: Found peer. What's device state of spiderman? addr=1055510769, defaddr=0 maxms=0, lastms=0
[Nov  7 17:19:46] DEBUG[28022]: devicestate.c:458 do_state_change: Changing state for IAX2/spiderman - state 2 (In use)
[Nov  7 17:19:46] DEBUG[28022]: devicestate.c:438 devstate_event: device 'IAX2/spiderman' state '2'
[Nov  7 17:19:46] DEBUG[28052]: app_queue.c:1330 handle_statechange: Device 'IAX2/spiderman' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Nov  7 17:19:46] DEBUG[28034]: chan_iax2.c:2714 sched_delay_remove: schedule decrement of callno used for 62.233.208.241 in 60 seconds
  == CDR updated on IAX2/spiderman-7784
[Nov  7 17:19:47] DEBUG[13309]: pbx.c:4067 pbx_extension_helper: Launching 'Verbose'
    -- Executing [2 at incoming-from-spiderman:1] Verbose("IAX2/spiderman-7784", "Customer pressed key 2") in new stack
Customer pressed key 2
[Nov  7 17:19:47] DEBUG[13309]: pbx.c:4067 pbx_extension_helper: Launching 'Goto'
    -- Executing [2 at incoming-from-spiderman:2] Goto("IAX2/spiderman-7784", "storiesmenu-en,2666,1") in new stack
    -- Goto (storiesmenu-en,2666,1)
[Nov  7 17:19:47] DEBUG[13309]: pbx.c:4067 pbx_extension_helper: Launching 'BackGround'
    -- Executing [2666 at storiesmenu-en:1] BackGround("IAX2/spiderman-7784", "custom/l_stories/en_service_menu") in new stack
[Nov  7 17:19:47] DEBUG[13309]: channel.c:5018 set_format: Set channel IAX2/spiderman-7784 to write format gsm
[Nov  7 17:19:47] DEBUG[13309]: channel.c:3402 ast_settimeout: Scheduling timer at (50 requested / 50 actual) timer ticks per second
    -- <IAX2/spiderman-7784> Playing 'custom/l_stories/en_service_menu.gsm' (language 'en')
[Nov  7 17:19:49] DEBUG[28045]: acl.c:715 ast_ouraddrfor: For destination '192.168.2.124', our source address is '10.0.0.6'.
[Nov  7 17:19:49] DEBUG[28045]: chan_sip.c:3243 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.0.0.6:5060
[Nov  7 17:19:49] DEBUG[28045]: chan_sip.c:7215 sip_alloc: Allocating new SIP dialog for 2a117190-c1f63b91-a8eee9ca at 192.168.2.124 - REGISTER (No RTP)

More information about the asterisk-users mailing list