Page 1 of 2

Pause after called party answers before agent can hear them

PostPosted: Fri Feb 09, 2007 4:56 pm
by ckwall
There is a small pause that occurs after the dialed party answers the phone before the agent can hear them. The caller says hello about 2 times before the agent is able to hear them or talk to them. Any ideas?

PostPosted: Sat Feb 10, 2007 1:01 am
by mflorell
What kind of trunks are you using?

What version of Asterisk?

What verison of astGUIclient?

What is the loadavg of your server when this happens?

What are the specs on your server?

PostPosted: Sat Feb 10, 2007 8:49 am
by ckwall
SIP Trunks
Asterisk SVN-branch-1.2-r48356M
astguiclient_2.0.3b2

[root@dialer ~]# top
top - 06:45:54 up 1 day, 18:24, 1 user, load average: 0.00, 0.00, 0.00
Tasks: 94 total, 2 running, 92 sleeping, 0 stopped, 0 zombie
Cpu(s): 1.0% us, 0.7% sy, 0.0% ni, 98.3% id, 0.0% wa, 0.0% hi, 0.0% si
Mem: 2075720k total, 827340k used, 1248380k free, 84656k buffers
Swap: 2031608k total, 0k used, 2031608k free, 499752k cached

[root@dialer src]# lspci
00:00.0 Host bridge: VIA Technologies, Inc. K8T800Pro Host Bridge
00:00.1 Host bridge: VIA Technologies, Inc. K8T800Pro Host Bridge
00:00.2 Host bridge: VIA Technologies, Inc. K8T800Pro Host Bridge
00:00.3 Host bridge: VIA Technologies, Inc. K8T800Pro Host Bridge
00:00.4 Host bridge: VIA Technologies, Inc. K8T800Pro Host Bridge
00:00.7 Host bridge: VIA Technologies, Inc. K8T800Pro Host Bridge
00:01.0 PCI bridge: VIA Technologies, Inc. VT8237 PCI bridge [K8T800/K8T890 South]
00:09.0 Ethernet controller: Intel Corporation 82546GB Gigabit Ethernet Controller (rev 03)
00:09.1 Ethernet controller: Intel Corporation 82546GB Gigabit Ethernet Controller (rev 03)
00:0a.0 Ethernet controller: Marvell Technology Group Ltd. 88E8001 Gigabit Ethernet Controller (rev 13)
00:0f.0 RAID bus controller: VIA Technologies, Inc. VIA VT6420 SATA RAID Controller (rev 80)
00:0f.1 IDE interface: VIA Technologies, Inc. VT82C586A/B/VT82C686/A/B/VT823x/A/C PIPC Bus Master IDE (rev 06)
00:10.0 USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 81)
00:10.1 USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 81)
00:10.2 USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 81)
00:10.3 USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 81)
00:10.4 USB Controller: VIA Technologies, Inc. USB 2.0 (rev 86)
00:11.0 ISA bridge: VIA Technologies, Inc. VT8237 ISA bridge [KT600/K8T800/K8T890 South]
00:18.0 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] HyperTransport Technology Configuration
00:18.1 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] Address Map
00:18.2 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] DRAM Controller
00:18.3 Host bridge: Advanced Micro Devices [AMD] K8 [Athlon64/Opteron] Miscellaneous Control
01:00.0 VGA compatible controller: nVidia Corporation NV18 [GeForce4 MX 4000 AGP 8x] (rev c1)
[root@dialer src]#

PostPosted: Sat Feb 10, 2007 8:57 am
by mflorell
Are you using the "sip-silence" Playback line at the beginning of your 8365 exten?

What Processor and speed?

What Linux distro?

