[asterisk-bugs] [Asterisk 0016936]: Qualify frequency has big pauses. Asterisk stops sending SIP OPTIONS to keep NAT alive

Tue Apr 20 05:31:19 CDT 2010

A NOTE has been added to this issue. 
====================================================================== 
https://issues.asterisk.org/view.php?id=16936 
====================================================================== 
Reported By:                ib2
Assigned To:                
====================================================================== 
Project:                    Asterisk
Issue ID:                   16936
Category:                   Channels/chan_sip/General
Reproducibility:            sometimes
Severity:                   major
Priority:                   normal
Status:                     feedback
Asterisk Version:           1.6.2.4 
JIRA:                       SWP-993 
Regression:                 No 
Reviewboard Link:            
SVN Branch (only for SVN checkouts, not tarball releases): N/A 
SVN Revision (number only!):  
Request Review:              
====================================================================== 
Date Submitted:             2010-03-01 13:54 CST
Last Modified:              2010-04-20 05:31 CDT
====================================================================== 
Summary:                    Qualify frequency has big pauses. Asterisk stops
sending SIP OPTIONS to keep NAT alive
Description: 
We have several SIP phone peers that that becomes UNREACHABLE since
upgrading to Asterisk 1.6.2.x

[10:08:44] chan_sip.c: Peer '202_117' is now UNREACHABLE!  Last qualify:
100
[10:11:25] chan_sip.c: Peer '202_117' is now Reachable. (86ms / 2000ms)
[11:59:03] chan_sip.c: Peer '202_117' is now UNREACHABLE!  Last qualify:
91
[12:11:27] chan_sip.c: Peer '202_117' is now Reachable. (85ms / 2000ms)
[13:17:21] chan_sip.c: Peer '202_117' is now UNREACHABLE!  Last qualify:
90
[13:41:27] chan_sip.c: Peer '202_117' is now Reachable. (92ms / 2000ms)

The phone is UNREACHABLE until it registers again. The phone does not know
that it is UNREACHABLE.
Asterisk reports the phone as UNREACHABLE after a big pause in sending SIP
OPTIONS to keep NAT alive. Therefore NAT table is lost and asterisk cannot
receive SIP OK reply from the phone.

The typical interval between the occurrence is shown above
====================================================================== 

---------------------------------------------------------------------- 
 (0120629) lvl (reporter) - 2010-04-20 05:31
 https://issues.asterisk.org/view.php?id=16936#c120629 
---------------------------------------------------------------------- 
We are experiencing exactly the same situation on an 1.6.2.5 machine. At
some point, Asterisk will just (randomly) stop sending its minutly OPTIONS
packet to the phone, and by the time it resumes it, the NAT mapping has
disappeared and the phone will be UNREACHABLE until the phone itself
realises it has disconnected.

The setup on this machine is nothing out of the ordinary, except for that
we make major use of notifications/hints with the Custom devstates

---- SIP.conf:

[general]
limitonpeers=yes

[phone](!)
type=friend
host=dynamic
nat=yes
qualify=yes
call-limit=100

----

This is a prime example of the problem. Asterisk sends an OPTION packet to
this phone every :30, until 11:06:30. After that, it suddenly halts, just
to resume at 11:13:40 as if nothing has ever happened; but by that time the
NAT mapping has disappeared, and after 4 retransmits, asterisk considers
the phone unreachable. 

  [Apr 20 11:01:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:02:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:03:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:04:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:05:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:06:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:13:40] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT)
to a.a.a.a:2128:
  [Apr 20 11:13:41] VERBOSE[1163] chan_sip.c: Retransmitting
https://issues.asterisk.org/view.php?id=1 (NAT) to
a.a.a.a:2128:

Inbetween 11:06:30 and 11:13:40 there is no attempted communication with
this host at all; neither is there any error message in the dialog at
11:06:30.

[Apr 20 11:06:30] VERBOSE[1163] chan_sip.c: Reliably Transmitting (NAT) to
a.a.a.a:2128:
OPTIONS sip:phone3 at o.o.o.o:5060 SIP/2.0
Via: SIP/2.0/UDP a.a.a.a:5060;branch=z9hG4bK2514da63;rport
Max-Forwards: 70
From: "asterisk" <sip:asterisk at a.a.a.a>;tag=as7cb0d683
To: <sip:phone3 at o.o.o.o:5060>
Contact: <sip:asterisk at a.a.a.a>
Call-ID: 462573744d998b5b6ed97e272e2a7154 at a.a.a.a
CSeq: 102 OPTIONS
User-Agent: Asterisk PBX 1.6.2.5-0ubuntu1
Date: Tue, 20 Apr 2010 09:06:30 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Content-Length: 0

[Apr 20 11:06:30] VERBOSE[1163] chan_sip.c: 
<--- SIP read from UDP:a.a.a.a:2128 --->
SIP/2.0 200 OK
To: <sip:phone3 at o.o.o.o:5060>;tag=c9760b6edbc9f2b0i0
From: "asterisk" <sip:asterisk at a.a.a.a>;tag=as7cb0d683
Call-ID: 462573744d998b5b6ed97e272e2a7154 at a.a.a.a
CSeq: 102 OPTIONS
Via: SIP/2.0/UDP a.a.a.a:5060;branch=z9hG4bK2514da63
Server: Linksys/SPA942-6.1.5(a)
Content-Length: 0
Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER
Supported: replaces

The timing is never exactly the same; sometimes it only takes about 2
minutes for asterisk to resume its qualify messages, other times it will
take up to 15. I've checked all logfiles and debug messages, but couldn't
find any explanation for the problem. 

Issue History 
Date Modified    Username       Field                    Change               
====================================================================== 
2010-04-20 05:31 lvl            Note Added: 0120629                          
======================================================================