SIP 401 Unauthorised regisration challenge ignored by Asterisk

4 posts / 0 new
Last post
Colonel_P
Colonel_P's picture
SIP 401 Unauthorised regisration challenge ignored by Asterisk

I am hoping that someone out there can help me out.

I have a FreePBX installation running version 2.8.1.5 and Asterisk version 1.6.2.20.

I have a SIP trunk defined to a public service provider and that works OK but I have noticed that quite often, Asterisk takes a long time to register the trunk.

The normal process, and what I would expect to happen, is for Asterisk to send a Register request, The service provider challenges with SIP 401 Unauthorised, Asterisk replies with new registration request adding the correct auth parameters generated from the challenge.

What seems to be happening is, Asterisk sends a Register request, The service provider challenges with SIP 401 Unauthorised, Asterisk ignores this challenge and re-transmitts the original request.

debug log .....
------------------------------------------------------------------------
[Dec 1 22:01:50] VERBOSE[26237] chan_sip.c: Reliably Transmitting (NAT) to 80.93.165.111:5060:
REGISTER sip:sip.numbergroup-services.com SIP/2.0
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK15bd82e9;rport
Max-Forwards: 70
From: ;tag=as56e0e721
To:
Call-ID:

CSeq: 1309 REGISTER
User-Agent: FPBX-2.8.1(1.6.2.20)
Authorization: Digest username="MyAccount", realm="sip.numbergroup-services.com", algorithm=MD5, uri="sip:sip.numbergroup-services.com", nonce="91458f8c-3c01-11e2-aab6-03dda959c092", response="04f26cdda5c7e7f88e5c6d9482a60fd6", qop=auth, cnonce="40cab4cc", nc=00000003
Expires: 600
Contact:
Content-Length: 0

---
[Dec 1 22:01:50] VERBOSE[26237] chan_sip.c: Really destroying SIP dialog '290d455e3efd4fb70419d01c274571b3@127.0.0.1' Method: REGISTER
[Dec 1 22:01:50] VERBOSE[26237] chan_sip.c:
<--- SIP read from UDP:80.93.165.111:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK15bd82e9;rport=61810
From: ;tag=as56e0e721
To: ;tag=F91aUKHDaHe4a
Call-ID:

CSeq: 1309 REGISTER
User-Agent: numbergroup.com
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, precondition, path, replaces
WWW-Authenticate: Digest realm="sip.numbergroup-services.com", nonce="556b2372-3c02-11e2-b292-03dda959c092", stale=true, algorithm=MD5, qop="auth"
Content-Length: 0

<------------->
[Dec 1 22:01:50] VERBOSE[26237] chan_sip.c: --- (11 headers 0 lines) ---
[Dec 1 22:01:51] VERBOSE[26237] chan_sip.c: Retransmitting #1 (NAT) to 80.93.165.111:5060:
REGISTER sip:sip.numbergroup-services.com SIP/2.0
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK15bd82e9;rport
Max-Forwards: 70
From: ;tag=as56e0e721
To:
Call-ID:

CSeq: 1309 REGISTER
User-Agent: FPBX-2.8.1(1.6.2.20)
Authorization: Digest username="MyAccount", realm="sip.numbergroup-services.com", algorithm=MD5, uri="sip:sip.numbergroup-services.com", nonce="91458f8c-3c01-11e2-aab6-03dda959c092", response="04f26cdda5c7e7f88e5c6d9482a60fd6", qop=auth, cnonce="40cab4cc", nc=00000003
Expires: 600
Contact:
Content-Length: 0

----------------------------------------------------------------------------

This challenge being ignored continues for a couple of minutes and then, eventually, Asterisk does acknowledge the register challenge and responds appropriately, finally registering the trunk.
What I have noted is the line .... [Dec 1 22:01:50] VERBOSE[26237] chan_sip.c: Really destroying SIP dialog '290d455e3efd4fb70419d01c274571b3@127.0.0.1' Method: REGISTER ..... which I am guessing may have something to do with it.

Anyway, after a time, the trunk does register successfully.

e.g....
-------------------------------------------------------------------

