vicidial_log entries with QUEUE status

[peacy]

Hi,

I have noticed a strange problem on my vicidial installation. After I run the VDAD report I noticed that some of the log entries showed 'QUEUE' status.

After a lengthy investigation I have found the following:

These are the entries from last friday that were in 'QUEUE' in status. The status and the user columns are pulled in from vicidial_list (linked through lead_id):

Code: Select all

+---------------------+--------------------+---------+--------+--------+
| call_date           | uniqueid           | lead_id | status | user   |
+---------------------+--------------------+---------+--------+--------+
| 2007-10-05 09:26:53 | 1191572802.1002769 |   19364 | DROP   | VDAD   |
| 2007-10-05 09:28:08 | 1191572876.1002951 |   19729 | NMP    | jimmy  |
| 2007-10-05 09:33:04 | 1191573173.1003931 |   31035 | CBHOLD | jimmy  |
| 2007-10-05 09:37:09 | 1191573414.1004469 |   34565 | NMP    | bryony |
+---------------------+--------------------+---------+--------+--------+


Here's the output from agiout showing that the call has been transferred to an agent:

Code: Select all

2007-10-05 9:28:08|agi-VDADtransfer.agi|AGI Environment Dump:
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- accountcode =
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- callerid = unknown
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- calleridname = V1005092756000019729
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- callingani2 = 0
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- callingpres = 0
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- callingtns = 0
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- callington = 0
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- channel = Zap/2-1
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- context = default
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- dnid = 815138
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- enhanced = 0.0
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- extension = 8365
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- language = en
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- priority = 3
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- rdnis = unknown
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- request = agi-VDADtransfer.agi
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- type = Zap
2007-10-05 9:28:08|agi-VDADtransfer.agi| -- uniqueid = 1191572876.100295
2007-10-05 9:28:08|agi-VDADtransfer.agi|AGI Variables: |1191572876.100295|Zap/2-1|8365|Zap|V1005092756000019729|V1005092756000019729|3|
2007-10-05 9:28:08|agi-VDADtransfer.agi|+++++ VDAD START : |19729|2007-10-05 9:28:08|1.2.24|3|
2007-10-05 9:28:08|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V1005092756000019729';|
2007-10-05 9:28:08|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V1005092756000019729' and status IN('LIVE','XFER');|
2007-10-05 9:28:08|agi-VDADtransfer.agi|--    VDAD : |1|update of vac table: V1005092756000019729
|UPDATE vicidial_auto_calls set uniqueid='1191572876.100295', channel='Zap/2-1',status='LIVE',stage='LIVE-0' where callerid='V1005092756000019729' order by call_time desc limit 1;|
2007-10-05 9:28:08|agi-VDADtransfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1191572876.100295','19729','NWSAGTS','2007-10-05 9:28:08','1191572888','QUEUE','44','01213579102','VDAD','N')|
2007-10-05 9:28:08|agi-VDADtransfer.agi|--    VDAD : |19729|19729|insert to vicidial_log: 1191572876.100295
2007-10-05 9:28:08|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.2.3' and campaign_id = 'NWSAGTS' and call_time < "2007-10-05 09:27:56" and lead_id != '19729';|
2007-10-05 9:28:08|agi-VDADtransfer.agi||SELECT count(*) FROM vicidial_live_agents where server_ip='192.168.2.3' and campaign_id = 'NWSAGTS' and last_update_time > '20071005092803';|
2007-10-05 9:28:08|agi-VDADtransfer.agi||CONCURRENT TRANSFERS AUTO SETTING: 1 (1)|
2007-10-05 9:28:08|agi-VDADtransfer.agi|--    VDAD get agent: |1|update of vla table: NWSAGTS|192.168.2.3
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='19729',uniqueid='1191572876.100295', channel='Zap/2-1', callerid='V1005092756000019729' where status = 'READY' and server_ip='192.168.2.3' and campaign_id='NWSAGTS' and last_update_time > '20071005092803' order by last_call_finish limit 1;|
2007-10-05 9:28:08|agi-VDADtransfer.agi||SELECT conf_exten,user,extension FROM vicidial_live_agents where status IN('QUEUE','INCALL') and server_ip='192.168.2.3' and campaign_id='NWSAGTS' and callerid='V1005092756000019729' and channel='Zap/2-1' order by last_call_time limit 1;|
2007-10-05 9:28:08|agi-VDADtransfer.agi|--    VDAD XFER : |1|update of vac table: V1005092756000019729
|UPDATE vicidial_auto_calls set status='XFER', stage='XFER-0' where callerid='V1005092756000019729';|
2007-10-05 9:28:08|agi-VDADtransfer.agi|exiting the VDAD app, transferring call to 8600051
2007-10-05 9:28:08|agi-VDADtransfer.agi|XXXXXXXXXX VDAD transferred: start|stop   2007-10-05 9:28:08|2007-10-05 9:28:08


