[Solved]Incoming calls not received due to SIP registrations

Asterisk Asterisk Support
1

I have been working on this for a while and I think I have finally found out what is causing the issue. Basically it boils down to incoming calls are not received and my provider says they receive a CHANUNAVAIL message. I believe this is caused by the destroying and reregistration of the sip trunk. This is from my logs:

[Jun 17 04:37:21] VERBOSE[4004] chan_sip.c: Scheduling destruction of SIP dialog ‘14b69a1d02d875f960a0beec721dd101@10.1.1.8’ in 32000 ms (Method: REGISTER)
[Jun 17 04:37:21] NOTICE[4004] chan_sip.c: Outbound Registration: Expiry for inbound8.vitelity.net is 60 sec (Scheduling reregistration in 45 s)

Notice how the destruction is set for 32 seconds and the reregistration is set for 45 seconds. In my mind that means that there is 13 seconds that the channel doesn’t exist. Here is a little bit further down showing the destruction and the reregistration:

[Jun 17 04:37:53] VERBOSE[4004] chan_sip.c: Really destroying SIP dialog ‘14b69a1d02d875f960a0beec721dd101@10.1.1.8’ Method: REGISTER
[Jun 17 04:38:06] NOTICE[4004] chan_sip.c: – Re-registration for username@inbound8.vitelity.net

Again, notice how these are exactly 13 seconds apart.

How do I set it so that the destroying and re-registration happen at the same time, or even have the re-registration happen before the destruction?

Thanks,
Trevor

2

I found this Bug:

issues.asterisk.org/view.php?id=15942

Anyone know how I can solve this?

3

The destruction message does not relate to the registration interval, but when Asterisk stops looking for reply or retransmission. It’s a red herring.

You can solve the quoted issue by submitting source code (with suitable licences to the bug tracker) that fixes the problem.

It looks like you can work round it by by setting a default expiry which is less than the value that your service provider will actually set the expiry to.

4

David,

Thanks for the reply. I can turn on sip debug and watch for the “really destroying sip dialog” and then if I try to make a call to the server I receive a fast busy, and my provider says they received a ‘CHANUNAVAIL’ message. Given this, I don’t think it is a red herring.

I have tried to set the default expiry, and can set it to anything I want (and will see it in the sip registration to my provider), but the provider always sets it at 60 seconds (per the rfc the default expiry is just a suggestion from me). The session is always destroyed in 32 seconds and reregisters in 45 seconds. If I try to call within that 13 seconds the call fails.

5

If it were really destroying the session, rather than the dialogue, in 32 seconds, a lot of people would have problems, as 1 minute is rather a frequent re-registration interval.

In the code (1.6.1.0) below, it is the first line that sets the timer that leads to the next registration action, but the last line that results in the 32 second message.

AST_SCHED_DEL(sched, r->timeout); if (r->call) r->call = dialog_unref(r->call, "unsetting registry->call pointer-- case 200"); p->registry = registry_unref(p->registry, "unref registry entry p->registry"); /* Let this one hang around until we have all the responses */ sip_scheddestroy(p, DEFAULT_TRANS_TIMEOUT);
The comment is actually pointing out that one could probably destroy the dialogue immediately, if things were working properly.

In any case, this is an outbound registration and it is service providers system that is marking you unavailable. The dialogue destruction is purely local and they will have no idea that you have done it.

I think you need to provide the full trace of the register dialogue.

6

David,

Thanks again for the response. Here is the registration info:

[Jun 17 16:42:42] NOTICE[4004] chan_sip.c: – Re-registration for username@inbound8.vitelity.net
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: Reliably Transmitting (NAT) to 64.2.142.108:5060:
REGISTER sip:inbound8.vitelity.net SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK2d934bf9;rport
Max-Forwards: 70
From: sip:username@inbound8.vitelity.net;tag=as604a44c1
To: sip:username@inbound8.vitelity.net
Call-ID: 2a12392e3a52d264313fa45502a9ffc5@10.1.1.8
CSeq: 1886 REGISTER
User-Agent: Asterisk PBX 1.6.2.8
Authorization: Digest username=“username”, realm=“asterisk”, algorithm=MD5, uri=“sip:inbound8.vitelity.net”, nonce=“633eda2e”,

response="e670ff45df8739f9f178d3b5a8887c93"
Expires: 40
Contact: sip:s@XXX.XXX.XXX.XXX
Content-Length: 0

