recurring problem - dropped calls, not transfered to agents

[ragnadik]

Hi,

I have this recurring problem that occurs every 7-10 days and the only way I can fixed it is to reset the running asterisk process. This is what happens every 7-10 days:

1. I would get lots of dropped calls even if agents are waiting.

2. The following errors would appear in Fastagi log:

DBD::mysql::db do failed: Duplicate entry '1209596318.1013663' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209596315.1013646' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209596323.1013677' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209596326.1013689' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209596390.1013715' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209607264.1013725' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209607732.1013730' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209607737.1013732' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209607750.1013739' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209607757.1013739' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.
DBD::mysql::db do failed: Duplicate entry '1209607762.1013744' for key 1 at /usr/share/astguiclient/FastAGI_log.pl line 411, <STDIN> line 21.

3. VDAD report indicates that the average call duration for dropped calls is between 9-10 seconds. When I don't have this problem, average call duration for dropped calls is 5 secs. This is consistent with my drop seconds set in the campaign.

4. Problem is isolated per server. If I get the fastagilog errors on server1, only agents logged in on that server are affected. And I only have to reset running asterisk process on that server.

My setup is:
All servers are HP, 2 x dual Xeons (4 processors total)
1 DB server - 4 GB
1 web server - 2 GB
3 asterisk servers - 2 GB each (maximum of 24 agents per server)

Distro: Centos 5.1
Asterisk: 1.2.24
Vicidial: 2.0.3
Load Average is minimal. most of the time < 1.0 sometimes between 1.0 and 2.0 (using top)

I am using extension 8370:

exten => 8370,1,Playback(sip-silence)
exten => 8370,2,AGI(agi://127.0.0.1:4577/call_log)
exten => 8370,3,AMD(2500|1500|300|4000|120|50|5|256)
exten => 8370,4,AGI(VD_amd.agi,${EXTEN})
exten => 8370,5,AGI(agi-VDAD_LO_transfer.agi,${EXTEN})
exten => 8370,6,AGI(agi-VDAD_LO_transfer.agi,${EXTEN})
exten => 8370,7,Hangup

Here are some log output from agiout:

2008-05-01 6:58:56|VD_amd.agi|Perl Environment Dump:
2008-05-01 6:58:56|VD_amd.agi|0|8370
2008-05-01 6:58:56|VD_amd.agi|AGI Environment Dump:
2008-05-01 6:58:56|VD_amd.agi| -- accountcode =
2008-05-01 6:58:56|VD_amd.agi| -- callerid = 8008888888
2008-05-01 6:58:56|VD_amd.agi| -- calleridname = V0501065837112244953
2008-05-01 6:58:56|VD_amd.agi| -- callingani2 = 0
2008-05-01 6:58:56|VD_amd.agi| -- callingpres = 0
2008-05-01 6:58:56|VD_amd.agi| -- callingtns = 0
2008-05-01 6:58:56|VD_amd.agi| -- callington = 0
2008-05-01 6:58:56|VD_amd.agi| -- channel = SIP/TURON-09a6c100
2008-05-01 6:58:56|VD_amd.agi| -- context = default
2008-05-01 6:58:56|VD_amd.agi| -- dnid = unknown
2008-05-01 6:58:56|VD_amd.agi| -- enhanced = 0.0
2008-05-01 6:58:56|VD_amd.agi| -- extension = 8370
2008-05-01 6:58:56|VD_amd.agi| -- language = en
2008-05-01 6:58:56|VD_amd.agi| -- priority = 4
2008-05-01 6:58:56|VD_amd.agi| -- rdnis = unknown
2008-05-01 6:58:56|VD_amd.agi| -- request = VD_amd.agi
2008-05-01 6:58:56|VD_amd.agi| -- type = SIP
2008-05-01 6:58:56|VD_amd.agi| -- uniqueid = 1209596318.1013662
2008-05-01 6:58:56|VD_amd.agi|AGI Variables: |1209596318.1013662|SIP/TURON-09a6c100|8370|SIP|V0501065837112244953|
2008-05-01 6:58:56|VD_amd.agi|+++++ VD amd START : |112244953|2008-05-01 6:58:56||4|V0501065837112244953|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|Perl Environment Dump:
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|0|8370
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|callerID changed: V0501065837112244953
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|AGI Environment Dump:
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- accountcode =
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- callerid = 8008888888
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- calleridname = V0501065837112244953
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- callingani2 = 0
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- callingpres = 0
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- callingtns = 0
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- callington = 0
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- channel = SIP/TURON-09a6c100
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- context = default
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- dnid = unknown
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- enhanced = 0.0
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- extension = 8370
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- language = en
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- priority = 5
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- rdnis = unknown
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- request = agi-VDAD_LO_transfer.agi
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- type = SIP
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi| -- uniqueid = 1209596318.1013662
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|AGI Variables: |1209596318.1013662|SIP/TURON-09a6c100|8370|SIP|V0501065837112244953|V0501065837112244953|5|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|+++++ VDAD START : |112244953|2008-05-01 6:58:56|1.2.24|5|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V0501065837112244953';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V0501065837112244953' and status IN('LIVE','XFER');|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|-- VDAD : |0E0|update of vac table: V0501065837112244953
|UPDATE vicidial_auto_calls set uniqueid='1209596318.1013662', channel='SIP/TURON-09a6c100',status='LIVE',stage='LIVE-0' where callerid='V0501065837112244953' order by call_time desc limit 1;|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|


2008-05-01 6:58:58|VD_amd.agi|-- VDAD vicidial_list update: |1|112244933
2008-05-01 6:58:58|VD_amd.agi|-- VDAC record deleted: |0E0| |112244933|1209596315.1013647|
2008-05-01 6:58:58|VD_amd.agi||SELECT start_epoch FROM vicidial_log where uniqueid='1209596315.1013647' and lead_id='112244933' order by call_date desc limit 1;|
2008-05-01 6:58:58|VD_amd.agi|no VDL record found: 1209596315.1013647 V0501065834112244933 112244933 1209596315.1013647
2008-05-01 6:58:58|VD_amd.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed,length_in_sec,end_epoch) values('1209596315.1013647','112244933','','2008-05-01 6:58:58','1209596338','A','','','VDAD','N','3','1209596341')|
2008-05-01 6:58:58|VD_amd.agi||SELECT am_message_exten,amd_send_to_vmx FROM vicidial_campaigns where campaign_id = '';|
2008-05-01 6:58:58|VD_amd.agi|-- AMD campaign values: ||||
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:59:01|VD_amd.agi|Perl Environment Dump:
2008-05-01 6:59:01|VD_amd.agi|0|8370
2008-05-01 6:59:01|VD_amd.agi|AGI Environment Dump:
2008-05-01 6:59:01|VD_amd.agi| -- accountcode =
2008-05-01 6:59:01|VD_amd.agi| -- callerid = 8008888888
2008-05-01 6:59:01|VD_amd.agi| -- calleridname = V0501065843112244965
2008-05-01 6:59:01|VD_amd.agi| -- callingani2 = 0
2008-05-01 6:59:01|VD_amd.agi| -- callingpres = 0
2008-05-01 6:59:01|VD_amd.agi| -- callingtns = 0
2008-05-01 6:59:01|VD_amd.agi| -- callington = 0
2008-05-01 6:59:01|VD_amd.agi| -- channel = SIP/TURON-09a61188
2008-05-01 6:59:01|VD_amd.agi| -- context = default
2008-05-01 6:59:01|VD_amd.agi| -- dnid = unknown
2008-05-01 6:59:01|VD_amd.agi| -- enhanced = 0.0
2008-05-01 6:59:01|VD_amd.agi| -- extension = 8370
2008-05-01 6:59:01|VD_amd.agi| -- language = en
2008-05-01 6:59:01|VD_amd.agi| -- priority = 4
2008-05-01 6:59:01|VD_amd.agi| -- rdnis = unknown
2008-05-01 6:59:01|VD_amd.agi| -- request = VD_amd.agi
2008-05-01 6:59:01|VD_amd.agi| -- type = SIP
2008-05-01 6:59:01|VD_amd.agi| -- uniqueid = 1209596323.1013674
2008-05-01 6:59:01|VD_amd.agi|AGI Variables: |1209596323.1013674|SIP/TURON-09a61188|8370|SIP|V0501065843112244965|
2008-05-01 6:59:01|VD_amd.agi|+++++ VD amd START : |112244965|2008-05-01 6:59:01||4|V0501065843112244965|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|Perl Environment Dump:
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|0|8370
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|callerID changed: V0501065843112244965
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|AGI Environment Dump:
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- accountcode =
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- callerid = 8008888888
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- calleridname = V0501065843112244965
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- callingani2 = 0
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- callingpres = 0
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- callingtns = 0
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- callington = 0
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- channel = SIP/TURON-09a61188
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- context = default
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- dnid = unknown
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- enhanced = 0.0
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- extension = 8370
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- language = en
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- priority = 5
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- rdnis = unknown
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- request = agi-VDAD_LO_transfer.agi
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- type = SIP
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi| -- uniqueid = 1209596323.1013674
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|AGI Variables: |1209596323.1013674|SIP/TURON-09a61188|8370|SIP|V0501065843112244965|V0501065843112244965|5|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|+++++ VDAD START : |112244965|2008-05-01 6:59:01|1.2.24|5|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_live_agents where callerid='V0501065843112244965';|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where callerid='V0501065843112244965' and status IN('LIVE','XFER');|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|-- VDAD : |1|update of vac table: V0501065843112244965
|UPDATE vicidial_auto_calls set uniqueid='1209596323.1013674', channel='SIP/TURON-09a61188',status='LIVE',stage='LIVE-0' where callerid='V0501065843112244965' order by call_time desc limit 1;|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||INSERT INTO vicidial_log (uniqueid,lead_id,campaign_id,call_date,start_epoch,status,phone_code,phone_number,user,processed) values('1209596323.1013674','112244965','EBCERT','2008-05-01 6:59:01','1209596341','QUEUE','1','8012539092','VDAD','N')|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|-- VDAD : |112244965|112244965|insert to vicidial_log: 1209596323.1013674
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = 'EBCERT' and call_time < "2008-05-01 06:58:43" and lead_id != '112244965';|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_live_agents where server_ip='192.168.0.6' and campaign_id = 'EBCERT' and last_update_time > '20080501065856';|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||CONCURRENT TRANSFERS AUTO SETTING: 2 (8)|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|-- VDAD get agent: |1|update of vla table: EBCERT|192.168.0.6
|UPDATE vicidial_live_agents set status='QUEUE',lead_id='112244965',uniqueid='1209596323.1013674', channel='SIP/TURON-09a61188', call_server_ip='192.168.0.6', callerid='V0501065843112244965' where status = 'READY' and server_ip='192.168.0.6' and campaign_id='EBCERT' and last_update_time > '20080501065856' order by last_call_finish limit 1;|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi||SELECT conf_exten,user,extension FROM vicidial_live_agents where status IN('QUEUE','INCALL') and server_ip='192.168.0.6' and campaign_id='EBCERT' and callerid='V0501065843112244965' and channel='SIP/TURON-09a61188' order by last_call_time limit 1;|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|-- VDAD XFER : |1|update of vac table: V0501065843112244965
|UPDATE vicidial_auto_calls set status='XFER', stage='XFER-0' where callerid='V0501065843112244965';|
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|exiting the VDAD app, transferring call to 8600057
2008-05-01 6:59:01|agi-VDAD_LO_transfer.agi|XXXXXXXXXX VDAD transferred: start|stop 2008-05-01 6:59:01|2008-05-01 6:59:01
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi||SELECT count(*) FROM vicidial_auto_calls where status = 'LIVE' and server_ip!='192.168.0.6' and campaign_id = '' and call_time < "" and lead_id != '';|
2008-05-01 6:58:56|agi-VDAD_LO_transfer.agi|WWWWWWWW VDAD XFER REMOTE WAIT: |0||SIP/TURON-09a6c100|V0501065837112244953|1209596318.1013662|
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi||SELECT voicemail_ext FROM vicidial_campaigns where campaign_id = '' limit 1;|
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi|-- VDAD call_hungup timout: |VH050165906||SIP/TURON-09a6c100|insert to vicidial_manager
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi|-- VDAD vac record deleted: |0E0||
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi||UPDATE vicidial_log set status='DROP',end_epoch='1209596346',length_in_sec='10' where uniqueid = '1209596318.1013662';|
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi|-- VDAD vicidial_log update: |1|1209596318.1013662
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi||UPDATE vicidial_list set status='DROP' where lead_id = '112244953';|
2008-05-01 6:59:06|agi-VDAD_LO_transfer.agi|-- VDAD vicidial_list update: |1|112244953
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi|Perl Environment Dump:
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi|0|8370
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi|callerID changed: V0501065837112244953
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi|AGI Environment Dump:
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- accountcode =
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- callerid = unknown
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- calleridname = V0501065837112244953
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- callingani2 = 0
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- callingpres = 0
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- callingtns = 0
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- callington = 0
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- channel = SIP/TURON-09a6c100
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- context = default
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- dnid = unknown
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- enhanced = 0.0
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- extension = 8370
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- language = en
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- priority = 6
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- rdnis = unknown
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- request = agi-VDAD_LO_transfer.agi
2008-05-01 6:59:07|agi-VDAD_LO_transfer.agi| -- type = SIP

