Asterisk briefly hangs

Distro Discussion & Help
1

I’ve got a PBX with the oft-reported symptom of Aastra phones going to “No Service”. The issue seems to be a result of asterisk randomly being slow to respond to REGISTER requests from phones.

A Wireshark capture compared to the asterisk sip debug proved the following:
SIP packets come and go at times fairly normally but suddenly, and for no apparent reason, the packets that are received on the ethernet interface don’t show up in asterisk for 10 to 20 seconds. In the meantime requests continue to come in from various phones and the SIP trunk but they seem to get “Queued” before asterisk deals with them. When asterisk does wake up it receives all the “Queued” requests and deals with them immediately - all within 1 second.

Apache seems to have similar problems because the web interface sometimes “locks up” for 20 seconds or so and it is common to see the “Timeout” warning for Webserver in FreePBX system status.

This is a 3.211.63-8 distro running on an AMD Athlon™ II X2 240 Processor, 2 cores.

CPU, HDD, and memory usage are low.

What do you think? Bad hardware?

2

What firmware are you running on the Aastras? I had random ‘no service’ messages on Aastra phones years ago that I tracked down to a slow responding NTP server.

3

I would also check DNS. Remember chan_sip is a blocking request so if its busy trying to resolve a FQDN all other SIP request get queued up until DNSMGR is done.

In /etc/resolv do you have 127.0.0.1 as the first DNS server. Make sure you have that set.

4

Aastra firmware is 3.2.2.2063, but that’s not the issue. The phones are responding just fine - it’s asterisk where the problem develops.

127.0.0.1 & 8.8.8.8 were the DNS servers, I changed to the two OpenDNS servers but it didn’t affect the issue at all.

5

Also, the only reference to an external hostname I have in asterisk is the SIP trunk configuration: fromdomain=edm.trk.tprm.ca. The rest are static IP’s.

6

Here is the full SIP debug from one such instance. Asterisk takes 17 seconds to respond to the REGISTER:

[code] [2013-05-10 14:36:45] VERBOSE[2035] chan_sip.c: — (12 headers 0 lines) —
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c:
<— SIP read from UDP:192.168.99.129:5060 —>
REGISTER sip:192.168.99.250:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.99.129;branch=z9hG4bK6e77d34e8671b42a4
Max-Forwards: 70
From: “Mike Balfour” sip:[email protected]:5060;tag=8b1e8d706b
To: “Mike Balfour” sip:[email protected]:5060
Call-ID: 4adfb6eb7fb364bd
CSeq: 13793 REGISTER
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
Allow-Events: aastra-xml, talk, hold, conference, LocalModeStatus
Authorization: Digest username=“226”,realm=“asterisk”,nonce=“3ab7bdce”,uri=“sip:192.168.99.250:5060”,response=“a4bb2d375c028c6fcc749626670ab79f”,algorithm=MD5
Contact: “Mike Balfour” sip:[email protected]:5060;transport=udp
Supported: path
User-Agent: Aastra 9480i/3.2.2.2063
Content-Length: 0

