vicidial.org

by **mflorell** » Mon Sep 18, 2006 12:15 pm

your agiout looks fine, but something is not running properly.

Check the vdautodial.date file for the time you see a CANCEL go through in VDhangup and see if the lead_id of the call shows up as a "dead NA call added to log".

Make sure your call_log.agi script is logging the call as over with an end_epoch and that it actually shows up in the call_log table with the proper caller_code field.

by **enjay** » Mon Sep 18, 2006 12:35 pm

Something is going on with those scripts Im thinking. Here is something that shows up for an ANSWERED call

Database Entry: (NOTICE THE UNIQUEID from Database Vs. AGIOUT logfile).

Code: Select all: +--------------------+----------------------------------+---------------+-------+-------------+-----------+---------------+----------------------+---------------------+-------------+---------------------+------------+---------------+---------------+ | uniqueid | channel | channel_group | type | server_ip | extension | number_dialed | caller_code | start_time | start_epoch | end_time | end_epoch | length_in_sec | length_in_min | +--------------------+----------------------------------+---------------+-------+-------------+-----------+---------------+----------------------+---------------------+-------------+---------------------+------------+---------------+---------------+ | 1158599910.7934799 | Local/15053444299@default-394c,1 | | Local | 192.168.0.6 | 8365 | | V0918101828001009127 | 2006-09-18 10:18:36 | 1158599916 | 2006-09-18 10:18:56 | 1158599936 | 20 | 0.33 | +--------------------+----------------------------------+---------------+-------+-------------+-----------+---------------+----------------------+---------------------+-------------+---------------------+------------+---------------+---------------+

AGI Output: There might be a little overlap here.

