Analysis of Astrad v13 registration graph

André Guimarães, 2012-04-24

Switzernet

1. Introduction.. 1

2. Causes. 2

Debug on 412255XXX88. 3

Debug on 412255XXX73. 11

3. Comparison with Astrad v11. 14

Introduction

After the installation of the first Astrad v13 in production, it was noticed that the registration curve shown in Cacti was more instable than in the previous version.

Bellow a screenshot of Astrad v11 and Astrad v13 which have similar number of customers.

The curve in astrad v13 (shown above) is very unstable when compared with every other server (astrad14 shown bellow as an example of astrad v11).

Causes

Monitoring the registration events it was possible to discover that the cause was a mass deletion from table location3 (which is used by the graphs above) by the event Evt_Unregister. This event deletes all registrations from location3 that have expired more than 5 minutes ago. It is executed each 5 minutes. In the select bellow several simultaneous UNREGISTERs can be seen. This happens each 5 minutes.

mysql> select * from registration2 order by id;

...

| 287 | 412255XXX33 | 91.121.151.75 | XXX.199.65.93 | 5060 | 2012-04-24 10:18:38 | NULL | REGISTER |

| 288 | 413250XXX62 | 91.121.151.75 | XX.56.211.235 | 5061 | 2012-04-24 10:18:38 | NULL | REGISTER |

| 289 | 412255XXX97 | 91.121.151.75 | XXX.83.6.242 | 5060 | 2012-04-24 10:18:38 | NULL | REGISTER |

| 290 | 412155XXX69 | 91.121.151.75 | XXX.193.226.136 | 49187 | 2012-04-24 10:18:40 | NULL | REGISTER |

| 291 | 412155XXX62 | 91.121.151.75 | XX.90.20.26 | 40858 | 2012-04-24 10:09:38 | NULL | UNREGISTER |

| 292 | 412255XXX13 | 91.121.151.75 | XXX.62.185.142 | 61409 | 2012-04-24 10:10:12 | NULL | UNREGISTER |

| 293 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 10758 | 2012-04-24 10:05:48 | NULL | UNREGISTER |

| 294 | 413150XXX32 | 91.121.151.75 | XX.4.242.207 | 53256 | 2012-04-24 10:09:52 | NULL | UNREGISTER |

| 295 | 412450XXX54 | 91.121.151.75 | XX.107.178.4 | 50838 | 2012-04-24 10:07:02 | NULL | UNREGISTER |

| 296 | 412450XXX11 | 91.121.151.75 | XXX.195.184.56 | 54631 | 2012-04-24 10:09:36 | NULL | UNREGISTER |

| 297 | 413250XXX45 | 91.121.151.75 | XX.107.137.34 | 57621 | 2012-04-24 10:10:15 | NULL | UNREGISTER |

| 298 | 412255XXX73 | 91.121.151.75 | XX.202.116.224 | 53340 | 2012-04-24 10:06:36 | NULL | UNREGISTER |

| 299 | 412255XXX73 | 91.121.151.75 | XXX.193.244.173 | 56197 | 2012-04-24 10:08:13 | NULL | UNREGISTER |

| 300 | 412155XXX54 | 91.121.151.75 | XX.203.133.215 | 60896 | 2012-04-24 10:10:14 | NULL | UNREGISTER |

| 301 | 412155XXX42 | 91.121.151.75 | XX.167.66.60 | 17470 | 2012-04-24 10:16:42 | NULL | REGISTER |

| 302 | 412255XXX67 | 91.121.151.75 | XX.62.186.3 | 36211 | 2012-04-24 10:18:44 | NULL | REGISTER |

| 303 | 412155XXX00 | 91.121.151.75 | XXX.82.132.78 | 5060 | 2012-04-24 10:18:46 | NULL | REGISTER |

| 304 | 412155XXX90 | 91.121.151.75 | XXX.169.161.255 | 5060 | 2012-04-24 10:20:46 | NULL | REGISTER |

...

To see how many entries will be deleted by the event, execute the following query in astrad13.switzernet.com:

mysql> select count(username) from location3 where expires < DATE_SUB(NOW(), INTERVAL 5 MINUTE);

+-----------------+

| count(username) |

+-----------------+

| 8 |

+-----------------+

1 row in set (0.00 sec)

