[Home]

Summary:ASTERISK-01459: SIP registration fails with Bad Request 400 until "reload" is executed
Reporter:timecop (timecop)Labels:
Date Opened:2004-04-23 00:16:34Date Closed:2011-06-07 14:10:35
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:SIP Registration to my provider fails immediately after asterisk start with "Bad Request 400".

This will repeat in about 30 second intervals until "reload" is executed, after that the process completes correctly.

included sample log in "additional information".



****** ADDITIONAL INFORMATION ******

ASTERISK_IP = global internet accessible IP address of the asterisk server
ASTERISK_INT_IP = internal IP address of the asterisk server
PROVIDER_IP = IP Address of the SIP provider
PROVIDER_DOMAIN = Domain name of the SIP provider (resolves to the IP above)
PROVIDER_REALM = Realm of the SIP provider (different from the domain name above)
MY_PHONE_NUMBER = My telephone number at the SIP provider
MY_USERNAME = My username at the sip provider

sip.conf:
register => MY_PHONE_NUMBER:my_secret_at_sip:MY_USERNAME@PROVIDER_DOMAIN

[PROVIDER_DOMAIN]
type=peer
username=MY_USERNAME
secret=my_secret_at_sip
host=PROVIDER_DOMAIN
fromuser=MY_PHONE_NUMBER
fromdomain=PROVIDER_DOMAIN
canreinvite=no
context=my_sip_context
disallow=all
allow=g729
allow=ulaw
allow=gsm

after reload, registration succeeds without 400 error.

log:
Asterisk Ready.
*CLI>
*CLI> Apr 23 12:25:35 NOTICE[98311]: chan_sip.c:3203 sip_reg_timeout: Registration for 'MY_PHONE_NUMBER@PROVIDER_IP' timed out, trying again
   -- Got SIP response 400 "Bad Request" back from PROVIDER_IP
sip debug
SIP Debugging Enabled
*CLI>
*CLI> Apr 23 12:25:55 NOTICE[98311]: chan_sip.c:3203 sip_reg_timeout: Registration for 'MY_PHONE_NUMBER@PROVIDER_IP' timed out, trying again
11 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK08f31e73
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as4b05cf75
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 106 REGISTER
User-Agent: X-PRO build 1082
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060


Sip read:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK08f31e73
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as4b05cf75
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291679556
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 106 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 03:25:56 GMT
WWW-Authenticate: Digest realm="PROVIDER_REALM", domain="PROVIDER_IP", nonce="1082690325628404", opaque="", stale=FALSE, algorithm=MD5


9 headers, 0 lines
12 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK0840af07
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as4b05cf75
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 107 REGISTER
User-Agent: X-PRO build 1082
Authorization: Digest username="MY_USERNAME", realm="PROVIDER_REALM", algorithm="MD5", uri="PROVIDER_IP", nonce="1082690325628404", response="21ef250550ef40feff76ae848d391c05", opaque=""
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060


Sip read:
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK0840af07
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as4b05cf75
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291679556
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 107 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 03:25:56 GMT


8 headers, 0 lines
   -- Got SIP response 400 "Bad Request" back from PROVIDER_IP
Destroying call '3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP'
Apr 23 12:26:15 NOTICE[98311]: chan_sip.c:3203 sip_reg_timeout: Registration for 'MY_PHONE_NUMBER@PROVIDER_IP' timed out, trying again
11 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK6bc873de
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as710e8ea1
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 108 REGISTER
User-Agent: X-PRO build 1082
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060


Sip read:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK6bc873de
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as710e8ea1
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291679576
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 108 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 03:26:16 GMT
WWW-Authenticate: Digest realm="PROVIDER_REALM", domain="PROVIDER_IP", nonce="1082690325628404", opaque="", stale=FALSE, algorithm=MD5


9 headers, 0 lines
12 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK036714fc
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as710e8ea1
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 109 REGISTER
User-Agent: X-PRO build 1082
Authorization: Digest username="MY_USERNAME", realm="PROVIDER_REALM", algorithm="MD5", uri="PROVIDER_IP", nonce="1082690325628404", response="21ef250550ef40feff76ae848d391c05", opaque=""
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060

*CLI>

Sip read:
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK036714fc
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as710e8ea1
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291679577
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 109 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 03:26:17 GMT