Code: Select all: 2006-09-18 10:18:36|call_log.agi|AGI Environment Dump: 2006-09-18 10:18:36|call_log.agi| -- accountcode = 2006-09-18 10:18:36|call_log.agi| -- callerid = 8887112243 2006-09-18 10:18:36|call_log.agi| -- calleridname = V0918101828001009127 2006-09-18 10:18:36|call_log.agi| -- callingani2 = 0 2006-09-18 10:18:36|call_log.agi| -- callingpres = 0 2006-09-18 10:18:36|call_log.agi| -- callingtns = 0 2006-09-18 10:18:36|call_log.agi| -- callington = 0 2006-09-18 10:18:36|call_log.agi| -- channel = Local/15053444299@default-394c,2 2006-09-18 10:18:36|call_log.agi| -- context = default 2006-09-18 10:18:36|call_log.agi| -- dnid = unknown 2006-09-18 10:18:36|call_log.agi| -- enhanced = 0.0 2006-09-18 10:18:36|call_log.agi| -- extension = h 2006-09-18 10:18:36|call_log.agi| -- language = en 2006-09-18 10:18:36|call_log.agi| -- priority = 1 2006-09-18 10:18:36|call_log.agi| -- rdnis = unknown 2006-09-18 10:18:36|call_log.agi| -- request = call_log.agi 2006-09-18 10:18:36|call_log.agi| -- type = Local 2006-09-18 10:18:36|call_log.agi| -- uniqueid = 1158599910.79349 2006-09-18 10:18:36|call_log.agi|AGI Variables: |1158599910.79349|Local/15053444299@default-394c,2|h|Local|V0918101828001009127| 2006-09-18 10:18:36|call_log.agi||CALL HUNG UP| 2006-09-18 10:18:36|call_log.agi||DELETE from live_inbound where uniqueid='1158599910.79349' and server_ip='192.168.0.6'| 2006-09-18 10:18:36|call_log.agi|+++++ CALL LOG HUNGUP: |1158599910.79349|Local/15053444299@default-394c,2|h|2006-09-18 10:18:36|min: | 2006-09-18 10:18:36|call_log.agi|Perl Environment Dump: 2006-09-18 10:18:36|call_log.agi|0|8365 2006-09-18 10:18:36|call_log.agi|AGI Environment Dump: 2006-09-18 10:18:36|call_log.agi| -- accountcode = 2006-09-18 10:18:36|call_log.agi| -- callerid = 8887112243 2006-09-18 10:18:36|call_log.agi| -- calleridname = V0918101828001009127 2006-09-18 10:18:36|call_log.agi| -- callingani2 = 0 2006-09-18 10:18:36|call_log.agi| -- callingpres = 0 2006-09-18 10:18:36|call_log.agi| -- callingtns = 0 2006-09-18 10:18:36|call_log.agi| -- callington = 0 2006-09-18 10:18:36|call_log.agi| -- channel = Local/15053444299@default-394c,1 2006-09-18 10:18:36|call_log.agi| -- context = default 2006-09-18 10:18:36|call_log.agi| -- dnid = unknown 2006-09-18 10:18:36|call_log.agi| -- enhanced = 0.0 2006-09-18 10:18:36|call_log.agi| -- extension = 8365 2006-09-18 10:18:36|call_log.agi| -- language = en 2006-09-18 10:18:36|call_log.agi| -- priority = 1 2006-09-18 10:18:36|call_log.agi| -- rdnis = unknown 2006-09-18 10:18:36|call_log.agi| -- request = call_log.agi 2006-09-18 10:18:36|call_log.agi| -- type = Local 2006-09-18 10:18:36|call_log.agi| -- uniqueid = 1158599910.79348 2006-09-18 10:18:36|call_log.agi|AGI Variables: |1158599910.79348|Local/15053444299@default-394c,1|8365|Local|V0918101828001009127| 2006-09-18 10:18:36|call_log.agi|+++++ CALL LOG START : 2006-09-18 10:18:36 2006-09-18 10:18:36|call_log.agi||INSERT INTO call_log (uniqueid,channel,channel_group,type,server_ip,extension,number_dialed,start_time,start_epoch,end_time,end_epoch,length_in_sec,length_in_min,caller_code) values('1158599910.79348','Local/15053444299@default-394c,1','','Local','192.168.0.6','8365','','2006-09-18 10:18:36','1158599916','','','','','V0918101828001009127')| 2006-09-18 10:18:36|call_log.agi|AGI Environment Dump: 2006-09-18 10:18:36|call_log.agi| -- accountcode = 2006-09-18 10:18:36|call_log.agi| -- callerid = 8887112243 2006-09-18 10:18:36|call_log.agi| -- calleridname = unknown 2006-09-18 10:18:36|call_log.agi| -- callingani2 = 0 2006-09-18 10:18:36|call_log.agi| -- callingpres = 0 2006-09-18 10:18:36|call_log.agi| -- callingtns = 0 2006-09-18 10:18:36|call_log.agi| -- callington = 0 2006-09-18 10:18:36|call_log.agi| -- channel = Local/8500998@default-e3ec,1 2006-09-18 10:18:36|call_log.agi| -- context = default 2006-09-18 10:18:36|call_log.agi| -- dnid = unknown 2006-09-18 10:18:36|call_log.agi| -- enhanced = 0.0 2006-09-18 10:18:36|call_log.agi| -- extension = h 2006-09-18 10:18:36|call_log.agi| -- language = en 2006-09-18 10:18:36|call_log.agi| -- priority = 1 2006-09-18 10:18:36|call_log.agi| -- rdnis = unknown 2006-09-18 10:18:36|call_log.agi| -- request = call_log.agi 2006-09-18 10:18:36|call_log.agi| -- type = Local 2006-09-18 10:18:36|call_log.agi| -- uniqueid = 1158599910.79342 2006-09-18 10:18:36|call_log.agi|AGI Variables: |1158599910.79342|Local/8500998@default-e3ec,1|h|Local|8887112243| 2006-09-18 10:18:36|call_log.agi||CALL HUNG UP| 2006-09-18 10:18:36|call_log.agi||DELETE from live_inbound where uniqueid='1158599910.79342' and server_ip='192.168.0.6'| 2006-09-18 10:18:36|call_log.agi|+++++ CALL LOG HUNGUP: |1158599910.79342|Local/8500998@default-e3ec,1|h|2006-09-18 10:18:36|min: | 2006-09-18 10:18:36|VD_hangup.agi|Perl Environment Dump: 2006-09-18 10:18:36|VD_hangup.agi|0|PRI-----DEBUG-----16-----ANSWER-----6-----0 2006-09-18 10:18:36|VD_hangup.agi|AGI Environment Dump: 2006-09-18 10:18:36|VD_hangup.agi| -- accountcode = 2006-09-18 10:18:36|VD_hangup.agi| -- callerid = 8887112243 2006-09-18 10:18:36|VD_hangup.agi| -- calleridname = V0918101828001009127 2006-09-18 10:18:36|VD_hangup.agi| -- callingani2 = 0 2006-09-18 10:18:36|VD_hangup.agi| -- callingpres = 0 2006-09-18 10:18:36|VD_hangup.agi| -- callingtns = 0 2006-09-18 10:18:36|VD_hangup.agi| -- callington = 0 2006-09-18 10:18:36|VD_hangup.agi| -- channel = Local/15053444299@default-394c,2 2006-09-18 10:18:36|VD_hangup.agi| -- context = default 2006-09-18 10:18:36|VD_hangup.agi| -- dnid = unknown 2006-09-18 10:18:36|VD_hangup.agi| -- enhanced = 0.0 2006-09-18 10:18:36|VD_hangup.agi| -- extension = h 2006-09-18 10:18:36|VD_hangup.agi| -- language = en 2006-09-18 10:18:36|VD_hangup.agi| -- priority = 2 2006-09-18 10:18:36|VD_hangup.agi| -- rdnis = unknown 2006-09-18 10:18:36|VD_hangup.agi| -- request = VD_hangup.agi 2006-09-18 10:18:36|VD_hangup.agi| -- type = Local 2006-09-18 10:18:36|VD_hangup.agi| -- uniqueid = 1158599910.79349 2006-09-18 10:18:36|VD_hangup.agi|AGI Variables: |1158599910.79349|Local/15053444299@default-394c,2|h|Local|V0918101828001009127| 2006-09-18 10:18:36|VD_hangup.agi|VD_hangup : V0918101828001009127 Local/15053444299@default-394c,2 2 1009127 2006-09-18 10:18:36|VD_hangup.agi|-- VDhangup Local DEBUG: |PRI|V0918101828001009127|ANSWER|16| 2006-09-18 10:18:36|VD_hangup.agi|+++++ VDAD START LOCAL CHANNEL: EXITING- 2 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|Perl Environment Dump: 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|0|8365 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|callerID changed: V0918101828001009127 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|AGI Environment Dump: 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- accountcode = 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- callerid = 8887112243 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- calleridname = V0918101828001009127 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- callingani2 = 0 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- callingpres = 0 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- callingtns = 0 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- callington = 0 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- channel = Zap/9-1 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- context = default 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- dnid = unknown 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- enhanced = 0.0 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- extension = 8365 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- language = en 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- priority = 2 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- rdnis = unknown 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- request = agi-VDAD_LB_transfer.agi 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- type = Zap 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi| -- uniqueid = 1158599910.79348 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|AGI Variables: |1158599910.79348|Zap/9-1|8365|Zap|V0918101828001009127|V0918101828001009127|2| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|+++++ VDAD START : |1009127|2006-09-18 10:18:36|1.2|2| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|-- VDAD : |1|update of vac table: V0918101828001009127 |UPDATE vicidial_auto_calls set uniqueid='1158599910.79348', channel='Zap/9-1',status='LIVE' where callerid='V0918101828001009127' order by call_time desc limit 1;| 2006-09-18 10:18:36|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('1158599910.79348','1009127','1003','2006-09-18 10:18:36','1158599916','QUEUE','','5053444299','VDAD','N')| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|-- VDAD : |1009127|1009127|insert to vicidial_log: 1158599910.79348 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and campaign_id = '1003' and call_time < "2006-09-18 10:18:28" and lead_id != '1009127';| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|-- VDAD get agent: |1|update of vla table: 1003|192.168.0.6 |UPDATE vicidial_live_agents set status='QUEUE',lead_id='1009127',uniqueid='1158599910.79348', channel='Zap/9-1', call_server_ip='192.168.0.6', callerid='V0918101828001009127' where status = 'READY' and campaign_id='1003' and last_update_time > '19691231165955' order by last_call_finish limit 1;| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi||SELECT conf_exten,user,extension,server_ip FROM vicidial_live_agents where status = 'QUEUE' and campaign_id='1003' and callerid='V0918101828001009127' and channel='Zap/9-1' order by last_call_time limit 1;| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|-- VDAD XFER : |1|update of vac table: V0918101828001009127 |UPDATE vicidial_auto_calls set status='XFER' where callerid='V0918101828001009127';| 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|exiting the VDAD app, transferring call to 2006-09-18 10:18:36|agi-VDAD_LB_transfer.agi|XXXXXXXXXX VDAD transferred: start|stop 2006-09-18 10:18:36|2006-09-18 10:18:36

As you can see the UniqueID that is logged in the database is CLOSE but different from that of the AGI output.

database: 1158599910.7934799
AGIout: 1158599910.79349 (where is the 7 & 9 in the end of it).

Anything with a CANCEL does not show up at all in the database (based on caller_code) I can lookup every ANSWER and they show up but no CANCELS.

-Art

by **mflorell** » Mon Sep 18, 2006 2:58 pm