[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: Retransmitting #4 (NAT) to 80.93.165.111:5060:
REGISTER sip:sip.numbergroup-services.com SIP/2.0
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK15bd82e9;rport
Max-Forwards: 70
From: ;tag=as56e0e721
To:
Call-ID:

CSeq: 1309 REGISTER
User-Agent: FPBX-2.8.1(1.6.2.20)
Authorization: Digest username="MyAccount", realm="sip.numbergroup-services.com", algorithm=MD5, uri="sip:sip.numbergroup-services.com", nonce="91458f8c-3c01-11e2-aab6-03dda959c092", response="04f26cdda5c7e7f88e5c6d9482a60fd6", qop=auth, cnonce="40cab4cc", nc=00000003
Expires: 600
Contact:
Content-Length: 0

---
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c:
<--- SIP read from UDP:80.93.165.111:5060 --->
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK15bd82e9;rport=61810
From: ;tag=as56e0e721
To: ;tag=F91aUKHDaHe4a
Call-ID:

CSeq: 1309 REGISTER
User-Agent: numbergroup.com
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, precondition, path, replaces
WWW-Authenticate: Digest realm="sip.numbergroup-services.com", nonce="556b2372-3c02-11e2-b292-03dda959c092", stale=true, algorithm=MD5, qop="auth"
Content-Length: 0

<------------->
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: --- (11 headers 0 lines) ---
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: Responding to challenge, registration to domain/host name sip.numbergroup-services.com
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: REGISTER 11 headers, 0 lines
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: Reliably Transmitting (NAT) to 80.93.165.111:5060:
REGISTER sip:sip.numbergroup-services.com SIP/2.0
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK687936da;rport
Max-Forwards: 70
From: ;tag=as4ee9fa6e
To:
Call-ID:

CSeq: 1310 REGISTER
User-Agent: FPBX-2.8.1(1.6.2.20)
Authorization: Digest username="MyAccount", realm="sip.numbergroup-services.com", algorithm=MD5, uri="sip:sip.numbergroup-services.com", nonce="556b2372-3c02-11e2-b292-03dda959c092", response="cc6527ff1c6201bdc236e8d0e5325e12", qop=auth, cnonce="4d6643fa", nc=00000001
Expires: 600
Contact:
Content-Length: 0

---
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c:
<--- SIP read from UDP:80.93.165.111:5060 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.132:5060;branch=z9hG4bK687936da;rport=61810
From: ;tag=as4ee9fa6e
To: ;tag=8j20D6ecyr29H
Call-ID:

CSeq: 1310 REGISTER
Contact: ;expires=600
Date: Sat, 01 Dec 2012 21:59:17 GMT
User-Agent: numbergroup.com
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, precondition, path, replaces
Content-Length: 0

<------------->
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: --- (12 headers 0 lines) ---
[Dec 1 22:01:58] VERBOSE[26237] chan_sip.c: Scheduling destruction of SIP dialog '290d455e3efd4fb70419d01c274571b3@127.0.0.1' in 32000 ms (Method: REGISTER)
[Dec 1 22:01:58] NOTICE[26237] chan_sip.c: Outbound Registration: Expiry for sip.numbergroup-services.com is 300 sec (Scheduling reregistration in 285 s)

----------------------------------------------------------------------------

Can anyone give me any clues as to why the Asterisk SIP stack should randomly ignore the challenge in this way? I am sure that it must be somethong to do with the server configuration but I don't know where to look. I am prety sure this is not a networking issue as the SIP messages are clearly received by the server as they can be seen in the debug, and also the trunk does register eventualy.

Any pointers would be greatly appreciated. I have searched the forum and not found anything like this on there. Hopefully somone out there can help me.

Thanks,

Colin.

Colonel_P
Colonel_P's picture
more info from Asterisk logs.

I have taken some debug logs and found that the reason for the message being ignored is that Asterisk thinks the CSEQ is out of order, what I don't understand is WHY? .....

[Dec 2 00:29:11] NOTICE[2780] chan_sip.c: -- Re-registration for

[Dec 2 00:29:11] VERBOSE[2780] dnsmgr.c: > doing dnsmgr_lookup for 'sip.numbergroup-services.com'
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Allocating new SIP dialog for

- REGISTER (No RTP)
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: OBPROXY: Not applying OBproxy to this call
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: SIP Registry sip.numbergroup-services.com: refcount now 3
[Dec 2 00:29:11] DEBUG[2780] acl.c: Found IP address for this socket
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 192.168.1.88:5060
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: SIP Registry sip.numbergroup-services.com: refcount now 4
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Scheduled a registration timeout for sip.numbergroup-services.com id #16090
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: >>> Re-using Auth data for

[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Initializing initreq for method REGISTER - callid

[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 0 [ 49]: REGISTER sip:sip.numbergroup-services.com SIP/2.0
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/UDP 192.168.1.88:5060;branch=z9hG4bK60a88995;rport
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 3 [ 72]: From: ;tag=as17dd56e9
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 4 [ 55]: To:
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 5 [ 51]: Call-ID:

[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 6 [ 19]: CSeq: 3913 REGISTER
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 7 [ 32]: User-Agent: FPBX-2.7.0(1.6.2.11)
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 8 [275]: Authorization: Digest username="MyAccount", realm="sip.numbergroup-services.com", algorithm=MD5, uri="sip:sip.numbergroup-services.com", nonce="f24e45e8-3c16-11e2-b7d1-03dda959c092", response="297557dedf6cfe095d01e07a3672c85b", qop=auth, cnonce="517d24d5", nc=00000002
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 9 [ 12]: Expires: 120
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 10 [ 29]: Contact:
[Dec 2 00:29:11] VERBOSE[2780] chan_sip.c: REGISTER 11 headers, 0 lines
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: REGISTER attempt 1 to

[Dec 2 00:29:11] VERBOSE[2780] chan_sip.c: Reliably Transmitting (NAT) to 80.93.165.111:5060:
REGISTER sip:sip.numbergroup-services.com SIP/2.0

Via: SIP/2.0/UDP 192.168.1.88:5060;branch=z9hG4bK60a88995;rport

Max-Forwards: 70

From: ;tag=as17dd56e9

To:

Call-ID:

CSeq: 3913 REGISTER

User-Agent: FPBX-2.7.0(1.6.2.11)

Authorization: Digest username="MyAccount", realm="sip.numbergroup-services.com", algorithm=MD5, uri="sip:sip.numbergroup-services.com", nonce="f24e45e8-3c16-11e2-b7d1-03dda959c092", response="297557dedf6cfe095d01e07a3672c85b", qop=auth, cnonce="517d24d5", nc=00000002

Expires: 120

Contact:

Content-Length: 0

---
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #16091
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 80.93.165.111:5060
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: SIP Registry sip.numbergroup-services.com: refcount now 3
[Dec 2 00:29:11] VERBOSE[2780] chan_sip.c:
<--- SIP read from UDP:80.93.165.111:5060 --->
SIP/2.0 401 Unauthorized

Via: SIP/2.0/UDP 192.168.1.88:5060;branch=z9hG4bK60a88995;rport=64877

From: ;tag=as17dd56e9

To: ;tag=Q5tr5ZDZ0cjpB

Call-ID:

CSeq: 3913 REGISTER

User-Agent: numbergroup.com

Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY

Supported: timer, precondition, path, replaces

WWW-Authenticate: Digest realm="sip.numbergroup-services.com", nonce="35b6b798-3c17-11e2-ba0c-03dda959c092", stale=true, algorithm=MD5, qop="auth"

Content-Length: 0

<------------->
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 0 [ 24]: SIP/2.0 401 Unauthorized
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.1.88:5060;branch=z9hG4bK60a88995;rport=64877
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 2 [ 72]: From: ;tag=as17dd56e9
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 3 [ 73]: To: ;tag=Q5tr5ZDZ0cjpB
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 4 [ 51]: Call-ID:

[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 5 [ 19]: CSeq: 3913 REGISTER
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 6 [ 27]: User-Agent: numbergroup.com
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 7 [ 88]: Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 8 [ 46]: Supported: timer, precondition, path, replaces
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 9 [146]: WWW-Authenticate: Digest realm="sip.numbergroup-services.com", nonce="35b6b798-3c17-11e2-ba0c-03dda959c092", stale=true, algorithm=MD5, qop="auth"
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 10 [ 17]: Content-Length: 0
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 11 [ 0]:
[Dec 2 00:29:11] VERBOSE[2780] chan_sip.c: --- (11 headers 0 lines) ---
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Ignoring out of order response 3913 (expecting 3912)
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: SIP message could not be handled, bad request:

[Dec 2 00:29:12] DEBUG[2780] chan_sip.c: SIP TIMER: Rescheduling retransmission #16091 (1) REGISTER - 2
[Dec 2 00:29:12] DEBUG[2780] chan_sip.c: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #16091))

tonyclewis
tonyclewis's picture
I remember this being a

I remember this being a issue with Asterisk 1.6 something. I suggest getting onto latest Asterisk 1.8

Tony Lewis
Schmooze Com/FreePBX
Opening a Bug or Feature request demo video

Colonel_P
Colonel_P's picture
Tony, You are quite right

Tony,

You are quite right ... built a new server using the latest Distro (1.1010.210.62-3) and that issue does not appear.

Thanks.