[asterisk-dev] SIP register expiry timer
Joshua Foshee
Joshua.Foshee at LogixCom.com
Tue May 4 12:53:36 CDT 2010
Ok I did a little more debugging to file rather then CLI and found this.
It looks like it was wanting a 338 message and it got a 339. Are they
getting out of order? I'm fairly new to debuging SIP so please be
patient with me. Thanks, Josh
[May 4 12:46:23] NOTICE[4045] chan_sip.c: -- Re-registration for
405233xxxx at sip.broadvoice.com@sip.broadvoice.com
[May 4 12:46:23] VERBOSE[4045] dnsmgr.c: > doing dnsmgr_lookup
for 'sip.broadvoice.com'
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Allocating new SIP dialog for
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com - REGISTER (No RTP)
[May 4 12:46:23] DEBUG[4045] chan_sip.c: OBPROXY: Not applying OBproxy
to this call
[May 4 12:46:23] DEBUG[4045] chan_sip.c: OBPROXY: Not applying OBproxy
to this call
[May 4 12:46:23] DEBUG[4045] chan_sip.c: SIP Registry
sip.broadvoice.com: refcount now 3
[May 4 12:46:23] DEBUG[4045] acl.c: Found IP address for this socket
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Setting SIP_TRANSPORT_UDP with
address 98.174.176.x:5060
[May 4 12:46:23] DEBUG[4045] chan_sip.c: SIP Registry
sip.broadvoice.com: refcount now 4
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Scheduled a registration
timeout for sip.broadvoice.com id #1424
[May 4 12:46:23] DEBUG[4045] chan_sip.c: >>> Re-using Auth data for
405233xxxx at sip.broadvoice.com@sip.broadvoice.com
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Initializing initreq for
method REGISTER - callid
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 0 [ 39]: REGISTER
sip:sip.broadvoice.com SIP/2.0
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 1 [ 63]: Via:
SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8;rport
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 2 [ 16]:
Max-Forwards: 70
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 3 [ 56]: From:
<sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 4 [ 39]: To:
<sip:405233xxxx at sip.broadvoice.com>
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 5 [ 60]: Call-ID:
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 6 [ 18]: CSeq: 339
REGISTER
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 7 [ 32]: User-Agent:
Asterisk PBX 1.6.2.6
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 8 [233]:
Authorization: Digest username="405233xxxx", realm="BroadWorks",
algorithm=MD5, uri="sip:sip.bro$
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 9 [ 13]: Expires:
1800
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 10 [ 29]: Contact:
<sip:s at 98.174.176.x>
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 11 [ 17]:
Content-Length: 0
[May 4 12:46:23] VERBOSE[4045] chan_sip.c: REGISTER 12 headers, 0 lines
[May 4 12:46:23] DEBUG[4045] chan_sip.c: REGISTER attempt 1 to
405233xxxx at sip.broadvoice.com@sip.broadvoice.com
[May 4 12:46:23] VERBOSE[4045] chan_sip.c: Reliably Transmitting (no
NAT) to 206.15.140.221:5060:
REGISTER sip:sip.broadvoice.com SIP/2.0
Via: SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8;rport
Max-Forwards: 70
From: <sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
To: <sip:405233xxxx at sip.broadvoice.com>
Call-ID: 54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
CSeq: 339 REGISTER
User-Agent: Asterisk PBX 1.6.2.6
Authorization: Digest username="405233xxxx", realm="BroadWorks",
algorithm=MD5, uri="sip:sip.broadvoice.com",
nonce="BroadWorksXg8svzetfTxfnkywBW", response$
Expires: 1800
Contact: <sip:s at 98.174.176.x>
Content-Length: 0
---
[May 4 12:46:23] DEBUG[4045] chan_sip.c: *** SIP TIMER: Initializing
retransmit timer on packet: Id #1425
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Trying to put 'REGISTER si'
onto UDP socket destined for 206.15.140.221:5060
[May 4 12:46:23] DEBUG[4045] chan_sip.c: SIP Registry
sip.broadvoice.com: refcount now 3
[May 4 12:46:23] VERBOSE[4045] chan_sip.c:
<--- SIP read from UDP:206.15.140.221:5060 --->
SIP/2.0 200 OK
Call-ID: 54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
CSeq: 339 REGISTER
From: <sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
To: <sip:405233xxxx at sip.broadvoice.com>
Via: SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8
Contact: <sip:s at 98.174.176.x>
Expires: 30
Content-Length: 0
<------------->
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 0 [ 14]: SIP/2.0 200
OK
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 1 [ 60]: Call-ID:
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 2 [ 18]: CSeq: 339
REGISTER
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 3 [ 56]: From:
<sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 4 [ 39]: To:
<sip:405233xxxx at sip.broadvoice.com>
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 5 [ 57]: Via:
SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 6 [ 29]: Contact:
<sip:s at 98.174.176.x>
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 7 [ 11]: Expires: 30
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 8 [ 20]:
Content-Length: 0
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Header 9 [ 0]:
[May 4 12:46:23] VERBOSE[4045] chan_sip.c: --- (9 headers 0 lines) ---
[May 4 12:46:23] DEBUG[4045] chan_sip.c: Ignoring out of order response
339 (expecting 338)
[May 4 12:46:23] DEBUG[4045] chan_sip.c: SIP message could not be
handled, bad request:
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com $
[May 4 12:46:24] DEBUG[4045] chan_sip.c: SIP TIMER: Rescheduling
retransmission #1425 (1) REGISTER - 2
[May 4 12:46:24] DEBUG[4045] chan_sip.c: ** SIP timers: Rescheduling
retransmission 2 to 1000 ms (t1 500 ms (Retrans id #1425))
[May 4 12:46:24] VERBOSE[4045] chan_sip.c: Retransmitting #1 (no NAT)
to 206.15.140.221:5060:
REGISTER sip:sip.broadvoice.com SIP/2.0
Via: SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8;rport
Max-Forwards: 70
From: <sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
To: <sip:405233xxxx at sip.broadvoice.com>
Call-ID: 54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
CSeq: 339 REGISTER
User-Agent: Asterisk PBX 1.6.2.6
Authorization: Digest username="405233xxxx", realm="BroadWorks",
algorithm=MD5, uri="sip:sip.broadvoice.com",
nonce="BroadWorksXg8svzetfTxfnkywBW", response$
Expires: 1800
Contact: <sip:s at 98.174.176.x>
Content-Length: 0
---
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Trying to put 'REGISTER si'
onto UDP socket destined for 206.15.140.221:5060
[May 4 12:46:24] VERBOSE[4045] chan_sip.c:
<--- SIP read from UDP:206.15.140.221:5060 --->
SIP/2.0 200 OK
Call-ID: 54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
CSeq: 339 REGISTER
From: <sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
To: <sip:405233xxxx at sip.broadvoice.com>
Call-ID: 54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
CSeq: 339 REGISTER
User-Agent: Asterisk PBX 1.6.2.6
Authorization: Digest username="405233xxxx", realm="BroadWorks",
algorithm=MD5, uri="sip:sip.broadvoice.com",
nonce="BroadWorksXg8svzetfTxfnkywBW", response$
Expires: 1800
Contact: <sip:s at 98.174.176.x>
Content-Length: 0
---
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Trying to put 'REGISTER si'
onto UDP socket destined for 206.15.140.221:5060
[May 4 12:46:24] VERBOSE[4045] chan_sip.c:
<--- SIP read from UDP:206.15.140.221:5060 --->
SIP/2.0 200 OK
Call-ID: 54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
CSeq: 339 REGISTER
From: <sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
To: <sip:405233xxxx at sip.broadvoice.com>
Via: SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8
Contact: <sip:s at 98.174.176.x>
Expires: 30
Content-Length: 0
<------------->
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 0 [ 14]: SIP/2.0 200
OK
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 1 [ 60]: Call-ID:
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 2 [ 18]: CSeq: 339
REGISTER
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 3 [ 56]: From:
<sip:405233xxxx at sip.broadvoice.com>;tag=as6edb5bf6
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 4 [ 39]: To:
<sip:405233xxxx at sip.broadvoice.com>
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 5 [ 57]: Via:
SIP/2.0/UDP 98.174.176.x:5060;branch=z9hG4bK18dfe8e8
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 6 [ 29]: Contact:
<sip:s at 98.174.176.x>
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 7 [ 11]: Expires: 30
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 8 [ 20]:
Content-Length: 0
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Header 9 [ 0]:
[May 4 12:46:24] VERBOSE[4045] chan_sip.c: --- (9 headers 0 lines) ---
[May 4 12:46:24] DEBUG[4045] chan_sip.c: Ignoring out of order response
339 (expecting 338)
[May 4 12:46:24] DEBUG[4045] chan_sip.c: SIP message could not be
handled, bad request:
54d2c0f828b6eb944ba5a75662e2e280 at sip.broadvoice.com $
[May 4 12:46:25] DEBUG[4045] chan_sip.c: SIP TIMER: Rescheduling
retransmission #1425 (2) REGISTER - 2
[May 4 12:46:25] DEBUG[4045] chan_sip.c: ** SIP timers: Rescheduling
retransmission 3 to 2000 ms (t1 500 ms (Retrans id #1425))
[May 4 12:46:25] VERBOSE[4045] chan_sip.c: Retransmitting #2 (no NAT)
to 206.15.140.221:5060:
-----Original Message-----
From: asterisk-dev-bounces at lists.digium.com
[mailto:asterisk-dev-bounces at lists.digium.com] On Behalf Of Nick Lewis
Sent: Tuesday, May 04, 2010 11:14 AM
To: Asterisk Developers Mailing List
Subject: Re: [asterisk-dev] SIP register expiry timer
>Not withstanding the other issues you could enable debug on the cli to
>see why the 200 OK is not being matched to the REGISTER (causing the
>retransmission). This could be because find_call() is not able to match
>the Call-ID or the from-tag or it could be due to a min-expiry problem.
>Either way, the cli debug should elucidate
Sorry Josh I did not read before write
I think that the cli is more use than the log as find_call uses
ast_debug (rather than
ast_log) for its output which I think may only go to the cli
-- N_L
More information about the asterisk-dev
mailing list