The inconsistency is because the data is stored as a float instead of a string.

What version of MySQL are you using?

You could try changing it to a VARCHAR like we do for BRI-stufft installations:
http://astguiclient.sourceforge.net/faq.html#04040

Make sure system is not active when you do those updates though, it takes a while to do them on a system with a lot of calls in the call_log and vicidial_log.

by **enjay** » Mon Sep 18, 2006 3:34 pm

mysql Ver 14.7 Distrib 4.1.20, for redhat-linux-gnu (i386) using readline 4.3

by **enjay** » Mon Sep 18, 2006 3:59 pm

In the vicidial_auto_calls table I notice that all of the CANCEL calls have a uniqueid of NULL

Code: Select all: +--------------+-------------+-------------+--------+---------+----------+----------------------+---------+------------+--------------+---------------------+-----------+ | auto_call_id | server_ip | campaign_id | status | lead_id | uniqueid | callerid | channel | phone_code | phone_number | call_time | call_type | +--------------+-------------+-------------+--------+---------+----------+----------------------+---------+------------+--------------+---------------------+-----------+ | 833339 | 192.168.0.5 | 1002 | SENT | 178148 | NULL | V0918135502000178148 | NULL | | 9517807625 | 2006-09-18 13:55:02 | OUT | +--------------+-------------+-------------+--------+---------+----------+----------------------+---------+------------+--------------+---------------------+-----------+

by **enjay** » Mon Sep 18, 2006 10:24 pm

I'll get back at this tomorrow, I've been working on this 16 hours today I've tried everything I can think of and everything you've asked with the same results.

I hate to rebuild the whole thing, but Im at my whits end here..

by **mflorell** » Tue Sep 19, 2006 5:34 am

Changing to VARCHAR did nothing to help?

by **enjay** » Tue Sep 19, 2006 10:17 am

Going to do some more testing this morning with it though last night appeared as though nothing had changed, I still saw no NA's and plenty of cancels.

I wonder if its having issues interpretting the CANCEL vs DROP vs NOANSWER vs CHANUNAVAIL vs ANSWER

by **mflorell** » Tue Sep 19, 2006 11:12 am

I have 10s of thousands of CANCEL NAs in my vicidial_log every day so I know it does log them here. I am using almost all PRIs.

by **enjay** » Tue Sep 19, 2006 11:41 am

I have 2 PRI's and 3 E&M Wink T1's though problem exists across the board. I just cant pinpoint where the problem is actually.. I see the agiout see's cancels.. but the vdauto script doesnt turn them into NA's.

by **enjay** » Tue Sep 19, 2006 11:56 am

I just copied all the default astguiclient stuff

"agc/vicidial.php" etc etc etc so that I could rule out that maybe I had messed something up in my code that could have cause it but I experience the same thing.. I have not modified any of the agi stuff so I doubt thats the issue..

I upgraded to MySQL 5.0.24a last night to see if that would fix anything.

by **mflorell** » Tue Sep 19, 2006 12:06 pm

You kind of have that reversed, this is an issue with the agi scripts or the perl scripts or possibly a server setting. This would have nothing to do with any PHP scripts since the CANCEL calls never make it to any of those.

by **enjay** » Tue Sep 19, 2006 12:09 pm

yea I figured as such it was just something I "HAD" to do for self re-assurance that I didnt break something

could this have something to do with it?

in my vicidial_auto_calls the CANCEL calls come up with

Code: Select all: +--------------+-------------+-------------+--------+---------+----------+----------------------+---------+------------+--------------+---------------------+-----------+ | auto_call_id | server_ip | campaign_id | status | lead_id | uniqueid | callerid | channel | phone_code | phone_number | call_time | call_type | +--------------+-------------+-------------+--------+---------+----------+----------------------+---------+------------+--------------+---------------------+-----------+ | 847319 | 192.168.0.6 | 1003 | SENT | 948670 | | V0919100547000948670 | NULL | | 5056238349 | 2006-09-19 10:05:47 | OUT | +--------------+-------------+-------------+--------+---------+----------+----------------------+---------+------------+--------------+---------------------+-----------+

while the answered calls come up with:

Code: Select all: +--------------+-------------+-------------+--------+---------+--------------------+----------------------+----------+------------+--------------+---------------------+-----------+ | auto_call_id | server_ip | campaign_id | status | lead_id | uniqueid | callerid | channel | phone_code | phone_number | call_time | call_type | +--------------+-------------+-------------+--------+---------+--------------------+----------------------+----------+------------+--------------+---------------------+-----------+ | 217922 | 192.168.0.6 | 1003 | XFER | 758776 | 1154558807.1439867 | V0802154646000758776 | Zap/3-1 | | 5056273345 | 2006-08-02 15:46:46 | OUT | +--------------+-------------+-------------+--------+---------+--------------------+----------------------+----------+------------+--------------+---------------------+-----------+ 15 rows in set (0.00 sec)

by **mflorell** » Tue Sep 19, 2006 12:29 pm

That does look like mine for the ones that become CANCELs. But as soon as they are hungup the AST_VDauto_dial script deletes them right away when they are detected as hungup.

Are there any corresponding call_log table records for those caller_codes?

by **enjay** » Tue Sep 19, 2006 12:32 pm

There is not one for any of the CANCELS but yes for the ANSWERS

Code: Select all: mysql> select * from call_log where caller_code="V0919100547000948670"; Empty set (0.00 sec) mysql> select * from call_log where caller_code="V0802154646000758776"; +--------------------+----------------------------------+---------------+-------+-------------+-----------+---------------+----------------------+---------------------+-------------+---------------------+-----------+---------------+---------------+ | uniqueid | channel | channel_group | type | server_ip | extension | number_dialed | caller_code | start_time | start_epoch | end_time | end_epoch | length_in_sec | length_in_min | +--------------------+----------------------------------+---------------+-------+-------------+-----------+---------------+----------------------+---------------------+-------------+---------------------+-----------+---------------+---------------+ | 1154558807.1439867 | Local/15056273345@default-8c6c,1 | | Local | 192.168.0.6 | 8365 | | V0802154646000758776 | 2006-08-02 15:47:04 | 1154558824 | 0000-00-00 00:00:00 | 0 | 0 | 0.00 | +--------------------+----------------------------------+---------------+-------+-------------+-----------+---------------+----------------------+---------------------+-------------+---------------------+-----------+---------------+---------------+

by **mflorell** » Tue Sep 19, 2006 2:34 pm

can you post some Asterisk CLI output with agi output set to STDERR of a call being initiated and Dialed so we can see what call_log.agi is doing with the log for your calls?

by **mflorell** » Tue Sep 19, 2006 3:33 pm

