CALL CONGESTION on Vicidial - Xlite works well [SOLVED]
Posted: Wed Jan 15, 2014 2:23 pm
Hello everyone i have a small cluster installation with 1 DB/Web server + 3 Telephony Server all installed with Vicibox 4.0
Despite the OS is a little old, Vicidial is update to the current 2054 SVN revision on all the servers.
Almost everything is working, but im having a specific issue and i cant see what is going wrong.
For one of my campaigns i have to dial a third party verification system, so on every single Sale i have to make a 3-Way Call to and external DID, for almost a Year this has been working great but since last week i am getting a pop-up saying:
Call Rejected: CONGESTION
Cause: 38 - Network out of order.
SIP: 500 - Server internal failure
My first guess was that my carrier was having issues and i reported, they already have change my routes but the problem persist, the funny thing is that if i dial directly with Xlite IT WORKS, under the same server, under the extension the only difference is that if i log into vicidial and Manual dial that specific number i got this screen:
This is how my dialplan looks like for this number:
Intentionaly ommit // so the forum doesnt detect the AGI as a link
exten => _91XXXXXXXXXX,1,AGI(agi:127.0.0.1:4577/call_log)
exten => _91XXXXXXXXXX,2,Dial(SIP/${EXTEN:1}@vitel-outbound,,TtoR)
exten => _91XXXXXXXXXX,3,Hangup
This are the logs:
[This log is from a WORKING CALL Directy from the xlite ]
[Jan 15 10:40:13] -- Executing [911234567890@default:1] AGI("SIP/5858-00000077", "agi:127.0.0.1:4577/call_log") in new stack
[Jan 15 10:40:13] -- Executing [911234567890@default:2] Dial("SIP/5858-00000077", "SIP/11234567890@vitel-outbound||TtoR") in new stack
[Jan 15 10:40:13] -- Called 11234567890@vitel-outbound
[Jan 15 10:40:23] == Spawn extension (default, 911234567890, 2) exited non-zero on 'SIP/5858-00000077'
[This is a log from a NON WORKING CALL using Vicidial Agent Interface]
[Jan 15 10:41:42] -- Executing [911234567890@default:1] AGI("Local/8600056@default-7674,1", "agi:127.0.0.1:4577/call_log") in new stack
[Jan 15 10:41:42] -- Executing [911234567890@default:2] Dial("Local/8600056@default-7674,1", "SIP/11234567890@vitel-outbound||TtoR") in new stack
[Jan 15 10:41:42] -- Called 11234567890@vitel-outbound
[Jan 15 10:41:43] -- Executing [8309@default:2] Monitor("Local/58600056@default-0e40,1", "wav|20140115-104142_1234567890") in new stack
[Jan 15 10:41:56] -- Executing [911234567890@default:3] Hangup("Local/8600056@default-7674,1", "") in new stack
[Jan 15 10:41:56] == Spawn extension (default, 911234567890, 3) exited non-zero on 'Local/8600056@default-7674,1'
[Jan 15 10:42:47] -- AGI Script agi:127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----38-----CONGESTION---------- completed, returning 0
[Jan 15 10:42:47] -- Got SIP response 500 "Server internal failure" back from 64.2.142.188
[Jan 15 10:42:47] -- SIP/vitel-outbound-00000081 is circuit-busy
The log is incomplete but i just wanted to show you that everything was exactly the same on the dialplan, but when i place the Call trough the interface the calls got CONGESTION, why can be this happening?
Thank you guys in advance...
[UPDATE]
Same behavior with multiple carriers this test was with Vitelity but AlcazarNetworks, Conexiant, Checkbox and Flowroute gave me same results, Xlite works, Agent Interface don´t
[UPDATE 2]
SIP DEBUG (WORKING)
[Codec negotiation here]
---
[Jan 15 13:19:14]
<--- SIP read from 70.167.153.130:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 201.140.139.82:5060;branch=z9hG4bK16059b85;rport=35221
From: "5858" <sip:29528250@sip.flowroute.com>;tag=as5cc38b18
To: <sip:29528250*18137744984@sip.flowroute.com;cpd=on>
Call-ID: 13ef7b1b461162752392e7ed785493b3@sip.flowroute.com
CSeq: 102 INVITE
Content-Length: 0
<------------->
[Jan 15 13:19:14] --- (7 headers 0 lines) ---
[Jan 15 13:19:17]
<--- SIP read from 70.167.153.130:5060 --->
SIP/2.0 183 Session Progress
From: "5858" <sip:29528250@sip.flowroute.com>;tag=as5cc38b18
To: <sip:29528250*18137744984@sip.flowroute.com;cpd=on>;tag=SDghtjf99-gK0cd190d1
Via: SIP/2.0/UDP 201.140.139.82:5060;branch=z9hG4bK16059b85;rport=35221
Call-ID: 13ef7b1b461162752392e7ed785493b3@sip.flowroute.com
CSeq: 102 INVITE
Record-Route: <sip:216.115.69.133;lr>
Record-Route: <sip:70.167.153.130;lr>
Contact: <sip:+18137744984@67.16.125.60:5060;transport=udp>
Content-Length: 218
Content-Type: application/sdp
v=0
o=- 12190 17204 IN IP4 67.16.125.60
s=-
c=IN IP4 67.16.125.60
t=0 0
m=audio 52412 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:20
<------------->
SIP DEBUG (NON WORKING)
[Codec negotiation & stuff here]
---
[Jan 15 13:17:25]
<--- SIP read from 70.167.153.130:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 201.140.139.82:5060;branch=z9hG4bK22dc2ad0;rport=35221
From: "DV820615Wc4techc4teW" <sip:29528250@sip.flowroute.com>;tag=as6042c1c2
To: <sip:29528250*18137744984@sip.flowroute.com;cpd=on>
Call-ID: 1e005f9f597b84d0408df0256f29c797@sip.flowroute.com
CSeq: 102 INVITE
Content-Length: 0
<------------->
[Jan 15 13:17:25] --- (7 headers 0 lines) ---
[Jan 15 13:17:37]
<--- SIP read from 70.167.153.130:5060 --->
OPTIONS sip:201.140.139.82:35221 SIP/2.0
Max-Forwards: 10
Record-Route: <sip:70.167.153.130;lr>
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bK6153.90b2a3492df458c5540c3df411e9921a.0
Via: SIP/2.0/UDP 216.115.69.131:5060;branch=0
Route: <sip:70.167.153.130;lr;received='sip:201.140.139.82:35221'>
From: sip:ping@invalid;tag=780e9d57
To: sip:201.140.139.82:35221
Call-ID: 7b4c5a45-1669ac52-013b415@216.115.69.131
CSeq: 1 OPTIONS
Content-Length: 0
<------------->
[Jan 15 13:17:37] --- (11 headers 0 lines) ---
[Jan 15 13:17:37] Looking for s in trunkinbound (domain 201.140.139.82)
[Jan 15 13:17:37]
<--- Transmitting (NAT) to 70.167.153.130:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bK6153.90b2a3492df458c5540c3df411e9921a.0;received=70.167.153.130
Via: SIP/2.0/UDP 216.115.69.131:5060;branch=0
From: sip:ping@invalid;tag=780e9d57
To: sip:201.140.139.82:35221;tag=as5c080bb7
Call-ID: 7b4c5a45-1669ac52-013b415@216.115.69.131
CSeq: 1 OPTIONS
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Accept: application/sdp
Content-Length: 0
<------------>
[Jan 15 13:17:37] Scheduling destruction of SIP dialog '7b4c5a45-1669ac52-013b415@216.115.69.131' in 32000 ms (Method: OPTIONS)
[Jan 15 13:17:40] Really destroying SIP dialog '0c26e475-b03ca0de-e87df17@70.167.153.136' Method: OPTIONS
I only included the sip debug log where there is a difference, all before this point is exactly the same for both, obiusly the information from the Caller ID and the Call ID is quite different, but everything else is exactly the same
Working Full log: http://pastebin.com/1kd5REfr
Non Working Full Log: http://pastebin.com/kpgvAM8A
Despite the OS is a little old, Vicidial is update to the current 2054 SVN revision on all the servers.
Almost everything is working, but im having a specific issue and i cant see what is going wrong.
For one of my campaigns i have to dial a third party verification system, so on every single Sale i have to make a 3-Way Call to and external DID, for almost a Year this has been working great but since last week i am getting a pop-up saying:
Call Rejected: CONGESTION
Cause: 38 - Network out of order.
SIP: 500 - Server internal failure
My first guess was that my carrier was having issues and i reported, they already have change my routes but the problem persist, the funny thing is that if i dial directly with Xlite IT WORKS, under the same server, under the extension the only difference is that if i log into vicidial and Manual dial that specific number i got this screen:
This is how my dialplan looks like for this number:
Intentionaly ommit // so the forum doesnt detect the AGI as a link
exten => _91XXXXXXXXXX,1,AGI(agi:127.0.0.1:4577/call_log)
exten => _91XXXXXXXXXX,2,Dial(SIP/${EXTEN:1}@vitel-outbound,,TtoR)
exten => _91XXXXXXXXXX,3,Hangup
This are the logs:
[This log is from a WORKING CALL Directy from the xlite ]
[Jan 15 10:40:13] -- Executing [911234567890@default:1] AGI("SIP/5858-00000077", "agi:127.0.0.1:4577/call_log") in new stack
[Jan 15 10:40:13] -- Executing [911234567890@default:2] Dial("SIP/5858-00000077", "SIP/11234567890@vitel-outbound||TtoR") in new stack
[Jan 15 10:40:13] -- Called 11234567890@vitel-outbound
[Jan 15 10:40:23] == Spawn extension (default, 911234567890, 2) exited non-zero on 'SIP/5858-00000077'
[This is a log from a NON WORKING CALL using Vicidial Agent Interface]
[Jan 15 10:41:42] -- Executing [911234567890@default:1] AGI("Local/8600056@default-7674,1", "agi:127.0.0.1:4577/call_log") in new stack
[Jan 15 10:41:42] -- Executing [911234567890@default:2] Dial("Local/8600056@default-7674,1", "SIP/11234567890@vitel-outbound||TtoR") in new stack
[Jan 15 10:41:42] -- Called 11234567890@vitel-outbound
[Jan 15 10:41:43] -- Executing [8309@default:2] Monitor("Local/58600056@default-0e40,1", "wav|20140115-104142_1234567890") in new stack
[Jan 15 10:41:56] -- Executing [911234567890@default:3] Hangup("Local/8600056@default-7674,1", "") in new stack
[Jan 15 10:41:56] == Spawn extension (default, 911234567890, 3) exited non-zero on 'Local/8600056@default-7674,1'
[Jan 15 10:42:47] -- AGI Script agi:127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----38-----CONGESTION---------- completed, returning 0
[Jan 15 10:42:47] -- Got SIP response 500 "Server internal failure" back from 64.2.142.188
[Jan 15 10:42:47] -- SIP/vitel-outbound-00000081 is circuit-busy
The log is incomplete but i just wanted to show you that everything was exactly the same on the dialplan, but when i place the Call trough the interface the calls got CONGESTION, why can be this happening?
Thank you guys in advance...
[UPDATE]
Same behavior with multiple carriers this test was with Vitelity but AlcazarNetworks, Conexiant, Checkbox and Flowroute gave me same results, Xlite works, Agent Interface don´t
[UPDATE 2]
SIP DEBUG (WORKING)
[Codec negotiation here]
---
[Jan 15 13:19:14]
<--- SIP read from 70.167.153.130:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 201.140.139.82:5060;branch=z9hG4bK16059b85;rport=35221
From: "5858" <sip:29528250@sip.flowroute.com>;tag=as5cc38b18
To: <sip:29528250*18137744984@sip.flowroute.com;cpd=on>
Call-ID: 13ef7b1b461162752392e7ed785493b3@sip.flowroute.com
CSeq: 102 INVITE
Content-Length: 0
<------------->
[Jan 15 13:19:14] --- (7 headers 0 lines) ---
[Jan 15 13:19:17]
<--- SIP read from 70.167.153.130:5060 --->
SIP/2.0 183 Session Progress
From: "5858" <sip:29528250@sip.flowroute.com>;tag=as5cc38b18
To: <sip:29528250*18137744984@sip.flowroute.com;cpd=on>;tag=SDghtjf99-gK0cd190d1
Via: SIP/2.0/UDP 201.140.139.82:5060;branch=z9hG4bK16059b85;rport=35221
Call-ID: 13ef7b1b461162752392e7ed785493b3@sip.flowroute.com
CSeq: 102 INVITE
Record-Route: <sip:216.115.69.133;lr>
Record-Route: <sip:70.167.153.130;lr>
Contact: <sip:+18137744984@67.16.125.60:5060;transport=udp>
Content-Length: 218
Content-Type: application/sdp
v=0
o=- 12190 17204 IN IP4 67.16.125.60
s=-
c=IN IP4 67.16.125.60
t=0 0
m=audio 52412 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=maxptime:20
<------------->
SIP DEBUG (NON WORKING)
[Codec negotiation & stuff here]
---
[Jan 15 13:17:25]
<--- SIP read from 70.167.153.130:5060 --->
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 201.140.139.82:5060;branch=z9hG4bK22dc2ad0;rport=35221
From: "DV820615Wc4techc4teW" <sip:29528250@sip.flowroute.com>;tag=as6042c1c2
To: <sip:29528250*18137744984@sip.flowroute.com;cpd=on>
Call-ID: 1e005f9f597b84d0408df0256f29c797@sip.flowroute.com
CSeq: 102 INVITE
Content-Length: 0
<------------->
[Jan 15 13:17:25] --- (7 headers 0 lines) ---
[Jan 15 13:17:37]
<--- SIP read from 70.167.153.130:5060 --->
OPTIONS sip:201.140.139.82:35221 SIP/2.0
Max-Forwards: 10
Record-Route: <sip:70.167.153.130;lr>
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bK6153.90b2a3492df458c5540c3df411e9921a.0
Via: SIP/2.0/UDP 216.115.69.131:5060;branch=0
Route: <sip:70.167.153.130;lr;received='sip:201.140.139.82:35221'>
From: sip:ping@invalid;tag=780e9d57
To: sip:201.140.139.82:35221
Call-ID: 7b4c5a45-1669ac52-013b415@216.115.69.131
CSeq: 1 OPTIONS
Content-Length: 0
<------------->
[Jan 15 13:17:37] --- (11 headers 0 lines) ---
[Jan 15 13:17:37] Looking for s in trunkinbound (domain 201.140.139.82)
[Jan 15 13:17:37]
<--- Transmitting (NAT) to 70.167.153.130:5060 --->
SIP/2.0 404 Not Found
Via: SIP/2.0/UDP 70.167.153.130;branch=z9hG4bK6153.90b2a3492df458c5540c3df411e9921a.0;received=70.167.153.130
Via: SIP/2.0/UDP 216.115.69.131:5060;branch=0
From: sip:ping@invalid;tag=780e9d57
To: sip:201.140.139.82:35221;tag=as5c080bb7
Call-ID: 7b4c5a45-1669ac52-013b415@216.115.69.131
CSeq: 1 OPTIONS
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces
Accept: application/sdp
Content-Length: 0
<------------>
[Jan 15 13:17:37] Scheduling destruction of SIP dialog '7b4c5a45-1669ac52-013b415@216.115.69.131' in 32000 ms (Method: OPTIONS)
[Jan 15 13:17:40] Really destroying SIP dialog '0c26e475-b03ca0de-e87df17@70.167.153.136' Method: OPTIONS
I only included the sip debug log where there is a difference, all before this point is exactly the same for both, obiusly the information from the Caller ID and the Call ID is quite different, but everything else is exactly the same
Working Full log: http://pastebin.com/1kd5REfr
Non Working Full Log: http://pastebin.com/kpgvAM8A