The same query executed in an Astrad v11 returns 0 results (tested in 3 servers at different times). In astrad13.switzernet.com there are always some expired accounts.

Debug on 412255XXX88

To see if the information was correct a ngrep was executed to filter one of the delete numbers.

The account had only one registration in location3.

mysql> select *, NOW() from location3 where username = 412255XXX88 order by username;

+-------------+-----------------+-------+---------------------+---------------------+-----------+---------------------+

+-------------+-----------------+-------+---------------------+---------------------+-----------+---------------------+

| 412255XXX88 | XX.50.222.38 | 7968 | 2012-04-24 10:50:06 | 2012-04-24 10:45:06 | fring | 2012-04-24 10:48:59 |

+-------------+-----------------+-------+---------------------+---------------------+-----------+---------------------+

In table multiple_ua there were two registrations for this server:

mysql> select * from multiple_ua where username = 412255XXX88;

+-------------+-----------------+-----------------+-------+

+-------------+-----------------+-----------------+-------+

| 412255XXX88 | 213.251.169.218 | XXX.202.201.100 | 5061 |

| 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 18545 |

| 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 7968 |

+-------------+-----------------+-----------------+-------+

The ngrep result is the following with comments in green:

astrad13:~# ngrep host XX.50.222.38 and port 5060 -t

interface: eth0 (91.121.151.0/255.255.255.0)

filter: (ip or ip6) and ( host XX.50.222.38 and port 5060 )

U 2012/04/24 10:49:31.485529 91.121.151.75:5060 -> XX.50.222.38:7968 # Empty packets are being sent to ports 7968 and 18545

. # by the script /etc/astrad/script/ast-send-empty.pl

# # to the ip and port in multiple_ua

U 2012/04/24 10:49:31.487238 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:49:46.745551 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:49:46.746754 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:50:02.082973 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:50:02.084140 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:50:08.963383 XX.50.222.38:18545 -> 91.121.151.75:5060# The phone also sends keep alives. The keep alive is

.................. # sent from the ip and port in location3 from where the

# # the last registration was received

U 2012/04/24 10:50:17.331196 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:50:17.332196 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:50:32.584188 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:50:32.585211 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:50:47.806341 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:50:47.807569 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:51:03.024688 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:51:03.025438 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:51:08.965360 XX.50.222.38:18545 -> 91.121.151.75:5060

..................

U 2012/04/24 10:51:18.252006 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:51:18.253128 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:51:33.497587 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:51:33.498848 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:51:48.740077 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:51:48.741083 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:52:03.975539 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:52:03.976308 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:52:08.987346 XX.50.222.38:18545 -> 91.121.151.75:5060

..................

U 2012/04/24 10:52:19.209273 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:52:19.210036 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:52:34.444519 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:52:34.445538 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:52:49.683155 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:52:49.684182 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:53:04.921470 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:53:04.923404 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:53:08.982649 XX.50.222.38:18545 -> 91.121.151.75:5060

..................

U 2012/04/24 10:53:09.397058 XX.50.222.38:18545 -> 91.121.151.75:5060# Registration arrives from same ip and port

REGISTER sip:sip17.youroute.net SIP/2.0..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bK19101dd4e00619109c1bc2fb618a1bfc;rport..CSeq: 79 REGISTER..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..Contact: <sip:412255XXX88@172.16.13.209:56251;transport=udp>..User-Agent: fring..Expires: 3600..Max-Forwards: 70..Authorization: Digest username="412255XXX88", realm="switzernet", nonce="7544c194", uri="sip:sip17.youroute.net", response="df849471b8cf67f6aff865792762752a", algorithm=MD5..Content-Length: 0....

U 2012/04/24 10:53:09.399314 91.121.151.75:5060 -> XX.50.222.38:18545

SIP/2.0 401 Unauthorized..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bK19101dd4e00619109c1bc2fb618a1bfc;received=XX.50.222.38;rport=18545..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net;tag=as2a5cf13e..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..CSeq: 79 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..WWW-Authenticate: Digest algorithm=MD5, realm="switzernet", nonce="19efef69"..Content-Length: 0....

U 2012/04/24 10:53:10.055277 XX.50.222.38:18545 -> 91.121.151.75:5060

