SIP 401 Unauthorised regisration challenge ignored by Asterisk

General Help
1

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: sip:[email protected];tag=as56e0e721
To: sip:[email protected]
Call-ID: [email protected]
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: sip:[email protected]
Content-Length: 0

[Dec 1 22:01:50] VERBOSE[26237] chan_sip.c: Really destroying SIP dialog ‘[email protected]’ 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: sip:[email protected];tag=as56e0e721
To: sip:[email protected];tag=F91aUKHDaHe4a
Call-ID: [email protected]
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: sip:[email protected];tag=as56e0e721
To: sip:[email protected]
Call-ID: [email protected]
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: sip:[email protected]
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 ‘[email protected]’ 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: sip:[email protected];tag=as56e0e721
To: sip:[email protected]
Call-ID: [email protected]
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: sip:[email protected]
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: sip:[email protected];tag=as56e0e721
To: sip:[email protected];tag=F91aUKHDaHe4a
Call-ID: [email protected]
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: sip:[email protected];tag=as4ee9fa6e
To: sip:[email protected]
Call-ID: [email protected]
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: sip:[email protected]
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: sip:[email protected];tag=as4ee9fa6e
To: sip:[email protected];tag=8j20D6ecyr29H
Call-ID: [email protected]
CSeq: 1310 REGISTER
Contact: sip:[email protected]:5060;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 ‘[email protected]’ 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.

2

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 [email protected]
[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 [email protected] - 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 [email protected]
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Initializing initreq for method REGISTER - callid [email protected]
[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: sip:[email protected];tag=as17dd56e9
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 4 [ 55]: To: sip:[email protected]
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 5 [ 51]: Call-ID: [email protected]
[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: sip:[email protected]
[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 [email protected]
[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: sip:[email protected];tag=as17dd56e9

To: sip:[email protected]

Call-ID: [email protected]

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: sip:[email protected]

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: sip:[email protected];tag=as17dd56e9

To: sip:[email protected];tag=Q5tr5ZDZ0cjpB

Call-ID: [email protected]

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: sip:[email protected];tag=as17dd56e9
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 3 [ 73]: To: sip:[email protected];tag=Q5tr5ZDZ0cjpB
[Dec 2 00:29:11] DEBUG[2780] chan_sip.c: Header 4 [ 51]: Call-ID: [email protected]
[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: [email protected]
[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))

3

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

4

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.