ASTERISK-19579: ERROR we couldn't allocate a port for RTP instance while DAHDI bridgeing

[Home]

Summary: ASTERISK-19579: ERROR we couldn't allocate a port for RTP instance while DAHDI bridgeing

Reporter: Maciej Krajewski (jamicque) Labels:

Date Opened: 2012-03-23 05:25:26 Date Closed: 2012-04-26 08:25:19

Priority: Major Regression? Yes

Status: Closed/Complete Components: Core/Channels

Versions: 1.8.9.2 Frequency of
Occurrence Constant

Related
Issues:
is related to ASTERISK-19192 ERROR we couldn't allocate a port for RTP instance

Environment: Attachments: ( 0) 19.04.tar.gz
( 1) 24.04.tar.gz
( 2) asterisk.log.gz
( 3) chan_dahdi.conf
( 4) fd_leak.diff
( 5) sip.conf

Description: this issue is related to ASTERISK-19192.
The problem still exists in 1.8.9.2 when the call is bridged between DAHDI and SIP.
Call scenario seems to be the same as Mark described in https://issues.asterisk.org/jira/browse/ASTERISK-19192?focusedCommentId=187830&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-187830

Today two of asterisk's blew up - I had many logs saying
{code}
03-23 07:00:40] ERROR[10571] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:00:40] WARNING[10571] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:00:42] ERROR[10571] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:00:42] WARNING[10571] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:28:03] ERROR[11305] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:28:03] WARNING[11305] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:28:05] ERROR[11305] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:28:05] WARNING[11305] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:28:07] ERROR[11305] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0xb40add88'
[2012-03-23 07:28:07] WARNING[11305] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:28:09] ERROR[11305] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0xb40add88'
[2012-03-23 07:28:09] WARNING[11305] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:37:15] ERROR[11543] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:37:15] WARNING[11543] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:37:17] ERROR[11543] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:37:17] WARNING[11543] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:37:19] ERROR[11543] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:37:19] WARNING[11543] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:37:21] ERROR[11543] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:37:21] WARNING[11543] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:45:51] ERROR[11764] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0x138e7898'
[2012-03-23 07:45:51] WARNING[11764] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
[2012-03-23 07:45:53] ERROR[11764] res_rtp_asterisk.c: Oh dear... we couldn't allocate a port for RTP instance '0xb4e9b4a8'
[2012-03-23 07:45:53] WARNING[11764] app_dial.c: Unable to create channel of type 'SIP' (cause 20 - Unknown)
{code}

Unfortunately I can not attach the full debug log (I had only messages level), now I've turned the full log. Hope that maybe what I've attached is sufficient.
The problem did not occur on 1.4 branch.

Now when I see the ports are still not freed (the are still growing up) - here are some other logs

{code}
asterisk -rx "sip show channels"
Peer User/ANR Call ID Format Hold Last Message Expiry Peer
10.10.10.2 XXXXXXXXXXXXXX 73d4dbfb521da86 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 65c3fc3b723395a 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 37509edf54d5c4b 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 6922da1137cd978 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 40cf4bb10d893a0 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 795b7fe36869fa8 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 70ac9e4b2d3e1b4 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 51dc00c5782a465 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 1e9a435c0f36f68 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 1e82cbe96901c4c 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 072c02a27ecc05d 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 6f74d8c307f05cb 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 2d362b747751255 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 4b892e717b3c25b 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 3f173fab2f2e875 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 68b6e45d2ee1473 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 448f023b24081ce 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 2e67b0253d0535e 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 1d9f4c736628056 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 390e7dff4d515c6 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 1b47f0ee2090533 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 158820c2766a809 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 0cb258292883936 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 5aae232850fae59 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 1c2c64534c51ea9 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 409d4f9517ddfe4 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 4a59d93f72af9fb 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 782f01d72dc9f66 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 56994064582ec21 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 5255133377e0d10 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 5db903a20e8205c 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 53e1f4fd0dc3d46 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.2 XXXXXXXXXXXXXX 50def44b18dc4cf 0x8 (alaw) No Rx: ACK <none> sip2
10.10.10.1 XXXXXXXXXXXXXX 22c924cb2d53faa 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 2120337931d2fc2 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.1 XXXXXXXXXXXXXX 5a991b637038aad 0x8 (alaw) No Rx: ACK <none> sip1
10.10.10.2 XXXXXXXXXXXXXX 510e346e7866c89 0x8 (alaw) No Rx: ACK <none> sip2
37 active SIP dialogs
{code}

