a mistake of my ViciDial configuration or carrier's?

[lmora]

FACTS:
I'm getting few messages at Asterisk CLI of "service unavailable" from my SIP carrier but my carrier claims that I have something wrong in my configuration since they got a cancel message from me.

Please take a look at the following example:

it took 3 seconds from the moment vicidial executed AGI to the reception of circuit-busy message.
The call was automatically labeled as NA.
=> CLI messages:

[Oct 12 14:39:25] VERBOSE[6149] logger.c: [Oct 12 14:39:25] -- Executing [852018717212442@default:1] AGI("Local/852018717212442@default-dc57,2", "agi://127.0.0.1:4577/call_log") in new stack
[Oct 12 14:39:25] VERBOSE[6149] logger.c: [Oct 12 14:39:25] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Oct 12 14:39:25] VERBOSE[6149] logger.c: [Oct 12 14:39:25] -- Executing [852018717212442@default:2] Dial("Local/852018717212442@default-dc57,2", "SIP/sip_iVoice/528717212442||tTor") in new stack
[Oct 12 14:39:25] VERBOSE[6149] logger.c: [Oct 12 14:39:25] -- Called sip_iVoice/528717212442
[Oct 12 14:39:27] VERBOSE[6149] logger.c: [Oct 12 14:39:27] -- SIP/sip_iVoice-08211238 is ringing
[Oct 12 14:39:27] VERBOSE[6149] logger.c: [Oct 12 14:39:27] -- SIP/sip_iVoice-08211238 is making progress passing it to Local/852018717212442@default-dc57,2
[Oct 12 14:39:28] VERBOSE[4742] logger.c: [Oct 12 14:39:28] -- Got SIP response 503 "Service Unavailable" back from 208.89.104.241
[Oct 12 14:39:28] VERBOSE[6144] logger.c: [Oct 12 14:39:28] -- SIP/sip_iVoice-08205df8 is circuit-busy

=>Carrier's perspective:
it took 18 seconds from the moment they started ringing to when cancel message was received.
They say:
"we got here normal call clear, not any error"
"our switch sent ringing signal to that number and see the CANCEL from your switch after 180 ringing message to you"
Their support:

-------------------------- 12 Oct 15:39:27.019/GLOBAL/ser[64011]: SENDING message to 189.238.21.76:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 189.238.21.76:5060;branch=z9hG4bK71af5b62;rport=5060 Record-Route: <sip:208.89.104.241;ftag=as5b7a854b;lr> From: V1012143924000474568 <sip:0000000000@189.238.21.76>;tag=as5b7a854b To: <sip:528717212442@208.89.104.241>;tag=49f9625c6cd516eeaabc6ca1cd78fef6 Call-ID: 1f5b80f201c6df3c3e2d41b460f2c003@189.238.21.76 CSeq: 103 INVITE Server: Sippy Content-Length: 195 Content-Type: application/sdp

--------------------------- 12 Oct 15:39:45.233/GLOBAL/ser[64011]: RECEIVED message from 189.238.21.76:5060: CANCEL sip:528717212442@208.89.104.241 SIP/2.0 Via: SIP/2.0/UDP 189.238.21.76:5060;branch=z9hG4bK71af5b62;rport From: "V1012143924000474568" <sip:0000000000@189.238.21.76>;tag=as5b7a854b To: <sip:528717212442@208.89.104.241> Call-ID: 1f5b80f201c6df3c3e2d41b460f2c003@189.238.21.76 CSeq: 103 CANCEL User-Agent: DigestPBX Max-Forwards: 70 Remote-Party-ID: "V1012143924000474568" <sip:0000000000@189.238.21.76>;privacy=off;screen=no Content-Length: 0 ---------------------------------------------------

By the way, I'm not getting any error like those if I dial through a different sip termination carrier.

Questions
- is carrier guilty or not?
- is it part of handshake process that ViciDial / Asterisk sends a cancel signal back after getting a circuit-busy signal from SIP Carrier?

I'd appreciate your comments.

[williamconley]

could be several things. you should do a sip debug at the asterisk cli

Code: Select all

asterisk> sip debug

