Problem with vicidial_log and vicidial_agent_log

[tukak]

Hello,
we are running vicidial VERSION: 2.0.5-174, BUILD: 90522-0506 on our site and are having trouble with time agents were working according to the vicidial_log and vicidial_agent_log. We are doing only outbound calls.

For some calls there are more then one line generated in vicidial_log. In coresponding vicidial_agent_log where times are higher than they suppose to be.

For example :
Vicidial_log (I've removed the phone number for obvious reason)

Code: Select all

uniqueid   lead_id   list_id   campaign_id   call_date   start_epoch   end_epoch   length_in_sec   status   phone_code   phone_number   user   comments   processed   user_group   term_reason   alt_dial
1256545109.146527   1225612   186   O2TV2   2009-10-26 09:18:29   1256545109   1256545171   62   INCALL   420   xxx 819   MANUAL   N   O2   AGENT   MAIN
1256545172.146571   1225612   186   O2TV2   2009-10-26 09:19:33   1256545173   1256545222   49   INCALL   420   xxx 819   MANUAL   N   O2   AGENT   MAIN
1256545223.146615   1225612   186   O2TV2   2009-10-26 09:20:23   1256545223   1256545232   9   INCALL   420   xxx 819   MANUAL   N   O2   AGENT   MAIN
1256545236.146632   1225612   186   O2TV2   2009-10-26 09:20:36   1256545236   1256545278   42   CBHOLD   420   xxx 819   MANUAL   N   O2   AGENT   MAIN


corresponding vicidial_agent_log :

Code: Select all

agent_log_id   user   server_ip   event_time   lead_id   campaign_id   pause_epoch   pause_sec   wait_epoch   wait_sec   talk_epoch   talk_sec   dispo_epoch   dispo_sec   status   user_group   comments   sub_status
1929358   819   10.0.99.6   2009-10-26 09:18:14   1225612   O2TV2   1256545094   0   1256545236   142   1256545236   162   1256545278   9   CBHOLD   O2   MANUAL   LOGIN

However, the next log for this agent is at 09:21:27 (thats less then 3 minutes from 09:18:14)
But when I sum the wait_sec, talk_sec and dispo_sec for this call, it's more then 5 minutes.
It's not happening on every call, but the it's getting more and more noticable in overall stats.

We thought that the problem could be in amount of data in log tables, so we deleted old records and optimized the tables. Unfortunately, it did not help.

Any idea, what can be wrong? Or what can I do to debug this thing more?

Thanks for any response.
Lukas

[williamconley]

If the call sent to the agent takes time to get to the agent, that time is included in the "vicidial_log" because it's a log of the entire conversation from the view of the PROSPECT, not the agent. so that call could have overlapped while the call was being routed (especially if there was hold time or transfers involved).

otherwise, you'll have to test this OFF your system's normal run time, with some controlled calling (ONE call at a time to see if it is registering call times properly) to find the flaw, if there is one.

but this was a great post, if there are others with the same issue, and the same build, they may find you and we may identify a bug. On the other hand, that will still require someone to do that in-depth testing.

[tukak]

I've turned on mysql error logging for vicidial and I'm getting thousands of errors simillar to this (the numbers of course changes) :

Code: Select all

2009-10-27 13:32:12|vdc_db_query|00057|1062|Duplicate entry '1256646506.184782' for key 1|INSERT INTO vicidial_log (uniqueid,lead_id,list_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,comments,processed,user_group,alt_dial) values('1256646506.184782','1301264','800','PRACANT','2009-10-27 13:32:12','1256646732','DONEM','420','xxxxx','673','MANUAL','N','','MAIN');|673|10.0.99.6|1256633694_64713745409|

Any hint how is the uniqueid generated and what could be the cause that it's not unique anymore?

Update :
Found out, that this uniqueid was inserted not a long time ago and than it tried to insert the same uniqueid again for another lead_id:

Code: Select all

2009-10-27 13:28:27|vdc_db_query|00057|0||INSERT INTO vicidial_log (uniqueid,lead_id,list_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,comments,processed,user_group,alt_dial) values('1256646506.184782','1301488','800','PRACANT','2009-10-27 13:28:27','1256646507','INCALL','420','xxx','673','MANUAL','N','O2','MAIN');|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:28:27|vdc_db_query|00058|0||UPDATE vicidial_auto_calls SET uniqueid='1256646506.184782' where lead_id='1301488';|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:29:37|vdc_db_query|00060|0||SELECT start_epoch,term_reason,uniqueid,campaign_id FROM vicidial_log where uniqueid='1256646506.184782' and lead_id='1301488' order by call_date desc limit 1;|673|10.0.99.6|1256633694_64713745409|


2009-10-27 13:29:37|vdc_db_query|00089|0||SELECT term_reason,uniqueid from vicidial_log where uniqueid='1256646506.184782' and lead_id='1301488' order by call_date desc limit 1;|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:29:37|vdc_db_query|00186|0||SELECT count(*) from vicidial_log where uniqueid='1256646506.184782' and lead_id='1301488';|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:29:37|vdc_db_query|00090|0||UPDATE vicidial_log set term_reason='AGENT', end_epoch='1256646577', length_in_sec='70' where uniqueid='1256646506.184782' and lead_id='1301488' and user='673' order by call_date desc limit 1;|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:32:12|vdc_db_query|00060|0||SELECT start_epoch,term_reason,uniqueid,campaign_id FROM vicidial_log where uniqueid='1256646506.184782' and lead_id='1301264' order by call_date desc limit 1;|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:32:12|vdc_db_query|00089|0||SELECT term_reason,uniqueid from vicidial_log where uniqueid='1256646506.184782' and lead_id='1301264' order by call_date desc limit 1;|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:32:12|vdc_db_query|00186|0||SELECT count(*) from vicidial_log where uniqueid='1256646506.184782' and lead_id='1301264';|673|10.0.99.6|1256633694_64713745409|


2009-10-27 13:32:12|vdc_db_query|00057|1062|Duplicate entry '1256646506.184782' for key 1|INSERT INTO vicidial_log (uniqueid,lead_id,list_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,comments,processed,user_group,alt_dial) values('1256646506.184782','1301264','800','PRACANT','2009-10-27 13:32:12','1256646732','DONEM','420','xxx','673','MANUAL','N','','MAIN');|673|10.0.99.6|1256633694_64713745409|

2009-10-27 13:32:12|vdc_db_query|00090|0||UPDATE vicidial_log set term_reason='AGENT', end_epoch='1256646732', length_in_sec='0' where uniqueid='1256646506.184782' and lead_id='1301264' and user='673' order by call_date desc limit 1;|673|10.0.99.6|1256633694_64713745409|


Thanks, Lukas

[mflorell]

That's normal(uniqueid duplication), it's just part of the redundancy of logging to ensure that everything gets logged.