{code}
netstat -lup | grep 10
udp 0 0 *:10368 *:* 31362/asterisk
udp 0 0 *:10624 *:* 31362/asterisk
udp 0 0 *:11008 *:* 31362/asterisk
udp 0 0 *:10112 *:* 31362/asterisk
udp 0 0 *:10369 *:* 31362/asterisk
udp 0 0 *:10625 *:* 31362/asterisk
udp 308 0 *:11009 *:* 31362/asterisk
udp 0 0 *:10113 *:* 31362/asterisk
udp 0 0 *:10626 *:* 31362/asterisk
udp 0 0 *:10114 *:* 31362/asterisk
udp 0 0 *:17410 *:* 31362/asterisk
udp 0 0 *:10882 *:* 31362/asterisk
udp 0 0 *:11010 *:* 31362/asterisk
udp 0 0 *:10498 *:* 31362/asterisk
udp 0 0 *:10627 *:* 31362/asterisk
udp 0 0 *:10115 *:* 31362/asterisk
udp 308 0 *:10883 *:* 31362/asterisk
udp 308 0 *:11011 *:* 31362/asterisk
udp 308 0 *:10499 *:* 31362/asterisk
udp 0 0 *:10628 *:* 31362/asterisk
............
......... and so on
{code}

{code}
netstat -lup | grep 10 | grep asterisk | wc -l
730
{code}

The scenario of a call is that all incoming (only) are coming through DAHDI to SIP. The sip channel is multiply transferred using the semi-attended transfer by the other side (REFFER).

Comments: By: Matt Jordan (mjordan) 2012-03-23 15:09:33.438-0500

I think we are going to need more information.

We require a complete debug log to help triage the issue. This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information

In addition, please attach a SIP trace (either a pcap or have sip set debug on in the DEBUG log), along with your chan_dahdi.conf and sip.conf configurations.

By: Maciej Krajewski (jamicque) 2012-03-23 17:20:07.079-0500

I have set the debug on full + sip debug after this situation now I'm watiting for this to happen once agin- the connection are still raising, when this will happen again I'll attach the logs.
By: Maciej Krajewski (jamicque) 2012-03-23 17:24:27.398-0500

here are the requested config files.
Should the debug file be of the occred error situation or could it be the debug from sample connection?
By: Richard Mudgett (rmudgett) 2012-03-23 17:54:03.948-0500

FYI Don't forget to send the issue back when you are done providing feedback. Otherwise, the issue may languish because the issue looks like you have not responded to the question.

By: Maciej Krajewski (jamicque) 2012-03-30 06:28:27.572-0500

I've attached the logs on full debug with sip from the hole day.
From the logs you can see that there are many RTCP connecions.
The channels weren't hanging.
There are 4xe1 connected to the asterisk I had to restart the asterisk becouse there were in down state (the connected device) siad that.
before the restart I've checked the number of opened ports....

netstat -lup | grep asterisk | wc -l
9951

By: Kinsey Moore (kmoore) 2012-04-13 09:27:21.932-0500

Looking at your log file, there are no instances of the error you describe above. I only see the following problem:

[Jan 18 11:03:57] WARNING[13223] channel.c: Channel allocation failed: Can't create alert pipe! Try increasing max file descriptors with ulimit -n
[Jan 18 11:03:57] WARNING[13223] chan_sip.c: Unable to allocate AST channel structure for SIP channel

