[asterisk-users] 4 sec delay in voice menu (asterisk)
Albert
alberton at wp.pl
Mon Nov 7 08:28:36 CST 2011
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)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20111107/182c3633/attachment.htm>
More information about the asterisk-users
mailing list