(don't forget to "sip no debug" later, that screen will get mighty confusing after a while.)

do that at the moment you dial with JUST that ONE call in progress. and check all the back and forth negotiations.

you may find that you and your provider could not agree on a codec to transmit the sound, their upline provider may kill the call at the moment of sound transmission because your callerid is "00000000000", all sorts of things have happened. but it should be somewhere in the sip debug code.

if you choose to post it, please preserve the line endings, it helps readability.

[lmora]

Thanks William

I turned on the debugger and wasn't able to find the clue for my issues.
I ran this linux command

grep -i unavailable /var/log/asterisk/messages | grep -c "208.89.104.241"

and and I got 476 "Service Unavailable" from my sip carrier all day !!

The following is the story of a call that ended up as a "Service Unavailable" message. I underscored a message that may messing up things that is related to an authorized thing. what do you think?

Hopefully you can see something in it.

[Oct 13 18:37:09] VERBOSE[5876] logger.c: [Oct 13 18:37:09] == Parsing '/etc/asterisk/manager.conf': [Oct 13 18:37:09] VERBOSE[5876] logger.c: [Oct 13 18:37:09] Found
[Oct 13 18:37:09] VERBOSE[5876] logger.c: [Oct 13 18:37:09] == Manager 'sendcron' logged on from 127.0.0.1
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] -- Executing [852018717211878@default:1] AGI("Local/852018717211878@default-26c0,2", "agi://127.0.0.1:4577/call_log") in new stack
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] -- AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] -- Executing [852018717211878@default:2] Dial("Local/852018717211878@default-26c0,2", "SIP/sip_iVoice/528717211878||tTor") in new stack
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] Audio is at 189.238.49.164 port 17928
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] Adding codec 0x100 (g729) to SDP
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] Adding non-codec 0x1 (telephone-event) to SDP
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] Reliably Transmitting (NAT) to 208.89.104.241:5060:
INVITE sip:528717211878@208.89.104.241 SIP/2.0^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK42734445;rport^M
From: "V1013183709000474374" <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>^M
Contact: <sip:8186474919@189.238.49.164>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 102 INVITE^M
User-Agent: DigestPBX^M
Max-Forwards: 70^M
Remote-Party-ID: "V1013183709000474374" <sip:8186474919@189.238.49.164>;privacy=off;screen=no^M
Date: Tue, 13 Oct 2009 23:37:09 GMT^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Content-Type: application/sdp^M
Content-Length: 265^M
^M
v=0^M
o=root 4741 4741 IN IP4 189.238.49.164^M
s=session^M
c=IN IP4 189.238.49.164^M
t=0 0^M
m=audio 17928 RTP/AVP 18 101^M
a=rtpmap:18 G729/8000^M
a=fmtp:18 annexb=no^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=silenceSupp:off - - - -^M
a=ptime:20^M
a=sendrecv^M

---
[Oct 13 18:37:09] VERBOSE[5877] logger.c: [Oct 13 18:37:09] -- Called sip_iVoice/528717211878
[Oct 13 18:37:09] VERBOSE[5880] logger.c: [Oct 13 18:37:09] == Parsing '/etc/asterisk/manager.conf': [Oct 13 18:37:09] VERBOSE[5880] logger.c: [Oct 13 18:37:09] Found


<--- SIP read from 208.89.104.241:5060 --->
SIP/2.0 100 trying -- your call is important to us^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK42734445;rport=5060^M
From: "V1013183709000474374" <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 102 INVITE^M
Server: Sip EXpress router (0.9.6 (i386/freebsd))^M
Content-Length: 0^M


<------------->
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] --- (8 headers 0 lines) ---
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09]
<--- SIP read from 208.89.104.241:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK42734445;rport=5060^M
Record-Route: <sip:208.89.104.241;ftag=as35e120e4;lr>^M
From: V1013183709000474374 <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 102 INVITE^M
Server: Sippy^M
WWW-Authenticate: Digest realm="208.89.104.241",nonce="15875885897168b64bb435b78d332a2c4907"^M
^M

<------------->
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] --- (9 headers 0 lines) ---
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] Transmitting (NAT) to 208.89.104.241:5060:
ACK sip:528717211878@208.89.104.241 SIP/2.0^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK42734445;rport^M
From: "V1013183709000474374" <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>^M
Contact: <sip:8186474919@189.238.49.164>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 102 ACK^M
User-Agent: DigestPBX^M
Max-Forwards: 70^M
Remote-Party-ID: "V1013183709000474374" <sip:8186474919@189.238.49.164>;privacy=off;screen=no^M
Content-Length: 0^M
^M

---
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] Audio is at 189.238.49.164 port 17928
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] Adding codec 0x100 (g729) to SDP
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] Adding non-codec 0x1 (telephone-event) to SDP
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09] Reliably Transmitting (NAT) to 208.89.104.241:5060:
INVITE sip:528717211878@208.89.104.241 SIP/2.0^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK7b47ccc6;rport^M
From: "V1013183709000474374" <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>^M
Contact: <sip:8186474919@189.238.49.164>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 103 INVITE
User-Agent: DigestPBX^M
Max-Forwards: 70^M
Remote-Party-ID: "V1013183709000474374" <sip:8186474919@189.238.49.164>;privacy=off;screen=no^M
Authorization: Digest username="425145975", realm="208.89.104.241", algorithm=MD5, uri="sip:528717211878@208.89.104.241", nonce="15875885897168b64bb435b78d332a2c4907", response="901e47092402cc46d812a866088ae1ff"^M
Date: Tue, 13 Oct 2009 23:37:09 GMT^M
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY^M
Supported: replaces^M
Content-Type: application/sdp^M
Content-Length: 265^M