PostPosted: Sat Feb 10, 2007 9:05 am
by ckwall
Are you using the "sip-silence" Playback line at the beginning of your 8365 exten?
; VICIDIAL_auto_dialer transfer script:
exten => 8365,1,Playback(sip-silence)
exten => 8365,n,AGI(call_log.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,Hangup

What Processor and speed?
AMD Athlon(tm) 64 Processor 3500+

What Linux distro?
CentOS 4.4

PostPosted: Sat Feb 10, 2007 1:59 pm
by mflorell
Who is your carrier?

I use T1 PRI lines and IAX trunks and the transfer time is always less than half a second.

PostPosted: Sat Feb 10, 2007 10:58 pm
by Op3r
hows your network diagram? are they connected locally? is it a normal occurrence even if you do manual dial directly?

PostPosted: Sun Feb 11, 2007 2:48 pm
by ckwall
This is only when the campaign auto dials. if I manually dial, it works just fine. I used the manual dial link on the agc/vicidial.php screen to test, while logged into a campaign.

PostPosted: Sun Feb 11, 2007 2:52 pm
by ckwall
it seems to be something in my settings. Based on the fact that manually dialing from asterisk and manually dialing from AGC work just fine. It is only when I am using the autodial that I have this issue.

PostPosted: Sun Feb 11, 2007 9:30 pm
by Op3r
whats the load of your server when you are on auto dial mode? is it a multiserver set up?

PostPosted: Mon Feb 12, 2007 10:23 am
by ckwall
It is only a single server with 4 phones connected to it. For my testing I am able to reproduce this issue with only one phone on logged in and as little as 1 lead in the list to be dialed. The load is very minimal.

This is top output whith the dialer running and dialing out a number in autodial mode:
Cpu(s): 1.0% us, 0.3% sy, 0.0% ni, 98.7% id, 0.0% wa, 0.0% hi, 0.0% si
Mem: 2075720k total, 355764k used, 1719956k free, 43252k buffers
Swap: 2031608k total, 0k used, 2031608k free, 203488k cached

PostPosted: Mon Feb 12, 2007 1:03 pm
by mflorell
Auto dial will not send a call to an agent until the Answer signal is sent from the carrier. There are many SIP termination providers that send this Answer signal 1-5 seconds after the actual Answer has occured. I would recommend trying another carrier or another piece of SIP termination equipment.

PostPosted: Mon Feb 12, 2007 1:18 pm
by ckwall
well... when i use manual dial it all works just fine. i am acutually using T1s, but they are plugged into another asterisk server. So I am using SIP to get from the vicidial server to the other asterisk server which is connected to the Zaptel device (PRI lines) If this were an issue with carrier and answer, wouldnt I this issue with manual dial from vicidial and manual dial from asterisk?

PostPosted: Mon Feb 12, 2007 1:49 pm
by mflorell
In auto-dial mode the call is not placed from within the meetme room as it is when you manual dial. In manual dial you hear the ringing and the Answer signal doesn't matter. In auto-dial mode, the Answer signal is what triggers the call to be forwarded on to the agent's meetme room.

How is your PRI-connected Asterisk server configured?(Asterisk version/Linux version/Loadavg)

PostPosted: Mon Feb 12, 2007 2:57 pm
by ckwall
How is your PRI-connected Asterisk server configured?(Asterisk version/Linux version/Loadavg)

Asterisk version 1.2.14
Linux Version Redhat Enterprise 4.4
cat /proc/loadavg
0.77 1.31 1.36 2/171 16772

PostPosted: Mon Feb 12, 2007 3:44 pm
by ckwall
I wonder if that is the case... I am going to plug a t1 into it and see how that affects it.

PostPosted: Tue Feb 13, 2007 11:28 am
by ckwall
I have added a T1 and am placing the calls from there... It seem that it does not make any difference.

PostPosted: Tue Feb 13, 2007 12:36 pm
by ckwall
so dialing from the dialer in autodial mode out via zap to a pri t1 does not eliminate the pause. I had one call with a 3.5 second pause from the time the call was answered until the time the agent phone could hear them.

PostPosted: Tue Feb 13, 2007 3:03 pm
by ckwall
if it matters, this was an upgrade from 2.0.1 to 2.0.3

PostPosted: Tue Feb 13, 2007 3:35 pm
by mflorell
Have you watched the Asterisk CLI while you are calling to see when the Answer signal is sent from the carrier?

Is your database on the same server?

Have you tried an IAX or SIP trunk from another carrier to see if the delay is the same for other carriers?

PostPosted: Tue Feb 13, 2007 3:43 pm
by ckwall
the database is on a different server. I will watch the answer and see what I can find. I can reporoduce the issue with sip and iax connections to another server as well as with a voice PRI directly into my digium card on that server. so it makes no difference what carrier i use.

PostPosted: Tue Feb 13, 2007 3:56 pm
by mflorell
Have you actually tried another carrier, or just SIP/IAX to the same PRI connected on another Asterisk server?

PostPosted: Tue Feb 13, 2007 4:00 pm
by ckwall
from when the call is dialed and answered till the time the two parties can talk to each other there is about 2 seconds of delay.

Here is what is happening:

Started the CLI to watch the output

== Manager 'sendcron' logged off from 10.0.1.180
== Manager 'sendcron' logged off from 10.0.1.180

From the agc/vicidial.php I logged the agent in.

== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 10.0.1.180

Answered the ringing agent phone

> Channel SIP/1718-086e91c0 was answered.
== Manager 'sendcron' logged off from 10.0.1.180
-- Executing MeetMe("SIP/1718-086e91c0", "8600053|q") in new stack
== Parsing '/etc/asterisk/meetme.conf': Found
-- Created MeetMe conference 1022 for conference '8600053'
== Refreshing DNS lookups.
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 10.0.1.180
-- Executing AGI("Local/91801828XXXX@default-0ead,2", "call_log.agi|91801828XXXX") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/call_log.agi
-- AGI Script call_log.agi completed, returning 0
-- Executing Dial("Local/91801828XXXX@default-0ead,2", "Zap/g1/1801828XXXX||tTo") in new stack
-- Requested transfer capability: 0x00 - SPEECH
-- Called g1/1801828XXXX
-- Zap/3-1 is proceeding passing it to Local/91801828XXXX@default-0ead,2
Feb 13 13:47:57 NOTICE[27010]: channel.c:2482 __ast_request_and_dial: Don't know what to do with control frame 15
-- Zap/3-1 is making progress passing it to Local/91801828XXXX@default-0ead,2
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 10.0.1.180
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 10.0.1.180
== Manager 'sendcron' logged off from 10.0.1.180
== Manager 'sendcron' logged off from 10.0.1.180

Answered my cell phone

-- Zap/3-1 answered Local/91801828XXXX@default-0ead,2
> Channel Local/91801828XXXX@default-0ead,1 was answered.
== Manager 'sendcron' logged off from 10.0.1.180
-- Executing AGI("Local/91801828XXXX@default-0ead,1", "call_log.agi|8365") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/call_log.agi
== Spawn extension (default, 91801828XXXX, 2) exited non-zero on 'Local/91801828XXXX@default-0ead,2'
-- Executing DeadAGI("Local/91801828XXXX@default-0ead,2", "call_log.agi|h") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/call_log.agi
-- AGI Script call_log.agi completed, returning 0
-- Executing AGI("Zap/3-1", "agi-VDADtransfer.agi|8365") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDADtransfer.agi
-- AGI Script call_log.agi completed, returning 0
-- Executing DeadAGI("Local/91801828XXXX@default-0ead,2", "VD_hangup.agi|PRI-----NODEBUG-----16-----ANSWER-----13-----0") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/VD_hangup.agi
-- AGI Script VD_hangup.agi completed, returning 0
-- AGI Script agi-VDADtransfer.agi completed, returning 0
-- Executing MeetMe("Zap/3-1", "8600053|q") in new stack
== Parsing '/etc/asterisk/manager.conf': Found
== Manager 'sendcron' logged on from 10.0.1.180

Was able to hear and talk to both sides of the call at this point

-- Executing MeetMe("Local/78600053@default-eb32,2", "8600053|q") in new stack
> Channel Local/78600053@default-eb32,1 was answered.
-- Executing Answer("Local/78600053@default-eb32,1", "") in new stack
-- Executing Monitor("Local/78600053@default-eb32,1", "wav|20070213-134813_801828XXXX") in new stack
-- Executing Wait("Local/78600053@default-eb32,1", "3600") in new stack
-- Channel 0/3, span 1 got hangup request
== Spawn extension (default, 8600053, 1) exited non-zero on 'Zap/3-1'
-- Executing DeadAGI("Zap/3-1", "call_log.agi|h") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/call_log.agi
-- AGI Script call_log.agi completed, returning 0
-- Executing DeadAGI("Zap/3-1", "VD_hangup.agi|PRI-----NODEBUG-----16---------------") in new stack
-- Launched AGI Script /var/lib/asterisk/agi-bin/VD_hangup.agi
-- AGI Script VD_hangup.agi completed, returning 0
-- Hungup 'Zap/3-1'
dialer*CLI>
[root@dialer ~]#

PostPosted: Tue Feb 13, 2007 4:02 pm
by ckwall
Have you actually tried another carrier, or just SIP/IAX to the same PRI connected on another Asterisk server?


The pri is from a different provider

PostPosted: Wed Feb 14, 2007 7:32 am
by mflorell
Could you post the agiout logfile output for the transfer AGI script from this time period?

PostPosted: Wed Feb 14, 2007 10:00 am
by ckwall
I think this is for that call. Let me know if it looks like I missed something:

2007-02-13 13:47:57|call_log.agi|Perl Environment Dump:
2007-02-13 13:47:57|call_log.agi|0|91801828XXXX
2007-02-13 13:47:57|call_log.agi|AGI Environment Dump:
2007-02-13 13:47:57|call_log.agi| -- accountcode =
2007-02-13 13:47:57|call_log.agi| -- callerid = 1801828000
2007-02-13 13:47:57|call_log.agi| -- calleridname = V0213134756000000320
2007-02-13 13:47:57|call_log.agi| -- callingani2 = 0
2007-02-13 13:47:57|call_log.agi| -- callingpres = 0
2007-02-13 13:47:57|call_log.agi| -- callingtns = 0
2007-02-13 13:47:57|call_log.agi| -- callington = 0
2007-02-13 13:47:57|call_log.agi| -- channel = Local/91801828XXXX@default-0ead,2
2007-02-13 13:47:57|call_log.agi| -- context = default
2007-02-13 13:47:57|call_log.agi| -- dnid = unknown
2007-02-13 13:47:57|call_log.agi| -- enhanced = 0.0
2007-02-13 13:47:57|call_log.agi| -- extension = 91801828XXXX
2007-02-13 13:47:57|call_log.agi| -- language = en
2007-02-13 13:47:57|call_log.agi| -- priority = 1
2007-02-13 13:47:57|call_log.agi| -- rdnis = unknown
2007-02-13 13:47:57|call_log.agi| -- request = call_log.agi
2007-02-13 13:47:57|call_log.agi| -- type = Local
2007-02-13 13:47:57|call_log.agi| -- uniqueid = 1171399677.279
2007-02-13 13:47:57|call_log.agi|AGI Variables: |1171399677.279|Local/91801828XXXX@default-0ead,2|91801828XXXX|Local|V0213134756000000320|
2007-02-13 13:47:57|call_log.agi|+++++ CALL LOG START : 2007-02-13 13:47:57
2007-02-13 13:47:57|call_log.agi||INSERT INTO call_log (uniqueid,channel,channel_group,type,server_ip,extension,number_dialed,start_time,start_epoch,end_time,end_epoch,length_in_sec,length_in_min,caller_code) values('1171399677.279','Local/91801828XXXX@default-0ead,2','','Local','10.0.1.180','918018285230','','2007-02-13 13:47:57','1171399677','','','',$
2007-02-13 13:48:10|call_log.agi|Perl Environment Dump:

PostPosted: Wed Feb 14, 2007 1:24 pm
by mflorell
can you post the agi-VDADtransfer.agi part?

PostPosted: Wed Feb 14, 2007 1:49 pm
by ckwall
2007-02-13 13:47:57|call_log.agi|Perl Environment Dump:
2007-02-13 13:47:57|call_log.agi|0|91801828XXXX
2007-02-13 13:47:57|call_log.agi|AGI Environment Dump:
2007-02-13 13:47:57|call_log.agi| -- accountcode =
2007-02-13 13:47:57|call_log.agi| -- callerid = 1801828000
2007-02-13 13:47:57|call_log.agi| -- calleridname = V0213134756000000320
2007-02-13 13:47:57|call_log.agi| -- callingani2 = 0
2007-02-13 13:47:57|call_log.agi| -- callingpres = 0
2007-02-13 13:47:57|call_log.agi| -- callingtns = 0
2007-02-13 13:47:57|call_log.agi| -- callington = 0
2007-02-13 13:47:57|call_log.agi| -- channel = Local/91801828XXXX@default-0ead,2
2007-02-13 13:47:57|call_log.agi| -- context = default
2007-02-13 13:47:57|call_log.agi| -- dnid = unknown
2007-02-13 13:47:57|call_log.agi| -- enhanced = 0.0
2007-02-13 13:47:57|call_log.agi| -- extension = 91801828XXXX
2007-02-13 13:47:57|call_log.agi| -- language = en
2007-02-13 13:47:57|call_log.agi| -- priority = 1
2007-02-13 13:47:57|call_log.agi| -- rdnis = unknown
2007-02-13 13:47:57|call_log.agi| -- request = call_log.agi
2007-02-13 13:47:57|call_log.agi| -- type = Local
2007-02-13 13:47:57|call_log.agi| -- uniqueid = 1171399677.279
2007-02-13 13:47:57|call_log.agi|AGI Variables: |1171399677.279|Local/91801828XXXX@default-0ead,2|91801828XXXX|Local|V0213134756000000320|
2007-02-13 13:47:57|call_log.agi|+++++ CALL LOG START : 2007-02-13 13:47:57
2007-02-13 13:47:57|call_log.agi||INSERT INTO call_log (uniqueid,channel,channel_group,type,server_ip,extension,number_dialed,start_time,start_epoch,end_time,end_epoch,length_in_sec,length_in_min,caller_code) values('1171399677.279','Local/91801828XXXX@default-0ead,2','','Local','10.0.1.180','91801828XXXX','','2007-02-13 13:47:57','1171399677','','','','','V0213134756000000320')|
2007-02-13 13:48:10|call_log.agi|Perl Environment Dump:
2007-02-13 13:48:10|call_log.agi|0|8365
2007-02-13 13:48:10|call_log.agi|AGI Environment Dump:
2007-02-13 13:48:10|call_log.agi| -- accountcode =
2007-02-13 13:48:10|call_log.agi| -- callerid = 1801828000
2007-02-13 13:48:10|call_log.agi| -- calleridname = V0213134756000000320
2007-02-13 13:48:10|call_log.agi| -- callingani2 = 0
2007-02-13 13:48:10|call_log.agi| -- callingpres = 0
2007-02-13 13:48:10|call_log.agi| -- callingtns = 0
2007-02-13 13:48:10|call_log.agi| -- callington = 0
2007-02-13 13:48:10|call_log.agi| -- channel = Local/91801828XXXX@default-0ead,1
2007-02-13 13:48:10|call_log.agi| -- context = default
2007-02-13 13:48:10|call_log.agi| -- dnid = unknown
2007-02-13 13:48:10|call_log.agi| -- enhanced = 0.0
2007-02-13 13:48:10|call_log.agi| -- extension = 8365
2007-02-13 13:48:10|call_log.agi| -- language = en
2007-02-13 13:48:10|call_log.agi| -- priority = 1
2007-02-13 13:48:10|call_log.agi| -- rdnis = unknown
2007-02-13 13:48:10|call_log.agi| -- request = call_log.agi
2007-02-13 13:48:10|call_log.agi| -- type = Local
2007-02-13 13:48:10|call_log.agi| -- uniqueid = 1171399677.278
2007-02-13 13:48:10|call_log.agi|AGI Variables: |1171399677.278|Local/91801828XXXX@default-0ead,1|8365|Local|V0213134756000000320|
2007-02-13 13:48:10|call_log.agi|+++++ CALL LOG START : 2007-02-13 13:48:10
2007-02-13 13:48:10|call_log.agi||INSERT INTO call_log (uniqueid,channel,channel_group,type,server_ip,extension,number_dialed,start_time,start_epoch,end_time,end_epoch,length_in_sec,length_in_min,caller_code) values('1171399677.278','Local/91801828XXXX@default-0ead,1','','Local','10.0.1.180','8365','','2007-02-13 13:48:10','1171399690','','','','','V0213134756000000320')|
2007-02-13 13:48:11|call_log.agi|AGI Environment Dump:
2007-02-13 13:48:11|call_log.agi| -- accountcode =
2007-02-13 13:48:11|call_log.agi| -- callerid = 1801828000
2007-02-13 13:48:11|call_log.agi| -- calleridname = V0213134756000000320
2007-02-13 13:48:11|call_log.agi| -- callingani2 = 0
2007-02-13 13:48:11|call_log.agi| -- callingpres = 0
2007-02-13 13:48:11|call_log.agi| -- callingtns = 0
2007-02-13 13:48:11|call_log.agi| -- callington = 0
2007-02-13 13:48:11|call_log.agi| -- channel = Local/91801828XXXX@default-0ead,2
2007-02-13 13:48:11|call_log.agi| -- context = default
2007-02-13 13:48:11|call_log.agi| -- dnid = unknown
2007-02-13 13:48:11|call_log.agi| -- enhanced = 0.0
2007-02-13 13:48:11|call_log.agi| -- extension = h
2007-02-13 13:48:11|call_log.agi| -- language = en
2007-02-13 13:48:11|call_log.agi| -- priority = 1
2007-02-13 13:48:11|call_log.agi| -- rdnis = unknown
2007-02-13 13:48:11|call_log.agi| -- request = call_log.agi
2007-02-13 13:48:11|call_log.agi| -- type = Local
2007-02-13 13:48:11|call_log.agi| -- uniqueid = 1171399677.279
2007-02-13 13:48:11|call_log.agi|AGI Variables: |1171399677.279|Local/91801828XXXX@default-0ead,2|h|Local|V0213134756000000320|
2007-02-13 13:48:11|call_log.agi||CALL HUNG UP|
2007-02-13 13:48:11|call_log.agi||1171399677.2790000|1171399677|
2007-02-13 13:48:11|call_log.agi|QUERY done: start time = 1171399677 | sec: 14 | min: 0.23 |
2007-02-13 13:48:11|call_log.agi||UPDATE call_log set end_time='2007-02-13 13:48:11',end_epoch='1171399691',length_in_sec=14,length_in_min=' 0.23' where uniqueid='1171399677.279'|
2007-02-13 13:48:11|call_log.agi||DELETE from live_inbound where uniqueid='1171399677.279' and server_ip='10.0.1.180'|
2007-02-13 13:48:11|call_log.agi|+++++ CALL LOG HUNGUP: |1171399677.279|Local/91801828XXXX@default-0ead,2|h|2007-02-13 13:48:11|min: 0.23|
2007-02-13 13:48:11|agi-VDADtransfer.agi|Perl Environment Dump:
2007-02-13 13:48:11|agi-VDADtransfer.agi|0|8365
2007-02-13 13:48:11|agi-VDADtransfer.agi|callerID changed: V0213134756000000320
2007-02-13 13:48:11|agi-VDADtransfer.agi|AGI Environment Dump:
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- accountcode =
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- callerid = 1801828000
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- calleridname = V0213134756000000320
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- callingani2 = 0
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- callingpres = 0
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- callingtns = 0
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- callington = 0
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- channel = Zap/3-1
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- context = default
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- dnid = unknown
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- enhanced = 0.0
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- extension = 8365
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- language = en
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- priority = 2
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- rdnis = unknown
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- request = agi-VDADtransfer.agi
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- type = Zap
2007-02-13 13:48:11|agi-VDADtransfer.agi| -- uniqueid = 1171399677.278
2007-02-13 13:48:11|agi-VDADtransfer.agi|AGI Variables: |1171399677.278|Zap/3-1|8365|Zap|V0213134756000000320|V0213134756000000320|2|
2007-02-13 13:48:11|agi-VDADtransfer.agi|+++++ VDAD START : |320|2007-02-13 13:48:11|SVN-branch-1.2-r4835|2|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD : |1|update of vac table: V0213134756000000320
|UPDATE vicidial_auto_calls set uniqueid='1171399677.278', channel='Zap/3-1',status='LIVE',stage='LIVE-0' where callerid='V0213134756000000320' order by call_time desc limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1171399677.278','320','9999','2007-02-13 13:48:11','1171399691','QUEUE','1','801828XXXX','VDAD','N')|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD : |320|320|insert to vicidial_log: 1171399677.278
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_live_agents where server_ip='10.0.1.180' and campaign_id = '9999' and last_update_time > '20070213134806';|
2007-02-13 13:48:11|agi-VDADtransfer.agi||CONCURRENT TRANSFERS AUTO SETTING: 1 (0)|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|VD_hangup.agi|Perl Environment Dump:
2007-02-13 13:48:11|VD_hangup.agi|0|PRI-----NODEBUG-----16-----ANSWER-----13-----0
2007-02-13 13:48:11|VD_hangup.agi|AGI Environment Dump:
2007-02-13 13:48:11|VD_hangup.agi| -- accountcode =
2007-02-13 13:48:11|VD_hangup.agi| -- callerid = 1801828000
2007-02-13 13:48:11|VD_hangup.agi| -- calleridname = V0213134756000000320
2007-02-13 13:48:11|VD_hangup.agi| -- callingani2 = 0
2007-02-13 13:48:11|VD_hangup.agi| -- callingpres = 0
2007-02-13 13:48:11|VD_hangup.agi| -- callingtns = 0
2007-02-13 13:48:11|VD_hangup.agi| -- callington = 0
2007-02-13 13:48:11|VD_hangup.agi| -- channel = Local/91801828XXXX@default-0ead,2
2007-02-13 13:48:11|VD_hangup.agi| -- context = default
2007-02-13 13:48:11|VD_hangup.agi| -- dnid = unknown
2007-02-13 13:48:11|VD_hangup.agi| -- enhanced = 0.0
2007-02-13 13:48:11|VD_hangup.agi| -- extension = h
2007-02-13 13:48:11|VD_hangup.agi| -- language = en
2007-02-13 13:48:11|VD_hangup.agi| -- priority = 2
2007-02-13 13:48:11|VD_hangup.agi| -- rdnis = unknown
2007-02-13 13:48:11|VD_hangup.agi| -- request = VD_hangup.agi
2007-02-13 13:48:11|VD_hangup.agi| -- type = Local
2007-02-13 13:48:11|VD_hangup.agi| -- uniqueid = 1171399677.279
2007-02-13 13:48:11|VD_hangup.agi|AGI Variables: |1171399677.279|Local/91801828XXXX@default-0ead,2|h|Local|V0213134756000000320|
2007-02-13 13:48:11|VD_hangup.agi|DEBUG: NODEBUG
2007-02-13 13:48:11|VD_hangup.agi|VD_hangup : V0213134756000000320 Local/91801828XXXX@default-0ead,2 2 320
2007-02-13 13:48:11|VD_hangup.agi|-- VDhangup Local DEBUG: |PRI|V0213134756000000320|ANSWER|16|
2007-02-13 13:48:11|VD_hangup.agi|+++++ VDAD START LOCAL CHANNEL: EXITING- 2
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |0E0|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|NNNNNNNNNN No agent record found!!!
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='10.0.1.180' and campaign_id = '9999' and call_time < "2007-02-13 13:47:56" and lead_id != '320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD get agent: |1|update of vla table: 9999|10.0.1.180
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='320',uniqueid='1171399677.278', channel='Zap/3-1', callerid='V0213134756000000320' where status = 'READY' and server_ip='10.0.1.180' and campaign_id='9999' and last_update_time > '20070213134806' order by random_id limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi||SELECT conf_exten,user,extension FROM vicidial_live_agents where status = 'QUEUE' and server_ip='10.0.1.180' and campaign_id='9999' and callerid='V0213134756000000320' and channel='Zap/3-1' order by last_call_time limit 1;|
2007-02-13 13:48:11|agi-VDADtransfer.agi|-- VDAD XFER : |1|update of vac table: V0213134756000000320
|UPDATE vicidial_auto_calls set status='XFER', stage='XFER-2' where callerid='V0213134756000000320';|
2007-02-13 13:48:11|agi-VDADtransfer.agi|exiting the VDAD app, transferring call to 8600053
2007-02-13 13:48:13|agi-VDADtransfer.agi|XXXXXXXXXX VDAD transferred: start|stop 2007-02-13 13:48:11|2007-02-13 13:48:13
2007-02-13 13:48:16|call_log.agi|AGI Environment Dump:
2007-02-13 13:48:16|call_log.agi| -- accountcode =
2007-02-13 13:48:16|call_log.agi| -- callerid = unknown
2007-02-13 13:48:16|call_log.agi| -- calleridname = V0213134756000000320
2007-02-13 13:48:16|call_log.agi| -- callingani2 = 0
2007-02-13 13:48:16|call_log.agi| -- callingpres = 0
2007-02-13 13:48:16|call_log.agi| -- callingtns = 0
2007-02-13 13:48:16|call_log.agi| -- callington = 0
2007-02-13 13:48:16|call_log.agi| -- channel = Zap/3-1
2007-02-13 13:48:16|call_log.agi| -- context = default
2007-02-13 13:48:16|call_log.agi| -- dnid = unknown
2007-02-13 13:48:16|call_log.agi| -- enhanced = 0.0
2007-02-13 13:48:16|call_log.agi| -- extension = h
2007-02-13 13:48:16|call_log.agi| -- language = en
2007-02-13 13:48:16|call_log.agi| -- priority = 1
2007-02-13 13:48:16|call_log.agi| -- rdnis = unknown
2007-02-13 13:48:16|call_log.agi| -- request = call_log.agi
2007-02-13 13:48:16|call_log.agi| -- type = Zap
2007-02-13 13:48:16|call_log.agi| -- uniqueid = 1171399677.278
2007-02-13 13:48:16|call_log.agi|AGI Variables: |1171399677.278|Zap/3-1|h|Zap|V0213134756000000320|
2007-02-13 13:48:16|call_log.agi||CALL HUNG UP|
2007-02-13 13:48:16|call_log.agi||1171399677.2780001|1171399690|
2007-02-13 13:48:16|call_log.agi|QUERY done: start time = 1171399690 | sec: 6 | min: 0.10 |
2007-02-13 13:48:16|call_log.agi||UPDATE call_log set end_time='2007-02-13 13:48:16',end_epoch='1171399696',length_in_sec=6,length_in_min=' 0.10' where uniqueid='1171399677.278'|
2007-02-13 13:48:16|call_log.agi||DELETE from live_inbound where uniqueid='1171399677.278' and server_ip='10.0.1.180'|
2007-02-13 13:48:16|call_log.agi|+++++ CALL LOG HUNGUP: |1171399677.278|Zap/3-1|h|2007-02-13 13:48:16|min: 0.10|
2007-02-13 13:48:16|VD_hangup.agi|Perl Environment Dump:
2007-02-13 13:48:16|VD_hangup.agi|0|PRI-----NODEBUG-----16---------------
2007-02-13 13:48:16|VD_hangup.agi|AGI Environment Dump:
2007-02-13 13:48:16|VD_hangup.agi| -- accountcode =
2007-02-13 13:48:16|VD_hangup.agi| -- callerid = unknown
2007-02-13 13:48:16|VD_hangup.agi| -- calleridname = V0213134756000000320
2007-02-13 13:48:16|VD_hangup.agi| -- callingani2 = 0
2007-02-13 13:48:16|VD_hangup.agi| -- callingpres = 0
2007-02-13 13:48:16|VD_hangup.agi| -- callingtns = 0
2007-02-13 13:48:16|VD_hangup.agi| -- callington = 0
2007-02-13 13:48:16|VD_hangup.agi| -- channel = Zap/3-1
2007-02-13 13:48:16|VD_hangup.agi| -- context = default
2007-02-13 13:48:16|VD_hangup.agi| -- dnid = unknown
2007-02-13 13:48:16|VD_hangup.agi| -- enhanced = 0.0
2007-02-13 13:48:16|VD_hangup.agi| -- extension = h
2007-02-13 13:48:16|VD_hangup.agi| -- language = en
2007-02-13 13:48:16|VD_hangup.agi| -- priority = 2
2007-02-13 13:48:16|VD_hangup.agi| -- rdnis = unknown
2007-02-13 13:48:16|VD_hangup.agi| -- request = VD_hangup.agi
2007-02-13 13:48:16|VD_hangup.agi| -- type = Zap
2007-02-13 13:48:16|VD_hangup.agi| -- uniqueid = 1171399677.278
2007-02-13 13:48:16|VD_hangup.agi|AGI Variables: |1171399677.278|Zap/3-1|h|Zap|V0213134756000000320|
2007-02-13 13:48:16|VD_hangup.agi|DEBUG: NODEBUG
2007-02-13 13:48:16|VD_hangup.agi|VD_hangup : V0213134756000000320 Zap/3-1 2 320
2007-02-13 13:48:16|VD_hangup.agi||SELECT lead_id,callerid FROM vicidial_auto_calls where uniqueid = '1171399677.278' limit 1;|
2007-02-13 13:48:16|VD_hangup.agi|-- VDAC record deleted: |1| |320|1171399677.278|V0213134756000000320|10.0.1.180
2007-02-13 13:48:16|VD_hangup.agi||SELECT start_epoch,status FROM vicidial_log where uniqueid='1171399677.278' and lead_id='320' limit 1;|
2007-02-13 13:48:16|VD_hangup.agi|no VDL record found: 1171399677.278 V0213134756000000320 320 1171399677.278
2007-02-13 13:48:16|VD_hangup.agi||SELECT start_epoch,status,closecallid FROM vicidial_closer_log where lead_id = '320' and call_date > "2007-02-13 07:48:16" order by call_date desc limit 1;|
2007-02-13 13:48:16|VD_hangup.agi|no VDL or VDCL record found: 1171399677.278 V0213134756000000320 320 1171399677.278

PostPosted: Wed Feb 14, 2007 10:28 pm
by mflorell
Did you have an agent logged in to take this call?

NNNNNNNNNN No agent record found!!!

It looks like it took 2 seconds before there seemed to be an agent logged in.

PostPosted: Wed Feb 14, 2007 11:06 pm
by ckwall
yes. agent 1718 was logged in.

PostPosted: Thu Feb 15, 2007 7:14 am
by mflorell
This might not be it, but there have been several occurances of a problem like this being caused by CentOS.

For some reason the default 'nice' process prioritization for perl scripts is lowered on perl scripts and they do not run as they should. I have only seen this problem on some CentOS installs, and I have never found a way to fix it other than to change Distros to anything else.

PostPosted: Thu Feb 15, 2007 1:04 pm
by ckwall
Bulding an RHE 4.4 box to test this theory.

PostPosted: Wed Feb 28, 2007 9:39 am
by ckwall
I reinstalled all of this on RedHat Enterprise 4 and I have the same issue. Please help me.
I dont know if I mentioned this earlier or not. I am using the beta version because I need the alternate number feature. I dont know if this matters. Please help. I have been at this for a month now.

PostPosted: Wed Feb 28, 2007 4:30 pm
by mflorell
Have you tried another carrier like BinFone or Voxee just to test that it isn't your carrier?

CentOS is really just RHEL, can you try anything else like Fedora, Slackware, Debian, etc...?

PostPosted: Thu Apr 12, 2007 2:37 pm
by eijal
mflorell wrote:Are you using the "sip-silence" Playback line at the beginning of your 8365 exten?


If I use the "sip-silence" Playback line at the beginning of the 8365 extension.
It will be more or less delay?
I think more delay
thanks

PostPosted: Thu Apr 12, 2007 3:23 pm
by mflorell
If you are using a SIP provider there is a chance that using sip-silence would actually make the delay much less.

PostPosted: Thu Apr 12, 2007 5:58 pm
by eijal
mflorell wrote:If you are using a SIP provider there is a chance that using sip-silence would actually make the delay much less.


I am using IAX2 trunks, and my agents are using SIP phones.
Could I have less delay with these settings?

THANKS

PostPosted: Fri Apr 13, 2007 3:38 am
by mflorell
You can tell by looking at your /var/log/astguiclient/agiout.2007-04-XX file and see if more than one agi-VDADtransfer script runs for each call. If it does then yes you would reduce transfer time using sip-silence.

PostPosted: Fri Apr 13, 2007 5:24 pm
by eijal
If more agi-VDADtransfer help with less delay. In the exten 8365 can I use more agi-VDADtransfer and with sip-silence, like this?
Code: Select all
; VICIDIAL_auto_dialer transfer script:
exten => 8365,1,Playback(sip-silence)
exten => 8365,n,AGI(agi://127.0.0.1:4577/call_log)
;exten => 8365,n,AGI(call_log.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,AGI(agi-VDADtransfer.agi,${EXTEN})
exten => 8365,n,Hangup


THANKS

PostPosted: Fri Apr 13, 2007 9:21 pm
by mflorell
No.

post results from your agiout file for agi-VDADtransfer.