8 headers, 0 lines
   -- Got SIP response 400 "Bad Request" back from PROVIDER_IP
Destroying call '3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP'

*CLI>
*CLI> stop now
Comments:By: timecop (timecop) 2004-04-23 00:44:59

I forgot to mention I modified Asterisk user-agent string to say
"User-Agent: X-PRO build 1082"
however this makes no difference, of course.

Posting a log of "after" reload SIP headers:

*CLI> sip show registry
Host                  Username     Refresh State
PROVIDER_IP:5060    MY_PHONE_NUMBER  120 Auth. Sent
*CLI> Apr 23 13:24:38 NOTICE[98311]: chan_sip.c:3203 sip_reg_timeout: Registration for 'MY_PHONE_NUMBER@PROVIDER_IP' timed out, trying again
   -- Got SIP response 400 "Bad Request" back from PROVIDER_IP
Apr 23 13:24:58 NOTICE[98311]: chan_sip.c:3203 sip_reg_timeout: Registration for 'MY_PHONE_NUMBER@PROVIDER_IP' timed out, trying again
   -- Got SIP response 400 "Bad Request" back from PROVIDER_IP

*CLI> sip debug
SIP Debugging Enabled
*CLI> Apr 23 13:25:18 NOTICE[98311]: chan_sip.c:3203 sip_reg_timeout: Registration for 'MY_PHONE_NUMBER@PROVIDER_IP' timed out, trying again
11 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK54e14f5f
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as7b172797
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 108 REGISTER
User-Agent: X-PRO build 1082
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060

*CLI>

Sip read:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK54e14f5f
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as7b172797
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291683119
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 108 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 04:25:19 GMT
WWW-Authenticate: Digest realm="PROVIDER_REALM", domain="PROVIDER_IP", nonce="1082693766296201", opaque="", stale=FALSE, algorithm=MD5


9 headers, 0 lines
12 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK70a0a6c7
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as7b172797
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 109 REGISTER
User-Agent: X-PRO build 1082
Authorization: Digest username="MY_USERNAME", realm="PROVIDER_REALM", algorithm="MD5", uri="PROVIDER_IP", nonce="1082693766296201", response="541aa7c5fadf805dae3ff99d3275e753", opaque=""
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060


Sip read:
SIP/2.0 400 Bad Request
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK70a0a6c7
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as7b172797
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291683119
Call-ID: 3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP
CSeq: 109 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 04:25:19 GMT


8 headers, 0 lines
   -- Got SIP response 400 "Bad Request" back from PROVIDER_IP
Destroying call '3d1b58ba507ed7ab2eb141f241b71efb@ASTERISK_INT_IP'

*CLI> reload

*CLI> 11 headers, 0 lines
Reliably Transmitting:
REGISTER sip:fwd.pulver.com SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK57958445
From: <sip:267210@fwd.pulver.com>;tag=as5994ad17
To: <sip:267210@fwd.pulver.com>
Call-ID: 3989aae74c880953453d776008ea8783@ASTERISK_INT_IP
CSeq: 102 REGISTER
User-Agent: X-PRO build 1082
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to 192.246.69.223:5060
11 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK2acd5204
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as2c169c3b
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 7a9737f0092f13c61d35d30d3df60df9@ASTERISK_INT_IP
CSeq: 102 REGISTER
User-Agent: X-PRO build 1082
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060


Sip read:
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK2acd5204
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as2c169c3b
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=3291683122
Call-ID: 7a9737f0092f13c61d35d30d3df60df9@ASTERISK_INT_IP
CSeq: 102 REGISTER
Content-Length: 0
Date: Fri, 23 Apr 2004 04:25:22 GMT
WWW-Authenticate: Digest realm="PROVIDER_REALM", domain="PROVIDER_IP", nonce="1082694322567390", opaque="", stale=FALSE, algorithm=MD5


9 headers, 0 lines
12 headers, 0 lines
Reliably Transmitting:
REGISTER sip:PROVIDER_DOMAIN SIP/2.0
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK08cfb83b
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as2c169c3b
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 7a9737f0092f13c61d35d30d3df60df9@ASTERISK_INT_IP
CSeq: 103 REGISTER
User-Agent: X-PRO build 1082
Authorization: Digest username="MY_USERNAME", realm="PROVIDER_REALM", algorithm="MD5", uri="PROVIDER_IP", nonce="1082694322567390", response="8ed842b5e7de9364a24b20bf947522c6", opaque=""
Expires: 120
Contact: <sip:s@ASTERISK_IP>
Event: registration
Content-Length: 0

