vicidial.org

VICIDIAL astGUIclient discussion forum
http://www.vicidial.org/VICIDIALforum/

Calls dropping like flies

http://www.vicidial.org/VICIDIALforum/viewtopic.php?f=4&t=5517

Page 1 of 1

Calls dropping like flies

PostPosted: Fri May 02, 2008 11:38 pm
by i_magic
Gawd, I dunno what happened today. Maybe I got up on a wrong foot or something, but I've been seeing 20% dropped calls today. This is despite constantly seeing agents that are ready. I would literally watch the timeonVDAD screen and see DROPPED number jump up by 5-6 even though this whole time there were agents available to receive the call.

My system is: Slackware 12.0
Asterisk 1.12.24
AGC 2.0.4 (which was given out at the recent boot camp)
I followed scratch install.
Average load is usually below 1. Haven't seen it go above 2 since a I moved the database to another server a few days ago.

I looked at the output of ASTVDauto and noticed something that might not look good:

2008-05-03 00:20:41|US 207.90.4.159: agents: 7 dial_level: 2.5|
2008-05-03 00:20:41|US 207.90.4.159: Calls to place: 1 (34 - 33) 34 |
2008-05-03 00:20:41|CAMPAIGN DIFFERENTIAL: 34.7 9.05 (9.05 - 0)|
2008-05-03 00:20:41|LOCAL TRUNK SHORTAGE: 0|0 (34 - 40)|
2008-05-03 00:20:41|US 207.90.4.159: CALLING|
|UPDATE vicidial_hopper set status='QUEUE', user='VDAD_207.90.4.159' where campaign_id='US' and status='READY' order by priority desc,hopper_id LIMIT 1|
hopper rows updated to QUEUE: |1|
|SELECT lead_id,alt_dial FROM vicidial_hopper where campaign_id='US' and status='QUEUE' and user='VDAD_207.90.4.159' order by priority desc,hopper_id LIMIT 1|
|UPDATE vicidial_hopper set status='INCALL' where lead_id='922717'|
hopper row updated to INCALL: |1|922717|
2008-05-03 00:20:41|| number call dialed|US|V0503002041000922717|INSERT INTO vicidial_manager values('','','2008-05-03 00:20:41','NEW','N','207.90.4.159','','Originate','V0503002041000922717','Exten: 8368','Context: default','Channel: Local/15106582972@default','Priority: 1','Callerid: "V0503002041000922717" <0000000000>','Timeout: 20000','','','','')|-7.00|NONE||
TIME DEBUG: -5|-4|1| GMT: 04:20
2008-05-03 00:20:41|| lagged call vla agent PAUSED 0E0|20080503002011|20080503002031|20080503002041||
2008-05-03 00:20:41|| lagged call vac agent DELETED 0E0|2008-05-03 00:18:41||
2008-05-03 00:20:41|| lastcalldate UPDATED 1|'80209'||
2008-05-03 00:20:41|| logindate UPDATED 1|'US'||

loop counter: |5699623|
TIME DEBUG: -5|-4|1| GMT: 04:20
2008-05-03 00:20:43|LIVE AGENTS LOGGED IN: 31 ACTIVE CALLS: 34|
2008-05-03 00:20:43|OLD TRUNK SHORTS CLEARED: 9 |'','US'||
2008-05-03 00:20:43|US 207.90.4.159: agents: 4 dial_level: 2.5|
2008-05-03 00:20:43|US 207.90.4.159: Calls to place: -4 (30 - 34) 34 |
2008-05-03 00:20:43|CAMPAIGN DIFFERENTIAL: 34.65 8.75 (8.75 - 0)|
2008-05-03 00:20:43|LOCAL TRUNK SHORTAGE: 0|0 (30 - 40)|
2008-05-03 00:20:43|US 207.90.4.159: CALLING|
TIME DEBUG: -5|-4|1| GMT: 04:20
2008-05-03 00:20:43|| dead call vac deleted|165679|869967|V0503002021000869967|1209788441|1|||
2008-05-03 00:20:43|| dead NA call added to log 1209788421.1428230|869967|3237178970|SENT|NA|1||
2008-05-03 00:20:43|| dead call vac lead marked NA|869967|3237178970|SENT||
2008-05-03 00:20:43|| dead call vla agent PAUSED 0E0|869967|3237178970|SENT||
2008-05-03 00:20:43|| lagged call vla agent PAUSED 0E0|20080503002013|20080503002033|20080503002043||
2008-05-03 00:20:43|| lagged call vac agent DELETED 0E0|2008-05-03 00:18:43||
2008-05-03 00:20:43|| logindate UPDATED 1|'US'||

