<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
{font-family:"Cambria Math";
panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
{font-family:Calibri;
panose-1:2 15 5 2 2 2 4 3 2 4;}
@font-face
{font-family:"Calibri Light";
panose-1:2 15 3 2 2 2 4 3 2 4;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0in;
margin-bottom:.0001pt;
font-size:12.0pt;
font-family:"Calibri",sans-serif;}
h3
{mso-style-priority:9;
mso-style-link:"Heading 3 Char";
margin-top:2.0pt;
margin-right:0in;
margin-bottom:0in;
margin-left:0in;
margin-bottom:.0001pt;
page-break-after:avoid;
font-size:12.0pt;
font-family:"Calibri Light",sans-serif;
color:#1F3763;
font-weight:normal;}
a:link, span.MsoHyperlink
{mso-style-priority:99;
color:#0563C1;
text-decoration:underline;}
a:visited, span.MsoHyperlinkFollowed
{mso-style-priority:99;
color:#954F72;
text-decoration:underline;}
p.msonormal0, li.msonormal0, div.msonormal0
{mso-style-name:msonormal;
mso-margin-top-alt:auto;
margin-right:0in;
mso-margin-bottom-alt:auto;
margin-left:0in;
font-size:11.0pt;
font-family:"Calibri",sans-serif;}
span.Heading3Char
{mso-style-name:"Heading 3 Char";
mso-style-priority:9;
mso-style-link:"Heading 3";
font-family:"Calibri Light",sans-serif;
color:#1F3763;}
span.EmailStyle19
{mso-style-type:personal;
font-family:"Calibri",sans-serif;
color:windowtext;}
span.EmailStyle20
{mso-style-type:personal;
font-family:"Calibri",sans-serif;
color:windowtext;}
span.EmailStyle21
{mso-style-type:personal-reply;
font-family:"Calibri",sans-serif;
color:windowtext;}
.MsoChpDefault
{mso-style-type:export-only;
font-size:10.0pt;}
@page WordSection1
{size:8.5in 11.0in;
margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
{page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal"><span style="font-size:11.0pt">After this had been happening for a while, OpenSIPS began constantly logging a single line:<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Jul 26 18:20:17 [7006] ERROR:core:handle_new_connect: failed to accept connection(24): Too many open files<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">This was logging thousands of times per second and quickly filled our entire disk. It also began logging every SIP message received in full, even though logging levels had not been changed.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I took a look at file descriptors on the system and found that OpenSIPS’ TCP Main thread has 65536 open file descriptors.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"># opensipsctl ps<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=0 PID=6981 Type=attendant<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=1 PID=6983 Type=event-route handler<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=2 PID=6984 Type=MI Datagram<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=3 PID=6985 Type=MI Datagram<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=4 PID=6986 Type=MI Datagram<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=5 PID=6987 Type=time_keeper<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=6 PID=6988 Type=timer<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=7 PID=6989 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=8 PID=6990 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=9 PID=6991 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=10 PID=6992 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=11 PID=6993 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=12 PID=6994 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=13 PID=6995 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=14 PID=6996 Type=SIP receiver udp:10.32.18.155:5060<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=15 PID=6997 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=16 PID=6998 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=17 PID=6999 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=18 PID=7000 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=19 PID=7001 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=20 PID=7002 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=21 PID=7003 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=22 PID=7004 Type=TCP receiver<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=23 PID=7005 Type=Timer handler<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">Process:: ID=24 PID=7006 Type=TCP main<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"># ls /proc/7006/fd/ | wc -l<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">65536<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">All of the other OpenSIPS process had hundreds of open FDs as well. My first thought is that many of the connections being opened for HEP are being leaked.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I captured a trap with the system in this state:
<a href="https://pastebin.com/H4M9eUSu">https://pastebin.com/H4M9eUSu</a><o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt;color:black">Ben Newlin </span>
<span style="font-size:11.0pt"><o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
<div style="border:none;border-top:solid #B5C4DF 1.0pt;padding:3.0pt 0in 0in 0in">
<p class="MsoNormal"><b><span style="color:black">From: </span></b><span style="color:black">Users <users-bounces@lists.opensips.org> on behalf of Ben Newlin <Ben.Newlin@genesys.com><br>
<b>Reply-To: </b>OpenSIPS users mailling list <users@lists.opensips.org><br>
<b>Date: </b>Friday, July 26, 2019 at 12:46 PM<br>
<b>To: </b>OpenSIPS users mailling list <users@lists.opensips.org><br>
<b>Subject: </b>Re: [OpenSIPS-Users] HEP Tracing exhausting TCP connections<o:p></o:p></span></p>
</div>
<div>
<p class="MsoNormal"><span style="font-size:11.0pt"><o:p> </o:p></span></p>
</div>
<p class="MsoNormal"><span style="font-size:11.0pt">It turns out the netstat example I provided was a smaller case. Here is an example where a single OpenSIPS instance had attempted over 400 TCP connections to the capture server:
<a href="https://pastebin.com/4jKQtZZY">https://pastebin.com/4jKQtZZY</a></span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt;color:black">Ben Newlin </span>
<o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<div style="border:none;border-top:solid #B5C4DF 1.0pt;padding:3.0pt 0in 0in 0in">
<p class="MsoNormal"><b><span style="color:black">From: </span></b><span style="color:black">Users <users-bounces@lists.opensips.org> on behalf of Ben Newlin <Ben.Newlin@genesys.com><br>
<b>Reply-To: </b>OpenSIPS users mailling list <users@lists.opensips.org><br>
<b>Date: </b>Friday, July 26, 2019 at 12:17 PM<br>
<b>To: </b>"users@lists.opensips.org" <users@lists.opensips.org><br>
<b>Subject: </b>[OpenSIPS-Users] HEP Tracing exhausting TCP connections</span><o:p></o:p></p>
</div>
<div>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
</div>
<p class="MsoNormal"><span style="font-size:11.0pt">Hello,</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt">We are experiencing an issue with the siptrace module using HEPv3 over TCP. What we are seeing is that when traffic increases, OpenSIPS is opening a much larger number of sockets to our capture server than
we expect. We have our capture server configured to accept a maximum of 2048 connections.</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt">We believe that the module is intended to share TCP connections to the capture server; something like one per process. We have found that if we increase traffic at a certain pace, OpenSIPS will attempt to
open multiple connections per process and will exhaust the 2048 port limit on the server. When this happens, connections begin to fail and the max async messages (hep_async_max_postponed_chunks) is exceeded. We believe this causes the proto_hep module to switch
to blocking TCP, as we see all OpenSIPS processes then block against siptrace for up to 5 minutes. The proto_hep TCP connect and send timeouts are set to the defaults, but these do not seem to be being honored for non-async connections.</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I was able to capture the output of netstat and opensipsctl ps during the issue and they are available here:
<a href="https://pastebin.com/jAMnSE8z">https://pastebin.com/jAMnSE8z</a>. You can see that even though we only have 16 UDP/TCP listener threads, there are almost 100 TCP connections open to the configured proto_hep server. This is for just one instance.</span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt">I was also able to capture a trap while this was occurring, but not while OpenSIPS was blocked which was my hope. It is difficult to time that occurrence exactly but we will keep trying. Trap output is here:
<a href="https://pastebin.com/cqGhrZrf">https://pastebin.com/cqGhrZrf</a></span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt"> </span><o:p></o:p></p>
<p class="MsoNormal"><span style="font-size:11.0pt;color:black">Ben Newlin </span>
<o:p></o:p></p>
</div>
</body>
</html>