[asterisk-dev] SIP register expiry timer
Klaus Darilion
klaus.mailinglists at pernau.at
Tue May 4 14:28:06 CDT 2010
Looks like a bug in Asterisk - if it is sending CSEq 339 then it should
accept CSeq 339.
regards
klaus
On 04.05.2010 19:53, Joshua Foshee wrote:
> 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