REGISTER sip:sip17.youroute.net SIP/2.0..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bK3e041ed4e00619109c1bc2fb618a1bfc;rport..CSeq: 80 REGISTER..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..Contact: <sip:412255XXX88@172.16.13.209:56251;transport=udp>..User-Agent: fring..Expires: 3600..Max-Forwards: 70..Authorization: Digest username="412255XXX88", realm="switzernet", nonce="19efef69", uri="sip:sip17.youroute.net", response="9d7f83072ba833eb5ea507273306b7c5", algorithm=MD5..Content-Length: 0....

U 2012/04/24 10:53:10.061621 91.121.151.75:5060 -> XX.50.222.38:18545

SIP/2.0 200 OK..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bK3e041ed4e00619109c1bc2fb618a1bfc;received=XX.50.222.38;rport=18545..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net;tag=as2a5cf13e..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..CSeq: 80 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..Expires: 300..Contact: <sip:412255XXX88@172.16.13.209:56251;transport=udp>;expires=300..Date: Tue, 24 Apr 2012 08:53:10 GMT..Content-Length: 0....

U 2012/04/24 10:53:20.163985 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:53:20.164743 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:53:35.399344 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:53:35.400103 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:53:50.646970 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:53:50.647783 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:54:05.676369 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:54:05.677131 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:54:10.465528 XX.50.222.38:18545 -> 91.121.151.75:5060

..................

U 2012/04/24 10:54:20.914633 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:54:20.915875 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:54:36.388464 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:54:36.390691 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:54:51.641078 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:54:51.642598 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:55:06.889173 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:55:06.889931 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:55:10.467871 XX.50.222.38:18545 -> 91.121.151.75:5060

..................

U 2012/04/24 10:55:22.127898 91.121.151.75:5060 -> XX.50.222.38:7968

U 2012/04/24 10:55:22.128653 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:55:37.368693 91.121.151.75:5060 -> XX.50.222.38:7968 # Last packet sent to this IP and port due. It was

. # deleted from DBA multiple_ua.

# # Due to this we stop sending keep alives

U 2012/04/24 10:55:37.369450 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:56:10.486086 XX.50.222.38:18545 -> 91.121.151.75:5060# Telephone sends 2 keep alives from different ports

.................. # and immediately sends a registration from the new

# # port.

U 2012/04/24 10:57:10.494788 XX.50.222.38:31953 -> 91.121.151.75:5060

..................

U 2012/04/24 10:57:11.263822 XX.50.222.38:31953 -> 91.121.151.75:5060

REGISTER sip:sip17.youroute.net SIP/2.0..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bKa4908dd5e00619109c1bc2fb618a1bfc;rport..CSeq: 81 REGISTER..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..Contact: <sip:412255XXX88@172.16.13.209:56251;transport=udp>..User-Agent: fring..Expires: 3600..Max-Forwards: 70..Authorization: Digest username="412255XXX88", realm="switzernet", nonce="19efef69", uri="sip:sip17.youroute.net", response="9d7f83072ba833eb5ea507273306b7c5", algorithm=MD5..Content-Length: 0....

U 2012/04/24 10:57:11.265797 91.121.151.75:5060 -> XX.50.222.38:31953

SIP/2.0 401 Unauthorized..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bKa4908dd5e00619109c1bc2fb618a1bfc;received=XX.50.222.38;rport=31953..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net;tag=as333b419f..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..CSeq: 81 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..WWW-Authenticate: Digest algorithm=MD5, realm="switzernet", nonce="2354c0ba"..Content-Length: 0....

U 2012/04/24 10:57:11.876585 XX.50.222.38:31953 -> 91.121.151.75:5060

REGISTER sip:sip17.youroute.net SIP/2.0..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bK100b8fd5e00619109c1bc2fb618a1bfc;rport..CSeq: 82 REGISTER..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..Contact: <sip:412255XXX88@172.16.13.209:56251;transport=udp>..User-Agent: fring..Expires: 3600..Max-Forwards: 70..Authorization: Digest username="412255XXX88", realm="switzernet", nonce="2354c0ba", uri="sip:sip17.youroute.net", response="8b3607b615831ed66ae7b36575484581", algorithm=MD5..Content-Length: 0....

U 2012/04/24 10:57:11.882710 91.121.151.75:5060 -> XX.50.222.38:31953

