We have a periodic problem with the communication between mediaproxy (kamailio module) <-> media-dispatcher <-> media-relay
The problems seems to be that media-dispatcher mixes the requests and answers, so kamailio get a wrong answer to its request.
Kamailio 3.1.1
Mediaproxy 2.4.4
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.
This log snippet illustrates the problem well. We have added a few extra debug information:
PID 3433 sends a update request to dispatcher
dispatcher sends request to relay 10.253.253.32
relay 10.253.253.32 answers dispatcher
PID 5214 sends a remove request to dispatcher
dispatcher sends request to relay 10.253.253.32
relay 10.253.253.32 answers dispatcher
dispatcher answer PID 3433 with the answer for PID 5214
The answer for PID 3433 is newer received by kamailio.
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: WARNING: <script>: new request M=INVITE RURI=sip:40804XXX@76752XXX.example.com F=sip:40804XXX@76752XXX.example.com T=sip:40804XXX@172.16.9.20 IP=172.16.9.20 ID=738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Command update Headers ['type: request', 'call_id: 738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk', 'cseq: 102', 'from_uri: 40804XXX@76752XXX.example.com', 'to_uri: 40804XXX@172.16.9.20', 'from_tag: as35017b2b', 'user_agent: one-connect', 'signaling_ip: 172.16.9.20', 'media: audio:172.16.9.18:50934:sendrecv:ice=no']
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Issuing "update" command to relay at 10.253.253.32
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: To relay update 7529;type: request;call_id: 738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk;cseq: 102;from_uri: 40804XXX@76752XXX.example.com;to_uri: 40804XXX@172.16.9.20;from_tag: as35017b2b;user_agent: one-connect;signaling_ip: 172.16.9.20;media: audio:172.16.9.18:50934:sendrecv:ice=no;;
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: line received 7529 172.16.8.32 63730
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5214]: WARNING: <script>: new request M=BYE RURI=sip:65981002@172.16.9.21:5060 F=sip:65982380@172.16.8.37 T=sip:65981002@172.16.8.8 IP=172.16.8.8 ID=24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Command remove Headers ['call_id: 24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060', 'from_tag: as792f4baa', 'to_tag: as798301b8']
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: Issuing "remove" command to relay at 10.253.253.32
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;;
May 15 08:02:33 sip-3-1 media-dispatcher[3433]: debug: line received 7530 {"from_tag": "as792f4baa", "start_time": 1400133626.74, "call_id": "24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060", "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": "172.16.9.18:58756", "end_time": 126, "caller_remote": "172.16.8.37:13014", "media_type": "audio", "callee_local": "172.16.8.32:61298", "timeout_wait": 0, "caller_local": "172.16.8.32:61296"}], "to_tag": "as798301b8", "to_uri": "65981002@172.16.8.8", "caller_ua": "Asterisk PBX 1.8.12.0", "callee_ua": "one-connect", "from_uri": "65982380@172.16.8.37"}
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': '24b6995108fc59946c0222084a79e1a7@172.16.8.37:5060', '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': '172.16.9.18:58756', 'caller_remote': '172.16.8.37:13014', 'media_type': 'audio', 'callee_local': '172.16.8.32:61298', 'timeout_wait': 0, 'caller_local': '172.16.8.32:61296', 'callee_packets': 6088}], 'duration': 126, 'to_uri': '65981002@172.16.8.8', 'from_uri': '65982380@172.16.8.37', 'callee_ua': 'one-connect', 'caller_ua': 'Asterisk PBX 1.8.12.0'}
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: ERROR: mediaproxy [mediaproxy.c:1689]: mediaproxy response removed^M
May 15 08:02:33 sip-3-1 /usr/local/sbin/kamailio[5211]: ERROR: mediaproxy [mediaproxy.c:1702]: Len of tokens: 1
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: 738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk
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=sip:40804XXX@76752600.example.com T=sip:40804XXX@172.16.9.20 IP=172.16.9.20 ID=738ce06b2a507610599b767b6b164657@hpbxout.one-connect.dk
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=51654c57361b47d0751b3d1c33d19a4d@172.16.8.34;code=200;reason=OK
--
Morten Isaksen