My initial observation:

1. call started 6:58:56. This timestamp appeared in the log until 6:59:06 when the call was dropped after 10 seconds.

2. I removed entries between 6:58:56 and 6:59:06 that is not related to this call. i just retained some to show that timestamp 6:58:56 is used for lines having 'WWWWWWWW VDAD XFER REMOTE WAIT: '

Anybody having the same problem? Please help!

Thanks!

[mflorell]

astGUIclient version?

Asterisk version?

[ragnadik]

Distro: Centos 5.1
Asterisk: 1.2.24
Vicidial: 2.0.3
Load Average is minimal. most of the time < 1.0 sometimes between 1.0 and 2.0 (using top)

[mflorell]

In general I would suggest upgrading to 2.0.4.1rc2

Do you have Preemption Model turned on in your kernel config?

Do you see any issues on the Asterisk CLI when these problems happen?

Do you have any logfiles in asterisk that are over 2GB when this happens?

[ragnadik]

Hi Matt,

From make menuconfig I get the following data about kernel preemption:

( ) No Forced Preemption (Server)
(X)Voluntary Kernel Preemption (Desktop)
( ) Preemptible Kernel (Low Latency Desktop)

(*) Preempt The Big Kernel Lock

What is the recommended value?

The asterisk CLI shows the usual Warning about avoided deadlocked 9 retries, but I get this warning all the time.

I don't have any log files over 2GB in /var/log/asterisk. I routinely delete the Master.csv file.

Thanks!

[mflorell]

Process preemption should really be set to "No Forced Preemption (Server)" to avoid problems with how VICIDIAL works. you will need to recompile the server after making that change.

As for the warnings about deadlocks, do you do a lot of recording?

[ragnadik]

Hi Matt,

Will recompile the kernel during the weekend. Will report back results later.

As for the recording, I am recording all calls with record delay set to zero.

Thanks again!

[mflorell]

Are you recording to tmpfs or RAM drive? If not you should switch to doing that as well, it will also help to reduce your load and problems.