[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c:
<— SIP read from UDP:64.2.142.108:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK2d934bf9;received=XXX.XXX.XXX.XXX;rport=24224
From: sip:username@inbound8.vitelity.net;tag=as604a44c1
To: sip:username@inbound8.vitelity.net
Call-ID: 2a12392e3a52d264313fa45502a9ffc5@10.1.1.8
CSeq: 1886 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0

<------------->
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: — (10 headers 0 lines) —
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c:
<— SIP read from UDP:64.2.142.108:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK2d934bf9;received=XXX.XXX.XXX.XXX;rport=24224
From: sip:username@inbound8.vitelity.net;tag=as604a44c1
To: sip:username@inbound8.vitelity.net;tag=as22830989
Call-ID: 2a12392e3a52d264313fa45502a9ffc5@10.1.1.8
CSeq: 1886 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="5cc37f88"
Content-Length: 0

<------------->
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: — (11 headers 0 lines) —
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: Responding to challenge, registration to domain/host name inbound8.vitelity.net
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: Reliably Transmitting (NAT) to 64.2.142.108:5060:
REGISTER sip:inbound8.vitelity.net SIP/2.0
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK02503be0;rport
Max-Forwards: 70
From: sip:username@inbound8.vitelity.net;tag=as6d3f901e
To: sip:username@inbound8.vitelity.net
Call-ID: 2a12392e3a52d264313fa45502a9ffc5@10.1.1.8
CSeq: 1887 REGISTER
User-Agent: Asterisk PBX 1.6.2.8
Authorization: Digest username=“username”, realm=“asterisk”, algorithm=MD5, uri=“sip:inbound8.vitelity.net”, nonce=“5cc37f88”,

response="b528f8c5d5fe7fb0341e0f55d09ab4f3"
Expires: 40
Contact: sip:s@XXX.XXX.XXX.XXX
Content-Length: 0

[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c:
<— SIP read from UDP:64.2.142.108:5060 —>
SIP/2.0 100 Trying
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK02503be0;received=XXX.XXX.XXX.XXX;rport=24224
From: sip:username@inbound8.vitelity.net;tag=as6d3f901e
To: sip:username@inbound8.vitelity.net
Call-ID: 2a12392e3a52d264313fa45502a9ffc5@10.1.1.8
CSeq: 1887 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0

<------------->
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: — (10 headers 0 lines) —
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c:
<— SIP read from UDP:64.2.142.108:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP XXX.XXX.XXX.XXX:5060;branch=z9hG4bK02503be0;received=XXX.XXX.XXX.XXX;rport=24224
From: sip:username@inbound8.vitelity.net;tag=as6d3f901e
To: sip:username@inbound8.vitelity.net;tag=as22830989
Call-ID: 2a12392e3a52d264313fa45502a9ffc5@10.1.1.8
CSeq: 1887 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Expires: 60
Contact: sip:s@XXX.XXX.XXX.XXX;expires=60
Date: Thu, 17 Jun 2010 16:42:43 GMT
Content-Length: 0

<------------->
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: — (13 headers 0 lines) —
[Jun 17 16:42:42] VERBOSE[4004] chan_sip.c: Scheduling destruction of SIP dialog ‘2a12392e3a52d264313fa45502a9ffc5@10.1.1.8’ in 32000 ms (Method: REGISTER)
[Jun 17 16:42:42] NOTICE[4004] chan_sip.c: Outbound Registration: Expiry for inbound8.vitelity.net is 60 sec (Scheduling reregistration in 45 s)

7

As long as the next successfully authenticated register is received by the provider in 60 seconds, that should work.

The provider has over-ridden your 40 second value.

8

The reregistration is happening as scheduled, every 45 seconds:

[Jun 17 17:27:01] VERBOSE[4004] chan_sip.c: Scheduling destruction of SIP dialog ‘438de6b55ce8195c0bdea41c2ee10bb2@10.1.1.8’ in 32000 ms (Method: REGISTER)
[Jun 17 17:27:01] NOTICE[4004] chan_sip.c: Outbound Registration: Expiry for inbound8.vitelity.net is 60 sec (Scheduling reregistration in 45 s)
[Jun 17 17:27:33] VERBOSE[4004] chan_sip.c: Really destroying SIP dialog ‘438de6b55ce8195c0bdea41c2ee10bb2@10.1.1.8’ Method: REGISTER

<------------->
[Jun 17 17:27:46] NOTICE[4004] chan_sip.c: – Re-registration for username@inbound8.vitelity.net
[Jun 17 17:27:46] VERBOSE[4004] chan_sip.c: REGISTER 12 headers, 0 lines
[Jun 17 17:27:46] VERBOSE[4004] chan_sip.c: Reliably Transmitting (NAT) to 64.2.142.108:5060:
REGISTER sip:inbound8.vitelity.net SIP/2.0

9

I am able to reproduce the failed calls easily. I simply wait for the NOTICE message saying the dialog is being destroyed and then call. If I call after the reregistration the call completes.

Since the unavailable time is 13 seconds out of every 45, it means that more than 20% of the time calls fail.

10

As I’ve already said, it is your provider that is rejecting. The dialogue expiry sends nothing to the provider. You’ve shown no evidence that the incoming call has been offered to you, and your description implies that it hasn’t. The bug has to be at the other end.

Incidentally, CHANUNAVAIL is Asterisk terminology, which is not represented in that form in a SIP message, so your provider must be using Asterisk. In fact their SIP headers confirm that they are using Asterisk. If they insist that your Asterisk is broken, simply ask them to tell you how you should configure it for them.

11

You are right, the call is never offered to me, and they are using asterisk. I have a support ticket opened with them, I will post any reply I get here.

12

David - Thanks for your help. This has been solved. The issue was caused by a timout on my Firewall. Once I changed that timeout to 60 seconds for SIP signaling everything started working.