Please increase ulimit and capture the log again.
By: Maciej Krajewski (jamicque) 2012-04-14 05:13:41.635-0500

Hi, as i have written in my last comment I had to restart asterisk, due to the fact that PRI interfaces where hanging and no new connections where accepted.
The ulimit was set to "ulimit -n 32000 -c unlimited"

The error from the console "Oh dear... we couldn't allocate.." wasn't reproduced. However, netstat exactly has shown that the ports aren't freed.
Over 9000 ports used by asterisk where there are no connections?

As I have written before I've done some reserach and these ports are rtcp sessions (but no rtp). It is a very similar SIP scenario like in ASTERISK-19192 (some SIP transfers) but this time the originating side is DAHDI not SIP. If I do the same connection (originationg side) using SIP not PRI channels the ports are freed.
Now I have to restart asterisk via cron every night due to the fact that number of used ports by asterisk is still rising.

By: Kinsey Moore (kmoore) 2012-04-17 12:13:56.034-0500

I have been digging through the log file you provided in search of clues as to how this happens. Most of what I see is DAHDI->queue->SIP where the SIP phone transfers the call to a DAHDI trunk. The difference I've seen for some of these is that sometimes the transferring phone will end the call with a BYE and sometimes the call will time out. This may be the cause of the issue, but I can not yet be certain.

Is the netstat output above associated with the logfile provided or are these unrelated? If they are unrelated, I would appreciate netstat output with a matching logfile so I can see which calls are leaking the ports.
By: Maciej Krajewski (jamicque) 2012-04-17 14:16:30

Hi the netstat is associated with the attached log.
As I've written before the problem is occuring 100% pecent. I'm reseting the asterisk every night becouse the open ports are rising (about 1000 per day).
I've tried to reproduce this error in my "test bench" hovewer I didn't used DAHDI as leg A but SIP and I did not reproduced it.
The described situation with not freeing ports occurs in 4 different asterisk instances.
By: Kinsey Moore (kmoore) 2012-04-19 08:48:28.964-0500

Hello Maciej,
Could you provide a more recent log with associated "sip show channels" indicating which calls/ports are stuck when the log file is saved? The "sip show channels" above is not correlated with the log file as far as I can tell since I can find none of the call IDs and none of the addresses in the log file are 10.10.10.x addresses.
By: Maciej Krajewski (jamicque) 2012-04-19 08:59:40.066-0500

Hi Kinsey,
Here are the logs from today 10.04.tar.gz (sip show channels + asterisk full)

netstat -lup | grep asterisk | wc -l
949

By: Kinsey Moore (kmoore) 2012-04-24 09:42:25.534-0500

Maciej,
The log file you provided in 19.04.tar.gz still does not match the "sip show channels" output. Were these two logs collected from the same Asterisk instance on the same computer? I am unable to find any of the call IDs from the "sip show channels" output in the log file.
By: Maciej Krajewski (jamicque) 2012-04-24 09:54:34.366-0500

The logs are from the same machine,
they where collected in the same time.
I've attached the logs again (24.0.2.tar.gz). Here are the commands i havve executed:
{code}
gx00:~# cat /var/log/asterisk/full | grep "2012-04-24" > full
gx00:~# asterisk -rx "sip show channels" > sip_show.txt
gx00:~# tar zcf 24.04.tar.gz full sip_show.txt
{code}

By: Kinsey Moore (kmoore) 2012-04-24 13:21:49.028-0500

Maciej,
Could you try out the patch I just attached? (fd_leak.diff) I think it will resolve the issue you are having.
By: Maciej Krajewski (jamicque) 2012-04-26 03:32:18.492-0500

I've applied the patch yesterday. After 1,5 day, everything seems to work fine. Number of used ports is on normal level. Thank you very much!