You should be seeing a LOT more output that that if you are in the Real Asterisk CLI and you have AGIOUTPUT set to STDERR.

What version of the agi scripts are you running?

by **enjay** » Tue Sep 19, 2006 3:53 pm

yea Im a goob, was in asterisk -r.. ok created a script file for it

http://www.magmanetworks.com/script.txt

-enjay

by **enjay** » Tue Sep 19, 2006 6:54 pm

Or here is an instance I pulled out of the script.txt file where I receive a BUSY from the asterisk server yet it doesnt get placed in the database. I know we have been talking about CANCEL's in general but anything other than ANSWERS arent working.

Code: Select all: -- Executing DeadAGI("Local/6022679357@default-b8b1,2", "call_log.agi|h") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/call_log.agi 2006-09-19 13:44:25|call_log.agi|AGI Environment Dump: 2006-09-19 13:44:25|call_log.agi| -- accountcode = 2006-09-19 13:44:25|call_log.agi| -- callerid = 6233888899 2006-09-19 13:44:25|call_log.agi| -- calleridname = V0919134413000662775 2006-09-19 13:44:25|call_log.agi| -- callingani2 = 0 2006-09-19 13:44:25|call_log.agi| -- callingpres = 0 2006-09-19 13:44:25|call_log.agi| -- callingtns = 0 2006-09-19 13:44:25|call_log.agi| -- callington = 0 2006-09-19 13:44:25|call_log.agi| -- channel = Local/6022679357@default-b8b1,2 2006-09-19 13:44:25|call_log.agi| -- context = default 2006-09-19 13:44:25|call_log.agi| -- dnid = unknown 2006-09-19 13:44:25|call_log.agi| -- enhanced = 0.0 2006-09-19 13:44:25|call_log.agi| -- extension = h 2006-09-19 13:44:25|call_log.agi| -- language = en 2006-09-19 13:44:25|call_log.agi| -- priority = 1 2006-09-19 13:44:25|call_log.agi| -- rdnis = unknown 2006-09-19 13:44:25|call_log.agi| -- request = call_log.agi 2006-09-19 13:44:25|call_log.agi| -- type = Local 2006-09-19 13:44:25|call_log.agi| -- uniqueid = 1158698654.12851 2006-09-19 13:44:25|call_log.agi|AGI Variables: |1158698654.12851|Local/6022679357@default-b8b1,2|h|Local|V0919134413000662775| 2006-09-19 13:44:25|call_log.agi||CALL HUNG UP| 2006-09-19 13:44:25|call_log.agi||DELETE from live_inbound where uniqueid='1158698654.12851' and server_ip='192.168.0.5'| 2006-09-19 13:44:25|call_log.agi|+++++ CALL LOG HUNGUP: |1158698654.12851|Local/6022679357@default-b8b1,2|h|2006-09-19 13:44:25|min: | -- AGI Script call_log.agi completed, returning 0 -- Executing DeadAGI("Local/6022679357@default-b8b1,2", "VD_hangup.agi|PRI-----NODEBUG-----17-----BUSY----------") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/VD_hangup.agi 2006-09-19 13:44:25|VD_hangup.agi|Perl Environment Dump: 2006-09-19 13:44:25|VD_hangup.agi|0|PRI-----NODEBUG-----17-----BUSY---------- 2006-09-19 13:44:25|VD_hangup.agi|AGI Environment Dump: 2006-09-19 13:44:25|VD_hangup.agi| -- accountcode = 2006-09-19 13:44:25|VD_hangup.agi| -- callerid = 6233888899 2006-09-19 13:44:25|VD_hangup.agi| -- calleridname = V0919134413000662775 2006-09-19 13:44:25|VD_hangup.agi| -- callingani2 = 0 2006-09-19 13:44:25|VD_hangup.agi| -- callingpres = 0 2006-09-19 13:44:25|VD_hangup.agi| -- callingtns = 0 2006-09-19 13:44:25|VD_hangup.agi| -- callington = 0 2006-09-19 13:44:25|VD_hangup.agi| -- channel = Local/6022679357@default-b8b1,2 2006-09-19 13:44:25|VD_hangup.agi| -- context = default 2006-09-19 13:44:25|VD_hangup.agi| -- dnid = unknown 2006-09-19 13:44:25|VD_hangup.agi| -- enhanced = 0.0 2006-09-19 13:44:25|VD_hangup.agi| -- extension = h 2006-09-19 13:44:25|VD_hangup.agi| -- language = en 2006-09-19 13:44:25|VD_hangup.agi| -- priority = 2 2006-09-19 13:44:25|VD_hangup.agi| -- rdnis = unknown 2006-09-19 13:44:25|VD_hangup.agi| -- request = VD_hangup.agi 2006-09-19 13:44:25|VD_hangup.agi| -- type = Local 2006-09-19 13:44:25|VD_hangup.agi| -- uniqueid = 1158698654.12851 2006-09-19 13:44:25|VD_hangup.agi|AGI Variables: |1158698654.12851|Local/6022679357@default-b8b1,2|h|Local|V0919134413000662775| 2006-09-19 13:44:25|VD_hangup.agi|DEBUG: NODEBUG 2006-09-19 13:44:25|VD_hangup.agi|VD_hangup : V0919134413000662775 Local/6022679357@default-b8b1,2 2 662775 2006-09-19 13:44:25|VD_hangup.agi||UPDATE vicidial_auto_calls set status='BUSY' where callerid = 'V0919134413000662775';| 2006-09-19 13:44:25|VD_hangup.agi|-- VDAC update: |1|662775 2006-09-19 13:44:25|VD_hangup.agi||UPDATE vicidial_list set status='B' where lead_id = '662775';| 2006-09-19 13:44:25|VD_hangup.agi|-- VDAD vicidial_list update: |1|662775 2006-09-19 13:44:25|VD_hangup.agi||UPDATE vicidial_log set status='B' where uniqueid = '1158698654.12851';| 2006-09-19 13:44:25|VD_hangup.agi|-- VDAD vicidial_log update: |0E0|1158698654.12851| 2006-09-19 13:44:25|VD_hangup.agi|+++++ VDAD START LOCAL CHANNEL: EXITING- 2 -- AGI Script VD_hangup.agi completed, returning 0

when I do a select * from vicidial_log where uniqueid="1158698654.12851";

I receive an empty set also in the call_log.

more examples to follow.

by **mflorell** » Tue Sep 19, 2006 8:17 pm

Do you have a call_log.agi entry directly before your "Dial" entry in extensions.conf for NXXNXXXXXX?

It looks like it's not there and that for some reason you might only have a call_log.agi entry at the beginning of your 8365 exten.