And the output from FASTagiout:

Code: Select all

2007-10-05 9:28:16|TEST_VDfastAGI|begin|Perl Environment Dump:
2007-10-05 9:28:16|TEST_VDfastAGI|begin|0|--debug
2007-10-05 9:28:16|TEST_VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|0|||)|
2007-10-05 9:28:16|TEST_VDfastAGI|begin|AGI Environment Dump:
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- accountcode =
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- callerid = unknown
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- calleridname = V1005092756000019729
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- callingani2 = 0
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- callingpres = 0
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- callingtns = 0
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- callington = 0
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- channel = Zap/2-1
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- context = default
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- dnid = 815138
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- enhanced = 0.0
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- extension = h
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- language = en
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- network = yes
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- network_script = VD_hangup--HVcauses--PRI-----NODEBUG-----0---------------)
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- priority = 2
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- rdnis = unknown
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- request = agi://127.0.0.1:4577/VD_hangup--HVcauses--PRI-----NODEBUG-----0---------------)
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- type = Zap
2007-10-05 9:28:16|TEST_VDfastAGI|begin| -- uniqueid = 1191572876.100295
2007-10-05 9:28:16|TEST_VDfastAGI|begin|AGI Variables: |1191572876.100295|Zap/2-1|h|Zap|V1005092756000019729|
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup|Process to run: |agi://127.0.0.1:4577/VD_hangup--HVcauses--PRI-----NODEBUG-----0---------------)|VD_hangup|END|
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup|DEBUG: NODEBUG
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup|VD_hangup : V1005092756000019729 Zap/2-1 2 19729
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup||SELECT lead_id,callerid,campaign_id,alt_dial,stage,UNIX_TIMESTAMP(call_time) FROM vicidial_auto_calls where uniqueid = '1191572876.100295' limit 1;|
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup|--    VDAC record deleted: |1|   |19729|1191572876.100295|V1005092756000019729|192.168.2.3
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup||SELECT start_epoch,status FROM vicidial_log where uniqueid='1191572876.100295' and lead_id='19729' limit 1;|
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup|no VDL record found: 1191572876.100295 V1005092756000019729 19729 1191572876.100295
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup||SELECT start_epoch,status,closecallid FROM vicidial_closer_log where lead_id = '19729' and call_date > "2007-10-05 03:28:16" order by call_date desc limit 1;|
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup|no VDL or VDCL record found: 1191572876.100295 V1005092756000019729 19729 1191572876.100295
2007-10-05 9:28:16|TEST_VDfastAGI|VD_hangup||SELECT auto_alt_dial,auto_alt_dial_statuses FROM vicidial_campaigns where campaign_id='NWSAGTS';|


From this I can see that the script cannot find the vicidial_log entry for this call.

So, when I tried to find it myself I noticed that searching for the uniqueid doesn't yield any results:

Code: Select all

mysql> select * from vicidial_log where uniqueid = '1191572876.1002951';
Empty set (0.00 sec)


BUT! This query does:

Code: Select all

mysql> select * from vicidial_log where uniqueid = 1191572876.1002951;
+--------------------+---------+---------+-------------+---------------------+-------------+-----------+---------------+--------+------------+--------------+------+----------+-----------+------------+
| 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 |
+--------------------+---------+---------+-------------+---------------------+-------------+-----------+---------------+--------+------------+--------------+------+----------+-----------+------------+
| 1191572876.1002951 |   19729 |    NULL | NWSAGTS     | 2007-10-05 09:28:08 |  1191572888 |      NULL |          NULL | QUEUE  | 44         | 01213579102  | VDAD | NULL     | N         | NULL       |
+--------------------+---------+---------+-------------+---------------------+-------------+-----------+---------------+--------+------------+--------------+------+----------+-----------+------------+
1 row in set (0.00 sec)


Could this be a bug in MySQL? How come when I search for the uniqueid and I enclose it in apostrophe then MySQL cannot find the record, but when I don't enclose it then everything is fine???

Anybody noticed anything similar?

Here's my setup:
- single box, AMD X2 5600+, 4G RAM, digium TE120P E1 card
- CentOS 5.0
- asterisk 1.2.24
- mysql 5.0.22
- system load avg ~1.1 with 7 agents
- all calls recorded

[mflorell]

