Vicidial Call Delivery too slow

[roche]

I have a campaing with the following configuration:

Hopper Level: 100
Auto Dial Level: 2.5
Next Agent Call: overall_user_level

I have waiting average of 1:19 I think is too much time waiting for a call.

I tryed incresing the Hopper Level, The Auto Dial level but It doesn't seem help.

Looking in the RealTime report I look some live call that are not delivery to any agent (all of them are waiting for calls)

Some one has experimented some behaivor like that?


Regards

[mflorell]

How many agents?

What kind of trunks are you using?

Do you see anything on the Asterisk CLI that would indicate dialing problems(ERRORS or WARNINGS or NOTICEs)?

Can you post some output from your ASTVDauto screen? (screen -x ASTVDauto)?

[roche]

How many agents?

In these moment only 4 agents

What kind of trunks are you using?

Aix termination

Do you see anything on the Asterisk CLI that would indicate dialing problems(ERRORS or WARNINGS or NOTICEs)?

These ones.


-- AMD: ANSWERING MACHINE: silenceDuration:2000 initialSilence:2000
Jul 5 16:07:42 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:42 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:43 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:43 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:43 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:43 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:43 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:44 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:44 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:44 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:44 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 5 16:07:45 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
-- AMD: IAX2/binfone00-19 9043713153 (null) (Fmt: 64)
-- AMD: initialSilence [2000] greeting [2000] afterGreetingSilence [400] totalAnalysisTime [5000] minimumWordLength [120] betweenWordsSilence [25] maximumNumberOfWords [5] silenceThreshold [256]

-------

-- AMD: initialSilence [2000] greeting [2000] afterGreetingSilence [400] totalAnalysisTime [5000] minimumWordLength [120] betweenWordsSilence [25] maximumNumberOfWords [5] silenceThreshold [256]
Jul 5 16:08:29 NOTICE[29478]: chan_iax2.c:3123 iax2_read: I should never be called!
-- AMD: IAX2/binfone00-4 9043713153 (null) (Fmt: 64)
-- AMD: initialSilence [2000] greeting [2000] afterGreetingSilence [400] totalAnalysisTime [5000] minimumWordLength [120] betweenWordsSilence [25] maximumNumberOfWords [5] silenceThreshold [256]
-- AMD: Word detected. iWordsCount:1
-- AMD: Changed state to STATE_IN_SILENCE
-- AMD: HUMAN: silenceDuration:400 afterGreetingSilence:400
-- AMD: ANSWERING MACHINE: silenceDuration:2000 initialSilence:2000
Jul 5 16:08:35 WARNING[2755]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame

----------------------------------------------------------------------------

[5] silenceThreshold [256]
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay 0, this delay -785093, threshold 1000, new offset 785093
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -47, this delay -86285, threshold 1120, new offset 785095
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -48, this delay -86286, threshold 1114, new offset 785094
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -49, this delay -86288, threshold 1116, new offset 785095
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -47, this delay -86285, threshold 1120, new offset 785094
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -1, this delay -785094, threshold 1000, new offset 785094
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -54, this delay -86293, threshold 1120, new offset 785095
Jul 5 16:20:13 WARNING[2755]: chan_iax2.c:695 jb_warning_output: Resyncing the jb. last_delay -46, this delay -86284, threshold 1118, new offset 785094

Can you post some output from your ASTVDauto screen? (screen -x ASTVDauto)?

screen -x ASTVDauto

TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:06|| lagged call vla agent PAUSED 0|20060705160336|20060705160356|20060705160406||
2006-07-05 16:04:06|| lagged call vac agent DELETED 0|2006-07-05 16:02:06||