SIP/2.0 200 OK..Via: SIP/2.0/UDP 172.16.13.209:56251;iid=1;branch=z9hG4bK100b8fd5e00619109c1bc2fb618a1bfc;received=XX.50.222.38;rport=31953..From: <sip:412255XXX88@sip17.youroute.net>;tag=b2d0ed9be00619109c1bc2fb618a1bfc..To: sip:412255XXX88@sip17.youroute.net;tag=as333b419f..Call-ID: b2d0ed9b-e006-1910-9b44-c2fb618a1bfc..CSeq: 82 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..Expires: 300..Contact: <sip:412255XXX88@172.16.13.209:56251;transport=udp>;expires=300..Date: Tue, 24 Apr 2012 08:57:11 GMT..Content-Length: 0....

U 2012/04/24 10:57:23.854591 91.121.151.75:5060 -> XX.50.222.38:18545 # Packets sent to both old and new port as both

. # locations are now in multiple_ua

U 2012/04/24 10:57:23.855356 91.121.151.75:5060 -> XX.50.222.38:31953

U 2012/04/24 10:57:39.063583 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:57:39.064351 91.121.151.75:5060 -> XX.50.222.38:31953

U 2012/04/24 10:57:54.264265 91.121.151.75:5060 -> XX.50.222.38:18545

U 2012/04/24 10:57:54.265021 91.121.151.75:5060 -> XX.50.222.38:31953

As the telephone has just registered with the new port, it still appears in location3. It will be deleted after at least 5 minutes.

mysql> select *, NOW() from location3 where username in (412255XXX88) order by username;

+-------------+--------------+-------+---------------------+---------------------+-----------+---------------------+

+-------------+--------------+-------+---------------------+---------------------+-----------+---------------------+

| 412255XXX88 | XX.50.222.38 | 31953 | 2012-04-24 11:02:11 | 2012-04-24 10:57:11 | fring | 2012-04-24 11:01:07 |

| 412255XXX88 | XX.50.222.38 | 18545 | 2012-04-24 10:58:10 | 2012-04-24 10:53:10 | fring | 2012-04-24 11:01:07 |

+-------------+--------------+-------+---------------------+---------------------+-----------+---------------------+

In table multiple_ua the new port appears:

mysql> select * from multiple_ua where username = 412255XXX88;

+-------------+-----------------+-----------------+-------+

+-------------+-----------------+-----------------+-------+

| 412255XXX88 | 213.251.169.218 | XXX.202.201.100 | 5061 |

| 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 31953 |

| 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 18545 |

+-------------+-----------------+-----------------+-------+

A table registration2 was created to track the deletions in registration. It shows that the phone keeps changing ports. The Unregister’s are made by the Event that cleans the table.

select * from registration2 where username in (412255XXX88) order by id,username;

+------+-------------+---------------+--------------+-------+---------------------+----------+------------+

+------+-------------+---------------+--------------+-------+---------------------+----------+------------+

| 182 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 9297 | 2012-04-24 10:17:52 | NULL | REGISTER |

| 293 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 10758 | 2012-04-24 10:05:48 | NULL | UNREGISTER |

| 351 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 9790 | 2012-04-24 10:21:54 | NULL | REGISTER |

| 518 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 9790 | 2012-04-24 10:25:56 | NULL | REGISTER |

| 674 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 9790 | 2012-04-24 10:29:58 | NULL | REGISTER |

| 715 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 9297 | 2012-04-24 10:17:52 | NULL | UNREGISTER |

| 842 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 28330 | 2012-04-24 10:33:59 | NULL | REGISTER |

| 1018 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 28330 | 2012-04-24 10:38:02 | NULL | REGISTER |

| 1129 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 9790 | 2012-04-24 10:29:58 | NULL | UNREGISTER |

| 1201 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 7968 | 2012-04-24 10:42:03 | NULL | REGISTER |

| 1353 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 7968 | 2012-04-24 10:46:05 | NULL | REGISTER |

| 1517 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 7968 | 2012-04-24 10:50:06 | NULL | REGISTER |

| 1547 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 28330 | 2012-04-24 10:38:02 | NULL | UNREGISTER |

| 1689 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 18545 | 2012-04-24 10:54:08 | NULL | REGISTER |

| 1857 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 18545 | 2012-04-24 10:58:10 | NULL | REGISTER |