<------------->
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c: — (14 headers 0 lines) —
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c: Sending to 192.168.99.129:5060 (NAT)
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c:
<— Transmitting (no NAT) to 192.168.99.129:5060 —>
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 192.168.99.129;branch=z9hG4bK6e77d34e8671b42a4;received=192.168.99.129
From: “Mike Balfour” sip:[email protected]:5060;tag=8b1e8d706b
To: “Mike Balfour” sip:[email protected]:5060;tag=as113fce95
Call-ID: 4adfb6eb7fb364bd
CSeq: 13793 REGISTER
Server: FPBX2.11.0rc1(1.8.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
WWW-Authenticate: Digest algorithm=MD5, realm=“asterisk”, nonce="1d5bb833"
Content-Length: 0

<------------>
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c: Scheduling destruction of SIP dialog ‘4adfb6eb7fb364bd’ in 32000 ms (Method: REGISTER)
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c:
<— SIP read from UDP:192.168.99.129:5060 —>
REGISTER sip:192.168.99.250:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.99.129;branch=z9hG4bK5ab922edbf0f0af23
Max-Forwards: 70
From: “Mike Balfour” sip:[email protected]:5060;tag=8b1e8d706b
To: “Mike Balfour” sip:[email protected]:5060
Call-ID: 4adfb6eb7fb364bd
CSeq: 13794 REGISTER
Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO
Allow-Events: aastra-xml, talk, hold, conference, LocalModeStatus
Authorization: Digest username=“226”,realm=“asterisk”,nonce=“1d5bb833”,uri=“sip:192.168.99.250:5060”,response=“bb1341bfa085e8933f1df7b58a7c97c6”,algorithm=MD5
Contact: “Mike Balfour” sip:[email protected]:5060;transport=udp
Supported: path
User-Agent: Aastra 9480i/3.2.2.2063
Content-Length: 0

<------------->
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c: — (14 headers 0 lines) —
[2013-05-10 14:36:50] VERBOSE[2035] chan_sip.c: Sending to 192.168.99.129:5060 (no NAT)
[2013-05-10 14:37:07] VERBOSE[2035] chan_sip.c: Reliably Transmitting (no NAT) to 192.168.99.129:5060:
OPTIONS sip:[email protected]:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 192.168.99.250:5060;branch=z9hG4bK0eadd59d
Max-Forwards: 70
From: “Unknown” sip:[email protected];tag=as0c355674
To: sip:[email protected]:5060;transport=udp
Contact: sip:[email protected]:5060
Call-ID: [email protected]:5060
CSeq: 102 OPTIONS
User-Agent: FPBX2.11.0rc1(1.8.21.0)
Date: Fri, 10 May 2013 20:37:07 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Content-Length: 0

[2013-05-10 14:37:07] VERBOSE[2035] chan_sip.c:
<— Transmitting (no NAT) to 192.168.99.129:5060 —>
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.99.129;branch=z9hG4bK5ab922edbf0f0af23;received=192.168.99.129
From: “Mike Balfour” sip:[email protected]:5060;tag=8b1e8d706b
To: “Mike Balfour” sip:[email protected]:5060;tag=as113fce95
Call-ID: 4adfb6eb7fb364bd
CSeq: 13794 REGISTER
Server: FPBX2.11.0rc1(1.8.21.0)
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
Supported: replaces, timer
Expires: 120
Contact: sip:[email protected]:5060;transport=udp;expires=120
Date: Fri, 10 May 2013 20:37:07 GMT
Content-Length: 0 [/code]

7

And the wireshark trace from the same time period:

No. Time Source Destination Protocol Length Info 1 0.000000 192.168.99.129 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 2 0.496298 192.168.99.129 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 3 0.541291 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 4 1.495758 192.168.99.129 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 5 2.541342 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 6 3.495681 192.168.99.129 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 7 4.541262 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 8 4.963308 GoodWayI_05:c9:f8 Aastra_1a:b2:48 ARP 42 Who has 192.168.99.129? Tell 192.168.99.250 9 4.963941 Aastra_1a:b2:48 GoodWayI_05:c9:f8 ARP 60 192.168.99.129 is at 00:08:5d:1a:b2:48 10 6.057517 192.168.99.126 192.168.99.250 SIP 782 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 11 6.110137 192.168.99.130 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 12 6.541197 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 13 6.549562 192.168.99.126 192.168.99.250 SIP 782 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 14 6.602430 192.168.99.130 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 15 7.549659 192.168.99.126 192.168.99.250 SIP 782 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 16 7.602523 192.168.99.130 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 17 8.541118 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 18 9.549701 192.168.99.126 192.168.99.250 SIP 782 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 19 9.602699 192.168.99.130 192.168.99.250 SIP 794 Request: REGISTER sip:192.168.99.250:5060 (fetch bindings) | 20 10.419322 Cisco_10:ca:70 LLDP_Multicast LLDP 64 Chassis Id = 68:bd:ab:10:ca:3f Port Id = g1 TTL = 120 21 10.541165 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 22 12.541097 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 23 14.541017 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 24 16.540708 192.168.99.250 192.168.99.129 SIP 622 Request: OPTIONS sip:[email protected]:5060;transport=udp | 25 16.540779 192.168.99.250 192.168.99.129 SIP 610 Status: 200 OK (0 bindings) | 26 16.540897 192.168.99.250 192.168.99.129 SIP 636 Request: NOTIFY sip:[email protected]:5060;transport=udp | 27 16.540921 Cisco_10:ca:70 Spanning-tree-(for-bridges)_00 STP 64 RST. Root = 32768/0/68:bd:ab:10:ca:3f Cost = 0 Port = 0x8031 28 16.541008 192.168.99.250 208.68.17.52 SIP 570 Request: OPTIONS sip:208.68.17.52 | 29 16.541201 192.168.99.250 192.168.99.129 SIP 591 Status: 401 Unauthorized (0 bindings) | 30 16.541335 192.168.99.250 192.168.99.129 SIP 591 Status: 401 Unauthorized (0 bindings) | 31 16.541469 192.168.99.250 192.168.99.129 SIP 591 Status: 401 Unauthorized (0 bindings) | 32 16.541587 192.168.99.250 192.168.99.126 SIP 571 Status: 401 Unauthorized (0 bindings) | 33 16.541703 192.168.99.250 192.168.99.130 SIP 579 Status: 401 Unauthorized (0 bindings) | 34 16.541832 192.168.99.250 192.168.99.126 SIP 583 Status: 401 Unauthorized (0 bindings) | 35 16.541961 192.168.99.250 192.168.99.130 SIP 591 Status: 401 Unauthorized (0 bindings) | 36 16.542088 192.168.99.250 192.168.99.126 SIP 583 Status: 401 Unauthorized (0 bindings) | 37 16.542215 192.168.99.250 192.168.99.130 SIP 591 Status: 401 Unauthorized (0 bindings) | 38 16.542343 192.168.99.250 192.168.99.126 SIP 583 Status: 401 Unauthorized (0 bindings) | 39 16.542476 192.168.99.250 192.168.99.130 SIP 591 Status: 401 Unauthorized (0 bindings) |

8

Well, I took a backup and replaced the server. The issue appears to have been resolved.