Guest u4910 Report post Posted 04/17/2009 02:47 AM Hi. I started a campaign with 6,077 calls on the 15th. I had them in an xml file and copied the file to the data directory. I noticed VG was really slow to load them and dial, so I took out the "priority sort" in the config.xml. Then I restarted VG. It took a few minutes but started dialing. It did calls all day on the 15th. now on the 16th it started calls again (4 lines) and I thought it would be about finished. I noticed that some calls were being made twice or more on each number. So I looked in the call que and there are still over 5,427 calls remaining in here (VG default database). So, I looked in the cdr out file, and there are 3,457 records in the CDR out on the 16th and 2,725 in the CDR out file on the 15h. So what is going on here? Are the calls not being deleted properly out of the call que as they are being made? How can I reconcile what has already been called and limit the call que (or delete records to not call people multiple times)? Some got as many as 6 calls! I attached the latest log. Thanks, this is time sensitive! 0416_1912_vgEngine.zip Share this post Link to post
SupportTeam Report post Posted 04/17/2009 03:34 AM Can you give us an example phone number that was called multiple times and we can then look in the trace to see what happened on calls to that number. I think you should have a look at the CDR logs to see what was the outcome of the calls. In the log that you have provided there is a large number of reports of Tri-Tones (Operator Intercept Special Information Tones) being played. In which case the call will be aborted as it looks like the phone company will not connect an outgoing call right now. In SIT cases VoiceGuide will dial the number at a later time. You will need to resolve why the phone company is playing the operator tone (SIT Tones) when VoiceGuide attempts to make a call on these lines. Share this post Link to post
Guest u4910 Report post Posted 04/20/2009 01:02 PM The SIT calls I'm not worried about at this point. I can work on that later. I see that calls were made on the 14th and repeated again on the 15th. Also it looks like the callque table is not purging it's records properly. Can it not handle 6,000 calls? bl2.zip Share this post Link to post
SupportTeam Report post Posted 04/20/2009 01:23 PM The CDR extract attached shows 10 numbers being dialed on 2009-04-15 19:20-19:35, and then the same 10 numbers being called on 2009-04-16 16:50-16:55. We would need to see the vgEngine traces from those times to see whether the same call entries were dialed twice or the calls were just loaded twice into the system. 6000 calls is a easily handled, even by the default database engine that ships with VoiceGuide. Once you get to loading 50,000-100,000+ calls into system you may want tolook at using MySQL or SQLServer etc. instead, but at 6000 calls level the retrieval speed is fine from the standard database engine. Here is the CDR extract that was attached to the previous post: purpose,phone,Field3,Field4,Field5,Field6,Field7,script,Field9,starttime,Field11 ,endtime,lencall,Field14,disp,Field16 Business License,912012694369,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:52:21,NULL,2009-04-16 16:53:40,79,0,ANSWERED_MACHINE, Business License,912012694369,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:21:26,NULL,2009-04-15 19:22:45,79,0,ANSWERED_MACHINE, Business License,912013520559,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:52:43,NULL,2009-04-16 16:53:50,67,0,ANSWERED_MACHINE, Business License,912013520559,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:21:51,NULL,2009-04-15 19:22:58,67,0,ANSWERED_MACHINE, Business License,912013974259,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:53:30,NULL,2009-04-16 16:54:42,72,0,ANSWERED, Business License,912013974259,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:21:51,NULL,2009-04-15 19:23:03,72,0,ANSWERED, Business License,912017396024,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:53:34,NULL,2009-04-16 16:54:11,36,0,ANSWERED_HUMAN, Business License,912017396024,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:22:50,NULL,2009-04-15 19:23:56,66,0,ANSWERED_MACHINE, Business License,912034865678,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:53:44,NULL,2009-04-16 16:55:03,80,0,ANSWERED_MACHINE, Business License,912034865678,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:23:02,NULL,2009-04-15 19:24:20,78,0,ANSWERED_MACHINE, Business License,912037686475,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:53:53,NULL,2009-04-16 16:54:24,31,0,ANSWERED_HUMAN, Business License,912037686475,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:23:06,NULL,2009-04-15 19:24:02,55,0,ANSWERED_HUMAN, Business License,912038650811,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:54:25,NULL,2009-04-16 16:54:53,28,0,ANSWERED_MACHINE, Business License,912038650811,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:24:00,NULL,2009-04-15 19:24:54,55,0,ANSWERED_MACHINE, Business License,912038823700,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:54:28,NULL,2009-04-16 16:55:16,49,0,ANSWERED_MACHINE, Business License,912038823700,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:24:05,NULL,2009-04-15 19:24:54,49,0,ANSWERED_MACHINE, Business License,912053914848,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:54:46,NULL,2009-04-16 16:55:09,23,0,ANSWERED_HUMAN, Business License,912053914848,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:24:24,NULL,2009-04-15 19:25:53,89,0,ANSWERED_MACHINE, Business License,912055929673,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:54:57,NULL,2009-04-16 16:55:46,49,0,ANSWERED_HUMAN, Business License,912055929673,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 08:58:52,NULL,2009-04-16 08:59:38,46,0,ANSWERED_HUMAN, Share this post Link to post
Guest u4910 Report post Posted 04/20/2009 02:16 PM Here is the trace from 4/16 in the morning. There are several. 0416_0824_vgEngine.zip Share this post Link to post
SupportTeam Report post Posted 04/20/2009 07:50 PM The attached trace goes from 08:24:20 till 09:59:15. This does not cover any of the times mentioned before. What are we supposed to be looking at in this trace? Share this post Link to post
Guest u4910 Report post Posted 04/21/2009 02:37 AM Attached is a file from the 16th. Look about this time. There is an entry that is close to an example. 165353.003 6 5 rv add [$RV_STARTTIME]{2009-04-16 16:53:53} Business License,912017396024,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-16 16:53:34,NULL,2009-04-16 16:54:11,36,0,ANSWERED_HUMAN, Business License,912017396024,,,,0,,e:\payrem\buslic_renew.wav,,2009-04-15 19:22:50,NULL,2009-04-15 19:23:56,66,0,ANSWERED_MACHINE, So above, this number was called twice. I'll attach the log with the other date as well. 0416_1528_vgEngine.zip Share this post Link to post
Guest u4910 Report post Posted 04/21/2009 03:04 AM File from the 15th 0415_1756_vgEngine.zip Share this post Link to post
SupportTeam Report post Posted 04/21/2009 04:27 AM The 0416_1528_vgEngine.zip trace does not go till 19:23, so its not possible to see the second call to 912017396024. Pleae .ZIP up and post the trace that covers the 19:23 time on the 16th April and we can then see why the call at 19:22:50 was made. What calls are we supposed to be looking at in the 0415_1756_vgEngine.zip trace? 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall objDbDataReader_Stage2.Read() returned True 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall objDbDataReader_Stage2.iFieldCount=18, sTaskTimestamp=165334.487, diff=00:00:00.1093743 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.iID=5288 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.guid=9333f2a7-a067-4ed5-98fb-575e47ed9252 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.strPhoneNumber=[2017396024] 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.strPhoneNumberPrefix=[91] 165334.597 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.datetimeActivation=[4/14/2009 3:54:45 PM] 165334.597 10 dial live=e:\payrem\buslic_renew.wav, am=e:\payrem\buslic_renew.wav, fax=, onNotAnswer=, onRetriesExhausted= 165334.597 10 dial iRetriesDelay_Seconds=300 165334.597 10 dial callque update id/guid=5288/9333f2a7-a067-4ed5-98fb-575e47ed9252 nextActivateTime=4/16/2009 4:58:34 PM, retriesLeft=1, iRelatedPortNumber=3 : completed ok 165334.597 10 dial FindCallQueryCompleted a call was found. Port= 3, sTaskTimestamp=165334.487, diff=00:00:00.1093743 165334.597 10 5 dial StartOutgoingCall start tel[2017396024] live[e:\payrem\buslic_renew.wav] am[e:\payrem\buslic_renew.wav] fax[] onNotAnswered[] onRetriesEnd[] rv[] CampaignName[business License] options[] ID=5288 165334.597 10 5 LineState set Dialing 165334.597 10 5 dial making call LineState settings: tel[912017396024] live[e:\payrem\buslic_renew.wav] am[e:\payrem\buslic_renew.wav] fax[] noAnswer[] retriesEnd[] OnHangup[] rv[[OutDial_RetriesLeft]{2}] options=[] 165334.597 10 5 answering machine detection enabled. sCallProgressOption = [DX_PAMDOPTEN] ... 165353.003 17 5 ev Dialogic 133,TDX_CALLP, crn=200009dd, 10,3,0,TDX_CALLP,CR_CNCT,CON_PVD ... 165353.003 6 5 Set_hCall crn=200009dd, called from OnOutboundCallAnswered_Start_HumanAnswer_Option 165353.003 6 5 dial DeleteFromOutDialQue ID=5288 165353.003 6 5 state Human answer. Playing e:\payrem\buslic_renew.wav 165353.003 10 dial Db_Delete_Entry begin id=5288 guid=9333f2a7-a067-4ed5-98fb-575e47ed9252 linkField=GUID, sql=[DELETE FROM CallQue WHERE ID=@iID; DELETE FROM PortToUse WHERE CallID=@iID;DELETE FROM CallQue WHERE GUID=@guid; DELETE FROM PortToUse WHERE CallGUID=@guid;] ... 165353.003 10 dial Db_Delete_Entry end id=5288 guid=9333f2a7-a067-4ed5-98fb-575e47ed9252 ... 165409.972 17 5 ev Dialogic 134,TDX_CST, crn=200009dd, 1697,0,0,DE_LCOF,, ... 165411.097 6 5 writing CDR logs 165411.097 6 5 cdr.sDisposition=ANSWERED_HUMAN 165411.097 6 5 NOTE strDialoutTelNbr=912017396024, strCallerIdNbr= 165411.097 6 5 VG.INI/Log/CDR_LastData_SaveRv=0 - RVs XML will NOT be saved in LastApplicationData CDR field. 165411.097 6 5 CDR (out) : "Business License","912017396024","","","","0","","e:\payrem\buslic_renew.wav","","2009-04-16 16:53:34","NULL","2009-04-16 16:54:11",36,0,"ANSWERED_HUMAN","" 165411.097 6 5 CDR SQL: INSERT INTO CdrOut (Account, Src, Dst, Dcontext, Clid, Channel, Dstchannel, Lastapp, Lastdata, Start, Answer, Hangup, Duration, Billsec, Disposition, Amaflags) VALUES ('Business License','912017396024','','','','0','','e:\payrem\buslic_renew.wav','','2009-04-16 16:53:34',NULL,'2009-04-16 16:54:11',36,0,'ANSWERED_HUMAN','') Share this post Link to post
Guest u4910 Report post Posted 04/21/2009 03:38 PM The attachment above ( 0416_1912_vgEngine.zip ( 465.18K ) ) has that. Share this post Link to post
Guest u4910 Report post Posted 04/21/2009 03:52 PM Take a look at this phone numbe: 3144238000 It was called on the 15th and 16th. Both were "Answering Machine". So the question is why it didn't delete it from the callque and call twice? 0415_1756 Phone number: 3144238000 "Business License","913144238000","","","","0","","e:\payrem\buslic_renew.wav","","2009-04-15 19:41:22","NULL","2009-04-15 19:42:45",83,0,"ANSWERED_MACHINE","" ScriptEvent EV_TIMEOUT_AFTERIDLE_ALLOWOUT || 194122.066 6 3 LineState set Null 194122.160 10 dial FindCallQueryCompleted some calls found (any lineid search), ID/GUID=-1/f8e24545-ce14-4fa9-b1c0-fc3400f44de5, sTaskTimestamp=194122.082, diff=00:00:00.0781245 194122.160 10 dial port 1 : LineStateAppPov=Connected 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall objDbDataReader_Stage2.Read() returned True 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall objDbDataReader_Stage2.iFieldCount=18, sTaskTimestamp=194122.160, diff=00:00:00.1718739 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.iID=3457 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.guid=f8e24545-ce14-4fa9-b1c0-fc3400f44de5 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.strPhoneNumber=[3144238000] 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.strPhoneNumberPrefix=[91] 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.datetimeActivation=[4/14/2009 3:53:18 PM] 194122.332 10 dial live=e:\payrem\buslic_renew.wav, am=e:\payrem\buslic_renew.wav, fax=, onNotAnswer=, onRetriesExhausted= 194122.332 10 dial iRetriesDelay_Seconds=300 194122.332 10 dial callque update id/guid=3457/f8e24545-ce14-4fa9-b1c0-fc3400f44de5 nextActivateTime=4/15/2009 7:46:22 PM, retriesLeft=1, iRelatedPortNumber=2 : completed ok 194122.332 10 dial FindCallQueryCompleted a call was found. Port= 2, sTaskTimestamp=194122.160, diff=00:00:00.1718739 194122.332 10 3 dial StartOutgoingCall start tel[3144238000] live[e:\payrem\buslic_renew.wav] am[e:\payrem\buslic_renew.wav] fax[] onNotAnswered[] onRetriesEnd[] rv[] CampaignName[business License] options[] ID=3457 194122.332 10 3 LineState set Dialing 194122.332 10 3 dial making call LineState settings: tel[913144238000] live[e:\payrem\buslic_renew.wav] am[e:\payrem\buslic_renew.wav] fax[ ===================== 0416_1528 Phone number: 3144238000 "Business License","913144238000","","","","0","","e:\payrem\buslic_renew.wav","","2009-04-16 17:06:46","NULL","2009-04-16 17:08:09",83,0,"ANSWERED_MACHINE","" 7 ScriptEvent EV_TIMEOUT_AFTERIDLE_ALLOWOUT || 170646.639 6 7 LineState set Null 170646.639 10 dial FindCallQueryCompleted some calls found (any lineid search), ID/GUID=-1/59e88a0c-2684-427c-9653-57993730400b, sTaskTimestamp=170646.592, diff=00:00:00.0468747 170646.639 10 dial port 1 : LineStateAppPov=Dialing 170646.639 10 dial port 2 : LineStateAppPov=Connected 170646.639 10 dial port 3 : LineStateAppPov=Connected 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall objDbDataReader_Stage2.Read() returned True 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall objDbDataReader_Stage2.iFieldCount=18, sTaskTimestamp=170646.639, diff=00:00:00.1093743 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.iID=5343 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.guid=59e88a0c-2684-427c-9653-57993730400b 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.strPhoneNumber=[3144238000] 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.strPhoneNumberPrefix=[91] 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.datetimeActivation=[4/14/2009 3:54:48 PM] 170646.748 10 dial live=e:\payrem\buslic_renew.wav, am=e:\payrem\buslic_renew.wav, fax=, onNotAnswer=, onRetriesExhausted= 170646.748 10 dial iRetriesDelay_Seconds=300 170646.764 10 dial callque update id/guid=5343/59e88a0c-2684-427c-9653-57993730400b nextActivateTime=4/16/2009 5:11:46 PM, retriesLeft=1, iRelatedPortNumber=4 : completed ok 170646.764 10 dial FindCallQueryCompleted a call was found. Port= 4, sTaskTimestamp=170646.639, diff=00:00:00.1249992 170646.764 10 7 dial StartOutgoingCall start tel[3144238000] live[e:\payrem\buslic_renew.wav] am[e:\payrem\buslic_renew.wav] fax[] onNotAnswered[] onRetriesEnd[] rv[] CampaignName[business License] options[] ID=5343 170646.764 10 7 LineState set Dialing 170646.764 10 7 dial making call LineState settings: tel[913144238000] live[e:\payrem\buslic_renew.wav] am[e:\payrem\buslic_renew.wav] fax[] noAnswer[] retriesEnd[] OnHangup[] rv[[OutDial_RetriesLeft]{2}] options=[] 170646.764 10 7 answering machine detection enabled. sCallProgressOption = [DX_PAMDOPTEN] 170646.764 10 7 rv clear all 170646.764 10 7 rv add [OutDial_RetriesLeft]{2} 170646.764 10 7 state Dialing 913144238000 170646.764 10 7 t set 60 sec : EV_TIMEOUT_MAKECALL_NORESPONSE 170646.764 10 7 LineState set Dialing 170646.764 10 7 rvns add [OutDial_Result]{NOTCONTACTED} 170646.764 10 7 rvns add [OutDial_Result]{NOANSWER} 170646.764 10 7 ktTel_MakeCall_Enqueue([913144238000],DX_PAMDOPTEN, 60,0,0,,) call 170646.764 10 7 tqTel que cmd_MakeCall [0,0,60,0,0][||913144238000|DX_PAMDOPTEN|] 170646.764 7 7 tqTel run cmd_MakeCall 170646.764 7 7 ev generic: ktTel_Completion 10000 0,Completion_MakeCall, crn=20000a21, 536873505,0,0,913144238000,,<result>ok</result><crn>536873505</crn> 170646.764 7 7 qScr add evktTelCompletion 0 Completion_MakeCall 170646.764 6 7 qScr run evktTelCompletion Completion_MakeCall, iActionID=0, crn=0[536873505|0|0|0|0][913144238000||<result>ok</result><crn>536873505</crn>|||] 170646.764 6 7 OnCompletion_ktTel_MakeCall sRet=[<result>ok</result><crn>536873505</crn>] 170646.764 6 7 LineState set Dialing 170646.764 6 7 ScriptState set , (called from OnCompletion_ktTel_MakeCall) 170646.764 6 7 state Dialing 913144238000... 170647.326 17 7 ev Dialogic 135,TDX_SETHOOK, crn=20000a21, 0,0,0,DX_OFFHOOK,CALL_OUTBOUND, 170647.326 17 7 qScr add evScriptEvent 135 TDX_SETHOOK 170647.326 6 7 qScr run evScriptEvent TDX_SETHOOK, iActionID=0, crn=20000a21[0|0|0|0|0][DX_OFFHOOK|CALL_OUTBOUND||||] Share this post Link to post
SupportTeam Report post Posted 04/21/2009 07:22 PM The number was loaded into the database twice. At the time the calls are loaded into the database the database assigns the unique ID to each row in the CallQue table. At the time rows are retrieved VoiceGuide reports the ID (and the GUID as well). We can see: first call: 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.iID=3457 194122.332 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.guid=f8e24545-ce14-4fa9-b1c0-fc3400f44de5 second call: 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.iID=5343 170646.748 10 dial DbProcessQueue_Callback_DoWorkFindCall oOutCallData.guid=59e88a0c-2684-427c-9653-57993730400b Share this post Link to post
Guest u4910 Report post Posted 04/21/2009 07:29 PM OK. I didn't think so, but I was wondering the same thing after looking at some of the ID's. I'll do some testing from this end. I thought I loaded it one time (copying the xml to the data directory), so I'll check that. Thanks Share this post Link to post
SupportTeam Report post Posted 04/21/2009 07:34 PM Also the initial activation time is set to the time the call was loaded, so we can see that first call was loaded at 4/14/2009 3:53:18 PM, and the second call was loaded at 4/14/2009 3:54:48 PM Share this post Link to post