You should link only by lead_id, not uniqueid, there can be multiple uniqueids per call and it is stored as Floating-point, not precision, so querying by it will not be reliable when trying to link it to another table.

As for why records show up as QUEUE status, there can be several reasons for it, the most common I have seen is an agent closing their browser when they are on a call, or while they are in dispo-screen.

How many QUEUE status leads do you get?

How many total calls in that time period?

[peacy]

Thanks for the reply Matt!

So:
I'm not linking on uniqueid - vicidial does...
Correct me if I'm wrong, but VD_hangup.agi supposed to update the vicidial_log table once the call has finished. (around line 318)

Last friday the system placed 1997 calls. Out of this 112 show up as 'QUEUE' in vicidial_log.

Today we had 5219 calls. Out this 291 show up with 'QUEUE' status.


I don't think the problem is with the agents because I double checked their login-logout records and they do look fine. Also, 100+ web-browser closures would be noticed in our small call-centre (max 7 agents).

I checked some of these leads, and I can see that the vicidial_list table contains proper disposition codes. I even found lead which had a 'DROP' status in vicidial_log and was left with a 'QUEUE' status in vicidial_log. Surely that wasn't caused by an agent. (I also checked the call_data field vs modify_date to make sure that these vicidial_log record really are the most recent calls made to that lead).

[mflorell]

That is a high percentage, I've only seen a couple per 10000 calls or so on any of the systems that I manage.

Can you tell me what the loadavg is on your system when it is at it's highest load?

Do you have Asterisk/VICIDIAL/DB/Web all on the same server?

[peacy]

The 15 min load average is around 0.8. The 1 min load average is between 0.5 and 1.5, but never goes above 2.

Yes, I have Asterisk/VICIDIAL/DB/Web all on the same server.


One thing I noticed is that the uniqueid what is in the database doesn't exactly match the one in log.

Log:

Code: Select all

2007-10-05 9:28:08|agi-VDADtransfer.agi| -- uniqueid = 1191572876.100295

Database:

Code: Select all

+--------------------+---------+---------------------+
| uniqueid           | lead_id | call_date           |
+--------------------+---------+---------------------+
| 1191572876.1002951 |   19729 | 2007-10-05 09:28:08 |
+--------------------+---------+---------------------+

[mflorell]

The uniqueids will not always match, because there are at least two for every outbound call.

Do you do recording on this server?

[peacy]

Yes, all calls are recorded. The recordings are going to a RAM-drive and moved to normal disk every hour.

[mflorell]

using a RAM drive should remove the problems that some people have with recording and having the DB on the same server.

[peacy]

I don't think it's related to load because it's happening even with only 1-2 agents logged on to the system.

Yesterday we had 4 agents, average load 0.38, max load 1.53.
2250 placed calls, 148 ended up in QUEUE status.

[mflorell]

There is probably a misconfiguration somewhere on your system then, although I'm not really sure as to what it would be since I've never seen that problem before.

[peacy]

I think I tracked down the source of this problem. (I need to test the solution though.)

I was checking which script creates/modifies the record in vicidial_log and here're my findings:
1. The record is created by VDADtransfer.agi, which sets (amongst other things) the user to VDAD and the status to QUEUE.
2. The record is updated by vdc_db_query.php when the call reaches the agent. The 'VDADcheckINCOMING' function will set the status to INCALL and the user field to the correct user.
3. When a disposition is submitted vdc_db_query.php updates the record again. The 'updateDISPO' function will set the selected status for the record.

Step 1 is clearly working, so no problems there.
Step 2 is the problem because the status is never updated to INCALL and the user is not set for the record.
Step 3 never completed, because the record is not found due to step 2 not working properly.

In step 2, the WHERE clause of the SQL statement contains the uniqueid field, which in some cases doesn't match. ("...where lead_id='$lead_id' and uniqueid='$uniqueid';")

Step 3 relies on data set in step 2, so the disposition is never updated. (The WHERE clause goes like this: "...where lead_id='$lead_id' and user='$user' order by uniqueid desc limit 1;")

I believe that the solution is to change the WHERE clause used in step 2 to a similar one used in step 3.

Original code:

Code: Select all

$stmt = "UPDATE vicidial_log set user='$user', comments='AUTO', list_id='$list_id', status='INCALL', user_group='$user_group' where lead_id='$lead_id' and uniqueid='$uniqueid';";

Changed code:

Code: Select all

$stmt = "UPDATE vicidial_log set user='$user', comments='AUTO', list_id='$list_id', status='INCALL', user_group='$user_group' where lead_id='$lead_id' order by uniqueid desc limit 1;";

This is all theory, but I will test it tonight will put it into production tomorrow if it works. Any comments welcome!