[Home]

Summary:ASTERISK-25793: chan_sip: Incoming SIP packets ignored
Reporter:Paul Sandys (paf)Labels:
Date Opened:2016-02-14 21:05:51.000-0600Date Closed:2016-02-16 05:27:25.000-0600
Priority:CriticalRegression?
Status:Closed/CompleteComponents:Channels/chan_sip/General
Versions:1.8.23.1 13.7.2 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Tried on both CentOS 5, FreeBSD 10.2. 1900 SIP peers. FreeBSD behaves slightly worse.Attachments:
Description:under load, the server starts ignoring incoming SIP packets. Here's a sample tcpdump and debug of a single peer:

sample tcpdump after 'sip reload':

21:48:23.388137 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 619
21:48:23.438331 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 344
21:48:26.875782 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 619
21:48:26.894757 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 344
21:48:27.230656 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 563
21:48:27.317277 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 341
21:48:27.428144 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 619
21:48:27.473680 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 344
21:48:28.229868 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 563
21:48:28.238773 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 341
21:48:28.875076 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 619
21:48:28.892387 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 344
21:48:32.875728 IP 216.139.145.228.5060 > 10.9.0.8.5062: SIP, length: 619
21:48:32.884182 IP 10.9.0.8.5062 > 216.139.145.228.5060: SIP, length: 344

All the SIP packets get replies from the 10.9.0.8 SIP peer.

However, asterisk sends upto 5 retries before it actually notices an incoming SIP packet back from 10.9.0.8:

[Feb 14 21:48:23] VERBOSE[100143] chan_sip.c: Reliably Transmitting (NAT) to 10.9.0.8:5062:
NOTIFY sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK3712732d;rport
Max-Forwards: 70
Route: <sip:uniti-203@10.9.0.8:5062>
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as71b74687
To: <sip:uniti-203@10.9.0.8:5062>;tag=1945212930
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 93048308@10.9.0.8
CSeq: 110 NOTIFY
User-Agent: USA-Connect SIP
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 95

Messages-Waiting: no
Message-Account: sip:asterisk@216.139.145.228
Voice-Message: 0/0 (0/0)

[Feb 14 21:48:26] VERBOSE[100143] chan_sip.c: Retransmitting #1 (NAT) to 10.9.0.8:5062:
NOTIFY sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK3712732d;rport
Max-Forwards: 70
Route: <sip:uniti-203@10.9.0.8:5062>
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as71b74687
To: <sip:uniti-203@10.9.0.8:5062>;tag=1945212930
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 93048308@10.9.0.8
CSeq: 110 NOTIFY
User-Agent: USA-Connect SIP
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 95

Messages-Waiting: no
Message-Account: sip:asterisk@216.139.145.228
Voice-Message: 0/0 (0/0)

---
[Feb 14 21:48:27] VERBOSE[100143] chan_sip.c: Reliably Transmitting (NAT) to 10.9.0.8:5062:
OPTIONS sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK36492eae;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as12d9c8a7
To: <sip:uniti-203@10.9.0.8:5062>
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 30aa358b55e4cd031dad502075c8d2e0@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: USA-Connect SIP
Date: Mon, 15 Feb 2016 02:48:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
NOTIFY sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK3712732d;rport
Max-Forwards: 70
Route: <sip:uniti-203@10.9.0.8:5062>
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as71b74687
To: <sip:uniti-203@10.9.0.8:5062>;tag=1945212930
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 93048308@10.9.0.8
CSeq: 110 NOTIFY
User-Agent: USA-Connect SIP
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 95

Messages-Waiting: no
Message-Account: sip:asterisk@216.139.145.228
Voice-Message: 0/0 (0/0)

---
[Feb 14 21:48:28] VERBOSE[100143] chan_sip.c: Retransmitting #1 (NAT) to 10.9.0.8:5062:
OPTIONS sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK36492eae;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as12d9c8a7
To: <sip:uniti-203@10.9.0.8:5062>
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 30aa358b55e4cd031dad502075c8d2e0@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: USA-Connect SIP
Date: Mon, 15 Feb 2016 02:48:27 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Feb 14 21:48:28] VERBOSE[100143] chan_sip.c:
<--- SIP read from UDP:10.9.0.8:5062 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK36492eae;rport
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as12d9c8a7
To: <sip:uniti-203@10.9.0.8:5062>;tag=3502137553
Call-ID: 30aa358b55e4cd031dad502075c8d2e0@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.0.40
Content-Length: 0

<------------->
[Feb 14 21:48:28] VERBOSE[100143] chan_sip.c: Retransmitting #3 (NAT) to 10.9.0.8:5062:
NOTIFY sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK3712732d;rport
Max-Forwards: 70
Route: <sip:uniti-203@10.9.0.8:5062>
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as71b74687
To: <sip:uniti-203@10.9.0.8:5062>;tag=1945212930
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 93048308@10.9.0.8
CSeq: 110 NOTIFY
User-Agent: USA-Connect SIP
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 95

