<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=utf-8">
<style>
<!--
@font-face
{font-family:Calibri}
@font-face
{font-family:Consolas}
p.MsoNormal, li.MsoNormal, div.MsoNormal
{margin:0cm;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";
color:black}
a:link, span.MsoHyperlink
{color:#0563C1;
text-decoration:underline}
a:visited, span.MsoHyperlinkFollowed
{color:#954F72;
text-decoration:underline}
pre
{margin:0cm;
margin-bottom:.0001pt;
font-size:10.0pt;
font-family:"Courier New";
color:black}
p.MsoListParagraph, li.MsoListParagraph, div.MsoListParagraph
{margin-top:0cm;
margin-right:0cm;
margin-bottom:0cm;
margin-left:36.0pt;
margin-bottom:.0001pt;
font-size:11.0pt;
font-family:"Calibri","sans-serif";
color:black}
p.msochpdefault, li.msochpdefault, div.msochpdefault
{margin-right:0cm;
margin-left:0cm;
font-size:10.0pt;
font-family:"Times New Roman","serif";
color:black}
span.emailstyle18
{font-family:"Calibri","sans-serif";
color:windowtext}
span.emailstyle19
{font-family:"Calibri","sans-serif";
color:#1F497D}
span.HTMLPreformattedChar
{font-family:"Consolas","serif";
color:black}
span.EmailStyle23
{font-family:"Calibri","sans-serif";
color:#1F497D}
span.EmailStyle24
{font-family:"Calibri","sans-serif";
color:windowtext}
.MsoChpDefault
{font-size:10.0pt}
@page WordSection1
{margin:72.0pt 72.0pt 72.0pt 72.0pt}
div.WordSection1
{}
-->
</style>
</head>
<body bgcolor="white" lang="EN-GB" link="#0563C1" vlink="#954F72">
<div class="WordSection1">
<p class="MsoNormal"><span style="color:#1F497D">Thanks Daniel,</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">I’ve changed the destination format and I’m seeing the same behaviour, but I made tests in various scenarios and my feeling is that Kamailio is doing the right thing.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">I don’t want to waste the readers’ time for what doesn’t appear to be an issue with Kamailio, so be warned if you keep reading.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">I moved to TCP (e.g. sip:10.0.0.1;transport=tcp) to have a better idea whether the problem was related to TLS only or not.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">The behaviour was basically the same, but it was easier to debug.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">Initially Kamailio sends the 2 OPTIONS requests within the same packet, e.g.:</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">T 2014/04/28 16:04:15.715917 MYIP:44191 -> 10.0.0.1:5060 [AP]</span></p>
<p class="MsoNormal"><span style="color:#1F497D">OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKe47.39ae71f3000000000000000000000000.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">To: <sip:10.0.0.1:5060;transport=tcp>.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">From: <sip:dispatcher@localhost>;tag=533cb9e91f4b999cf76861cbb9ed54ed-2a2c.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">CSeq: 10 OPTIONS.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Call-ID: 75918ba6133d8b07-15565@127.0.0.1.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Max-Forwards: 70.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Content-Length: 0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">User-Agent: kamailio (4.1.3 (x86_64/linux)).</span></p>
<p class="MsoNormal"><span style="color:#1F497D">.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKc57.0786b917000000000000000000000000.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">To: <sip:10.0.0.1:5060;transport=tcp>.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">From: <sip:dispatcher@localhost>;tag=533cb9e91f4b999cf76861cbb9ed54ed-7f23.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">CSeq: 10 OPTIONS.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Call-ID: 75918ba6133d8b08-15565@127.0.0.1.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Max-Forwards: 70.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Content-Length: 0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">User-Agent: kamailio (4.1.3 (x86_64/linux)).</span></p>
<p class="MsoNormal"><span style="color:#1F497D">.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">and Asterisk replies to both:</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">T 2014/04/28 16:04:15.717998 10,0.0.1:5060 -> MYIP:44191 [AP]</span></p>
<p class="MsoNormal"><span style="color:#1F497D">SIP/2.0 404 Not Found.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKe47.39ae71f3000000000000000000000000.0;received=MYIP;rport=44191.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">From: <sip:dispatcher@localhost>;tag=533cb9e91f4b999cf76861cbb9ed54ed-2a2c.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">To: <sip:10.0.0.1:5060;transport=tcp>;tag=as7421c5d4.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Call-ID: 75918ba6133d8b07-15565@127.0.0.1.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">CSeq: 10 OPTIONS.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Server: Truphone TAMS Server.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Supported: replaces, timer.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Accept: application/sdp.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Content-Length: 0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">T 2014/04/28 16:04:15.802983 10,0.0.1:5060 -> MYIP:44191 [AP]</span></p>
<p class="MsoNormal"><span style="color:#1F497D">SIP/2.0 404 Not Found.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKc57.0786b917000000000000000000000000.0;received=MYIP;rport=44191.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">From: <sip:dispatcher@localhost>;tag=533cb9e91f4b999cf76861cbb9ed54ed-7f23.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">To: <sip:10.0.0.1:5060;transport=tcp>;tag=as595d9838.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Call-ID: 75918ba6133d8b08-15565@127.0.0.1.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">CSeq: 10 OPTIONS.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Server: Truphone TAMS Server.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Supported: replaces, timer.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Accept: application/sdp.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Content-Length: 0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">but also Asterisk (1.8) marks the dialog for destruction:</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">“Scheduling destruction of SIP dialog '75918ba6133d8b08-15565@127.0.0.1' in 32000 ms (Method: OPTIONS)”</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">When Kamailio sends the following probe (after 30” from the first), Asterisk does not respond, and resets the TCP socket instead:</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">T 2014/04/28 16:04:45.620346 MYIP:44191 -> 10.0.0.1:5060 [AP]</span></p>
<p class="MsoNormal"><span style="color:#1F497D">OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKb57.25e82864000000000000000000000000.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">To: <sip:10.0.0.1:5060;transport=tcp>.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">From: <sip:dispatcher@localhost>;tag=533cb9e91f4b999cf76861cbb9ed54ed-8f22.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">CSeq: 10 OPTIONS.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Call-ID: 75918ba6133d8b09-15565@127.0.0.1.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Max-Forwards: 70.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Content-Length: 0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">User-Agent: kamailio (4.1.3 (x86_64/linux)).</span></p>
<p class="MsoNormal"><span style="color:#1F497D">.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">T 2014/04/28 16:04:45.622140 MYIP:44191 -> 10.0.0.1:5060 [AP]</span></p>
<p class="MsoNormal"><span style="color:#1F497D">OPTIONS sip:10.0.0.1:5060;transport=tcp SIP/2.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Via: SIP/2.0/TCP 192.168.142.170;branch=z9hG4bKa87.61f85cf3000000000000000000000000.0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">To: <sip:10.0.0.1:5060;transport=tcp>.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">From: <sip:dispatcher@localhost>;tag=533cb9e91f4b999cf76861cbb9ed54ed-5e98.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">CSeq: 10 OPTIONS.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Call-ID: 75918ba6133d8b0a-15565@127.0.0.1.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Max-Forwards: 70.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Content-Length: 0.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">User-Agent: kamailio (4.1.3 (x86_64/linux)).</span></p>
<p class="MsoNormal"><span style="color:#1F497D">.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D"><<NO REPLY>></span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">With tcpdump:</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">16:04:45.620352 IP (tos 0x0, ttl 241, id 28746, offset 0, flags [none], proto TCP (6), length 448)</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> MYIP.44191 > 10.0.0.1.5060: Flags [P.], cksum 0x95b7 (correct), seq 817:1225, ack 1057, win 63184, length 408</span></p>
<p class="MsoNormal"><span style="color:#1F497D">16:04:45.620516 IP (tos 0x0, ttl 64, id 45429, offset 0, flags [DF], proto TCP (6), length 40)</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> 10.0.0.1.5060 > MYIP.44191: Flags [R.], cksum 0xf813 (incorrect -> 0x1802), seq 1057, ack 1225, win 17136, length 0</span></p>
<p class="MsoNormal"><span style="color:#1F497D">16:04:45.622143 IP (tos 0x0, ttl 241, id 25284, offset 0, flags [none], proto TCP (6), length 448)</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> MYIP.44191 > 10.0.0.1.5060: Flags [P.], cksum 0x57ca (correct), seq 1225:1633, ack 1057, win 63184, length 408</span></p>
<p class="MsoNormal"><span style="color:#1F497D">16:04:45.622164 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 40)</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> 10.0.0.1.5060 > MYIP.44191: Flags [R], cksum 0xb792 (correct), seq 2351215564, win 0, length 0</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">This second group of OPTIONS times out, and Kamailio will open a new socket for the following probe.</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Changing the dispatcher’s probing interval from 30” to 10” confirms that OPTIONS requests within about 30” from the initial ones are correctly handled, but once Asterisk has destroyed the dialog, Kamailio times
out and needs to create a new socket (so every about 30” kamailio logs a 408).</span></p>
<p class="MsoNormal"><span style="color:#1F497D">I haven’t managed to replicate the problem with FS, so at the moment it seems only an issue with how Asterisk manages the TCP sockets created by Kamailio for probing.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">If you’ve read so far and have any hint or reference on why Asterisk behaves in this way, or examples of TCP/TLS destinations involving Asterisk for Kamailio dispatcher, I’d be grateful.</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D">Kind Regards,</span></p>
<p class="MsoNormal"><span style="color:#1F497D">Giacomo</span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<div>
<div style="border:none; border-top:solid #E1E1E1 1.0pt; padding:3.0pt 0cm 0cm 0cm">
<p class="MsoNormal"><b><span lang="EN-US" style="color:windowtext">From:</span></b><span lang="EN-US" style="color:windowtext"> sr-users-bounces@lists.sip-router.org [mailto:sr-users-bounces@lists.sip-router.org]
<b>On Behalf Of </b>Daniel-Constantin Mierla<br>
<b>Sent:</b> 28 April 2014 09:07<br>
<b>To:</b> Kamailio (SER) - Users Mailing List<br>
<b>Subject:</b> Re: [SR-Users] Dispatcher marks TLS destinations as Inactive when present in more than one set</span></p>
</div>
</div>
<p class="MsoNormal"> </p>
<p class="MsoNormal" style="margin-bottom:12.0pt">Hello,<br>
<br>
seems like an issue if the second OPTIONS is not sent out -- I will look over it.<br>
<br>
However, SIPS doesn't enforce tls, it means a secure connection which can be also VPN or a private wire.<br>
<br>
Can you give it a try with uris like:<br>
<br>
sip: _IP_ADDR_:5061;transport=tls<br>
<br>
?<br>
<br>
Cheers,<br>
Daniel<span style="font-size:12.0pt"></span></p>
<div>
<p class="MsoNormal">On 25/04/14 16:56, Giacomo Vacca wrote:</p>
</div>
<blockquote style="margin-top:5.0pt; margin-bottom:5.0pt">
<div>
<p class="MsoNormal">Hi all,</p>
<p class="MsoNormal">I’m seeing a strange behaviour with dispatcher in these conditions:</p>
<p class="MsoNormal"><span style="color:#1F497D"> </span></p>
<p class="MsoNormal">1. A destination requires TLS (e.g. <span class="MsoHyperlink">
sips:10.0.0.1:5061</span>)</p>
<p class="MsoNormal">2. The destination has flags 8 (i.e. in normal conditions we want AP, Active Probing) and dispatcher uses ds_probing_mode 1 (always probe)</p>
<p class="MsoNormal">3. The destination is present in more than one set</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">The behaviour is that the destination is marked as IP (Inactive Probing) in the set with a<span style="color:#1F497D">
</span>lower set number.</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">In other words at startup (or dispatcher reload):</p>
<p class="MsoNormal">SET_NO:: 2</p>
<p class="MsoNormal">SET:: 2</p>
<p class="MsoNormal"> URI:: <span class="MsoHyperlink">sips:10.0.0.1:5061</span> flags=AP priority=0 attrs=</p>
<p class="MsoNormal">SET:: 1</p>
<p class="MsoNormal"> URI:: <span class="MsoHyperlink">sips:10.0.0.1:5061</span> flags=AP priority=0 attrs=</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">After some time (about 30”, see below):</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">SET_NO:: 2</p>
<p class="MsoNormal">SET:: 2</p>
<p class="MsoNormal"> URI:: <span class="MsoHyperlink">sips:10.0.0.1:5061</span> flags=AP priority=0 attrs=</p>
<p class="MsoNormal">SET:: 1</p>
<p class="MsoNormal"> URI:: <span class="MsoHyperlink">sips:10.0.0.1:5061</span> flags=IP priority=0 attrs=</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">So the same destination is marked as AP and IP at the same time.</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">I’ve reproduced this with a brand new installation (4.1.3 on debian wheezy), but seen with 3.2.3 and 4.0.4 as well.</p>
<p class="MsoNormal">debian wheezy VM (Linux debian7 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux)</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">I can see (with either ssldump or asterisk’s ‘sip set debug on’) the first OPTIONS/404 (related to set #2), but not the second (related to set #1).</p>
<p class="MsoNormal">I haven’t seen (with tcpdump) the attempt to create a second connection to the destination (which makes me think that it either fails or kamailio attempts to re-use the existing one).</p>
<p class="MsoNormal">Probing for set #1 appears to time out (i.e. after 30” the response is considered a 408).</p>
<p class="MsoNormal">It happens with either Asterisk or FreeSWITCH as servers.</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Extract from tls.cfg:</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">[client:default]</p>
<p class="MsoNormal">verify_certificate = no</p>
<p class="MsoNormal">require_certificate = no</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Dispatcher configuration:</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">loadmodule "dispatcher.so"</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">[...]</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal"># ----- dispatcher params -----</p>
<p class="MsoNormal">modparam("dispatcher", "list_file", "/etc/kamailio/dispatcher.cfg")</p>
<p class="MsoNormal">modparam("dispatcher", "ds_ping_reply_codes", "class=2;code=404")</p>
<p class="MsoNormal">modparam("dispatcher", "ds_probing_mode", 1)</p>
<p class="MsoNormal">modparam("dispatcher", "ds_ping_interval", 30)</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">/etc/kamailio/dispatcher.cfg:</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">1 <span class="MsoHyperlink">sips:10.0.0.1:5061</span> 8 0</p>
<p class="MsoNormal">2 <span class="MsoHyperlink">sips:10.0.0.1:5061</span> 8 0</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">(I'm using 10.0.0.1 here for simplification only; the real IP address has been omitted).</p>
<p class="MsoNormal">Server (Asterisk or FreeSWITCH) certs are self-signed.</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Relevant logs (level 4):</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: dispatcher [dispatch.c:2453]: ds_check_timer(): probing set #2, URI
<span class="MsoHyperlink">sips:10.0.0.1:5061</span></p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<<span class="MsoHyperlink">sips:10.0.0.1:5061</span>></p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 49688</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> [tcp_main.c:1849]: tcp_send(): tcp_send: no open tcp connection found, opening new one</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> [ip_addr.c:243]: print_ip(): tcpconn_new: new tcp connection: 10.0.0.1</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> [tcp_main.c:1096]: tcpconn_new(): tcpconn_new: on port 5061, type 3</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> [tcp_main.c:1408]: tcpconn_add(): tcpconn_add: hashes: 1217:0:0, 1</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tls [tls_server.c:178]: tls_complete_init(): Using TLS domain TLSc<default></p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tls [tls_domain.c:700]: sr_ssl_ctx_info_callback(): SSL handshake started</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: <core> [tcp_main.c:2737]: tcpconn_1st_send(): pending write on new connection 0x7fd4813cdb70 (-1/225 bytes written)</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [tcp_main.c:3624]: handle_ser_child(): handle_ser_child: read response= 7fd4813cdb70, 5, fd 32 from 9 (11169)</p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x89dc40, 32, 2, 0x7fd4813cdb70), fd_no=24</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: dispatcher [dispatch.c:2453]: ds_check_timer(): probing set #1, URI
<span class="MsoHyperlink">sips:10.0.0.1:5061</span></p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [uac.c:243]: t_uac_prepare(): DEBUG:tm:t_uac: next_hop=<<span class="MsoHyperlink">sips:10.0.0.1:5061</span>></p>
<p class="MsoNormal">Apr 24 15:54:19 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [uac.c:182]: dlg2hash(): DEBUG: dlg2hash: 49689</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [io_wait.h:796]: io_watch_chg(): DBG: io_watch_chg (0x89dc40, 32, 0x1, 0xffffffff) fd_no=25 called</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [io_wait.h:617]: io_watch_del(): DBG: io_watch_del (0x89dc40, 32, -1, 0x0) fd_no=25 called</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [tcp_main.c:4302]: handle_tcpconn_ev(): tcp: DBG: sending to child, events 1</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [tcp_main.c:3973]: send2child(): selected tcp worker 0 13(11173) for activity on [tls:192.168.142.170:5061], 0x7fd4813cdb70</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_read.c:1510]: handle_io(): received n=8 con=0x7fd4813cdb70, fd=7</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x8e2040, 7, 2, 0x7fd4813cdb70), fd_no=1</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_main.c:2556]: tcpconn_do_send(): tcp_send: sending...</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_main.c:2590]: tcpconn_do_send(): tcp_send: after real write: c= 0x7fd4813cdb70 n=198 fd=7</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_main.c:2591]: tcpconn_do_send(): tcp_send: buf=#012#026#003#001</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_domain.c:712]: sr_ssl_ctx_info_callback(): SSL handshake done</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_domain.c:715]: sr_ssl_ctx_info_callback(): SSL disable renegotiation</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_server.c:413]: tls_connect(): TLS connect successful</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_server.c:420]: tls_connect(): tls_connect: new connection to 10.0.0.1:5061 using TLSv1/SSLv3 AES256-SHA 256</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_server.c:423]: tls_connect(): tls_connect: sending socket: 192.168.142.170:43914</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_server.c:305]: tls_dump_cert_info(): tls_connect: server certificate subject:/CN=REMOVED/O=REMOVED</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_server.c:309]: tls_dump_cert_info(): tls_connect: server certificate issuer:/CN=REMOVED/O=REMOVED</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_server.c:429]: tls_connect(): WARNING: tls_connect: server certificate verification failed!!!</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tls [tls_dump_vf.c:105]: tls_dump_verification_failure(): verification failure: self signed certificate in certificate chain</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_main.c:2556]: tcpconn_do_send(): tcp_send: sending...</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_main.c:2590]: tcpconn_do_send(): tcp_send: after real write: c= 0x7fd4813cdb70 n=805 fd=7</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_main.c:2591]: tcpconn_do_send(): tcp_send: buf=[...REMOVED...]</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_read.c:1317]: tcp_read_req(): tcp_read_req: content-length= 0</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:633]: parse_msg(): SIP Reply (status):</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:635]: parse_msg(): version: <SIP/2.0></p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:637]: parse_msg(): status: <404></p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:639]: parse_msg(): reason: <Not Found></p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK812c.b064d3e3000000000000000000000000.0>; state=6</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 234, <received> = <REMOVED>; state=6</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/parse_via.c:1284]: parse_via_param(): Found param type 235, <rport> = <59525>; state=16</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/parse_via.c:2672]: parse_via(): end of header reached, state=5</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:513]: parse_headers(): parse_headers: Via found, flags=2</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:515]: parse_headers(): parse_headers: this is the first via</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [receive.c:152]: receive_msg(): After parse_msg...</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_lookup.c:1072]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=0 T start=0xffffffffffffffff</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/parse_addr_spec.c:176]: parse_to_param(): DEBUG: add_param: tag=as232959d2</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/parse_addr_spec.c:893]: parse_addr_spec(): end of header reached, state=29</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:190]: get_hdr_field(): DEBUG: get_hdr_field: <To> [43]; uri=[sips:10.0.0.1:5061]</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:192]: get_hdr_field(): DEBUG: to body [<<span class="MsoHyperlink">sips:10.0.0.1:5061</span>>]</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [parser/msg_parser.c:170]: get_hdr_field(): get_hdr_field: cseq <CSeq>: <10> <OPTIONS></p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_lookup.c:949]: t_reply_matching(): DEBUG: t_reply_matching: hash 49688 label 0 branch 0</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_lookup.c:1004]: t_reply_matching(): DEBUG: t_reply_matching: reply matched (T=0x7fd4813cc530)!</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_lookup.c:1141]: t_check_msg(): DEBUG: t_check_msg: msg id=1 global id=1 T end=0x7fd4813cc530</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_reply.c:2206]: reply_received(): DEBUG: reply_received: org. status uas=0, uac[0]=0 local=2 is_invite=0)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=404</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_reply.c:2086]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_reply.c:2123]: local_reply(): DEBUG: local transaction completed</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fd4813cc530, callback type 1024, id 0 entered</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: dispatcher [dispatch.c:2392]: ds_options_callback(): OPTIONS-Request was finished with code 404 (to
<span class="MsoHyperlink">sips:10.0.0.1:5061</span>, group 2)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: tm [t_reply.c:1663]: cleanup_uac_timers(): DEBUG: cleanup_uac_timers: RETR/FR timers reset</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [usr_avp.c:644]: destroy_avp_list(): DEBUG:destroy_avp_list: destroying list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [xavp.c:448]: xavp_destroy_list(): destroying xavp list (nil)</p>
<p class="MsoNormal">Apr 24 15:54:20 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [receive.c:296]: receive_msg(): receive_msg: cleaning up</p>
<p class="MsoNormal">Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [io_wait.h:617]: io_watch_del(): DBG: io_watch_del (0x8e2040, 7, -1, 0x10) fd_no=2 called</p>
<p class="MsoNormal">Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_read.c:1437]: release_tcpconn(): releasing con 0x7fd4813cdb70, state 1, fd=7, id=1</p>
<p class="MsoNormal">Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11173]: DEBUG: <core> [tcp_read.c:1438]: release_tcpconn(): extra_data 0x7fd4813b51f0</p>
<p class="MsoNormal">Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [tcp_main.c:3385]: handle_tcp_child(): handle_tcp_child: reader response= 7fd4813cdb70, 1 from 0</p>
<p class="MsoNormal">Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [io_wait.h:390]: io_watch_add(): DBG: io_watch_add(0x89dc40, 32, 2, 0x7fd4813cdb70), fd_no=24</p>
<p class="MsoNormal">Apr 24 15:54:26 debian7 /usr/sbin/kamailio[11177]: DEBUG: <core> [tcp_main.c:3515]: handle_tcp_child(): handle_tcp_child: CONN_RELEASE 0x7fd4813cdb70 refcnt= 1</p>
<p class="MsoNormal">Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [t_reply.c:1304]: t_should_relay_response(): ->>>>>>>>> T_code=0, new_code=408</p>
<p class="MsoNormal">Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [t_reply.c:2086]: local_reply(): DEBUG: local_reply: branch=0, save=0, winner=0</p>
<p class="MsoNormal">Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [t_reply.c:2123]: local_reply(): DEBUG: local transaction completed</p>
<p class="MsoNormal">Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: tm [t_hooks.c:288]: run_trans_callbacks_internal(): DBG: trans=0x7fd4813e5890, callback type 1024, id 0 entered</p>
<p class="MsoNormal">Apr 24 15:54:49 debian7 /usr/sbin/kamailio[11169]: DEBUG: dispatcher [dispatch.c:2392]: ds_options_callback(): OPTIONS-Request was finished with code 408 (to
<span class="MsoHyperlink">sips:10.0.0.1:5061</span>, group 1)</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Probing set #2 goes OK.</p>
<p class="MsoNormal">Probing set #1: starts probing at 15:54:19, and times out 30" later at 15:54:49.</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Is this a bug, a misconfiguration, or perhaps a wrong way to manage dispatcher sets using TLS?</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Additional question: Is it not expected that a persistent TLS connection is established with a 'sips' dispatcher destination?</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal">Thanks in advance for the time to read through all this!</p>
<p class="MsoNormal">Giacomo</p>
<p class="MsoNormal"> </p>
<p class="MsoNormal"> </p>
</div>
<p class="MsoNormal"><span style="font-size:12.0pt; font-family:"Times New Roman","serif"">Truphone Limited, registered in England and Wales (registered company number: 04187081). Registered office: CityPoint, One Ropemaker Street, London EC2Y 9SS. VAT No.
GB 851 5278 19 <br>
<br clear="all">
This e-mail, and any attachment(s), may contain information which is confidential and/or privileged, and is intended for the addressee only. If you are not the intended recipient, you may not use, disclose, copy or distribute this information in any manner
whatsoever. If you have received this e-mail in error, please contact the sender immediately and delete it.<br>
<br>
<br>
<br>
</span></p>
<pre>_______________________________________________</pre>
<pre>SIP Express Router (SER) and Kamailio (OpenSER) - sr-users mailing list</pre>
<pre><a href="mailto:sr-users@lists.sip-router.org">sr-users@lists.sip-router.org</a></pre>
<pre><a href="http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users">http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-users</a></pre>
</blockquote>
<p class="MsoNormal"><span style="font-size:12.0pt; font-family:"Times New Roman","serif""><br>
<br>
</span></p>
<pre>-- </pre>
<pre>Daniel-Constantin Mierla - <a href="http://www.asipto.com">http://www.asipto.com</a></pre>
<pre><a href="http://twitter.com/#!/miconda">http://twitter.com/#!/miconda</a> - <a href="http://www.linkedin.com/in/miconda">http://www.linkedin.com/in/miconda</a></pre>
</div>
Truphone Limited, registered in England and Wales (registered company number: 04187081). Registered office: CityPoint, One Ropemaker Street, London EC2Y 9SS. VAT No. GB 851 5278 19
<br>
<br clear="both">
This e-mail, and any attachment(s), may contain information which is confidential and/or privileged, and is intended for the addressee only. If you are not the intended recipient, you may not use, disclose, copy or distribute this information in any manner whatsoever. If you have received this e-mail in error, please contact the sender immediately and delete it.<BR>
</body>
</html>