[Home]

Summary:ASTERISK-13618: Asterisk stop responding after unsuccesfull registration
Reporter:Antonis Psaras (apsaras)Labels:
Date Opened:2009-02-20 08:55:48.000-0600Date Closed:2011-06-07 14:03:08
Priority:MajorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Registration
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
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.
Comments:By: David Brillert (aragon) 2009-02-20 10:52:43.000-0600

This is just a shot in the dark..
But your last event was an IAX2 call.
There are some bug reports of IAX2 storms...
Maybe your network interface is getting swamped.
Are you seeing any of the other symptoms?

http://bugs.digium.com/view.php?id=13749
http://bugs.digium.com/view.php?id=13884
http://bugs.digium.com/view.php?id=14386
By: Antonis Psaras (apsaras) 2009-02-20 15:55:20.000-0600

No this is not the case. The problem seems to be a misconfigured SIP client. After a small search I found out that a specific client was trying to register his account using an Alcatel SIP enabled PBX. So I will come in contact with him and try to reproduce and trace the registration process. What I guess is that the Alcatel sends somehow my IP as his public IP which at the end produces a loop to my asterisk box but I have to check that further.
By: Joshua C. Colp (jcolp) 2009-02-24 13:03:13.000-0600

Okay if you would like to explore this more we will definitely need to see a SIP debug to see what the packets are like.
By: Antonis Psaras (apsaras) 2009-02-25 13:57:12.000-0600

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@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@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@1.1.1.1>;tag=as10a288df
To: <sip:4404613592@192.168.1.60:2048;line=beavcpsg>
Contact: <sip:asterisk@1.1.1.1>
Call-ID: 21f7aa6a5fd04e56745adbb472bc1889@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 #1 (NAT) to 2.2.2.2:49842:
OPTIONS sip:4404613592@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@1.1.1.1>;tag=as2112b55d
To: <sip:4404613592@192.168.1.60:2048;line=beavcpsg>
Contact: <sip:asterisk@1.1.1.1>
Call-ID: 483ab2741a5b2a1333854c0e1ae7d6a3@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?
By: Antonis Psaras (apsaras) 2009-02-25 13:58:58.000-0600

Just a note

Server Time is in EEST so Server Time and Packet 1 time are the same.
By: Joshua C. Colp (jcolp) 2009-03-11 15:59:17

You are using realtime with this, but in what way? do you have realtime caching enabled?
By: Antonis Psaras (apsaras) 2009-03-11 16:08:26

Yes I am using real time for sip,iax,voicemail and extension. Yes I have caching enabled.
By: Antonis Psaras (apsaras) 2009-03-27 07:47:00

It happened again and I managed to get some more info. What I found out is that is going on an endless loop sending OPTION packets and the client's URI is incorrect.

running sip show channels I get hundred of those lines

94.XXX.XXX.XXX    (None)      6916411f65b  00102/00000  0x0 (nothing)    No       Init: OPTIONS

one line
94.XXX.XXX.XXX    8467422068  4fdc021e304  00102/00000  0x0 (nothing)    No       Tx: CANCEL

Running sip show peers I get
8467422068/8467422068      94.XXX.XXX.XXX    D   N   A  61707    UNREACHABLE Cached RT

From SIP Debug I get

Retransmitting #2 (NAT) to 94.XXX.XXX.XXX:61707:
OPTIONS sip:8467422068@192.168.1.60:2051;line=5c5t0eco SIP/2.0
Via: SIP/2.0/UDP 78.ZZZ.ZZZ.ZZZ:5060;branch=z9hG4bK0cf6d0bf;rport
From: "asterisk" <sip:asterisk@78.ZZZ.ZZZ.ZZZ>;tag=as28f99847
To: <sip:8467422068@192.168.1.60:2051;line=5c5t0eco>
Contact: <sip:asterisk@78.ZZZ.ZZZ.ZZZ>
Call-ID: 276d912a2ac01a6925c1c046144dfa5a@78.ZZZ.ZZZ.ZZZ
CSeq: 102 OPTIONS
User-Agent: Microbase CommServer
Max-Forwards: 70
Date: Fri, 27 Mar 2009 12:30:37 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY
Supported: replaces
Content-Length: 0


which result to hundred of

[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
[Mar 27 14:30:23] NOTICE[28092]: chan_sip.c:16418 sip_poke_noanswer: Peer '8467422068' is now UNREACHABLE!  Last qualify: 0
By: Antonis Psaras (apsaras) 2009-03-30 10:26:39

The problem that I have is described at the following thread
http://bugs.digium.com/view.php?id=14196

"... I can get the qualify to work when the peer is alive, but once the peer goes away (after `sip reload`), the poke_peer goes into a spiral and floods the device off the network with OPTIONS...."

I update my asterisk to 1.4.24 but I have the same problem. Is this problem resolved? Do I have to download from trunk?
By: Tilghman Lesher (tilghman) 2009-05-20 09:52:13

Please upgrade to 1.4.25-rc1.  This has already been fixed in SVN.