Messages-Waiting: no
Message-Account: sip:asterisk@216.139.145.228
Voice-Message: 0/0 (0/0)

---
[Feb 14 21:48:32] VERBOSE[100143] chan_sip.c: Retransmitting #4 (NAT) to 10.9.0.8:5062:
NOTIFY sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK3712732d;rport
Max-Forwards: 70
Route: <sip:uniti-203@10.9.0.8:5062>
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as71b74687
To: <sip:uniti-203@10.9.0.8:5062>;tag=1945212930
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 93048308@10.9.0.8
CSeq: 110 NOTIFY
User-Agent: USA-Connect SIP
Event: message-summary
Content-Type: application/simple-message-summary
Subscription-State: active
Content-Length: 95

Messages-Waiting: no
Message-Account: sip:asterisk@216.139.145.228
Voice-Message: 0/0 (0/0)

---
[Feb 14 21:48:32] VERBOSE[100143] chan_sip.c:
<--- SIP read from UDP:10.9.0.8:5062 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK3712732d;rport
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as71b74687
To: <sip:uniti-203@10.9.0.8:5062>;tag=1945212930
Call-ID: 93048308@10.9.0.8
CSeq: 110 NOTIFY
Contact: <sip:uniti-203@10.9.0.8:5062>
User-Agent: Yealink SIP-W52P 25.73.0.40
Content-Length: 0

<------------->
[Feb 14 21:49:28] VERBOSE[100143] chan_sip.c: Reliably Transmitting (NAT) to 10.9.0.8:5062:
OPTIONS sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK6d13e65f;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as6e365fbd
To: <sip:uniti-203@10.9.0.8:5062>
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 4963151c7b4fdfe36e51774f3ab1a8fc@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: USA-Connect SIP
Date: Mon, 15 Feb 2016 02:49:28 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Feb 14 21:49:28] VERBOSE[100143] chan_sip.c:
<--- SIP read from UDP:10.9.0.8:5062 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK6d13e65f;rport
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as6e365fbd
To: <sip:uniti-203@10.9.0.8:5062>;tag=1225053376
Call-ID: 4963151c7b4fdfe36e51774f3ab1a8fc@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.0.40
Content-Length: 0

<------------->
BOSE[100143] chan_sip.c: Reliably Transmitting (NAT) to 10.9.0.8:5062:
OPTIONS sip:uniti-203@10.9.0.8:5062 SIP/2.0
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK2c2eb044;rport
Max-Forwards: 70
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as56b2ef15
To: <sip:uniti-203@10.9.0.8:5062>
Contact: <sip:Unknown@216.139.145.228:5060>
Call-ID: 43e5334f5b4ecfb266b8fa4968b66bd3@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: USA-Connect SIP
Date: Mon, 15 Feb 2016 02:50:28 GMT
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


---
[Feb 14 21:50:28] VERBOSE[100143] chan_sip.c:
<--- SIP read from UDP:10.9.0.8:5062 --->
SIP/2.0 200 OK
Via: SIP/2.0/UDP 216.139.145.228:5060;branch=z9hG4bK2c2eb044;rport
From: "Unknown" <sip:Unknown@216.139.145.228>;tag=as56b2ef15
To: <sip:uniti-203@10.9.0.8:5062>;tag=2003778940
Call-ID: 43e5334f5b4ecfb266b8fa4968b66bd3@216.139.145.228:5060
CSeq: 102 OPTIONS
User-Agent: Yealink SIP-W52P 25.73.0.40
Content-Length: 0

<------------->

Comments:By: Asterisk Team (asteriskteam) 2016-02-14 21:05:53.735-0600

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: Paul Sandys (paf) 2016-02-15 09:46:03.418-0600

It seems it's related to the chan_sip thread unable to process the UDP packets quick enough and they start dropping out of the system UDP buffers.

LInux UDP packet receive errors counter increases dramatically under load.

Before 'sip reload':

#netstat -s -u
Udp:
   90610147 packets received
   560701 packets to unknown port received.
   376701 packet receive errors
   82532640 packets sent

After 'sip reload':
Udp:
   90673068 packets received
   560705 packets to unknown port received.
   387273 packet receive errors
   82605540 packets sent


By: Joshua C. Colp (jcolp) 2016-02-15 10:50:42.197-0600

chan_sip only has a single thread handling all inbound UDP traffic, as a result if this gets bogged down then traffic will be delayed or potentially lost. This is a design limitation of chan_sip itself and is not easily fixable. The new chan_pjsip in 13 and above does not use the same threading model and does not suffer from the same problem.
By: Paul Sandys (paf) 2016-02-15 20:41:13.981-0600

I've found a reasonable workaround - increase the default socket buffer size using sysctl.

net.core.rmem_default = 16777216
net.core.rmem_max = 26214400
net.core.netdev_max_backlog = 250000

After this change, no more UDP "packet receive errors"

By: Asterisk Team (asteriskteam) 2016-02-15 20:41:14.877-0600

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.