[Asterisk-Users] Unable to Register to Asterisk through Proxy

Wed Feb 1 01:19:20 MST 2006

Hi,

Has anybody come across a situation where they were unable to register with Asterisk through a SIP stateless proxy server?

I'm getting an error:

"403 Authentication user name does not match account name"

As far as I can tell the requests reaching Asterisk with and without the proxy are identical excepting the IP address the REGISTER request is coming from and the Via header (nonces and digests are different of course but I've verified that the md5 hash is correct). As far as the information you'd expect to be used for the REGISTER operation I can't see any difference.

Success (no proxy) and failure (with proxy) logs for the REGISTER request are below.

INVITE requests through the same proxy work correctly with the same the same credentials. It just seems to be some IP address matching going on for the REGISTER command that's causing a problem. I have had a look at chan_sip.c but haven't been able to work it out as of yet.

Thanks,

Aaron 

========================================================================
sip.conf for user test

[test]
type=friend
host=dynamic
nat=yes
canreinvite=no
username=test
secret=test

==========================================================================
Failure REGISTER through Proxy:

xxx.xxx.xxx.xxx = Asterisk
yyy.yyy.yyy.yyy = Proxy
zzz.zzz.zzz.zzz = User Agent Public IP
192.168.1.2 = User Agent Private IP

<-- SIP read from yyy.yyy.yyy.yyy:5060:
REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKCefqJfo5hAO/paxgvw/iR7owic4=
Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bK882020b45b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000
To: "test" <sip:test at xxx.xxx.xxx.xxx>
Contact: <sip:test at xxx.xxx.xxx.xxx>
Call-ID: 3deb0da4bada8c3 at 192.168.1.2
CSeq: 65 REGISTER
Max-Forwards: 69
Expires: 600

Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 0: REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0 (36)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 1: Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKCefqJfo5hAO/paxgvw/iR7owic4= (80)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 2: Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bK882020b45b (101)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 3: From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000 (62)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 4: To: "test" <sip:test at xxx.xxx.xxx.xxx> (37)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 5: Contact: <sip:test at xxx.xxx.xxx.xxx> (35)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 6: Call-ID: 3deb0da4bada8c3 at 192.168.1.2 (36)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 7: CSeq: 65 REGISTER (17)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 8: Max-Forwards: 69 (16)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 9: Expires: 600 (12)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 10:  (0)
--- (10 headers 0 lines)---
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3106 sip_alloc: Allocating new SIP dialog for 3deb0da4bada8c3 at 192.168.1.2 - REGISTER (No RTP)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:10945 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Using latest REGISTER request as basis request
Sending to yyy.yyy.yyy.yyy : 5060 (non-NAT)
Transmitting (NAT) to yyy.yyy.yyy.yyy:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKCefqJfo5hAO/paxgvw/iR7owic4=;received=yyy.yyy.yyy.yyy
Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bK882020b45b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000
To: "test" <sip:test at xxx.xxx.xxx.xxx>
Call-ID: 3deb0da4bada8c3 at 192.168.1.2
CSeq: 65 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
Content-Length: 0

---
Transmitting (NAT) to yyy.yyy.yyy.yyy:5060:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKCefqJfo5hAO/paxgvw/iR7owic4=;received=yyy.yyy.yyy.yyy
Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bK882020b45b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as738d9ccd
Call-ID: 3deb0da4bada8c3 at 192.168.1.2
CSeq: 65 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
WWW-Authenticate: Digest realm="asterisk", nonce="6a62f137"
Content-Length: 0

---
Scheduling destruction of call '3deb0da4bada8c3 at 192.168.1.2' in 15000 ms
buffalo*CLI>
<-- SIP read from yyy.yyy.yyy.yyy:5060:
REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKaN3LqUmNnA6Bm9VM4+7lrnh97Bo=
Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bKe494c5046b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as738d9ccd
Contact: <sip:test at xxx.xxx.xxx.xxx>
Call-ID: 3deb0da4bada8c3 at 192.168.1.2
CSeq: 66 REGISTER
Max-Forwards: 69
Expires: 600
Authorization: Digest realm="asterisk",nonce="6a62f137"

Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 0: REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0 (36)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 1: Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKaN3LqUmNnA6Bm9VM4+7lrnh97Bo= (80)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 2: Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bKe494c5046b (101)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 3: From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000 (62)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 4: To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as738d9ccd (52)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 5: Contact: <sip:test at xxx.xxx.xxx.xxx> (35)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 6: Call-ID: 3deb0da4bada8c3 at 192.168.1.2 (36)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 7: CSeq: 66 REGISTER (17)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 8: Max-Forwards: 69 (16)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 9: Expires: 600 (12)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 10: Authorization: Digest realm="asterisk",nonce="6a62f137" (55)
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 11:  (0)
--- (11 headers 0 lines)---
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:3154 find_call: = Found Their Call ID: 3deb0da4bada8c3 at 192.168.1.2 Their Tag 632743770590650000 Our tag: as738d9ccd
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:10945 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Using latest REGISTER request as basis request
Sending to yyy.yyy.yyy.yyy : 5060 (NAT)
Transmitting (NAT) to yyy.yyy.yyy.yyy:5060:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKaN3LqUmNnA6Bm9VM4+7lrnh97Bo=;received=yyy.yyy.yyy.yyy
Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bKe494c5046b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as738d9ccd
Call-ID: 3deb0da4bada8c3 at 192.168.1.2
CSeq: 66 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
Content-Length: 0

---
Transmitting (NAT) to yyy.yyy.yyy.yyy:5060:
SIP/2.0 403 Authentication user name does not match account name
Via: SIP/2.0/UDP yyy.yyy.yyy.yyy:5060;branch=z9hG4bKaN3LqUmNnA6Bm9VM4+7lrnh97Bo=;received=yyy.yyy.yyy.yyy
Via: SIP/2.0/UDP 192.168.1.2:5066;received=zzz.zzz.zzz.zzz:64073;rport=64073;branch=z9hG4bKe494c5046b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743770590650000
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as738d9ccd
Call-ID: 3deb0da4bada8c3 at 192.168.1.2
CSeq: 66 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
Content-Length: 0

---
Feb  1 07:51:11 DEBUG[24601]: chan_sip.c:6461 register_verify: SIP REGISTER attempt failed for test : Bad digest user
Feb  1 07:51:11 NOTICE[24601]: chan_sip.c:10851 handle_request_register: Registration from '"test" <sip:test at xxx.xxx.xxx.xxx>;tag=as738d9ccd' failed for 'yyy.yyy.yyy.yyy' - Username/auth name mismatch
Scheduling destruction of call '3deb0da4bada8c3 at 192.168.1.2' in 15000 ms
Feb  1 07:51:26 DEBUG[24601]: chan_sip.c:1316 __sip_autodestruct: Auto destroying call '3deb0da4bada8c3 at 192.168.1.2'
Destroying call '3deb0da4bada8c3 at 192.168.1.2'

============================================================================
Successfull REGISTER without Proxy:

xxx.xxx.xxx.xxx = Asterisk
zzz.zzz.zzz.zzz = User Agent Public IP
192.168.1.2 = User Agent Private IP

Connected to Asterisk 1.2.4 currently running on buffalo (pid = 24591)
Verbosity is at least 99
Core debug is at least 99
buffalo*CLI>
<-- SIP read from zzz.zzz.zzz.zzz:64080:
REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKe0d5c5d46b
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250
To: "test" <sip:test at xxx.xxx.xxx.xxx>
Contact: <sip:test at xxx.xxx.xxx.xxx>
Call-ID: 03172de4f748d31 at 192.168.1.2
CSeq: 65 REGISTER
Max-Forwards: 70
Expires: 600

Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 0: REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0 (36)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKe0d5c5d46b (58)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 2: From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250 (62)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 3: To: "test" <sip:test at xxx.xxx.xxx.xxx> (37)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 4: Contact: <sip:test at xxx.xxx.xxx.xxx> (35)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 5: Call-ID: 03172de4f748d31 at 192.168.1.2 (36)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 6: CSeq: 65 REGISTER (17)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 7: Max-Forwards: 70 (16)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 8: Expires: 600 (12)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 9:  (0)
--- (9 headers 0 lines)---
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3106 sip_alloc: Allocating new SIP dialog for 03172de4f748d31 at 192.168.1.2 - REGISTER (No RTP)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:10945 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Using latest REGISTER request as basis request
Transmitting (NAT) to zzz.zzz.zzz.zzz:64080:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKe0d5c5d46b;received=zzz.zzz.zzz.zzz
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250
To: "test" <sip:test at xxx.xxx.xxx.xxx>
Call-ID: 03172de4f748d31 at 192.168.1.2
CSeq: 65 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
Content-Length: 0

---
Transmitting (NAT) to zzz.zzz.zzz.zzz:64080:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKe0d5c5d46b;received=zzz.zzz.zzz.zzz
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as1966334a
Call-ID: 03172de4f748d31 at 192.168.1.2
CSeq: 65 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
WWW-Authenticate: Digest realm="asterisk", nonce="1c45303e"
Content-Length: 0

---
Scheduling destruction of call '03172de4f748d31 at 192.168.1.2' in 15000 ms
buffalo*CLI>
<-- SIP read from zzz.zzz.zzz.zzz:64080:
REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0
Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKeac443f447
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as1966334a
Contact: <sip:test at xxx.xxx.xxx.xxx>
Call-ID: 03172de4f748d31 at 192.168.1.2
CSeq: 66 REGISTER
Max-Forwards: 70
Expires: 600
Authorization: Digest username="test",realm="asterisk",nonce="1c45303e",response="8fad3f83db27076c84592efe4975f3b7",uri="sip:xxx.xxx.xxx.xxx"

Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 0: REGISTER sip:xxx.xxx.xxx.xxx SIP/2.0 (36)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKeac443f447 (58)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 2: From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250 (62)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 3: To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as1966334a (52)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 4: Contact: <sip:test at xxx.xxx.xxx.xxx> (35)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 5: Call-ID: 03172de4f748d31 at 192.168.1.2 (36)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 6: CSeq: 66 REGISTER (17)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 7: Max-Forwards: 70 (16)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 8: Expires: 600 (12)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 9: Authorization: Digest username="test",realm="asterisk",nonce="1c45303e",response="8fad3f83db27076c84592efe4975f3b7",uri="sip:xxx.xxx.xxx.xxx" (141)
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3322 parse_request: Header 10:  (0)
--- (10 headers 0 lines)---
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:3154 find_call: = Found Their Call ID: 03172de4f748d31 at 192.168.1.2 Their Tag 632743773130806250 Our tag: as1966334a
Feb  1 07:55:25 DEBUG[24601]: chan_sip.c:10945 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER
Using latest REGISTER request as basis request
Sending to 192.168.1.2 : 5066 (NAT)
Transmitting (NAT) to zzz.zzz.zzz.zzz:64080:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKeac443f447;received=zzz.zzz.zzz.zzz
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as1966334a
Call-ID: 03172de4f748d31 at 192.168.1.2
CSeq: 66 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Contact: <sip:test at xxx.xxx.xxx.xxx>
Content-Length: 0

---
Transmitting (NAT) to zzz.zzz.zzz.zzz:64080:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.1.2:5066;branch=z9hG4bKeac443f447;received=zzz.zzz.zzz.zzz
From: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=632743773130806250
To: "test" <sip:test at xxx.xxx.xxx.xxx>;tag=as1966334a
Call-ID: 03172de4f748d31 at 192.168.1.2
CSeq: 66 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Expires: 600
Contact: <sip:test at xxx.xxx.xxx.xxx>;expires=600
Date: Wed, 01 Feb 2006 07:55:25 GMT
Content-Length: 0

---
Scheduling destruction of call '03172de4f748d31 at 192.168.1.2' in 15000 ms
Feb  1 07:55:25 DEBUG[24594]: chan_sip.c:11469 sip_devicestate: Checking device state for peer test
Feb  1 07:55:25 DEBUG[24594]: devicestate.c:187 do_state_change: Changing state for SIP/test - state 1 (Not in use)
Feb  1 07:55:25 DEBUG[24712]: app_queue.c:471 changethread: Device 'SIP/test' changed to state '1' (Not in use)
Feb  1 07:55:40 DEBUG[24601]: chan_sip.c:1316 __sip_autodestruct: Auto destroying call '03172de4f748d31 at 192.168.1.2'
Destroying call '03172de4f748d31 at 192.168.1.2'