by **enjay** » Tue Sep 19, 2006 9:27 pm

That was it man.. UN $*#*@($ BELIEVABLE!

Have I told you today that I love you? "in a non homosexual way".

by **mflorell** » Tue Sep 19, 2006 10:05 pm

Well thanks for that

I'm glad it's working for you now!

by **enjay** » Tue Sep 19, 2006 10:32 pm

ME TOO BRO meeeeeeeee too!

by **enjay** » Wed Sep 20, 2006 12:36 pm

So that fixed that problem but now Im getting HUGE load avg's because of it.

10:35:28 up 22:28, 1 user, load average: 45.62, 18.60, 15.74

I typically run in the 2.5-3.0 range before I added that. Thoughts?

-enjay

by **mflorell** » Wed Sep 20, 2006 12:51 pm

that makes no sense, what machine are those loadavgs from?

what does top show?

by **enjay** » Wed Sep 20, 2006 2:02 pm

These are on the main VICIDIAL Server that the people are calling out of.

its a 3.4ghz with Hyperthreading
2gb Ram
15k SCSI drives

here is a snippet of top over a 15 second period after I put the call_log.agi before my dial string. Note this continually goes up I've seen it as high as 45.xx load avg as you see above..

Code: Select all: top - 12:00:20 up 23:53, 1 user, load average: 8.73, 3.17, 1.93 Tasks: 123 total, 34 running, 89 sleeping, 0 stopped, 0 zombie Cpu(s): 67.3% us, 23.5% sy, 0.0% ni, 8.0% id, 0.0% wa, 0.3% hi, 0.8% si Mem: 2074900k total, 2004332k used, 70568k free, 32932k buffers Swap: 0k total, 0k used, 0k free, 1697888k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2411 root -11 0 62280 22m 5164 S 34.2 1.1 93:13.27 asterisk 2836 root 15 0 11252 6944 2536 S 9.3 0.3 29:41.98 AST_update.pl 10969 root 15 0 11308 5000 2500 S 6.6 0.2 0:00.20 agi-VDAD_LB_tra 10819 root 20 0 5948 4336 1800 S 4.0 0.2 0:00.12 AST_send_action 10899 root 20 0 4960 3064 1484 R 3.6 0.1 0:00.12 AST_send_action 10829 root 20 0 4828 2884 1484 R 3.3 0.1 0:00.10 AST_send_action 10832 root 20 0 5952 4320 1784 R 3.3 0.2 0:00.19 AST_send_action 10858 root 20 0 5512 3580 1568 R 3.3 0.2 0:00.11 AST_send_action 10743 root 20 0 5952 4312 1792 S 3.0 0.2 0:00.18 AST_send_action 10790 root 20 0 4964 2996 1492 R 3.0 0.1 0:00.09 AST_send_action 10798 root 20 0 4964 2988 1484 R 3.0 0.1 0:00.09 AST_send_action 10808 root 20 0 5952 4284 1776 S 3.0 0.2 0:00.18 AST_send_action 10827 root 20 0 5952 4316 1792 S 3.0 0.2 0:00.19 AST_send_action 10855 root 19 0 7236 3400 1680 R 3.0 0.2 0:00.09 VD_hangup.agi 10877 root 23 0 4960 3068 1484 R 3.0 0.1 0:00.09 AST_send_action 10889 root 20 0 4964 2972 1484 R 3.0 0.1 0:00.09 AST_send_action 10944 root 19 0 5776 3944 1620 R 3.0 0.2 0:00.09 AST_send_action 10995 root 19 0 10928 4220 2144 R 3.0 0.2 0:00.09 call_log.agi 10917 root 19 0 5952 4308 1792 S 2.7 0.2 0:00.09 AST_send_action 10770 root 20 0 5948 4280 1776 S 2.3 0.2 0:00.18 AST_send_action 10814 root 20 0 5952 4316 1792 S 2.0 0.2 0:00.19 AST_send_action 10763 root 20 0 5952 4312 1792 S 1.7 0.2 0:00.16 AST_send_action 2750 root 15 0 11892 7612 2528 S 1.3 0.4 3:14.84 AST_manager_lis 2759 root 16 0 9084 4792 2448 S 1.3 0.2 2:42.76 AST_manager_sen 10896 root 19 0 5948 4308 1792 S 1.3 0.2 0:00.12 AST_send_action 10931 root 20 0 6204 2372 1604 R 1.3 0.1 0:00.04 call_log.agi 10935 root 19 0 6204 2256 1492 R 1.3 0.1 0:00.04 call_log.agi 10951 root 19 0 4836 2912 1484 R 1.3 0.1 0:00.04 AST_send_action 10999 root 19 0 11016 4692 2516 R 1.3 0.2 0:00.04 call_log.agi 11007 root 20 0 4144 2052 1312 R 1.3 0.1 0:00.04 AST_send_action 11009 root 20 0 4960 3068 1484 R 1.3 0.1 0:00.04 AST_send_action 154 root 15 0 0 0 0 S 1.0 0.0 0:00.11 kswapd0 2337 root 16 0 5128 1892 1088 S 1.0 0.1 1:38.51 screen 10965 root 20 0 4432 2484 1480 R 1.0 0.1 0:00.03 AST_send_action 2796 root 16 0 12264 7988 2472 S 0.7 0.4 3:59.83 AST_VDauto_dial 2749 root 15 0 2696 1172 864 S 0.3 0.1 0:23.54 screen 7400 root 16 0 7412 2316 1860 R 0.3 0.1 0:00.10 sshd top - 12:00:26 up 23:53, 1 user, load average: 10.76, 3.68, 2.11 Tasks: 137 total, 36 running, 101 sleeping, 0 stopped, 0 zombie Cpu(s): 64.7% us, 28.0% sy, 0.0% ni, 6.4% id, 0.0% wa, 0.0% hi, 0.8% si Mem: 2074900k total, 1996376k used, 78524k free, 28600k buffers Swap: 0k total, 0k used, 0k free, 1664260k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2411 root -11 0 62300 22m 5164 S 36.9 1.1 93:15.38 asterisk 11160 root 15 0 11308 5000 2504 S 6.9 0.2 0:00.21 agi-VDAD_LB_tra 2836 root 17 0 11252 6944 2536 S 5.3 0.3 29:42.46 AST_update.pl 11078 root 20 0 5112 3228 1552 R 3.3 0.2 0:00.11 AST_send_action 11083 root 19 0 7292 3404 1712 R 3.3 0.2 0:00.12 call_log.agi 11097 root 19 0 6972 3128 1680 R 3.3 0.2 0:00.10 VD_hangup.agi 10938 root 20 0 4960 3104 1524 R 3.0 0.1 0:00.09 AST_send_action 10975 root 20 0 5096 3160 1528 R 3.0 0.2 0:00.10 AST_send_action 11005 root 20 0 5948 4312 1792 S 3.0 0.2 0:00.18 AST_send_action 11009 root 20 0 5948 4312 1792 S 3.0 0.2 0:00.13 AST_send_action 2750 root 15 0 11892 7612 2528 S 2.0 0.4 3:14.94 AST_manager_lis 10889 root 20 0 5952 4312 1792 S 2.0 0.2 0:00.15 AST_send_action 10991 root 20 0 5948 4308 1792 S 2.0 0.2 0:00.16 AST_send_action 11007 root 20 0 5948 4312 1792 S 2.0 0.2 0:00.10 AST_send_action 11093 root 19 0 5948 4312 1792 S 2.0 0.2 0:00.15 AST_send_action 11096 root 19 0 5948 4336 1796 S 1.6 0.2 0:00.15 AST_send_action 11137 root 19 0 4696 2756 1492 R 1.3 0.1 0:00.04 AST_send_action 11175 root 19 0 6204 2236 1488 R 1.3 0.1 0:00.04 call_log.agi 11183 root 19 0 6208 2240 1488 R 1.3 0.1 0:00.04 call_log.agi 11219 root 19 0 4436 2456 1480 R 1.3 0.1 0:00.04 AST_send_action 2759 root 16 0 9084 4792 2448 S 1.0 0.2 2:42.81 AST_manager_sen 154 root 15 0 0 0 0 S 0.7 0.0 0:00.14 kswapd0 2796 root 16 0 12264 7988 2472 S 0.7 0.4 3:59.89 AST_VDauto_dial 10973 root 19 0 10760 3888 1900 R 0.7 0.2 0:00.11 call_log.agi 2337 root 16 0 5128 1892 1088 S 0.3 0.1 1:38.53 screen 8824 root 16 0 2024 1016 784 R 0.3 0.0 0:00.32 top 10770 root 16 0 5948 4316 1792 S 0.3 0.2 0:00.19 AST_send_action 10798 root 20 0 5952 4312 1792 S 0.3 0.2 0:00.20 AST_send_action 10899 root 20 0 5948 4304 1792 S 0.3 0.2 0:00.13 AST_send_action 10944 root 19 0 5952 4344 1800 S 0.3 0.2 0:00.10 AST_send_action 10989 root 20 0 5952 4316 1792 S 0.3 0.2 0:00.11 AST_send_action 11104 root 19 0 5928 1624 1196 R 0.3 0.1 0:00.01 VD_hangup.agi 11132 root 19 0 5928 1656 1200 R 0.3 0.1 0:00.01 call_log.agi 11142 root 19 0 5928 1684 1204 R 0.3 0.1 0:00.01 call_log.agi 11177 root 19 0 3752 1428 1060 R 0.3 0.1 0:00.01 AST_send_action 11189 root 20 0 6204 2236 1488 R 0.3 0.1 0:00.01 call_log.agi 1 root 15 0 1748 600 520 S 0.0 0.0 0:03.51 init top - 12:00:32 up 23:53, 1 user, load average: 12.54, 4.16, 2.27 Tasks: 135 total, 37 running, 98 sleeping, 0 stopped, 0 zombie Cpu(s): 61.9% us, 28.8% sy, 0.0% ni, 7.9% id, 0.0% wa, 0.3% hi, 1.0% si Mem: 2074900k total, 1986096k used, 88804k free, 28608k buffers Swap: 0k total, 0k used, 0k free, 1664252k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2411 root -11 0 62316 22m 5164 S 42.8 1.1 93:17.90 asterisk 11172 root 19 0 10884 4432 2324 R 4.6 0.2 0:00.15 call_log.agi 11396 root 18 0 7248 3320 1684 R 4.0 0.2 0:00.12 call_log.agi 11219 root 19 0 5952 4308 1792 S 3.3 0.2 0:00.14 AST_send_action 11270 root 19 0 6988 3116 1680 R 3.3 0.2 0:00.10 call_log.agi 11312 root 15 0 11304 5004 2504 S 3.3 0.2 0:00.10 agi-VDAD_LB_tra 11047 root 21 0 5952 4332 1792 S 3.0 0.2 0:00.19 AST_send_action 11309 root 19 0 11088 4532 2236 R 3.0 0.2 0:00.09 VD_hangup.agi 11315 root 19 0 5948 4312 1792 S 2.7 0.2 0:00.08 AST_send_action 11146 root 19 0 10880 4428 2324 R 2.0 0.2 0:00.16 call_log.agi 11150 root 19 0 11012 4572 2408 R 2.0 0.2 0:00.15 call_log.agi 2750 root 16 0 11892 7612 2528 S 1.7 0.4 3:15.04 AST_manager_lis 10975 root 20 0 5952 4312 1792 S 1.7 0.2 0:00.15 AST_send_action 11078 root 20 0 5948 4312 1792 S 1.7 0.2 0:00.16 AST_send_action 11186 root 19 0 10884 4460 2328 R 1.7 0.2 0:00.15 call_log.agi 11257 root 19 0 5952 4308 1792 S 1.7 0.2 0:00.05 AST_send_action 2796 root 16 0 12264 7988 2472 S 1.3 0.4 3:59.93 AST_VDauto_dial 11319 root 20 0 5904 4100 1620 R 1.3 0.2 0:00.04 AST_send_action 11347 root 19 0 6204 2236 1488 R 1.3 0.1 0:00.04 call_log.agi 11375 root 19 0 6196 1984 1288 R 1.3 0.1 0:00.04 VD_hangup.agi 2337 root 15 0 5128 1892 1088 S 1.0 0.1 1:38.59 screen 2759 root 16 0 9084 4792 2448 S 1.0 0.2 2:42.84 AST_manager_sen 10938 root 20 0 5948 4308 1792 S 1.0 0.2 0:00.12 AST_send_action 8824 root 16 0 2024 1016 784 R 0.7 0.0 0:00.35 top 11353 root 19 0 5932 1660 1200 R 0.7 0.1 0:00.02 call_log.agi 11183 root 19 0 10884 4440 2328 R 0.3 0.2 0:00.15 call_log.agi 11295 root 19 0 5804 1532 1188 R 0.3 0.1 0:00.01 VD_hangup.agi 11324 root 19 0 5796 1528 1176 R 0.3 0.1 0:00.01 call_log.agi 11337 root 20 0 4148 2044 1312 R 0.3 0.1 0:00.01 AST_send_action 11349 root 20 0 4016 1772 1172 R 0.3 0.1 0:00.01 AST_send_action 11380 root 19 0 5932 1620 1196 R 0.3 0.1 0:00.01 VD_hangup.agi 11401 root 19 0 3884 1712 1172 R 0.3 0.1 0:00.01 AST_send_action 1 root 15 0 1748 600 520 S 0.0 0.0 0:03.51 init 2 root RT 0 0 0 0 S 0.0 0.0 0:00.51 migration/0 3 root 34 19 0 0 0 S 0.0 0.0 0:00.00 ksoftirqd/0 4 root RT 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/0 5 root RT 0 0 0 0 S 0.0 0.0 0:00.50 migration/1 top - 12:00:41 up 23:53, 1 user, load average: 14.07, 4.77, 2.49 Tasks: 110 total, 25 running, 85 sleeping, 0 stopped, 0 zombie Cpu(s): 59.9% us, 31.3% sy, 0.0% ni, 7.5% id, 0.0% wa, 0.2% hi, 1.2% si Mem: 2074900k total, 1948836k used, 126064k free, 28616k buffers Swap: 0k total, 0k used, 0k free, 1664244k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2411 root -11 0 62264 22m 5164 S 47.4 1.1 93:21.86 asterisk 11483 root 19 0 5948 4308 1792 S 5.6 0.2 0:00.18 AST_send_action 11465 root 20 0 5952 4336 1800 S 5.3 0.2 0:00.16 AST_send_action 11565 root 19 0 7668 3836 1768 R 3.6 0.2 0:00.11 VD_hangup.agi 11614 root 19 0 5772 3976 1612 R 3.3 0.2 0:00.10 AST_send_action 11493 root 19 0 5948 4312 1792 S 3.0 0.2 0:00.19 AST_send_action 11498 root 19 0 6852 3012 1680 R 3.0 0.1 0:00.09 call_log.agi 11581 root 19 0 5904 4092 1620 R 3.0 0.2 0:00.09 AST_send_action 11599 root 20 0 5772 3976 1620 R 3.0 0.2 0:00.09 AST_send_action 11612 root 19 0 6852 2968 1680 R 3.0 0.1 0:00.09 call_log.agi 11481 root 20 0 5904 4076 1616 R 2.7 0.2 0:00.19 AST_send_action 11561 root 20 0 10884 4432 2324 R 2.7 0.2 0:00.08 call_log.agi 11628 root 18 0 6460 2648 1680 R 2.3 0.1 0:00.07 call_log.agi 11462 root 20 0 4828 2932 1484 R 2.0 0.1 0:00.09 AST_send_action 2750 root 16 0 11892 7612 2528 S 1.3 0.4 3:15.16 AST_manager_lis 2759 root 15 0 9084 4792 2448 S 1.3 0.2 2:42.92 AST_manager_sen 2836 root 15 0 11252 6944 2536 S 1.3 0.3 29:43.16 AST_update.pl 2796 root 16 0 12264 7988 2472 S 1.0 0.4 4:00.02 AST_VDauto_dial 2337 root 16 0 5128 1892 1088 S 0.7 0.1 1:38.64 screen 11535 root 16 0 2024 1000 784 R 0.7 0.0 0:00.03 top 11486 root 19 0 5948 4340 1800 S 0.3 0.2 0:00.11 AST_send_action 11567 root 20 0 3880 1692 1172 R 0.3 0.1 0:00.01 AST_send_action 11588 root 20 0 5952 4316 1792 S 0.3 0.2 0:00.01 AST_send_action 11604 root 20 0 4016 1916 1240 R 0.3 0.1 0:00.01 AST_send_action 1 root 16 0 1748 600 520 S 0.0 0.0 0:03.51 init 2 root RT 0 0 0 0 S 0.0 0.0 0:00.51 migration/0 3 root 34 19 0 0 0 S 0.0 0.0 0:00.00 ksoftirqd/0 4 root RT 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/0 5 root RT 0 0 0 0 S 0.0 0.0 0:00.50 migration/1 6 root 34 19 0 0 0 S 0.0 0.0 0:00.00 ksoftirqd/1 7 root RT 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/1 8 root 10 -5 0 0 0 S 0.0 0.0 0:00.01 events/0 9 root 10 -5 0 0 0 S 0.0 0.0 0:00.00 events/1 10 root 17 -5 0 0 0 S 0.0 0.0 0:00.00 khelper 11 root 10 -5 0 0 0 S 0.0 0.0 0:00.00 kthread 14 root 20 -5 0 0 0 S 0.0 0.0 0:00.00 kacpid 91 root 10 -5 0 0 0 S 0.0 0.0 0:00.00 kblockd/0 top - 12:00:50 up 23:53, 1 user, load average: 16.40, 5.57, 2.77 Tasks: 120 total, 34 running, 86 sleeping, 0 stopped, 0 zombie Cpu(s): 67.0% us, 24.5% sy, 0.0% ni, 7.0% id, 0.0% wa, 0.3% hi, 1.2% si Mem: 2074900k total, 1963948k used, 110952k free, 28640k buffers Swap: 0k total, 0k used, 0k free, 1664740k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 2411 root -11 0 62296 22m 5164 S 33.2 1.1 93:25.28 asterisk 11854 root 16 0 11308 5004 2500 S 6.6 0.2 0:00.20 agi-VDAD_LB_tra 11895 root 18 0 5948 4332 1796 S 6.6 0.2 0:00.20 AST_send_action 11832 root 19 0 11176 4412 2144 R 4.6 0.2 0:00.14 VD_hangup.agi 11898 root 18 0 5948 4308 1792 S 4.3 0.2 0:00.13 AST_send_action 11656 root 22 0 4964 2988 1484 R 3.3 0.1 0:00.10 AST_send_action 11820 root 19 0 5248 3304 1552 R 3.3 0.2 0:00.11 AST_send_action 11830 root 19 0 5092 3156 1528 R 3.3 0.2 0:00.11 AST_send_action 11863 root 19 0 7104 3284 1680 R 3.3 0.2 0:00.10 VD_hangup.agi 11759 root 19 0 6988 3108 1680 R 3.0 0.1 0:00.09 call_log.agi 11803 root 20 0 5904 4100 1620 R 3.0 0.2 0:00.09 AST_send_action 11900 root 19 0 5244 3384 1552 R 3.0 0.2 0:00.09 AST_send_action 11699 root 19 0 5948 4308 1792 S 2.7 0.2 0:00.18 AST_send_action 2836 root 16 0 11252 6944 2536 S 2.3 0.3 29:43.83 AST_update.pl 11810 root 19 0 5948 4336 1796 S 2.3 0.2 0:00.07 AST_send_action 2796 root 15 0 12264 7988 2472 S 1.7 0.4 4:00.18 AST_VDauto_dial 11737 root 19 0 10884 4444 2328 R 1.7 0.2 0:00.15 call_log.agi 2750 root 16 0 11892 7612 2528 S 1.0 0.4 3:15.27 AST_manager_lis 2759 root 15 0 9084 4792 2448 S 1.0 0.2 2:43.00 AST_manager_sen 11768 root 19 0 11132 4764 2408 R 1.0 0.2 0:00.03 VD_hangup.agi 11798 root 20 0 5092 3160 1524 R 1.0 0.2 0:00.03 AST_send_action 11816 root 20 0 5952 4336 1800 S 1.0 0.2 0:00.03 AST_send_action 2337 root 16 0 5128 1892 1088 S 0.7 0.1 1:38.70 screen 1 root 15 0 1748 600 520 S 0.3 0.0 0:03.52 init 11567 root 16 0 5948 4316 1792 S 0.3 0.2 0:00.19 AST_send_action 11570 root 16 0 5948 4316 1792 S 0.3 0.2 0:00.16 AST_send_action 11614 root 16 0 5948 4316 1792 S 0.3 0.2 0:00.13 AST_send_action 11882 root 20 0 3880 1656 1172 R 0.3 0.1 0:00.01 AST_send_action 11886 root 19 0 3748 1420 1060 R 0.3 0.1 0:00.01 AST_send_action 2 root RT 0 0 0 0 S 0.0 0.0 0:00.51 migration/0 3 root 34 19 0 0 0 S 0.0 0.0 0:00.00 ksoftirqd/0 4 root RT 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/0 5 root RT 0 0 0 0 S 0.0 0.0 0:00.50 migration/1 6 root 34 19 0 0 0 S 0.0 0.0 0:00.00 ksoftirqd/1 7 root RT 0 0 0 0 S 0.0 0.0 0:00.00 watchdog/1 8 root 10 -5 0 0 0 S 0.0 0.0 0:00.01 events/0 9 root 10 -5 0 0 0 S 0.0 0.0 0:00.00 events/1