| 1964 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 7968 | 2012-04-24 10:50:06 | NULL | UNREGISTER |

| 2035 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 31953 | 2012-04-24 11:02:11 | NULL | REGISTER |

| 2196 | 412255XXX88 | 91.121.151.75 | XX.50.222.38 | 31953 | 2012-04-24 11:06:13 | NULL | REGISTER |

+------+-------------+---------------+--------------+-------+---------------------+----------+------------+

Even though the telephone sends keep alives, the NAT in the router expires and another port is used. During the time after stopping the keep alive packets until the registration the customer is unable to receive calls.

Debug on 412255XXX73

The ngrep of this account shows that there is a problem with the keep alives sent by the Astrad.

U 2012/04/24 14:00:09.704218 XX.193.244.173:56231 -> 91.121.151.75:5060

REGISTER sip:sip24.youroute.net SIP/2.0..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-97206887..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98179 REGISTER..Max-Forwards: 70..Authorization: Digest username="412255XXX73",realm="switzernet",nonce="287fd258",uri="sip:sip24.youroute.net",algorithm=MD5,response="c0c9fe1375d4687604d4649911fcd0fe"..Contact: 412255XXX73 <sip:412255XXX73@192.168.1.52:5060>;expires=600..User-Agent: Linksys/SPA1001-3.1.19(SE)..Content-Length: 0..Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER..Supported: x-sipura, replaces....

U 2012/04/24 14:00:09.706009 91.121.151.75:5060 -> XX.193.244.173:56231

SIP/2.0 401 Unauthorized..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-97206887;received=XX.193.244.173;rport=56231..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=as5a37a7db..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98179 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..WWW-Authenticate: Digest algorithm=MD5, realm="switzernet", nonce="000a5300"..Content-Length: 0....

U 2012/04/24 14:00:09.764946 XX.193.244.173:56231 -> 91.121.151.75:5060

REGISTER sip:sip24.youroute.net SIP/2.0..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-f0963eb4..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98180 REGISTER..Max-Forwards: 70..Authorization: Digest username="412255XXX73",realm="switzernet",nonce="000a5300",uri="sip:sip24.youroute.net",algorithm=MD5,response="15565996be930a304008964c84a52a86"..Contact: 412255XXX73 <sip:412255XXX73@192.168.1.52:5060>;expires=600..User-Agent: Linksys/SPA1001-3.1.19(SE)..Content-Length: 0..Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER..Supported: x-sipura, replaces....

U 2012/04/24 14:00:09.769483 91.121.151.75:5060 -> XX.193.244.173:56231

SIP/2.0 200 OK..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-f0963eb4;received=XX.193.244.173;rport=56231..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=as5a37a7db..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98180 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..Expires: 300..Contact: <sip:412255XXX73@192.168.1.52:5060>;expires=300..Date: Tue, 24 Apr 2012 12:00:09 GMT..Content-Length: 0....

U 2012/04/24 14:00:20.646576 91.121.151.75:5060 -> XX.193.244.173:56230.

U 2012/04/24 14:00:20.649290 91.121.151.75:5060 -> XX.193.244.173:56231.

U 2012/04/24 14:00:35.928629 91.121.151.75:5060 -> XX.193.244.173:56230. # We are sending the keep alive pacjets to the

# # correct address but also for an expired one

U 2012/04/24 14:00:35.929666 91.121.151.75:5060 -> XX.193.244.173:56231. # Here the expired one is removed and we stop

# # sending packets during 5 minutes until a new

U 2012/04/24 14:05:05.842758 XX.193.244.173:56232 -> 91.121.151.75:5060 # entry is added to multiple_ua

REGISTER sip:sip24.youroute.net SIP/2.0..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-1eba900c..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98181 REGISTER..Max-Forwards: 70..Authorization: Digest username="412255XXX73",realm="switzernet",nonce="000a5300",uri="sip:sip24.youroute.net",algorithm=MD5,response="15565996be930a304008964c84a52a86"..Contact: 412255XXX73 <sip:412255XXX73@192.168.1.52:5060>;expires=600..User-Agent: Linksys/SPA1001-3.1.19(SE)..Content-Length: 0..Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER..Supported: x-sipura, replaces....

U 2012/04/24 14:05:06.335999 XX.193.244.173:56232 -> 91.121.151.75:5060

