PRI call failure cause-cancel -More agent Idle time

[lvish]

Hi

This is a new install of VICIBOX on Dual Core , 8GB ram , vicidial version VERSION: 2.4-357a BUILD: 120125-2107 & 2 E1s connected to two Sangoma A101 card .

Issue is many calls are failing with PRI cause of CANCEL and leads status remains NEW under Called column.
Am able to dial these leads manually . I have seen maximum of 25 calls active , on an average 15 calls will be active normally.
45 agents and 60 channels are configured on this server.

Is it a platform/ capacity issue or I have missed any configs.

Pls find below the log captures.


Extensions.conf ( 9 is the prefix mentioned in campaign, leads are loaded with out phone code , only 10 digit phone number starting from 9 ,8 & 7 is loaded)

exten => _9X.,1,AGI(agi://127.0.0.1:4577/call_log)
exten => _9X.,2,Dial(${TRUNKX}/${EXTEN:1}/w,,To)
exten => _9X.,3,Hangup


Screens -ls

screen -ls
There are screens on:
4206.ASTfastlog (Detached)
5774.ASTlisten (Detached)
5771.ASTsend (Detached)
4096.asterisk (Detached)
32346.ASTVDadapt (Detached)
5768.ASTupdate (Detached)
5777.ASTVDremote (Detached)
4197.ASTVDauto (Detached)
4087.astshell20120425205224 (Detached)
9 Sockets in /var/run/screens/S-root

Dahdi Configs Bit modified after going through the vicidial & asterisk forums for the same issue.


;autogenerated by /usr/sbin/wancfg_dahdi do not hand edit
;autogenrated on 2012-04-25
;Dahdi Channels Configurations
;For detailed Dahdi options, view /etc/asterisk/chan_dahdi.conf.bak

[trunkgroups]

[channels]
context=default
usecallerid=yes
hidecallerid=no
callwaiting=yes
usecallingpres=yes
callwaitingcallerid=yes
threewaycalling=yes
transfer=yes
canpark=yes
cancallforward=yes
callreturn=yes
echocancel=no
echocancelwhenbridged=no
relaxdtmf=yes
rxgain=0.0
txgain=0.0
group=1
callgroup=1
pickupgroup=1
immediate=no
resetinterval=10000000
pridialplan = unknown
pridialplan = unknown
busydetect=no
priindication=outofband


;Sangoma A101 port 1 [slot:4 bus:26 span:1] <wanpipe1>
switchtype=euroisdn
context=from-internal
group=1
echocancel=yes
signalling=pri_cpe
channel =>1-15,17-31

;Sangoma A101 port 1 [slot:4 bus:32 span:2] <wanpipe2>
switchtype=euroisdn
context=from-internal
group=1
echocancel=yes
signalling=pri_cpe
channel =>32-46,48-62

CLI Out Put & FastAGI LOgs Telephone no. are changed to ZZZZZZZZZZ in below post.



[Apr 28 14:01:40] VERBOSE[31142] logger.c: [Apr 28 14:01:40] -- Hungup 'DAHDI/17-1'
[Apr 28 14:01:40] VERBOSE[31142] logger.c: [Apr 28 14:01:40] == Everyone is busy/congested at this time (1:0/1/0)
[Apr 28 14:01:40] VERBOSE[31142] logger.c: [Apr 28 14:01:40] -- Executing [9ZZZZZZZZZ@default:3] Hangup("Local/99444409423@default-2c7e,2", "") in new stack
[Apr 28 14:01:40] VERBOSE[31142] logger.c: [Apr 28 14:01:40] == Spawn extension (default, ZZZZZZZZZ, 3) exited non-zero on 'Local/99444409423@default-2c7e,2'
[Apr 28 14:01:40] VERBOSE[31142] logger.c: [Apr 28 14:01:40] -- Executing [h@default:1] DeadAGI("Local/99444409423@default-2c7e,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CONGESTION----------") in new stack
[Apr 28 14:01:40] DEBUG[30928] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/3-1
[Apr 28 14:01:40] DEBUG[30928] chan_dahdi.c: Not yet hungup... Calling hangup once with icause, and clearing call
[Apr 28 14:01:40] DEBUG[30928] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/3-1
[Apr 28 14:01:40] ERROR[30927] utils.c: write() returned error: Broken pipe
[Apr 28 14:01:40] VERBOSE[30928] logger.c: [Apr 28 14:01:40] -- Hungup 'DAHDI/3-1'
[Apr 28 14:01:40] ERROR[30927] utils.c: write() returned error: Broken pipe
[Apr 28 14:01:40] ERROR[30927] utils.c: write() returned error: Broken pipe
[Apr 28 14:01:40] VERBOSE[30927] logger.c: [Apr 28 14:01:40] == Manager 'sendcron' logged off from 127.0.0.1
[Apr 28 14:01:40] VERBOSE[30928] logger.c: [Apr 28 14:01:40] == Spawn extension (default, ZZZZZZZZZ, 2) exited non-zero on 'Local/99444385086@default-3f31,2'
[Apr 28 14:01:40] VERBOSE[30928] logger.c: [Apr 28 14:01:40] -- Executing [h@default:1] DeadAGI("Local/99444385086@default-3f31,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack
[Apr 28 14:01:41] VERBOSE[31140] logger.c: [Apr 28 14:01:41] -- DAHDI/15-1 is ringing
[Apr 28 14:01:41] VERBOSE[31142] logger.c: [Apr 28 14:01:41] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Apr 28 14:01:41] VERBOSE[31133] logger.c: [Apr 28 14:01:41] -- DAHDI/4-1 is ringing
[Apr 28 14:01:41] VERBOSE[30928] logger.c: [Apr 28 14:01:41] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0
[Apr 28 14:01:42] VERBOSE[5739] logger.c: [Apr 28 14:01:42] -- Channel 0/5, span 1 got hangup request, cause 42
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] -- DAHDI/5-1 is circuit-busy
[Apr 28 14:01:42] DEBUG[30849] chan_dahdi.c: Set option AUDIO MODE, value: ON(1) on DAHDI/5-1
[Apr 28 14:01:42] DEBUG[30849] chan_dahdi.c: Not yet hungup... Calling hangup once with icause, and clearing call
[Apr 28 14:01:42] DEBUG[30849] chan_dahdi.c: Set option AUDIO MODE, value: OFF(0) on DAHDI/5-1
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] -- Hungup 'DAHDI/5-1'
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] == Everyone is busy/congested at this time (1:0/1/0)
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] -- Executing [9ZZZZZZZZZ@default:3] Hangup("Local/8600059@default-0764,1", "") in new stack
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] == Spawn extension (default, 99841095716, 3) exited non-zero on 'Local/8600059@default-0764,1'
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] -- Executing [h@default:1] DeadAGI("Local/8600059@default-0764,1", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----42-----CONGESTION----------") in new stack
[Apr 28 14:01:42] VERBOSE[30849] logger.c: [Apr 28 14:01:42] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---------- completed, returning 0




2012-04-28 14:01:38|VDfastAGI|call_log|-- VDAD vicidial_log update: |1|1335601862.22697|INCALL|
2012-04-28 14:01:38|VDfastAGI|call_log|no VDCL record found: 1335601862.22697|V4281401020000351168|351168|1335601862.22697|1335601862.22697|1|
2012-04-28 14:01:38|VDfastAGI|call_log||SELECT auto_alt_dial,auto_alt_dial_statuses,use_internal_dnc,use_campaign_dnc FROM vicidial_campaigns where campaign_id='2002';|
2012-04-28 14:01:40|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2012-04-28 14:01:40|VDfastAGI|begin|Perl Environment Dump:
2012-04-28 14:01:40|VDfastAGI|begin|0|--debug
2012-04-28 14:01:40|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|21|CONGESTION||0|
2012-04-28 14:01:40|VDfastAGI|begin|AGI Environment Dump:
2012-04-28 14:01:40|VDfastAGI|begin| -- accountcode =
2012-04-28 14:01:40|VDfastAGI|begin| -- callerid = 00000000000
2012-04-28 14:01:40|VDfastAGI|begin| -- calleridname = V4281401300000351177
2012-04-28 14:01:40|VDfastAGI|begin| -- callingani2 = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- callingpres = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- callingtns = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- callington = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- channel = Local/9ZZZZZZZZZ@default-2c7e,2
2012-04-28 14:01:40|VDfastAGI|begin| -- context = default
2012-04-28 14:01:40|VDfastAGI|begin| -- dnid = unknown
2012-04-28 14:01:40|VDfastAGI|begin| -- enhanced = 0.0
2012-04-28 14:01:40|VDfastAGI|begin| -- extension = h
2012-04-28 14:01:40|VDfastAGI|begin| -- language = en
2012-04-28 14:01:40|VDfastAGI|begin| -- network = yes
2012-04-28 14:01:40|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----21-----CONGESTION----------
2012-04-28 14:01:40|VDfastAGI|begin| -- priority = 1
2012-04-28 14:01:40|VDfastAGI|begin| -- rdnis = unknown
2012-04-28 14:01:40|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2012-04-28 14:01:40|VDfastAGI|begin| -- type = Local
2012-04-28 14:01:40|VDfastAGI|begin| -- uniqueid = 1335601891.22732
2012-04-28 14:01:40|VDfastAGI|begin|AGI Variables: |1335601891.22732|Local/9ZZZZZZZZZ@default-2c7e,2|h|Local|V4281401300000351177|
2012-04-28 14:01:40|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CONGESTION----------|call_log|END|
2012-04-28 14:01:40|VDfastAGI|call_log||CALL HUNG UP|
2012-04-28 14:01:40|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|21|CONGESTION||0|
2012-04-28 14:01:40|VDfastAGI|begin| -- rdnis = unknown
2012-04-28 14:01:40|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2012-04-28 14:01:40|VDfastAGI|begin| -- type = Local
2012-04-28 14:01:40|VDfastAGI|begin| -- uniqueid = 1335601891.22732
2012-04-28 14:01:40|VDfastAGI|begin|AGI Variables: |1335601891.22732|Local/9ZZZZZZZZZ@default-2c7e,2|h|Local|V4281401300000351177|
2012-04-28 14:01:40|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----CONGESTION----------|call_log|END|
2012-04-28 14:01:40|VDfastAGI|call_log||CALL HUNG UP|
2012-04-28 14:01:40|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|21|CONGESTION||0|
2012-04-28 14:01:40|VDfastAGI|call_log||INSERT IGNORE INTO vicidial_carrier_log set uniqueid='1335601891.22732',call_date='2012-04-28 14:01:40',server_ip='10.111.105.10',lead_id='351177',hangup_cause='21',dialstatus='CONGESTION',channel='Local/9ZZZZZZZZZ3@default-2c7e,2',dial_time='',answered_time='';|
2012-04-28 14:01:40|VDfastAGI|call_log|-- CARRIER LOG insert: |1|351177|21
2012-04-28 14:01:40|VDfastAGI|call_log||1335601891.22732|1335601891|Local/9ZZZZZZZZZ@default-2c7e,2|0|
2012-04-28 14:01:40|VDfastAGI|call_log||UPDATE call_log set end_time='2012-04-28 14:01:40',end_epoch='1335601900',length_in_sec=9,length_in_min=' 0.15',channel='Local/9ZZZZZZZZZ@default-2c7e,2' where uniqueid='1335601891.22732'|
2012-04-28 14:01:40|VDfastAGI|call_log|QUERY done: start time = 1335601891 | sec: 9 | min: 0.15 |1
2012-04-28 14:01:40|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1335601891.22732','1335601891.22732') and server_ip='10.111.105.10'|
2012-04-28 14:01:40|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1335601891.22732|Local/9ZZZZZZZZZ@default-2c7e,2|h|2012-04-28 14:01:40|min: 0.15|
2012-04-28 14:01:40|VDfastAGI|call_log|DEBUG: NODEBUG
2012-04-28 14:01:40|VDfastAGI|call_log|VD_hangup : V4281401300000351177 Local/9ZZZZZZZZZ@default-2c7e,2 1 351177


2012-04-28 14:01:40|VDfastAGI|begin|+++++++++++++++++ FastAGI Start ++++++++++++++++++++++++++++++++++++++++
2012-04-28 14:01:40|VDfastAGI|begin|Perl Environment Dump:
2012-04-28 14:01:40|VDfastAGI|begin|0|--debug
2012-04-28 14:01:40|VDfastAGI|begin|URL HVcauses: |PRI|NODEBUG|16|ANSWER|18|18|
2012-04-28 14:01:40|VDfastAGI|begin|AGI Environment Dump:
2012-04-28 14:01:40|VDfastAGI|begin| -- accountcode =
2012-04-28 14:01:40|VDfastAGI|begin| -- callerid = 00000000000
2012-04-28 14:01:40|VDfastAGI|begin| -- calleridname = V4281400590000351166
2012-04-28 14:01:40|VDfastAGI|begin| -- callingani2 = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- callingpres = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- callingtns = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- callington = 0
2012-04-28 14:01:40|VDfastAGI|begin| -- channel = Local/9ZZZZZZZZZ@default-3f31,2
2012-04-28 14:01:40|VDfastAGI|begin| -- context = default
2012-04-28 14:01:40|VDfastAGI|begin| -- dnid = unknown
2012-04-28 14:01:40|VDfastAGI|begin| -- enhanced = 0.0
2012-04-28 14:01:40|VDfastAGI|begin| -- extension = h
2012-04-28 14:01:40|VDfastAGI|begin| -- language = en
2012-04-28 14:01:40|VDfastAGI|begin| -- network = yes
2012-04-28 14:01:40|VDfastAGI|begin| -- network_script = call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------
2012-04-28 14:01:40|VDfastAGI|begin| -- priority = 1
2012-04-28 14:01:40|VDfastAGI|begin| -- rdnis = unknown
2012-04-28 14:01:40|VDfastAGI|begin| -- request = agi://127.0.0.1:4577/call_log--HVcauses ... ----------
2012-04-28 14:01:40|VDfastAGI|begin| -- type = Local
2012-04-28 14:01:40|VDfastAGI|begin| -- uniqueid = 1335601859.22690
2012-04-28 14:01:40|VDfastAGI|begin|AGI Variables: |1335601859.22690|Local/9ZZZZZZZZZ@default-3f31,2|h|Local|V4281400590000351166|
2012-04-28 14:01:40|VDfastAGI|call_log|Process to run: |agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------|call_log|END|
2012-04-28 14:01:40|VDfastAGI|call_log||CALL HUNG UP|
2012-04-28 14:01:40|VDfastAGI|call_log|URL HVcauses: |PRI|NODEBUG|0|CANCEL||0|
2012-04-28 14:01:40|VDfastAGI|call_log||INSERT IGNORE INTO vicidial_carrier_log set uniqueid='1335601859.22690',call_date='2012-04-28 14:01:40',server_ip='10.111.105.10',lead_id='351166',hangup_cause='0',dialstatus='CANCEL',channel='Local/9ZZZZZZZZZ@default-3f31,2',dial_time='',answered_time='';|
2012-04-28 14:01:40|VDfastAGI|call_log|-- CARRIER LOG insert: |1|351166|0
2012-04-28 14:01:40|VDfastAGI|call_log||1335601859.22690|1335601859|Local/9ZZZZZZZZZ@default-3f31,2|0|
2012-04-28 14:01:40|VDfastAGI|call_log||UPDATE call_log set end_time='2012-04-28 14:01:40',end_epoch='1335601900',length_in_sec=41,length_in_min=' 0.68',channel='Local/9ZZZZZZZZZ@default-3f31,2' where uniqueid='1335601859.22690'|
2012-04-28 14:01:40|VDfastAGI|call_log|QUERY done: start time = 1335601859 | sec: 41 | min: 0.68 |1
2012-04-28 14:01:40|VDfastAGI|call_log||DELETE from live_inbound where uniqueid IN('1335601859.22690','1335601859.22690') and server_ip='10.111.105.10'|
2012-04-28 14:01:40|VDfastAGI|call_log|+++++ CALL LOG HUNGUP: |1335601859.22690|Local/9ZZZZZZZZZ@default-3f31,2|h|2012-04-28 14:01:40|min: 0.68|
2012-04-28 14:01:40|VDfastAGI|call_log|DEBUG: NODEBUG
2012-04-28 14:01:40|VDfastAGI|call_log|VD_hangup : V4281400590000351166 Local/9ZZZZZZZZZ@default-3f31,2 1 351166
2012-04-28 14:01:40|VDfastAGI|call_log|0||SELECT result FROM vicidial_cpd_log where callerid='V4281401300000351177' and result NOT IN('Voice','Unknown','???','') order by cpd_id desc limit 1;|
2012-04-28 14:01:40|VDfastAGI|call_log|-- VD_hangup Local DEBUG: |PRI|V4281401300000351177|CONGESTION|21|0||
2012-04-28 14:01:40|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1
2012-04-28 14:01:40|VDfastAGI|call_log|0||SELECT result FROM vicidial_cpd_log where callerid='V4281400590000351166' and result NOT IN('Voice','Unknown','???','') order by cpd_id desc limit 1;|
2012-04-28 14:01:40|VDfastAGI|call_log|-- VD_hangup Local DEBUG: |PRI|V4281400590000351166|CANCEL|0|0||
2012-04-28 14:01:40|VDfastAGI|call_log|+++++ VDAD START LOCAL CHANNEL: EXITING- 1


any help is highly appreciated!!

thanks in advance

lvish

[mcargile]

please go into your Admin -> Severs section and change the AGI Output to BOTH for the server in question. Next place another test call. Then type 'less -r /var/log/astguiclient/screenlog.0' and find the call. Post everything from the moment the call was attempted to the moment it hung up.

[lvish]

Hi

below are the output on CLI for a goodcall, screenlog.0 is not showing the logs since this morning.

-- Executing [9XXXXXXXXXXX@default:1] AGI("SIP/160-000000ae", "agi://127.0.0.1:4577/call_log") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
-- Executing [9XXXXXXXXXXX@default:2] Dial("SIP/160-000000ae", "DAHDI/G1/08066212021||To") in new stack
-- Requested transfer capability: 0x00 - SPEECH
-- Called G1/XXXXXXXXXXX
-- DAHDI/62-1 is proceeding passing it to SIP/160-000000ae
-- DAHDI/62-1 is making progress passing it to SIP/160-000000ae
-- DAHDI/62-1 is ringing
-- DAHDI/62-1 answered SIP/160-000000ae
-- Executing [h@default:1] DeadAGI("SIP/160-000000ae", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----9-----5") in new stack
-- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---9-----5 completed, returning 0
-- Hungup 'DAHDI/62-1'
== Spawn extension (default, 9XXXXXXXXXXX, 2) exited non-zero on 'SIP/160-000000ae'


regds

lvish

[mcargile]

When was the last time the server was rebooted? If it has been a while the screenlog.0 can fill up. Also make sure that Server Logs is set to Y in the server section. If not set it to Y and then reboot. This setting does not take effect till the whole asterisk process and screen process it sits in are restarted.

[lvish]

Hi


Server log is set to Yes and then rebooted. Below are capture of screen0 for a good call.



[May 2 20:25:24] -- Executing 9XXXXXXXXXXX@default:1] AGI("SIP/160-00000000", "agi://127.0.0.1:4577/call_l
og") in new stack
[May 2 20:25:24] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[May 2 20:25:24] -- Executing [9XXXXXXXXXXX@default:2] Dial("SIP/160-00000000", "DAHDI/G1/08066212021||To
") in new stack
[May 2 20:25:24] -- Requested transfer capability: 0x00 - SPEECH
[May 2 20:25:24] -- Called G1/XXXXXXXXXXX
[May 2 20:25:24] -- DAHDI/62-1 is proceeding passing it to SIP/160-00000000
[May 2 20:25:24] -- DAHDI/62-1 is making progress passing it to SIP/160-00000000
[May 2 20:25:25] -- DAHDI/62-1 is ringing
[May 2 20:25:27] -- DAHDI/62-1 answered SIP/160-00000000
[May 2 20:25:35] -- Channel 0/31, span 2 got hangup request, cause 16
[May 2 20:25:35] -- Executing [h@default:1] DeadAGI("SIP/160-00000000", "agi://127.0.0.1:4577/call_log--HVc
auses--PRI-----NODEBUG-----16-----ANSWER-----11-----8") in new stack
[May 2 20:25:35] WARNING[4613]: res_agi.c:2212 deadagi_exec: Running DeadAGI on a li
ve channel will cause problems, please use AGI
[May 2 20:25:35] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... --11-----8 completed, returning 0
[May 2 20:25:35] -- Hungup 'DAHDI/62-1'
[May 2 20:25:35] == Spawn extension (default, 9XXXXXXXXXXX, 2) exited non-zero on 'SIP/160-00000000'

[lvish]

Hi

Looks like this issue was bcos of quality of leads and unstable PRI span. PRI issue is fixed by the carrier. Agent wait time is acceptable (15- 20 sec) for past few days.

thanks for all the support.


regds

lvish