by **enjay** » Wed Sep 20, 2006 2:16 pm

This is what my dial string looks like:

Code: Select all: exten => _1NXXNXXXXXX,1,AGI(call_log.agi,${EXTEN}) exten => _1NXXNXXXXXX,2,Dial(Zap/g4/${EXTEN}||o) exten => _1NXXNXXXXXX,3,Dial(Zap/g6/${EXTEN}||o) exten => _1NXXNXXXXXX,4,Hangup

by **mflorell** » Wed Sep 20, 2006 2:56 pm

Wow, and that's the only thing that changed?

I guess I should try to streamline that script somehow, but I have not seen that kind of load on my servers.

What is the load on your database server?

Do you ever archive or delete records from your call_log table?

How many records are in your call_log table?

by **enjay** » Wed Sep 20, 2006 3:41 pm

Yup thats it as soon as I comment out that line at the begining of the dial string everything works great again system load comes back down to normal etc..

Database Specs
Dual Proc 3.2ghz XEON
4gb RAM
4 15k SCSI RAID5

Database load:

Code: Select all: 13:39:56 up 6 days, 16:11, 2 users, load average: 0.81, 1.01, 0.98

Code: Select all: mysql> select count(*) from call_log; +----------+ | count(*) | +----------+ | 333229 | +----------+ 1 row in set (0.00 sec) mysql>