loop counter: |5699622|
TIME DEBUG: -5|-4|1| GMT: 04:20
2008-05-03 00:20:46|LIVE AGENTS LOGGED IN: 32 ACTIVE CALLS: 31|
2008-05-03 00:20:46|OLD TRUNK SHORTS CLEARED: 9 |'','US'||
2008-05-03 00:20:46|US 207.90.4.159: agents: 4 dial_level: 2.5|
2008-05-03 00:20:46|US 207.90.4.159: Calls to place: -1 (30 - 31) 31 |
2008-05-03 00:20:46|CAMPAIGN DIFFERENTIAL: 34.6 8.5 (8.5 - 0)|
2008-05-03 00:20:46|LOCAL TRUNK SHORTAGE: 0|0 (30 - 40)|
2008-05-03 00:20:46|US 207.90.4.159: CALLING|
TIME DEBUG: -5|-4|1| GMT: 04:20
2008-05-03 00:20:46|| lagged call vla agent PAUSED 0E0|20080503002016|20080503002036|20080503002046||
2008-05-03 00:20:46|| lagged call vac agent DELETED 0E0|2008-05-03 00:18:46||
2008-05-03 00:20:46|| logindate UPDATED 1|'US'||

I would appreciate any pointers on what I can do to fix it.

-TJ

PostPosted: Sat May 03, 2008 1:02 am
by mflorell
Looking at the agiout.2008-05-02 file might help more(if you have AGI Output set to BOTH or FILE for this server) That way you can track individual calls that registered as DROP and see what happened.

PostPosted: Sat May 03, 2008 2:55 pm
by i_magic
Hey Matt, I looked at the FASTagi log as you suggested, but it's like... reading Italian (my wife is Italian, but I don't speak it yet :) )

What should I be looking for? I grepped for DROP calls and I did see a bunch and I saw something, which doesn't seem to make sense (although I get that a lot when I am dealing with something I don't understand :) )

Anyway, a lot of dropped calls have length_in_sec way above 5 seconds.
Here is a sample:

Code: Select all
 vicidial_list set status='DROP' where lead_id = '1001745';|
 vicidial_log set status='DROP', end_epoch='1209737272',length_in_sec='77' where uniqueid = '1209737183.6065
 vicidial_list set status='DROP' where lead_id = '1001775';|
 vicidial_log set status='DROP', end_epoch='1209737299',length_in_sec='1' where uniqueid = '1209737274.60759
 vicidial_list set status='DROP' where lead_id = '1001331';|
 vicidial_log set status='DROP', end_epoch='1209738777',length_in_sec='0' where uniqueid = '1209738760.62745
 vicidial_list set status='DROP' where lead_id = '1001601';|
 vicidial_log set status='DROP', end_epoch='1209738929',length_in_sec='1' where uniqueid = '1209738917.62946
 vicidial_list set status='DROP' where lead_id = '1001176';|
 vicidial_log set status='DROP', end_epoch='1209740319',length_in_sec='17' where uniqueid = '1209740293.6453
 vicidial_list set status='DROP' where lead_id = '942792';|
 vicidial_log set status='DROP', end_epoch='1209740975',length_in_sec='26' where uniqueid = '1209740932.6549
 vicidial_list set status='DROP' where lead_id = '944127';|
 vicidial_log set status='DROP', end_epoch='1209741153',length_in_sec='4' where uniqueid = '1209741143.65845
 vicidial_list set status='DROP' where lead_id = '966786';|
 vicidial_log set status='DROP', end_epoch='1209750032',length_in_sec='1' where uniqueid = '1209750019.72456
 vicidial_list set status='DROP' where lead_id = '949518';|
 vicidial_log set status='DROP', end_epoch='1209762082',length_in_sec='375' where uniqueid = '1209761702.890
 vicidial_list set status='DROP' where lead_id = '950517';|
 vicidial_log set status='DROP', end_epoch='1209763847',length_in_sec='18' where uniqueid = '1209763811.9262
 vicidial_list set status='DROP' where lead_id = '950638';|
 vicidial_log set status='DROP', end_epoch='1209764167',length_in_sec='5' where uniqueid = '1209764150.93111
 vicidial_list set status='DROP' where lead_id = '950824';|
 vicidial_log set status='DROP', end_epoch='1209764629',length_in_sec='5' where uniqueid = '1209764604.93628
 vicidial_list set status='DROP' where lead_id = '952758';|
 vicidial_log set status='DROP', end_epoch='1209771329',length_in_sec='58' where uniqueid = '1209771255.1002
 vicidial_list set status='DROP' where lead_id = '952772';|
 vicidial_log set status='DROP', end_epoch='1209771341',length_in_sec='69' where uniqueid = '1209771261.1002
 vicidial_list set status='DROP' where lead_id = '952802';|
 vicidial_log set status='DROP', end_epoch='1209771421',length_in_sec='65' where uniqueid = '1209771340.1003
 vicidial_list set status='DROP' where lead_id = '952837';|
 vicidial_log set status='DROP', end_epoch='1209771485',length_in_sec='49' where uniqueid = '1209771426.1004
 vicidial_list set status='DROP' where lead_id = '952849';|
 vicidial_log set status='DROP', end_epoch='1209771514',length_in_sec='44' where uniqueid = '1209771453.1004
 vicidial_list set status='DROP' where lead_id = '952918';|
 vicidial_log set status='DROP', end_epoch='1209771602',length_in_sec='5' where uniqueid = '1209771577.10064
 vicidial_list set status='DROP' where lead_id = '952896';|
 vicidial_log set status='DROP', end_epoch='1209771644',length_in_sec='113' where uniqueid = '1209771517.100
 vicidial_list set status='DROP' where lead_id = '952922';|
 vicidial_log set status='DROP', end_epoch='1209771687',length_in_sec='93' where uniqueid = '1209771582.1006
 vicidial_list set status='DROP' where lead_id = '953052';|
 vicidial_log set status='DROP', end_epoch='1209771830',length_in_sec='4' where uniqueid = '1209771821.10100
 vicidial_list set status='DROP' where lead_id = '953064';|
 vicidial_log set status='DROP', end_epoch='1209771873',length_in_sec='18' where uniqueid = '1209771840.1010
 vicidial_list set status='DROP' where lead_id = '952880';|
 vicidial_log set status='DROP', end_epoch='1209771908',length_in_sec='394' where uniqueid = '1209771503.100
 vicidial_list set status='DROP' where lead_id = '953089';|
 vicidial_log set status='DROP', end_epoch='1209771920',length_in_sec='31' where uniqueid = '1209771880.1011
 vicidial_list set status='DROP' where lead_id = '953102';|
 vicidial_log set status='DROP', end_epoch='1209771981',length_in_sec='52' where uniqueid = '1209771919.1011
 vicidial_list set status='DROP' where lead_id = '953144';|


Now one thing I did notice is that VDAD extension in the campaign was set to 8368. I used to have multi-server setup and I instructed our manager to make sure the extension is set to that. They used to forget to do that for new campaigns and constantly complained that they had agents idling for long time.

About a week ago I upgraded to one beefy server and I personally changed all campaigns' VDAD exten to 8365. I think the manager who is now very diligent in making sure they are set 8368 (without understanding what it actually means) went through and "corrected" them.

I don't have the auto_FILL script running (took off option 7 in astguiclient.conf) anymore. Could the above cause that?

I've been watching it this morning and it seems to behave better (calls only drop where there are no agents), but I get nowhere near as much load as I do in the evenings, so I am a bit reluctant to consider that I found the problem.

Thanks again,
-TJ

PostPosted: Sat May 03, 2008 6:53 pm
by mflorell
posting some of the output around the lines you posted would help. Seeing the output in context always helps the diagnosis.

From what you've described this might be carrier-related. I have seen it at some larger call centers before when a problem like this only happens in the evenings.

PostPosted: Sun May 04, 2008 7:12 pm
by i_magic
I just noticed I have both agiout and FASTagiout logs. Which one should I look at? (In my dial plan I am using FastAGI)

In agiout script I only found 1 DROP call over 5 sec. On FASTagiout, here is printout of the area of dropped call:

PostPosted: Sun May 04, 2008 7:22 pm
by i_magic
Sorry, here is sample from FASTagi log:

Code: Select all
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:39:13|TEST_VDfastAGI|begin| -- uniqueid = 1209703133.57525
2008-05-02 0:39:13|TEST_VDfastAGI|begin|AGI Variables: |1209703133.57525|Local/101161738822882@default-3d37,1|h|Local|V0502003853000901122|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:39:13|TEST_VDfastAGI|call_log||1209703133.5752499|1209703150|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|QUERY done: start time = 1209703150 | sec: 3 | min:     0.05 |
2008-05-02 0:39:13|TEST_VDfastAGI|call_log||UPDATE call_log set end_time='2008-05-02 0:39:13',end_epoch='1209703153',length_in_sec=3,length_in_min='    0.05',channel='Local/101161738822882@default-3d37,1' where uniqueid='1209703133.57525'|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209703133.57525' and server_ip='207.90.4.159'|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209703133.57525|Local/101161738822882@default-3d37,1|h|2008-05-02 0:39:13|min:     0.05|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|VD_hangup : V0502003853000901122 Local/101161738822882@default-3d37,1 1 901122
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V0502003853000901122||16|
2008-05-02 0:39:13|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-05-02 0:39:17|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:39:17|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:39:17|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:39:17|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:39:17|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- calleridname = V0502003853000901125
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- channel = Local/101161893057594@default-33c6,1
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- extension = 8368
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- network_script = call_log
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- uniqueid = 1209703134.57534
2008-05-02 0:39:17|TEST_VDfastAGI|begin|AGI Variables: |1209703134.57534|Local/101161893057594@default-33c6,1|8368|Local|V0502003853000901125|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log|call_log|START|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|+++++ CALL LOG START : 2008-05-02 0:39:17
2008-05-02 0:39:17|TEST_VDfastAGI|call_log||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('1209703134.57534','Local/101161893057594@default-33c6,1','','Local','207.90.4.159','8368','10116195522161','2008-05-02 0:39:17','1209703157','','','','','V0502003853000901125')|
2008-05-02 0:39:17|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:39:17|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:39:17|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:39:17|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|ANSWER|31|0|
2008-05-02 0:39:17|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- calleridname = V0502003845000901119
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- channel = Local/101161882963647@default-41a8,2
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----31-----0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----31-----0
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:39:17|TEST_VDfastAGI|begin| -- uniqueid = 1209703126.57521
2008-05-02 0:39:17|TEST_VDfastAGI|begin|AGI Variables: |1209703126.57521|Local/101161882963647@default-41a8,2|h|Local|V0502003845000901119|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----31-----0|call_log|END|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|ANSWER|31|0|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log||1209703126.5752101|1209703126|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|QUERY done: start time = 1209703126 | sec: 31 | min:     0.52 |
2008-05-02 0:39:17|TEST_VDfastAGI|call_log||UPDATE call_log set end_time='2008-05-02 0:39:17',end_epoch='1209703157',length_in_sec=31,length_in_min='    0.52',channel='Local/101161882963647@default-41a8,2' where uniqueid='1209703126.57521'|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209703126.57521' and server_ip='207.90.4.159'|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209703126.57521|Local/101161882963647@default-41a8,2|h|2008-05-02 0:39:17|min:     0.52|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|VD_hangup : V0502003845000901119 Local/101161882963647@default-41a8,2 1 901119
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V0502003845000901119|ANSWER|16|
2008-05-02 0:39:17|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-05-02 0:39:21|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:39:21|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:39:21|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:39:21|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|ANSWER|31|0|
2008-05-02 0:39:21|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- calleridname = V0502003902000901140
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- channel = Local/101161420377469@default-e080,2
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----19-----0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----19-----0
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:39:21|TEST_VDfastAGI|begin| -- uniqueid = 1209703142.57553
2008-05-02 0:39:21|TEST_VDfastAGI|begin|AGI Variables: |1209703142.57553|Local/101161420377469@default-e080,2|h|Local|V0502003902000901140|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----19-----0|call_log|END|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16|ANSWER|19|0|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log||1209703142.5755301|1209703142|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|QUERY done: start time = 1209703142 | sec: 19 | min:     0.32 |
2008-05-02 0:39:21|TEST_VDfastAGI|call_log||UPDATE call_log set end_time='2008-05-02 0:39:21',end_epoch='1209703161',length_in_sec=19,length_in_min='    0.32',channel='Local/101161420377469@default-e080,2' where uniqueid='1209703142.57553'|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209703142.57553' and server_ip='207.90.4.159'|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209703142.57553|Local/101161420377469@default-e080,2|h|2008-05-02 0:39:21|min:     0.32|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|VD_hangup : V0502003902000901140 Local/101161420377469@default-e080,2 1 901140
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V0502003902000901140|ANSWER|16|
2008-05-02 0:39:21|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-05-02 0:39:45|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:39:45|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:39:45|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:39:45|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|ANSWER|19|0|
2008-05-02 0:39:45|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- callerid = unknown
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- calleridname = V0502003853000901124
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- channel = SIP/callcentric.com-08342210
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- type = SIP
2008-05-02 0:39:45|TEST_VDfastAGI|begin| -- uniqueid = 1209703134.57531
2008-05-02 0:39:45|TEST_VDfastAGI|begin|AGI Variables: |1209703134.57531|SIP/callcentric.com-08342210|h|SIP|V0502003853000901124|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||1209703134.5753100|1209703163|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|QUERY done: start time = 1209703163 | sec: 22 | min:     0.37 |
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||UPDATE call_log set end_time='2008-05-02 0:39:45',end_epoch='1209703185',length_in_sec=22,length_in_min='    0.37',channel='SIP/callcentric.com-08342210' where uniqueid='1209703134.57531'|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209703134.57531' and server_ip='207.90.4.159'|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209703134.57531|SIP/callcentric.com-08342210|h|2008-05-02 0:39:45|min:     0.37|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|VD_hangup : V0502003853000901124 SIP/callcentric.com-08342210 1 901124
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time) FROM vicidial_auto_calls where uniqueid = '1209703134.57531' limit 1;|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|--    VDAC record deleted: |1|   |901124|1209703134.57531|V0502003853000901124|207.90.4.159
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||SELECT start_epoch,status FROM vicidial_log where uniqueid='1209703134.57531' and lead_id='901124' limit 1;|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||UPDATE vicidial_list set status='DROP' where lead_id = '901124';|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|--    VDAD vicidial_list update: |1|901124
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||UPDATE vicidial_log set status='DROP', end_epoch='1209703185',length_in_sec='22' where uniqueid = '1209703134.57531';|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|--    VDAD vicidial_log update: |1|1209703134.57531|QUEUE|
2008-05-02 0:39:45|TEST_VDfastAGI|call_log|no VDCL record found: 1209703134.57531 V0502003853000901124 901124 1209703134.57531
2008-05-02 0:39:45|TEST_VDfastAGI|call_log||SELECT auto_alt_dial,auto_alt_dial_statuses FROM vicidial_campaigns where campaign_id='ANZO';|
2008-05-02 0:40:00|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:40:00|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:40:00|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:40:00|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:00|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- calleridname = V0502003859000901126
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- channel = Local/101161397613673@default-8886,2
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:40:00|TEST_VDfastAGI|begin| -- uniqueid = 1209703139.57538
2008-05-02 0:40:00|TEST_VDfastAGI|begin|AGI Variables: |1209703139.57538|Local/101161397613673@default-8886,2|h|Local|V0502003859000901126|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------|call_log|END|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|CANCEL|||
2008-05-02 0:40:00|TEST_VDfastAGI|call_log||1209703139.5753801|1209703139|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|QUERY done: start time = 1209703139 | sec: 61 | min:     1.02 |
2008-05-02 0:40:00|TEST_VDfastAGI|call_log||UPDATE call_log set end_time='2008-05-02 0:40:00',end_epoch='1209703200',length_in_sec=61,length_in_min='    1.02',channel='Local/101161397613673@default-8886,2' where uniqueid='1209703139.57538'|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209703139.57538' and server_ip='207.90.4.159'|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209703139.57538|Local/101161397613673@default-8886,2|h|2008-05-02 0:40:00|min:     1.02|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|VD_hangup : V0502003859000901126 Local/101161397613673@default-8886,2 1 901126
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V0502003859000901126|CANCEL|0|
2008-05-02 0:40:00|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-05-02 0:40:11|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:40:11|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:40:11|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:40:11|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|CANCEL|||
2008-05-02 0:40:11|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- calleridname = V0502004011000901145
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- channel = Local/101161411868085@default-a67d,2
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- extension = 101161411868085
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- network_script = call_log
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- priority = 2
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:40:11|TEST_VDfastAGI|begin| -- uniqueid = 1209703211.57574
2008-05-02 0:40:11|TEST_VDfastAGI|begin|AGI Variables: |1209703211.57574|Local/101161411868085@default-a67d,2|101161411868085|Local|V0502004011000901145|
2008-05-02 0:40:11|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log|call_log|START|
2008-05-02 0:40:11|TEST_VDfastAGI|call_log|+++++ CALL LOG START : 2008-05-02 0:40:11
2008-05-02 0:40:11|TEST_VDfastAGI|call_log||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('1209703211.57574','Local/101161411868085@default-a67d,2','','Local','207.90.4.159','101161411868085','10116195522161','2008-05-02 0:40:11','1209703211','','','','','V0502004011000901145')|
2008-05-02 0:40:16|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:40:16|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:40:16|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:40:16|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:16|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- callerid = unknown
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- calleridname = S0805012341048615912
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- channel = SIP/20034-08210a70
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- type = SIP
2008-05-02 0:40:16|TEST_VDfastAGI|begin| -- uniqueid = 1209699664.53469
2008-05-02 0:40:16|TEST_VDfastAGI|begin|AGI Variables: |1209699664.53469|SIP/20034-08210a70|h|SIP|S0805012341048615912|
2008-05-02 0:40:16|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2008-05-02 0:40:16|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:40:16|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:16|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209699664.53469' and server_ip='207.90.4.159'|
2008-05-02 0:40:16|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209699664.53469|SIP/20034-08210a70|h|2008-05-02 0:40:16|min:     1.02|
2008-05-02 0:40:16|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:40:16|TEST_VDfastAGI|call_log|VD_hangup : S0805012341048615912 SIP/20034-08210a70 1 48615912
2008-05-02 0:40:16|TEST_VDfastAGI|call_log||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time) FROM vicidial_auto_calls where uniqueid = '1209699664.53469' limit 1;|
2008-05-02 0:40:16|TEST_VDfastAGI|call_log|VD hangup: no VDAC record found: 1209699664.53469 S0805012341048615912
2008-05-02 0:40:22|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:40:22|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:40:22|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:40:22|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:22|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- callerid = 0000000000
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- calleridname = V0502004021000901149
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- channel = Local/101161738781481@default-f34c,2
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- extension = 101161738781481
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- network_script = call_log
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- priority = 2
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:40:22|TEST_VDfastAGI|begin| -- uniqueid = 1209703222.57590
2008-05-02 0:40:22|TEST_VDfastAGI|begin|AGI Variables: |1209703222.57590|Local/101161738781481@default-f34c,2|101161738781481|Local|V0502004021000901149|
2008-05-02 0:40:22|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log|call_log|START|
2008-05-02 0:40:22|TEST_VDfastAGI|call_log|+++++ CALL LOG START : 2008-05-02 0:40:22
2008-05-02 0:40:22|TEST_VDfastAGI|call_log||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('1209703222.57590','Local/101161738781481@default-f34c,2','','Local','207.90.4.159','101161738781481','10116195522161','2008-05-02 0:40:22','1209703222','','','','','V0502004021000901149')|
2008-05-02 0:40:26|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:40:26|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:40:26|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:40:26|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:26|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- callerid = unknown
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- calleridname = ULGH34581209703226
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- channel = Local/55558615914@default-9660,2
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- language = en
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- network = yes
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- priority = 1
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- rdnis = unknown
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- type = Local
2008-05-02 0:40:26|TEST_VDfastAGI|begin| -- uniqueid = 1209703226.57601
2008-05-02 0:40:26|TEST_VDfastAGI|begin|AGI Variables: |1209703226.57601|Local/55558615914@default-9660,2|h|Local|V0502004021000901149|
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16---------------|call_log|END|
2008-05-02 0:40:26|TEST_VDfastAGI|call_log||CALL HUNG UP|
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:26|TEST_VDfastAGI|call_log||DELETE from live_inbound where uniqueid='1209703226.57601' and server_ip='207.90.4.159'|
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1209703226.57601|Local/55558615914@default-9660,2|h|2008-05-02 0:40:26|min:     1.02|
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|DEBUG: NODEBUG
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|VD_hangup : V0502004021000901149 Local/55558615914@default-9660,2 1 901149
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|--    VD_hangup Local DEBUG: |PRI|V0502004021000901149||16|
2008-05-02 0:40:26|TEST_VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2008-05-02 0:40:34|TEST_VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2008-05-02 0:40:34|TEST_VDfastAGI|begin|Perl Environment Dump:
2008-05-02 0:40:34|TEST_VDfastAGI|begin|0|--debug
2008-05-02 0:40:34|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16||||
2008-05-02 0:40:34|TEST_VDfastAGI|begin|AGI Environment Dump:
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- accountcode =
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- callerid = unknown
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- calleridname = V0502004021000901148
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- callingani2 = 0
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- callingpres = 0
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- callingtns = 0
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- callington = 0
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- channel = Local/101161733884472@default-05be,1
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- context = default
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- dnid = unknown
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- enhanced = 0.0
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- extension = h
2008-05-02 0:40:34|TEST_VDfastAGI|begin| -- language = en


