[asterisk-bugs] [Asterisk 0014518]: Asterisk stop responding after unsuccesfull registration
Asterisk Bug Tracker
noreply at bugs.digium.com
Wed Feb 25 13:57:13 CST 2009
A NOTE has been added to this issue.
======================================================================
http://bugs.digium.com/view.php?id=14518
======================================================================
Reported By: apsaras
Assigned To:
======================================================================
Project: Asterisk
Issue ID: 14518
Category: Channels/chan_sip/Registration
Reproducibility: random
Severity: major
Priority: normal
Status: feedback
Asterisk Version: 1.4.23-rc1
Regression: No
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Request Review:
======================================================================
Date Submitted: 2009-02-20 08:55 CST
Last Modified: 2009-02-25 13:57 CST
======================================================================
Summary: Asterisk stop responding after unsuccesfull
registration
Description:
We have an asterisk box set it up on realtime with Postgresql and ODBC as a
back end. The server is publicly to the internet having a few sip users
(20) registering on it and some iax trunks (5). The problem that appear is
that after a registration of a user with unknown parameters and not always
the same user the asterisk stops responding and keep looping.
-------A normal call just before the problem -----------
[Feb 19 10:20:33] VERBOSE[13333] logger.c: -- Executing
Dial("IAX2/microbasecc-13020", "SIP/vn/92202625|60|r")
[Feb 19 10:20:33] VERBOSE[13333] logger.c: -- Called vn/92202625
[Feb 19 10:20:34] VERBOSE[13333] logger.c: -- SIP/vn-19b38490 is
ringing
[Feb 19 10:20:34] VERBOSE[13333] logger.c: -- SIP/vn-19b38490 is
making progress passing it to IAX2/mbcc-13020
[Feb 19 10:20:43] VERBOSE[13333] logger.c: -- SIP/vn-19b38490 answered
IAX2/mbcc-13020
------------------------------
-----And the problem starts here
[Feb 19 10:21:05] VERBOSE[1580] logger.c: -- Added extension
'8467422068' priority 1 to sipregistrations
[Feb 19 10:21:09] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:21:13] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:21:13] VERBOSE[1580] logger.c: -- Added extension
'8467422068' priority 1 to sipregistrations
[Feb 19 10:21:17] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:21:21] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:21:25] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:21:27] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
..................
This is keep going for ever and it seems to loop back because each time an
Unreachable status is reported the reports are more offer. For example see
what happen after two minutes
[Feb 19 10:23:10] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:23:10] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:23:10] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
UNREACHABLE! Last qualify: 0
[Feb 19 10:23:10] NOTICE[1656] chan_sip.c: Peer '8467422068' is now
...............
We have more than 50 status reports for the same issue in a sec.
It seams that for unknown reason the user registeres with our IP? or with
loop back IP ? I can realy tell because the system is not responding.
The system comes back only with restart of the service.
======================================================================
----------------------------------------------------------------------
(0100747) apsaras (reporter) - 2009-02-25 13:57
http://bugs.digium.com/view.php?id=14518#c100747
----------------------------------------------------------------------
I didn't manage to find the customer in order to do a full trace but
unfortunatly the same thing happen with an other customer and I start
tracing SIP packet after the problem start. The following SIP packet keeps
repeating more than 5 times in a second.
MyGateway IP was masked to 1.1.1.1
Customers public IP was masked to 2.2.2.2
[Feb 25 21:36:24] NOTICE[16125] chan_sip.c: Peer '4404613592' is now
UNREACHABLE! Last qualify: 0
[Feb 25 21:36:24] VERBOSE[16125] logger.c: Really destroying SIP dialog
'1c1d164d03f1090c756a534a6cab8b65 at 1.1.1.1' Method: OPTIONS
[Feb 25 21:36:24] VERBOSE[16116] logger.c: Reliably Transmitting (NAT) to
2.2.2.2:49842:
OPTIONS sip:4404613592 at 192.168.1.60:2048;line=beavcpsg SIP/2.0
Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK08493512;rport
From: "asterisk" <sip:asterisk at 1.1.1.1>;tag=as10a288df
To: <sip:4404613592 at 192.168.1.60:2048;line=beavcpsg>
Contact: <sip:asterisk at 1.1.1.1>
Call-ID: 21f7aa6a5fd04e56745adbb472bc1889 at 1.1.1.1
CSeq: 102 OPTIONS
User-Agent: Microbase CommServer
Max-Forwards: 70
Date: Wed, 25 Feb 2009 19:36:24 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
---
[Feb 25 21:36:24] VERBOSE[16116] logger.c: -- Added extension
'4404613592' priority 1 to sipregistrations
[Feb 25 21:36:24] VERBOSE[16125] logger.c: Retransmitting
http://bugs.digium.com/view.php?id=1 (NAT) to
2.2.2.2:49842:
OPTIONS sip:4404613592 at 192.168.1.60:2048;line=beavcpsg SIP/2.0
Via: SIP/2.0/UDP 1.1.1.1:5060;branch=z9hG4bK5d7149ed;rport
From: "asterisk" <sip:asterisk at 1.1.1.1>;tag=as2112b55d
To: <sip:4404613592 at 192.168.1.60:2048;line=beavcpsg>
Contact: <sip:asterisk at 1.1.1.1>
Call-ID: 483ab2741a5b2a1333854c0e1ae7d6a3 at 1.1.1.1
CSeq: 102 OPTIONS
User-Agent: Microbase CommServer
Max-Forwards: 70
Date: Wed, 25 Feb 2009 18:57:49 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0
The system recovers only with service restart. As far as I understand
Asterisk for some reason keep sending OPTION messages to the client. An
other point that I mension is the time defference between client and
server.
Time on Server - 21:36:24
Time on SIP Packet 1 - Date: Wed, 25 Feb 2009 19:36:24 GMT
Time on SIP Packet 2 - Date: Wed, 25 Feb 2009 18:57:49 GMT
Is that time used anywhere in the code?
Issue History
Date Modified Username Field Change
======================================================================
2009-02-25 13:57 apsaras Note Added: 0100747
======================================================================
More information about the asterisk-bugs
mailing list