v=0^M
o=root 4741 4742 IN IP4 189.238.49.164^M
s=session^M
c=IN IP4 189.238.49.164^M
t=0 0^M
m=audio 17928 RTP/AVP 18 101^M
a=rtpmap:18 G729/8000^M
a=fmtp:18 annexb=no^M
a=rtpmap:101 telephone-event/8000^M
a=fmtp:101 0-16^M
a=silenceSupp:off - - - -^M
a=ptime:20^M
a=sendrecv^M


---
[Oct 13 18:37:09] VERBOSE[4817] logger.c: [Oct 13 18:37:09]
<--- SIP read from 208.89.104.241:5060 --->
SIP/2.0 100 trying -- your call is important to us^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK7b47ccc6;rport=5060^M
From: "V1013183709000474374" <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 103 INVITE^M
Server: Sip EXpress router (0.9.6 (i386/freebsd))^M
Content-Length: 0


<------------->
[Oct 13 18:37:12] VERBOSE[4817] logger.c: [Oct 13 18:37:12]
<--- SIP read from 208.89.104.241:5060 --->
SIP/2.0 503 Service Unavailable^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK7b47ccc6;rport=5060^M
Record-Route: <sip:208.89.104.241;ftag=as35e120e4;lr>^M
From: V1013183709000474374 <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>;tag=833a0d9c5861495f71f9b819cfa9fece^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 103 INVITE^M
Server: Sippy^M


<------------->
[Oct 13 18:37:12] VERBOSE[4817] logger.c: [Oct 13 18:37:12] --- (8 headers 0 lines) ---
[Oct 13 18:37:12] VERBOSE[4817] logger.c: [Oct 13 18:37:12] -- Got SIP response 503 "Service Unavailable" back from 208.89.104.241
[Oct 13 18:37:12] VERBOSE[4817] logger.c: [Oct 13 18:37:12] Transmitting (NAT) to 208.89.104.241:5060:
ACK sip:528717211878@208.89.104.241 SIP/2.0^M
Via: SIP/2.0/UDP 189.238.49.164:5060;branch=z9hG4bK7b47ccc6;rport^M
From: "V1013183709000474374" <sip:8186474919@189.238.49.164>;tag=as35e120e4^M
To: <sip:528717211878@208.89.104.241>;tag=833a0d9c5861495f71f9b819cfa9fece^M
Contact: <sip:8186474919@189.238.49.164>^M
Call-ID: 5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164^M
CSeq: 103 ACK^M
User-Agent: DigestPBX^M
Max-Forwards: 70^M
Remote-Party-ID: "V1013183709000474374" <sip:8186474919@189.238.49.164>;privacy=off;screen=no^M
Content-Length: 0^M
^M

---
[Oct 13 18:37:12] VERBOSE[5877] logger.c: [Oct 13 18:37:12] -- SIP/sip_iVoice-082636c0 is circuit-busy
[Oct 13 18:37:12] VERBOSE[5877] logger.c: [Oct 13 18:37:12] == Everyone is busy/congested at this time (1:0/1/0)
[Oct 13 18:37:12] VERBOSE[5877] logger.c: [Oct 13 18:37:12] -- Executing [852018717211878@default:3] Hangup("Local/852018717211878@default-26c0,2", "") in new stack
[Oct 13 18:37:12] VERBOSE[5877] logger.c: [Oct 13 18:37:12] == Spawn extension (default, 852018717211878, 3) exited non-zero on 'Local/852018717211878@default-26c0,2'
[Oct 13 18:37:12] VERBOSE[5877] logger.c: [Oct 13 18:37:12] -- Executing [h@default:1] DeadAGI("Local/852018717211878@default-26c0,2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----34-----CONGESTION----------") in new stack
[Oct 13 18:37:12] VERBOSE[5877] logger.c: [Oct 13 18:37:12] -- AGI Script agi://127.0.0.1:4577/call_log--HVcauses ... ---34-----CONGESTION---------- completed, returning 0
[Oct 13 18:37:12] VERBOSE[4817] logger.c: [Oct 13 18:37:12] Really destroying SIP dialog '5ce010d2452138d9353b7cdb1b1f3458@189.238.49.164' Method: INVITE
[Oct 13 18:37:13] VERBOSE[5876] logger.c: [Oct 13 18:37:13] == Manager 'sendcron' logged off from 127.0.0.1