-TJ

PostPosted: Sun May 04, 2008 11:17 pm
by mflorell
It would be helpful to see the agiout output file output for the agi-VDADtransfer script too, especially for call V0502003853000901124 for lead_id 901124.

PostPosted: Mon May 05, 2008 1:12 pm
by i_magic
Hey Matt, Here is snippet from agiout log. It makes me suspicious that I might have a SNAFU in my dialplan. What do you think?

Code: Select all
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|+++++ VDAD START : |901119|2008-05-02 0:39:17|1.2.24|3|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V0502003845000901119';|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V0502003845000901119' and status IN('LIVE','XFER');|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|--    VDAD : |1|update of vac table: V0502003845000901119
|UPDATE vicidial_auto_calls set uniqueid='1209703126.57520', channel='SIP/callcentric.com-083d7468',status='LIVE',stage='LIVE-0' where callerid='V0502003845000901119' order by call_time desc limit 1;|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1209703126.57520','901119','ANZO','2008-05-02 0:39:17','1209703157','QUEUE','1','011618829636','VDAD','N')|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|--    VDAD : |901119|901119|insert to vicidial_log: 1209703126.57520
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:45" and lead_id != '901119';|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where campaign_id = 'ANZO' and last_update_time > '20080502003912';|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||CONCURRENT TRANSFERS AUTO SETTING: 1 (5)|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |1|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901119',uniqueid='1209703126.57520', channel='SIP/callcentric.com-083d7468', call_server_ip='207.90.4.159', callerid='V0502003845000901119' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003912' order by last_call_finish limit 1;|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi||SELECT conf_exten,user,extension,server_ip FROM vicidial_live_agents where status IN('QUEUE','INCALL') and campaign_id='ANZO' and callerid='V0502003845000901119' and channel='SIP/callcentric.com-083d7468' order by last_call_time limit 1;|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|--    VDAD XFER : |1|update of vac table: V0502003845000901119
|UPDATE vicidial_auto_calls set status='XFER', stage='XFER-0' where callerid='V0502003845000901119';|
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|exiting the VDAD app, transferring call to 8615908
2008-05-02 0:39:17|agi-VDAD_LB_transfer.agi|XXXXXXXXXX VDAD transferred: start|stop   2008-05-02 0:39:17|2008-05-02 0:39:17
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|Perl Environment Dump:
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|0|8368
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|callerID changed: V0502003902000901140
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|AGI Environment Dump:
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- accountcode =
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- callerid = 0000000000
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- calleridname = V0502003902000901140
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- callingani2 = 0
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- callingpres = 0
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- callingtns = 0
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- callington = 0
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- channel = SIP/callcentric.com-08241c80
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- context = default
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- dnid = unknown
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- enhanced = 0.0
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- extension = 8368
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- language = en
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- priority = 2
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- rdnis = unknown
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- request = agi-VDAD_LB_transfer.agi
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- type = SIP
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi| -- uniqueid = 1209703142.57552
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|AGI Variables: |1209703142.57552|SIP/callcentric.com-08241c80|8368|SIP|V0502003902000901140|V0502003902000901140|2|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|+++++ VDAD START : |901140|2008-05-02 0:39:21|1.2.24|2|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V0502003902000901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V0502003902000901140' and status IN('LIVE','XFER');|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD : |1|update of vac table: V0502003902000901140
|UPDATE vicidial_auto_calls set uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80',status='LIVE',stage='LIVE-0' where callerid='V0502003902000901140' order by call_time desc limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1209703142.57552','901140','ANZO','2008-05-02 0:39:21','1209703161','QUEUE','1','011614203774','VDAD','N')|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD : |901140|901140|insert to vicidial_log: 1209703142.57552
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where campaign_id = 'ANZO' and last_update_time > '20080502003916';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||CONCURRENT TRANSFERS AUTO SETTING: 1 (5)|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|Perl Environment Dump:
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|0|8368
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|callerID changed: V0502003853000901124
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|AGI Environment Dump:
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- accountcode =
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- callerid = 0000000000
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- calleridname = V0502003853000901124
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- callingani2 = 0
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- callingpres = 0
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- callingtns = 0
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- callington = 0
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- channel = SIP/callcentric.com-08342210
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- context = default
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- dnid = unknown
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- enhanced = 0.0
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- extension = 8368
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- language = en
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- priority = 2
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- rdnis = unknown
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- request = agi-VDAD_LB_transfer.agi
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- type = SIP
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi| -- uniqueid = 1209703134.57531
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|AGI Variables: |1209703134.57531|SIP/callcentric.com-08342210|8368|SIP|V0502003853000901124|V0502003853000901124|2|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|+++++ VDAD START : |901124|2008-05-02 0:39:23|1.2.24|2|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V0502003853000901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V0502003853000901124' and status IN('LIVE','XFER');|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD : |1|update of vac table: V0502003853000901124
|UPDATE vicidial_auto_calls set uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210',status='LIVE',stage='LIVE-0' where callerid='V0502003853000901124' order by call_time desc limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1209703134.57531','901124','ANZO','2008-05-02 0:39:23','1209703163','QUEUE','1','011612625886','VDAD','N')|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD : |901124|901124|insert to vicidial_log: 1209703134.57531
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where campaign_id = 'ANZO' and last_update_time > '20080502003918';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||CONCURRENT TRANSFERS AUTO SETTING: 1 (5)|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:39:02" and lead_id != '901140';|
2008-05-02 0:39:21|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |1|ANZO|SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|--    VDAD get agent: |0E0|update of vla table: ANZO|207.90.4.159
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='901124',uniqueid='1209703134.57531', channel='SIP/callcentric.com-08342210', call_server_ip='207.90.4.159', callerid='V0502003853000901124' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003918' order by last_call_finish limit 1;|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi|NNNNNNNNNN No agent record found!!!
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi||SELECT voicemail_ext FROM vicidial_campaigns where campaign_id = 'ANZO' limit 1;|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|--    VDAD call_hungup timout: |VH050203927||SIP/callcentric.com-08241c80|insert to vicidial_manager
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|--    VDAD vac record deleted: |1|ANZO|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi||UPDATE vicidial_log set status='DROP',end_epoch='1209703167',length_in_sec='5' where uniqueid = '1209703142.57552';|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|--    VDAD vicidial_log update: |1|1209703142.57552
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi||UPDATE vicidial_list set status='DROP' where lead_id = '901140';|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|--    VDAD vicidial_list update: |1|901140
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|Perl Environment Dump:
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|0|8368
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|callerID changed: V0502003902000901140
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|AGI Environment Dump:
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- accountcode =
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- callerid = unknown
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- calleridname = V0502003902000901140
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- callingani2 = 0
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- callingpres = 0
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- callingtns = 0
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- callington = 0
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- channel = SIP/callcentric.com-08241c80
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- context = default
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- dnid = unknown
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- enhanced = 0.0
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- extension = 8368
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- language = en
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- priority = 3
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- rdnis = unknown
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- request = agi-VDAD_LB_transfer.agi
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- type = SIP
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi| -- uniqueid = 1209703142.57552
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|AGI Variables: |1209703142.57552|SIP/callcentric.com-08241c80|8368|SIP|V0502003902000901140|V0502003902000901140|3|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|+++++ VDAD START : |901140|2008-05-02 0:39:27|1.2.24|3|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V0502003902000901140';|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V0502003902000901140' and status IN('LIVE','XFER');|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|--    VDAD : |0E0|update of vac table: V0502003902000901140
|UPDATE vicidial_auto_calls set uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80',status='LIVE',stage='LIVE-0' where callerid='V0502003902000901140' order by call_time desc limit 1;|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-02 0:39:27|agi-VDAD_LB_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/callcentric.com-08241c80|V0502003902000901140|1209703142.57552|
2008-05-02 0:39:23|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = 'ANZO' and call_time < "2008-05-02 00:38:53" and lead_id != '901124';|


-TJ

PostPosted: Mon May 05, 2008 1:29 pm
by mflorell
Not sure it's a dialplan issue, this query looks correct:

UPDATE vicidial_live_agents set status='QUEUE',lead_id='901140',uniqueid='1209703142.57552', channel='SIP/callcentric.com-08241c80', call_server_ip='207.90.4.159', callerid='V0502003902000901140' where status = 'READY' and campaign_id='ANZO' and last_update_time > '20080502003916' order by last_call_finish limit 1;


It is not finding any records for agents ready to take calls. Are you sure that there are waiting READY status agents at these times?

PostPosted: Tue May 06, 2008 10:53 am
by i_magic
Maybe I happened to pick a lead that was actually dropped due to no agents being available. I hate to post gynormous logs and ask you find my problem, but if you are interested for the purposes of tracking down a bug (if there is one), I can send you all my logs for that day.
In the meantime, I did not see the problem repeat after I changed VDAD exten from 8368 to 8365. So it seems like it was a PEBKAC. :twisted:
Thanks Matt.

-TJ
All times are UTC - 5 hours
Page 1 of 1
Powered by phpBB® Forum Software © phpBB Group
http://www.phpbb.com/