I dont do any archiving/deleting..

-enjay

by **mflorell** » Wed Sep 20, 2006 6:35 pm

Wow, that very interesting. Are you using all DBI perl scripts?

How many calls do you place per server every 15 minutes at peak?
(VDAD stats report graph can show you this)

by **enjay** » Wed Sep 20, 2006 6:37 pm

Yea Im using all DBI scripts...

Code: Select all: GRAPH IN 15 MINUTE INCREMENTS OF TOTAL CALLS PLACED FROM THIS CAMPAIGN +------+-------------------------------------------------------------------------------------------------------+-------+-------+ | HOUR |0 48 104 168 233 297 361 425 489 553 618 682 746 810| DROPS | TOTAL | +------+-------------------------------------------------------------------------------------------------------+-------+-------+ |+1600+|>>>>>>>>D*******************************************************X | 57 | 506 | | 15 |>>>>>>>>>>>>D****************************************************************************************X | 89 | 802 | +------+-------------------------------------------------------------------------------------------------------+-------+-------+

The drops are high because I was messing with campaign dial level brought it from HARD_LIMIT of a max dial level of 4.5 down to RATIO at 2.5 because of the dropped calls

12 agents.

by **mflorell** » Wed Sep 20, 2006 8:07 pm

That's no more calls than we will do on a single server per 15 minutes(we regularly do over 1000 on a single server for some campaigns). And your hardware is equal to what we use, so I don't know why your loadavg would be skyrocketing.