loop counter: |5758872|
TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:09|LIVE AGENTS LOGGED IN: 3|
2006-07-05 16:04:09|HLPA 10.10.61.17: agents: 2 dial_level: 2.5|
2006-07-05 16:04:09|HLPA 10.10.61.17: Calls to place: 0 (5 - 5) |
2006-07-05 16:04:09|HLP 10.10.61.17: agents: 3 dial_level: 2.5|
2006-07-05 16:04:09|HLP 10.10.61.17: Calls to place: 0 (8 - |
2006-07-05 16:04:09|HLPA 10.10.61.17: CALLING|
2006-07-05 16:04:09|HLP 10.10.61.17: CALLING|
TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:09|| lagged call vla agent PAUSED 0|20060705160339|20060705160359|20060705160409||
2006-07-05 16:04:09|| lagged call vac agent DELETED 0|2006-07-05 16:02:09||

loop counter: |5758871|
TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:11|LIVE AGENTS LOGGED IN: 3|
2006-07-05 16:04:11|HLPA 10.10.61.17: agents: 2 dial_level: 2.5|
2006-07-05 16:04:11|HLPA 10.10.61.17: Calls to place: 0 (5 - 5) |
2006-07-05 16:04:11|HLP 10.10.61.17: agents: 3 dial_level: 2.5|
2006-07-05 16:04:11|HLP 10.10.61.17: Calls to place: 0 (8 - |
2006-07-05 16:04:11|HLPA 10.10.61.17: CALLING|
2006-07-05 16:04:11|HLP 10.10.61.17: CALLING|
TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:11|| lagged call vla agent PAUSED 0|20060705160341|20060705160401|20060705160411||
2006-07-05 16:04:11|| lagged call vac agent DELETED 0|2006-07-05 16:02:11||

loop counter: |5758870|
2006-07-05 16:04:11|| lagged call vac agent DELETED 0|2006-07-05 15:54:11|LIVE||
2006-07-05 16:04:11|| updating server parameters 30|8365|-6|default||
TIME DEBUG: -6|-6|0| GMT: 22:04
checking to see if listener is dead |1|
TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:14|LIVE AGENTS LOGGED IN: 3|
2006-07-05 16:04:14|HLPA 10.10.61.17: agents: 2 dial_level: 2.5|
2006-07-05 16:04:14|HLPA 10.10.61.17: Calls to place: 0 (5 - 5) |
2006-07-05 16:04:14|HLP 10.10.61.17: agents: 3 dial_level: 2.5|
2006-07-05 16:04:14|HLP 10.10.61.17: Calls to place: 0 (8 - |
2006-07-05 16:04:14|HLPA 10.10.61.17: CALLING|
2006-07-05 16:04:14|HLP 10.10.61.17: CALLING|
TIME DEBUG: -6|-6|0| GMT: 22:04
2006-07-05 16:04:14|| lagged call vla agent PAUSED 0|20060705160344|20060705160404|20060705160414||
2006-07-05 16:04:14|| lagged call vac agent DELETED 0|2006-07-05 16:02:14||

loop counter: |5758848|
TIME DEBUG: -6|-6|0| GMT: 22:05
2006-07-05 16:05:11|LIVE AGENTS LOGGED IN: 2|
2006-07-05 16:05:11|HLPA 10.10.61.17: agents: 2 dial_level: 2.5|
2006-07-05 16:05:11|HLPA 10.10.61.17: Calls to place: 0 (5 - 5) |
2006-07-05 16:05:11|HLPA 10.10.61.17: CALLING|
TIME DEBUG: -6|-6|0| GMT: 22:05
2006-07-05 16:05:11|| dead call vac deleted|64969|92231|V0705160442000092231|1152137110|1|||
2006-07-05 16:05:11|| dead NA call added to log 1152137083.2138000|92231|6104942558|SENT|NA||
2006-07-05 16:05:11|| dead call vac lead marked NA|92231|6104942558|SENT||
2006-07-05 16:05:11|| dead call vla agent PAUSED 0|92231|6104942558|SENT||
2006-07-05 16:05:11|| lagged call vla agent PAUSED 0|20060705160441|20060705160501|20060705160511||
2006-07-05 16:05:11|| lagged call vac agent DELETED 0|2006-07-05 16:03:11||

loop counter: |5758847|
TIME DEBUG: -6|-6|0| GMT: 22:05
2006-07-05 16:05:14|LIVE AGENTS LOGGED IN: 3|
2006-07-05 16:05:14|HLPA 10.10.61.17: agents: 2 dial_level: 2.5|
2006-07-05 16:05:14|HLPA 10.10.61.17: Calls to place: 0 (5 - 5) |
2006-07-05 16:05:14|HLP 10.10.61.17: agents: 3 dial_level: 2.5|
2006-07-05 16:05:14|HLP 10.10.61.17: Calls to place: 3 (8 - 5) |
2006-07-05 16:05:14|HLPA 10.10.61.17: CALLING|
2006-07-05 16:05:14|HLP 10.10.61.17: CALLING|
|UPDATE vicidial_hopper set status='QUEUE', user='VDAD_10.10.61.17' where campaign_id='HLP' and status='READY' order by hopper_id LIMIT 3|
hopper rows updated to QUEUE: |3|
|SELECT lead_id FROM vicidial_hopper where campaign_id='HLP' and status='QUEUE' and user='VDAD_10.10.61.17' LIMIT 1|
|UPDATE vicidial_hopper set status='INCALL' where lead_id='92238'|
hopper row updated to INCALL: |1|92238|
2006-07-05 16:05:14|| number call dialed|HLP|V0705160514000092238|INSERT INTO vicidial_manager values('','','2006-07-05 16:05:14','NEW','N','10.10.61.17','','Originate','V0705160514000092238','Exten: 8369','Context: default','Channel: Local/9813018849689@default','Priority: 1','Callerid: "V0705160514000092238" <9043713153>','Timeout: 26000','','','','')|-4.00||
|SELECT lead_id FROM vicidial_hopper where campaign_id='HLP' and status='QUEUE' and user='VDAD_10.10.61.17' LIMIT 1|
|UPDATE vicidial_hopper set status='INCALL' where lead_id='92239'|
hopper row updated to INCALL: |1|92239|
2006-07-05 16:05:14|| number call dialed|HLP|V0705160514000092239|INSERT INTO vicidial_manager values('','','2006-07-05 16:05:14','NEW','N','10.10.61.17','','Originate','V0705160514000092239','Exten: 8369','Context: default','Channel: Local/9816036222440@default','Priority: 1','Callerid: "V0705160514000092239" <9043713153>','Timeout: 26000','','','','')|-4.00||
|SELECT lead_id FROM vicidial_hopper where campaign_id='HLP' and status='QUEUE' and user='VDAD_10.10.61.17' LIMIT 1|
|UPDATE vicidial_hopper set status='INCALL' where lead_id='92240'|
hopper row updated to INCALL: |1|92240|
2006-07-05 16:05:14|| number call dialed|HLP|V0705160514000092240|INSERT INTO vicidial_manager values('','','2006-07-05 16:05:14','NEW','N','10.10.61.17','','Originate','V0705160514000092240','Exten: 8369','Context: default','Channel: Local/9815176490260@default','Priority: 1','Callerid: "V0705160514000092240" <9043713153>','Timeout: 26000','','','','')|-4.00||
TIME DEBUG: -6|-6|0| GMT: 22:05
2006-07-05 16:05:14|| lagged call vla agent PAUSED 0|20060705160444|20060705160504|20060705160514||
2006-07-05 16:05:14|| lagged call vac agent DELETED 0|2006-07-05 16:03:14||

[mflorell]

try turning your dial_level up to 4.0 or try not using AMD and see if either of those help.

[roche]

try turning your dial_level up to 4.0 or try not using AMD and see if either of those help.

Well I tryed It the average get better but the dropped calls is increasing ....

I didn't turn off the AMD because the agents begin to complain about the amount of AM.

The other thing was the calls Time On VDAD some time is high like 1:30 minutes.

For example

+------------+--------+----------+--------------------+---------------------+---------+
| CHANNEL | STATUS | CAMPAIGN | PHONE NUMBER | START TIME | MINUTES |
+------------+--------+----------+--------------------+---------------------+---------+
| | SENT | HLP | xxxxxxxxxxx | 2006-07-05 17:26:14 | 1:36 |
| | SENT | HLP | 1706xxxxxxx | 2006-07-05 17:26:14 | 1:36 |
| | SENT | HLP | 184xxxxxxxx | 2006-07-05 17:26:14 | 1:36 |
| | SENT | HLP | 15xxxxxxxxx | 2006-07-05 17:26:20 | 1:30 |
| | SENT | HLP | 16xxxxxxxxx | 2006-07-05 17:27:27 | 0:23 |
| | SENT | HLP | 19xxxxxxxxx | 2006-07-05 17:27:27 | 0:23 |
| | SENT | HLP | 12xxxxxxxxx | 2006-07-05 17:27:27 | 0:23 |
| | SENT | HLP | 16xxxxxxxxx | 2006-07-05 17:27:27 | 0:23 |
| | SENT | HLP | 19xxxxxxxxx | 2006-07-05 17:27:27 | 0:23 |
| | SENT | HLP | 15xxxxxxxxx | 2006-07-05 17:27:27 | 0:23 |
| | SENT | HLP | 18xxxxxxxxx | 2006-07-05 17:27:43 | 0:07 |
| | SENT | HLP | 12xxxxxxxxx | 2006-07-05 17:27:46 | 0:04 |
+------------+--------+----------+--------------------+---------------------+---------+

[mflorell]

What is the dial timeout that you have set in the campaign detail screen?

Have you tried dialing those numbers that are over 1 minute manually to see if they can be dialed?

[roche]

What is the dial timeout that you have set in the campaign detail screen?

Have you tried dialing those numbers that are over 1 minute manually to see if they can be dialed?

The dial time out is 26 seconds

Well, Yes those numbers can be dailed.

I avoid the jtbuffer messages forcing not to use it.

The calls seems to be delivering better but with sound quality problems.

the following message show up I don't know what is mean

Jul 6 15:10:40 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:10:40 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:10:40 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:11:24 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:11:24 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:11:24 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:11:24 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:11:24 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:12:20 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:12:20 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:12:20 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:12:20 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:12:20 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:08 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:08 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:08 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:08 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:45 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:45 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:45 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:15:45 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:16:44 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:16:44 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:16:44 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:23:47 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:23:47 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:23:47 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:23:47 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:23:47 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:24:39 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:24:39 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:24:39 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:26:54 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:26:54 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:26:54 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:26:54 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:29:00 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame
Jul 6 15:29:00 WARNING[2746]: chan_iax2.c:6454 socket_read: Received trunked frame before first full voice frame

[mflorell]

Those messages just mean that the channel signal("there is a call coming..") is arriving and the voice packets have not arrived yet. Usually means a bandwidth issue with latency.

[roche]

What is the dial timeout that you have set in the campaign detail screen?

Have you tried dialing those numbers that are over 1 minute manually to see if they can be dialed?

Well I still have the delivery issue.

I was wondering what happend if I would increased the AudoDial level in the drop down for example to 5? Yes I think It would screw something up but well ... I need to increase the delivery time.

[mflorell]

You will have to alter some code to allow you to do that in the admin.php, but you can do it. I've dialed at a dial_level of 23 before and it works fine if your servers can handle that many calls.

[maverick]

What are the possible solutions to make the calls faster on vici regardless of multiple campaigns running on it?

[mflorell]

This is a 6 year old thread, we have made a lot of changes since 2006. What are you trying to do exactly, how is your system set up and what version are you using?