U 2012/04/24 14:05:06.682563 91.121.151.75:5060 -> XX.193.244.173:56232

SIP/2.0 401 Unauthorized..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-1eba900c;received=XX.193.244.173;rport=56232..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=as2008092e..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98181 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..WWW-Authenticate: Digest algorithm=MD5, realm="switzernet", nonce="55214f44"..Content-Length: 0....

U 2012/04/24 14:05:06.691841 91.121.151.75:5060 -> XX.193.244.173:56232

U 2012/04/24 14:05:06.747403 XX.193.244.173:56232 -> 91.121.151.75:5060

REGISTER sip:sip24.youroute.net SIP/2.0..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-d354d75..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98182 REGISTER..Max-Forwards: 70..Authorization: Digest username="412255XXX73",realm="switzernet",nonce="55214f44",uri="sip:sip24.youroute.net",algorithm=MD5,response="bf6bce7981c7402b3c7b12d3898ad696"..Contact: 412255XXX73 <sip:412255XXX73@192.168.1.52:5060>;expires=600..User-Agent: Linksys/SPA1001-3.1.19(SE)..Content-Length: 0..Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER..Supported: x-sipura, replaces....

U 2012/04/24 14:05:06.752597 91.121.151.75:5060 -> XX.193.244.173:56232

SIP/2.0 200 OK..Via: SIP/2.0/UDP 192.168.1.52:5060;branch=z9hG4bK-d354d75;received=XX.193.244.173;rport=56232..From: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=dbc8335e32a4675co0..To: 412255XXX73 <sip:412255XXX73@sip24.youroute.net>;tag=as2008092e..Call-ID: 56f9ef30-63e88d2f@192.168.1.52..CSeq: 98182 REGISTER..Server: Astrad013..Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH..Supported: replaces, timer..Expires: 300..Contact: <sip:412255XXX73@192.168.1.52:5060>;expires=300..Date: Tue, 24 Apr 2012 12:05:06 GMT..Content-Length: 0....

U 2012/04/24 14:05:09.580816 91.121.151.75:5060 -> XX.193.244.173:56231. # After the new registration with new port we

# # restart resending keep alive packets. One for

U 2012/04/24 14:05:09.581827 91.121.151.75:5060 -> XX.193.244.173:56232. # the new port and another for the previous port

# # This situation keeps repeating

U 2012/04/24 14:05:24.817418 91.121.151.75:5060 -> XX.193.244.173:56231.

U 2012/04/24 14:05:24.818173 91.121.151.75:5060 -> XX.193.244.173:56232

This case shows a real problem. Astrad stopped sending packets (empty or Notifys) during 5 minutes and allowed the connexion to close. During this period the customer would be unable to receive calls.

Comparison with Astrad v11

By registering two phones in an Astrad v11 and then disconnecting one of them, we were able to replicate the scenario. However in the previous version, when there is only one phone in the table multiple_ua, the script that send Notifys starts send packets when the script that sends empty packets stops. The ngrep results are the following:

U 2012/04/26 10:23:28.040654 91.121.142.9:5060 -> 178.198.161.8:60309

U 2012/04/26 10:23:43.058961 91.121.142.9:5060 -> 178.198.161.8:1026

U 2012/04/26 10:23:43.060051 91.121.142.9:5060 -> 178.198.161.8:60309 # This entry expires and is removed from multiple_ua

U 2012/04/26 10:24:20.659757 91.121.142.9:5060 -> 178.198.161.8:1026 # The Notify script starts sending packets to active IP

NOTIFY sip:41215502419@178.198.161.8:1026 SIP/2.0..Via: SIP/2.0/UDP 91.121.142.9:5060;branch=z9hG4bK22e12869;rport..From: "asterisk" <sip:asterisk@91.121.142.9>;tag=as2a7611c4..To: <sip:41215502419@178.198.161.8:1026>..Contact: <sip:asterisk@91.121.142.9>..Call-ID: 64b99cfe6e93ee2765a55c966e11a9bb@91.121.142.9..CSeq: 102 NOTIFY..User-Agent: Asterisk PBX..Max-Forwards: 70..Event: keep-alive..Content-Length: 0....

U 2012/04/26 10:24:20.734148 178.198.161.8:1026 -> 91.121.142.9:5060