(no NAT) to PROVIDER_IP:5060


Sip read:
SIP/2.0 200 OK
Via: SIP/2.0/UDP ASTERISK_IP:5060;branch=z9hG4bK08cfb83b
From: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>;tag=as2c169c3b
To: <sip:MY_PHONE_NUMBER@PROVIDER_DOMAIN>
Call-ID: 7a9737f0092f13c61d35d30d3df60df9@ASTERISK_INT_IP
CSeq: 103 REGISTER
Contact: <sip:s@ASTERISK_IP>;q=0;expires=28800
Content-Length: 0
Date: Fri, 23 Apr 2004 04:25:22 GMT


9 headers, 0 lines
Destroying call '7a9737f0092f13c61d35d30d3df60df9@ASTERISK_INT_IP'


*CLI> sip show registry
Host                  Username     Refresh State              
PROVIDER_IP:5060    MY_PHONE_NUMBER  120 Registered          
*CLI> stop now
By: Olle Johansson (oej) 2004-04-23 03:14:33

The REGISTER messages Asterisk sends in the first and second example are equal. In the first case, the provider says "400 Bad Request" and in the second case "200 Ok"

I can't see an error on Asterisks behalf here, unless you show us what's handled differently after reload. I might be missing something, so please help me.

Also, ther's no User-agent that tells me what server you're trying to use. And there's no Reason header that explains why the server think it's a bad request. Maybe some packet sniffing will help you to check if we're sending malformed packets in the first case.


** About 400 Bad Request from RFC 3261:
-----
In the case of message-oriented transports (such as UDP), if the message has a Content-Length header
field, the message body is assumed to contain that many bytes. If there are additional bytes in the transport
packet beyond the end of the body, they MUST be discarded. If the transport packet ends before the end of
the message body, this is considered an error. If the message is a response, it MUST be discarded. If the
message is a request, the element SHOULD generate a 400 (Bad Request) response. If the message has no
Content-Length header field, the message body is assumed to end at the end of the transport packet.
In the case of stream-oriented transports such as TCP, the Content-Length header field indicates the size of
the body. The Content-Length header field MUST be used with stream oriented transports.

-----
21.4.1 400 Bad Request
The request could not be understood due to malformed syntax. The Reason-Phrase SHOULD identify the
syntax problem in more detail, for example, &ASTERISK-7999;Missing Call-ID header field&ASTERISK-8000;.

-----------
By: timecop (timecop) 2004-04-23 09:42:05

I did some preliminary analysis with tcpdump'ed packets.
they look same, but i didn't look too closely.
this is definitely "repeatable" though, with varying degree of success.
Not sure where the problem would be.
By: Mark Spencer (markster) 2004-04-23 09:52:47

Well when you figure out what is "different" i'll be happy to takea look at it.
By: Mark Spencer (markster) 2004-04-28 10:04:43

Any update here?
By: timecop (timecop) 2004-04-29 23:13:14

well, it happens.
the occurence is quite random.
Sometimes it'll manifest immediately after restarting asterisk after updating to latest CVS or just because of a needed restart.
Sometimes it won't.
I can't really paste tcpdump logs with all my provider account information, but from what comparing i did I can't see any differences except different hashes for passwords/challenges.

Could this be timing related somehow?
I guess might be provider's fault as well, if they don't even provide a reason in the error reply.
By: Mark Spencer (markster) 2004-05-02 01:18:54

I can't do anything without seeing what is different from a failed and a non-failed request.  I'll give you a few more days to come up with something or i'll have to close this as "cannot be duplicated"
By: alric (alric) 2004-05-05 15:32:10

Reminder sent to timecop

Have you been able to reliably reproduce this issue, or provide Mark with the information he requested?
By: timecop (timecop) 2004-05-05 19:20:59

Go ahead and close this.
I cannot provide any more details other than "it randomly occurs on one of my machines, even with current CVS".

I'd say the Voip provider is to blame.
By: alric (alric) 2004-05-05 19:47:10

Closed out.  Unable to reproduce reliably.  If the bug resurfaces (in a reproducable form) contact a bug marshall or open a new bug.