vicidial.org

I have install ViCibox 5 preload ISO in cluster, below is the configuration:
1 Database Server
2 Web Servers (VERSION: 2.8-409a BUILD: 130809-1410)
2 Telephony Servers (Asterisk 1.8.23.0-vici)

I am using TDM trunks for Inbound and Outbound Calls which are connected to AudioCodes (which converts TDM to SIP).
I have created SIP Carrier which is register on AudioCodes. There is no Problem with Inbound Calls.
but when i dial Outbound Call either from Agent Login or Extension directly, there is delay of 45-46 secs to call get connected to end device. I checked the logs on AudioCodes and found once call arrived on AudioCodes it gets connected to end device within a second. it means ViCi system taking 45 seconds to handover dial request to AudioCodes. there is no delay for Inbound calls. when i dial call from Agent console, Asterisk CLI shows below warning till the call gets connected to called party.
"WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1"

Below is the Asterisk CLI output when call dial from Agent Login:

vicit2*CLI>
== Manager 'sendcron' logged on from 127.0.0.1
== Using SIP RTP CoS mark 5
> Channel SIP/10680-00000035 was answered.
-- Executing [8600051@default:1] MeetMe("SIP/10680-00000035", "8600051,F") in new stack
== Parsing '/etc/asterisk/meetme.conf': == Found
== Parsing '/etc/asterisk/meetme-vicidial.conf': == Found
-- Created MeetMe conference 1023 for conference '8600051'
-- <SIP/10680-00000035> Playing 'conf-onlyperson.gsm' (language 'en')
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged on from 127.0.0.1
-- Executing [8600051@default:1] MeetMe("Local/8600051@default-00000041;2", "8600051,F") in new stack
> Channel Local/8600051@default-00000041;1 was answered.
-- Executing [98667582923@default:1] AGI("Local/8600051@default-00000041;1", "agi://127.0.0.1:4577/call_log") in new stack
-- AGI Script Executing Application: (EXEC) Options: (Set(_CAMPCUST=WESTPOST))
-- <Local/8600051@default-00000041;1>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
-- Executing [98667582923@default:2] Set("Local/8600051@default-00000041;1", "CALLERID(num)=986") in new stack
-- Executing [98667582923@default:3] Dial("Local/8600051@default-00000041;1", "SIP/172.30.41.50/67582923,45,") in new stack
== Using SIP RTP CoS mark 5
== Manager 'sendcron' logged on from 127.0.0.1
-- Executing [58600051@default:1] MeetMe("Local/58600051@default-00000042;2", "8600051,Fmq") in new stack
> Channel Local/58600051@default-00000042;1 was answered.
-- Executing [8309@default:1] Answer("Local/58600051@default-00000042;1", "") in new stack
-- Executing [8309@default:2] Monitor("Local/58600051@default-00000042;1", "wav,20131128-040358__10680_67582923") in new stack
-- Executing [8309@default:3] Wait("Local/58600051@default-00000042;1", "3600") in new stack
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
[Nov 28 10:04:01] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
[Nov 28 10:04:02] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:04] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:05] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
[Nov 28 10:04:06] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:07] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:09] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:10] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:11] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:13] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:14] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:15] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:16] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:18] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:19] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:20] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:21] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:23] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:24] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:25] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:27] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:28] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:29] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:30] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:32] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:33] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:34] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:36] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:37] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:38] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:39] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:41] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:42] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:43] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:45] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
[Nov 28 10:04:46] WARNING[26331]: channel.c:1513 __ast_queue_frame: Exceptionally long voice queue length queuing to Local/8600051@default-00000041;1
-- Called SIP/172.30.41.50/67582923
-- SIP/172.30.41.50-00000036 is ringing
-- SIP/172.30.41.50-00000036 is making progress passing it to Local/8600051@default-00000041;1
-- SIP/172.30.41.50-00000036 answered Local/8600051@default-00000041;1
vicit2*CLI>


Below is the Asterisk CLI output when dial call from Extension:

vicit2*CLI>
== Using SIP RTP CoS mark 5
-- Executing [98667582923@default:1] AGI("SIP/10680-00000031", "agi://127.0.0.1:4577/call_log") in new stack
-- <SIP/10680-00000031>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
-- Executing [98667582923@default:2] Set("SIP/10680-00000031", "CALLERID(num)=986") in new stack
-- Executing [98667582923@default:3] Dial("SIP/10680-00000031", "SIP/172.30.41.50/67582923,45,") in new stack
== Using SIP RTP CoS mark 5
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
== Manager 'sendcron' logged on from 127.0.0.1
== Manager 'sendcron' logged off from 127.0.0.1
-- Called SIP/172.30.41.50/67582923
-- SIP/172.30.41.50-00000032 is ringing
-- SIP/172.30.41.50-00000032 is making progress passing it to SIP/10680-00000031
-- SIP/172.30.41.50-00000032 answered SIP/10680-00000031
-- Locally bridging SIP/10680-00000031 and SIP/172.30.41.50-00000032
-- Executing [h@default:1] AGI("SIP/10680-00000031", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----64-----7") in new stack
-- <SIP/10680-00000031>AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... --64-----7 completed, returning 0
== Spawn extension (default, 98667582923, 3) exited non-zero on 'SIP/10680-00000031'
vicit2*CLI>



Request to help me to remove the latency.

is this tdm conversion happening on the same server vicidial is installed on? If so, consider moving it off that server to another asterisk installation to make your vicidial more generic (ie: replaceable in an emergency, without having to reconfigure that conversion system).

have you tried making a standard SIP call to a standard sip provider to demonstrate that the asterisk system can make a normal sip call without this problem?

also consider using sip debug to see if there is a challenge with communications that may be mentioned during debug.

also post your carrier configuration

interesting that the system is being told (in the dial line: ,45,) to wait 45 seconds and then terminate the call if there is no answer ... but it is instead waiting 45 seconds to initiate the call.

another serious point: you do not appear to have the "o" switch in your dial command line. Is your dial line in the carrier dialplan similar to this (with the "o" or "To" ... "o" is required, "T" is optional)?

Code: Select all

exten=>_91NXXNXXXXXX,n,Dial(${DIAL9TRUNK}/${EXTEN:1},,To)

Thanks for reply William,

TDM to SIP conversion is happening on AudioCodes Mediant 2000 device, Asterisk Server receive and send SIP calls only. I have installed 3 other systems of asterisk i.e. ViCidial 2.4, 2.8, Elastix. and call routing is working properly on these systems.

I tried SIP debug but didn't find any clue, if you want i can share the debug logs.

below is the configuration of Carrier:-

Registration String: register=>172.30.41.50
Account Entry:
[MTNL]
disallow=all
allow=alaw
type=friend
dtmfmode=rfc2833
context=default
qualify=no
host=172.30.41.50

Dialplan Entry:

exten => _986.,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _986.,n,Set(CALLERID(num)=986)
exten => _986.,n,Dial(SIP/172.30.41.50/${EXTEN:3},45,)
exten => _986.,n,Hangup()

I also tried "To" switch in Dial Command line, but there is no change in situation. I already tried reducing Wait time from 45 secs to 20 secs but that doesn't change anything.

Verify the asterisk version in admin->servers matches the asterisk version from "asterisk -V" at the command line.

Also please test with a generic sip carrier to see if this is directly related to your TDM interface sip or part of the Vicidial installation.

I'd even try a VMware installation of a fresh "stock" vicibox 5.0.3 installation to see if it experiences the same problem.

Please also verify the problem persists without the callerid(num) setting. I'd go through the system and try to make everything as "stock" as humanly possible to see if it will turn out to be a simple problem.

Or re-install with 4.0.3 and see if that helps (after all, it will still be able to upgrade to the latest SVN of Vicidial, it'll just have Asterisk 1.4 instead of 1.8 ...).

sip debugging may be useful as well.