<div dir="ltr"><div><div><div>Hi,<br><br>Answering myself.<br><br></div>The problem is documented here. <a href="http://mediaproxy.ag-projects.com/issues/2013">http://mediaproxy.ag-projects.com/issues/2013</a><br><br></div>
So far this patch has solved our problem.<br><br></div>/Morten<br></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Thu, May 15, 2014 at 2:45 PM, Morten Isaksen <span dir="ltr"><<a href="mailto:misak@misak.dk" target="_blank">misak@misak.dk</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr">We have a periodic problem with the communication between mediaproxy (kamailio module) <-> media-dispatcher <-> media-relay<br>
<br>The problems seems to be that media-dispatcher mixes the requests and answers, so kamailio get a wrong answer to its request.<br>
<br>Kamailio 3.1.1<br>Mediaproxy 2.4.4<br><br>I know they are old versions, but I have checket the new releases, and it does not look like anything related to this has been changed.<br><br>This log snippet illustrates the problem well. We have added a few extra debug information:<br>
<br>PID 3433 sends a update request to dispatcher<br>dispatcher sends request to relay 10.253.253.32<br>relay 10.253.253.32 answers dispatcher<br>PID 5214 sends a remove request to dispatcher<br>dispatcher sends request to relay 10.253.253.32<br>
relay 10.253.253.32 answers dispatcher<br>dispatcher answer PID 3433 with the answer for PID 5214<br><br>The answer for PID 3433 is newer received by kamailio.<br><br><br>May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: WARNING: <script>: new request M=INVITE RURI=<a href="mailto:sip%3A40804XXX@76752XXX.example.com" target="_blank">sip:40804XXX@76752XXX.example.com</a> F=<a href="mailto:sip%3A40804XXX@76752XXX.example.com" target="_blank">sip:40804XXX@76752XXX.example.com</a> T=<a href="mailto:sip%3A40804XXX@172.16.9.20" target="_blank">sip:40804XXX@172.16.9.20</a> IP=172.16.9.20 ID=<a href="mailto:738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk" target="_blank">738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk</a><br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Command update Headers ['type: request', 'call_id: <a href="mailto:738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk" target="_blank">738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk</a>', 'cseq: 102', 'from_uri: <a href="mailto:40804XXX@76752XXX.example.com" target="_blank">40804XXX@76752XXX.example.com</a>', 'to_uri: <a href="mailto:40804XXX@172.16.9.20" target="_blank">40804XXX@172.16.9.20</a>', 'from_tag: as35017b2b', 'user_agent: one-connect', 'signaling_ip: 172.16.9.20', 'media: audio:172.16.9.18:50934:sendrecv:ice=no']<br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Issuing "update" command to relay at 10.253.253.32 <br>May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: To relay update 7529;type: request;call_id: <a href="mailto:738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk" target="_blank">738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk</a>;cseq: 102;from_uri: <a href="mailto:40804XXX@76752XXX.example.com" target="_blank">40804XXX@76752XXX.example.com</a>;to_uri: <a href="mailto:40804XXX@172.16.9.20" target="_blank">40804XXX@172.16.9.20</a>;from_tag: as35017b2b;user_agent: one-connect;signaling_ip: 172.16.9.20;media: audio:172.16.9.18:50934:sendrecv:ice=no;;<br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: line received 7529 172.16.8.32 63730 <br>May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5214]: WARNING: <script>: new request M=BYE RURI=<a href="http://sip:65981002@172.16.9.21:5060" target="_blank">sip:65981002@172.16.9.21:5060</a> F=<a href="mailto:sip%3A65982380@172.16.8.37" target="_blank">sip:65982380@172.16.8.37</a> T=<a href="mailto:sip%3A65981002@172.16.8.8" target="_blank">sip:65981002@172.16.8.8</a> IP=172.16.8.8 ID=<a href="http://24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060" target="_blank">24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060</a><br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Command remove Headers ['call_id: <a href="http://24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060" target="_blank">24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060</a>', 'from_tag: as792f4baa', 'to_tag: as798301b8'] <br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Issuing "remove" command to relay at 10.253.253.32 <br>May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: To relay remove 7530;call_id: 24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060;from_tag: as792f4baa;to_tag: as798301b8;; <br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: line received 7530 {"from_tag": "as792f4baa", "start_time": 1400133626.74, "call_id": "<a href="http://24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060" target="_blank">24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060</a>", "duration": 126, "streams": [{"status": "closed", "caller_codec": "G711a", "post_dial_delay": 0.175052881241, "callee_codec": "G711a", "caller_bytes": 1269200, "start_time": 0, "callee_packets": 6088, "callee_bytes": 1217600, "caller_packets": 6346, "callee_remote": "<a href="http://172.16.9.18:58756" target="_blank">172.16.9.18:58756</a>", "end_time": 126, "caller_remote": "<a href="http://172.16.8.37:13014" target="_blank">172.16.8.37:13014</a>", "media_type": "audio", "callee_local": "<a href="http://172.16.8.32:61298" target="_blank">172.16.8.32:61298</a>", "timeout_wait": 0, "caller_local": "<a href="http://172.16.8.32:61296" target="_blank">172.16.8.32:61296</a>"}], "to_tag": "as798301b8", "to_uri": "<a href="mailto:65981002@172.16.8.8" target="_blank">65981002@172.16.8.8</a>", "caller_ua": "Asterisk PBX 1.8.12.0", "callee_ua": "one-connect", "from_uri": "<a href="mailto:65982380@172.16.8.37" target="_blank">65982380@172.16.8.37</a>"} <br>
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Got statistics: {'from_tag': 'as792f4baa', 'dialog_id': None, 'start_time': 1400133626.74, 'timed_out': False, 'call_id': '<a href="http://24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060" target="_blank">24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060</a>', 'to_tag': 'as798301b8', 'streams': [{'status': 'closed', 'caller_codec': 'G711a', 'post_dial_delay': 0.17505288124099999, 'callee_codec': 'G711a', 'start_time': 0, 'caller_bytes': 1269200, 'callee_bytes': 1217600, 'caller_packets': 6346, 'end_time': 126, 'callee_remote': '<a href="http://172.16.9.18:58756" target="_blank">172.16.9.18:58756</a>', 'caller_remote': '<a href="http://172.16.8.37:13014" target="_blank">172.16.8.37:13014</a>', 'media_type': 'audio', 'callee_local': '<a href="http://172.16.8.32:61298" target="_blank">172.16.8.32:61298</a>', 'timeout_wait': 0, 'caller_local': '<a href="http://172.16.8.32:61296" target="_blank">172.16.8.32:61296</a>', 'callee_packets': 6088}], 'duration': 126, 'to_uri': '<a href="mailto:65981002@172.16.8.8" target="_blank">65981002@172.16.8.8</a>', 'from_uri': '<a href="mailto:65982380@172.16.8.37" target="_blank">65982380@172.16.8.37</a>', 'callee_ua': 'one-connect', 'caller_ua': 'Asterisk PBX 1.8.12.0'} <br>
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: ERROR: mediaproxy [mediaproxy.c:1689]: mediaproxy response removed^M <br>May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: ERROR: mediaproxy [mediaproxy.c:1702]: Len of tokens: 1 <br>
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: ERROR: mediaproxy [mediaproxy.c:1713]: insufficient ports returned from mediaproxy: got 0, expected 1 callid: <a href="mailto:738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk" target="_blank">738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk</a><br>
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: ERROR: <script>: RTPPROXY: use_media_proxy failed bm: 4326 Code=1 M=INVITE RURI=sip:40804XXX@sip-core.uni-tel.local F=<a href="mailto:sip%3A40804XXX@76752600.example.com" target="_blank">sip:40804XXX@76752600.example.com</a> T=<a href="mailto:sip%3A40804XXX@172.16.9.20" target="_blank">sip:40804XXX@172.16.9.20</a> IP=172.16.9.20 ID=<a href="mailto:738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk" target="_blank">738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk</a><br>
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5214]: NOTICE: acc [acc.c:275]: ACC: transaction answered: timestamp=1400133753;method=BYE;from_tag=as04fb28c3;to_tag=367167352;call_id=<a href="mailto:51654c57361b47d0751b3d1c33d19a4d@172.16.8.34" target="_blank">51654c57361b47d0751b3d1c33d19a4d@172.16.8.34</a>;code=200;reason=OK<span class="HOEnZb"><font color="#888888"><br>
<br><br clear="all"><br>-- <br>Morten Isaksen<br>
</font></span></div>
</blockquote></div><br><br clear="all"><br>-- <br>Morten Isaksen<br>
</div>