SIP/2.0 200 OK..To: <sip:41215502419@178.198.161.8:1026>;tag=3d515a7243d4c69i0..From: "asterisk" <sip:asterisk@91.121.142.9>;tag=as2a7611c4..Call-ID: 64b99cfe6e93ee2765a55c966e11a9bb@91.121.142.9..CSeq: 102 NOTIFY..Via: SIP/2.0/UDP 91.121.142.9:5060;branch=z9hG4bK22e12869..Server: Linksys/SPA921-5.1.8..Content-Length: 0....

U 2012/04/26 10:24:50.887220 91.121.142.9:5060 -> 178.198.161.8:1026

NOTIFY sip:41215502419@178.198.161.8:1026 SIP/2.0..Via: SIP/2.0/UDP 91.121.142.9:5060;branch=z9hG4bK355fb1ed;rport..From: "asterisk" <sip:asterisk@91.121.142.9>;tag=as5a3351c7..To: <sip:41215502419@178.198.161.8:1026>..Contact: <sip:asterisk@91.121.142.9>..Call-ID: 7a1274a85c927e3f0fab1718068461bc@91.121.142.9..CSeq: 102 NOTIFY..User-Agent: Asterisk PBX..Max-Forwards: 70..Event: keep-alive..Content-Length: 0....

U 2012/04/26 10:24:50.954021 178.198.161.8:1026 -> 91.121.142.9:5060

SIP/2.0 200 OK..To: <sip:41215502419@178.198.161.8:1026>;tag=3d515a7243d4c69i0..From: "asterisk" <sip:asterisk@91.121.142.9>;tag=as5a3351c7..Call-ID: 7a1274a85c927e3f0fab1718068461bc@91.121.142.9..CSeq: 102 NOTIFY..Via: SIP/2.0/UDP 91.121.142.9:5060;branch=z9hG4bK355fb1ed..Server: Linksys/SPA921-5.1.8..Content-Length: 0....

The scripts in both versions are ok. The problem is that the new version does not sends Notifys at all.

The result of the AMI command is:

Action: COMMAND

Command: sip notify nat XXXXXXXXX

Response: Follows

Privilege: Command

Unable to find notify type 'nat'

Command 'sip notify nat XXXXXXXXX’ failed.

Looking into asterisk’s configuration file we can find the notify ‘nat’ but it is not loaded into asterisk. This requires a reload of the chan_sip module. A sip reload is not enough. This means that puppet has to be changed to restart asterisk.

Correction

Asterisk was restarted and afterwards the situation began to stabilize. The puppet script was changed to restart asterisk when the file /etc/asterisk/sip_notify.conf is changed.

With the notifys arriving correctly, the customer’s NAT table entry doesn’t expire and so the port from where the registrations are received is the same. In the image bellow we see that after reloading the file the amount of registered accounts drops (the graph don’t filter out expired accounts) and keeps the same level afterwards.

Conclusion

The problem in both cases is caused by a problem in sending keep alives. The script that should send Notifys was not working due to one of asterisk’s configuration files not being loaded. Due to this some customers would have the registration port changing due to expired NAT. When a new registration from that phone arrived to the server it would be interpreted as a multiple registration and both registrations would be moved to multiple_ua. When the expired registration was deleted from multiple_ua, the script stopped sending packets and the router would close the port again.

This is a serious problem as it prevents customers from receiving calls until the next registration. The problem was however minimized by the expiration timeout. While the expired account is not removed, Astrad keeps sending keep alives and the router port doesn’t change.

The correction is just to change the Puppet module to restart asterisk instead of reloading. In the previous asterisk version a “sip reload” would load sip_notify.conf. Now, to the file to be loaded, it is needed to restart asterisk or load and unload the chan_sip module.

Sugestion

We should have a script that would be executed on DBA to Detect on location_history frequent port changes. This would enable us to detect this kind of problems. We currently send NOTIFY packets to every phone registered in the Astrad and then sleep for 30 seconds. This means that the interval is superior to 30 seconds between keep alives. Empty packets are sent each 15 seconds for multiple_uas.

Resources

Astrad v10

http://switzernet.com/3/public/111129-astrad-V10/

Astrad v12

http://www.switzernet.com/3/public/120106-astrad-V12/

Astrad versions

http://switzernet.com/3/public/110126-astrad-versions/