It can't be a query issue since we have over a million call_log records in our system as any given time. What version of mysqlclientlibs are you using?

As for all of your drops using an ADAPT dial method, we usually set the target difference to a negative number and the dialer will still dial predictively, it just tries to keep an agent waiting for calls. We find this works very well for us while keeping drop rates very low.

by **enjay** » Wed Sep 20, 2006 10:07 pm

I found that lowering my MAX DIAL LEVEL to 2.5 seemed to bring the system to a workable area, and still maintain a ~10 second wait average across the board.

I will test tomarrow to ensure that it continues that way and that the dial level is acceptable and let you know. I also think Im gonna purchase another CPU as the dialers are DL360s (capable of 2 CPU's) that will greatly increase the productivity Im thinking. Not to mention Im going to be adding another 15 agents here shortly.

I think we've beat this one to death bro, and I definately appreciate all your help with it.

I believe my clientlibs are 10-3.23.58-6

-Art

by **mflorell** » Thu Sep 21, 2006 3:57 am

I have been thinking about optimizing the cal_log.agi script since it is called several times per call it should help if it is able to be changed to a FastAGI script or even just streamlined to something less intrusive.

So much to work on so little time

Let me know how moving to dual CPU helps you, I just put a Pentium D CPU in production last night and just received the parts for an Intel Core 2 Duo system yesterday, so I'll post my results about those two as well when I have some good data.

by **enjay** » Fri Sep 22, 2006 1:01 pm

Dude... that CPU made ALL the difference i cant believe how well it works with SMP..

I have 24 agents on this server now dialing at ADAPT_HARD_LIMIT 3.2

my load is under 1.0 full recording everything its screamin!

-enjay

by **mflorell** » Fri Sep 22, 2006 3:48 pm

Cool!

I just posted results of my P4-D test. Dual core makes A LOT of difference:
http://www.eflo.net/VICIDIALforum/viewtopic.php?p=3265

vicidial.org

Report Queries.

Who is online