<div dir="ltr">Thanks again for your help Richard.<div><br></div><div>Here's the complete log from a call from 1000 to 1104. This time both are linphone Android UACs sitting behind the same NAT router.</div><div>Sorry about the length but it's probably best if you can see the whole logs. I have xxed out the public IPs to protect the innocent.</div><div>You'll also notice I have tried adding ICE=force-relay and indeed it seems to be creating the proper relay candidates.</div><div><br></div><div>Thanks again,</div><div>Peter</div><div><br></div><div><br></div><div><br></div><div><div>Oct 23 17:35:50 pbx rtpengine[4633]: Got valid command from <a href="http://127.0.0.1:55139">127.0.0.1:55139</a>: offer - { "sdp": "v=0#015#012o=1000 3601 330 IN IP4 192.168.1.4#015#012s=Talk#015#012c=IN IP4 192.168.1.4#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:61bd100089ee2177c7cae0bb#015#012a=ice-ufrag:03cbec52#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 7076 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 85.xx.xx.247#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012 ...</div><div>Oct 23 17:35:50 pbx rtpengine[4633]: ... a=rtpmap:110 speex/8000#015#012a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=candidate:1 1 UDP 2130706431 192.168.1.4 7076 typ host#015#012a=candidate:1 2 UDP 2130706430 192.168.1.4 7077 typ host#015#012a=candidate:2 1 UDP 1694498815 85.xx.xx.247 7076 typ srflx raddr 192.168.1.4 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 7077 typ srflx raddr 192.168.1.4 rport 7077#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "gBRbDZzJvq", "received ...</div><div>Oct 23 17:35:50 pbx rtpengine[4633]: ... -from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "command": "offer" }</div><div>Oct 23 17:35:50 pbx rtpengine[4633]: [gBRbDZzJvq] Creating new call</div><div>Oct 23 17:35:50 pbx rtpengine[4633]: [gBRbDZzJvq] Returning to SIP proxy: d3:sdp1000:v=0#015#012o=1000 3601 330 IN IP4 192.168.1.4#015#012s=Talk#015#012c=IN IP4 192.168.1.4#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:61bd100089ee2177c7cae0bb#015#012a=ice-ufrag:03cbec52#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 7076 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 85.xx.xx.247#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012a=rtpmap:110 speex/8000 ...</div><div>Oct 23 17:35:50 pbx rtpengine[4633]: [gBRbDZzJvq] ... #015#012a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=candidate:1 1 UDP 2130706431 192.168.1.4 7076 typ host#015#012a=candidate:1 2 UDP 2130706430 192.168.1.4 7077 typ host#015#012a=candidate:2 1 UDP 1694498815 85.xx.xx.247 7076 typ srflx raddr 192.168.1.4 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 7077 typ srflx raddr 192.168.1.4 rport 7077#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12006 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 167772 ...</div><div>Oct 23 17:35:50 pbx rtpengine[4633]: [gBRbDZzJvq] ... 14 79.xx.xx.153 12007 typ relay#015#0126:result2:oke</div><div>Oct 23 17:35:53 pbx rtpengine[4633]: Got valid command from <a href="http://127.0.0.1:46671">127.0.0.1:46671</a>: answer - { "sdp": "v=0#015#012o=1104 1621 1986 IN IP4 192.168.1.16#015#012s=Talk#015#012c=IN IP4 192.168.1.16#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:922295838662ba3be2a9c973#015#012a=ice-ufrag:3fd0ad3b#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 1049 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 85.xx.xx.247#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr= ...</div><div>Oct 23 17:35:53 pbx rtpengine[4633]: ... on#015#012a=rtpmap:110 speex/8000#015#012a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=candidate:1 1 UDP 2130706431 192.168.1.16 7076 typ host#015#012a=candidate:1 2 UDP 2130706430 192.168.1.16 7077 typ host#015#012a=candidate:2 1 UDP 1694498815 85.xx.xx.247 1049 typ srflx raddr 192.168.1.16 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 1050 typ srflx raddr 192.168.1.16 rport 7077#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "gBRbDZzJvq", " ...</div><div>Oct 23 17:35:53 pbx rtpengine[4633]: ... received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "to-tag": "--XZThM", "command": "answer" }</div><div>Oct 23 17:35:53 pbx rtpengine[4633]: [gBRbDZzJvq] Returning to SIP proxy: d3:sdp1007:v=0#015#012o=1104 1621 1986 IN IP4 192.168.1.16#015#012s=Talk#015#012c=IN IP4 192.168.1.16#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:922295838662ba3be2a9c973#015#012a=ice-ufrag:3fd0ad3b#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 1049 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 85.xx.xx.247#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012a=rtpmap:110 speex/8 ...</div><div>Oct 23 17:35:53 pbx rtpengine[4633]: [gBRbDZzJvq] ... 000#015#012a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=candidate:1 1 UDP 2130706431 192.168.1.16 7076 typ host#015#012a=candidate:1 2 UDP 2130706430 192.168.1.16 7077 typ host#015#012a=candidate:2 1 UDP 1694498815 85.xx.xx.247 1049 typ srflx raddr 192.168.1.16 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 1050 typ srflx raddr 192.168.1.16 rport 7077#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12020 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP ...</div><div>Oct 23 17:35:53 pbx rtpengine[4633]: [gBRbDZzJvq] ...  16777214 79.xx.xx.153 12021 typ relay#015#0126:result2:oke</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: Got valid command from <a href="http://127.0.0.1:55139">127.0.0.1:55139</a>: offer - { "sdp": "v=0#015#012o=1000 3601 331 IN IP4 85.xx.xx.247#015#012s=Talk#015#012c=IN IP4 85.xx.xx.247#015#012b=AS:1024#015#012t=0 0#015#012a=nortpproxy:yes#015#012a=ice-pwd:61bd100089ee2177c7cae0bb#015#012a=ice-ufrag:03cbec52#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 7076 RTP/AVP 124 120 111 110 0 8 101#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012a ...</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: ... =rtpmap:110 speex/8000#015#012a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=nortpproxy:yes#015#012a=candidate:2 1 UDP 1694498815 85.xx.xx.247 7076 typ srflx raddr 192.168.1.4 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 7077 typ srflx raddr 192.168.1.4 rport 7077#015#012a=remote-candidates:1 192.168.1.1 7076 2 192.168.1.1 7077#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "gBRbDZzJvq", "received-from": [ "IP4", "85.xx.xx.247" ], "fr ...</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: ... om-tag": "R7wGZh8mM", "to-tag": "--XZThM", "command": "offer" }</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: [gBRbDZzJvq] Returning to SIP proxy: d3:sdp960:v=0#015#012o=1000 3601 331 IN IP4 85.xx.xx.247#015#012s=Talk#015#012c=IN IP4 85.xx.xx.247#015#012b=AS:1024#015#012t=0 0#015#012a=nortpproxy:yes#015#012a=ice-pwd:61bd100089ee2177c7cae0bb#015#012a=ice-ufrag:03cbec52#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 7076 RTP/AVP 124 120 111 110 0 8 101#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012a=rtpmap:110 speex/8000#015#012 ...</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: [gBRbDZzJvq] ... a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=nortpproxy:yes#015#012a=candidate:2 1 UDP 1694498815 85.xx.xx.247 7076 typ srflx raddr 192.168.1.4 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 7077 typ srflx raddr 192.168.1.4 rport 7077#015#012a=remote-candidates:1 192.168.1.1 7076 2 192.168.1.1 7077#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12006 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777214 79.xx.xx.153 12007 typ relay#015#0126:resu ...</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: [gBRbDZzJvq] ... lt2:oke</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: Got valid command from <a href="http://127.0.0.1:46671">127.0.0.1:46671</a>: answer - { "sdp": "v=0#015#012o=1104 1621 1988 IN IP4 192.168.1.1#015#012s=Talk#015#012c=IN IP4 192.168.1.1#015#012b=AS:1024#015#012t=0 0#015#012a=nortpproxy:yes#015#012a=ice-pwd:922295838662ba3be2a9c973#015#012a=ice-ufrag:3fd0ad3b#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 7076 RTP/AVP 124 120 111 110 0 8 101#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012a=rtp ...</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: ... map:110 speex/8000#015#012a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=nortpproxy:yes#015#012a=candidate:3 1 UDP 1862270975 192.168.1.1 7076 typ prflx raddr 192.168.1.16 rport 7076#015#012a=candidate:3 2 UDP 1862270974 192.168.1.1 7077 typ prflx raddr 192.168.1.16 rport 7077#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "gBRbDZzJvq", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "to-tag": "--XZThM", "command": "answer" }</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: [gBRbDZzJvq] Returning to SIP proxy: d3:sdp892:v=0#015#012o=1104 1621 1988 IN IP4 192.168.1.1#015#012s=Talk#015#012c=IN IP4 192.168.1.1#015#012b=AS:1024#015#012t=0 0#015#012a=nortpproxy:yes#015#012a=ice-pwd:922295838662ba3be2a9c973#015#012a=ice-ufrag:3fd0ad3b#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 7076 RTP/AVP 124 120 111 110 0 8 101#015#012a=rtpmap:124 opus/48000/2#015#012a=fmtp:124 useinbandfec=1; stereo=0; sprop-stereo=0#015#012a=rtpmap:120 SILK/16000#015#012a=rtpmap:111 speex/16000#015#012a=fmtp:111 vbr=on#015#012a=rtpmap:110 speex/8000#015#012a=fmt ...</div><div>Oct 23 17:35:56 pbx rtpengine[4633]: [gBRbDZzJvq] ... p:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=nortpproxy:yes#015#012a=candidate:3 1 UDP 1862270975 192.168.1.1 7076 typ prflx raddr 192.168.1.16 rport 7076#015#012a=candidate:3 2 UDP 1862270974 192.168.1.1 7077 typ prflx raddr 192.168.1.16 rport 7077#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12036 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777214 79.xx.xx.153 12037 typ relay#015#0126:result2:oke</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] Closing call due to timeout</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] Final packet stats:</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] --- Tag '--XZThM', created 1:05 ago, in dialogue with 'R7wGZh8mM'</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] ------ Media #1, port 12006 <>  85.xx.xx.247:7076 , 3 p, 256 b, 0 e</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] ------ Media #1, port 12007 <>  85.xx.xx.247:7077  (RTCP), 4 p, 352 b, 0 e</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] --- Tag 'R7wGZh8mM', created 1:05 ago, in dialogue with '--XZThM'</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] ------ Media #1, port 12036 <>  85.xx.xx.247:7076 , 4 p, 352 b, 0 e</div><div>Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] ------ Media #1, port 12037 <>  85.xx.xx.247:7077  (RTCP), 6 p, 480 b, 0 e</div><div>Oct 23 17:37:02 pbx rtpengine[4633]: Got valid command from <a href="http://127.0.0.1:46671">127.0.0.1:46671</a>: delete - { "ICE": "force-relay", "call-id": "gBRbDZzJvq", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "command": "delete" }</div><div>Oct 23 17:37:02 pbx rtpengine[4633]: [gBRbDZzJvq] Call-ID to delete not found</div><div>Oct 23 17:37:02 pbx rtpengine[4633]: Returning to SIP proxy: d7:warning38:Call-ID not found or tags didn't match6:result2:oke</div></div></div><div class="gmail_extra"><br><div class="gmail_quote">On Wed, Oct 22, 2014 at 11:04 PM, Richard Fuchs <span dir="ltr"><<a href="mailto:rfuchs@sipwise.com" target="_blank">rfuchs@sipwise.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div class="HOEnZb"><div class="h5">On 10/22/14 16:53, Peter Villeneuve wrote:<br>
> Thanks Richard.<br>
><br>
> I guess I'll have to keep looking then.<br>
><br>
> Have there been any changes in the syntax for rtpengine and its<br>
> integration with Kamailio 4.2 lately?<br>
><br>
> I have quite a few of those "empty IPs" (for lack of a better word)  in<br>
> the rtpengine logs and I can't figure out why they occur.<br>
><br>
> I have the following in my kamailio config<br>
><br>
> # RTPProxy control<br>
> route[NATMANAGE] {<br>
> #!ifdef WITH_NAT<br>
> if (is_request()) {<br>
> if(has_totag()) {<br>
> if(check_route_param("nat=yes")) {<br>
> setbflag(FLB_NATB);<br>
> }<br>
> }<br>
> }<br>
> if (!(isflagset(FLT_NATS) || isbflagset(FLB_NATB)))<br>
> return;<br>
><br>
> rtpengine_manage("replace-origin replace-session-connection");<br>
><br>
> if (is_request()) {<br>
> if (!has_totag()) {<br>
> if(t_is_branch_route()) {<br>
> add_rr_param(";nat=yes");<br>
> }<br>
> }<br>
> }<br>
> if (is_reply()) {<br>
> if(isbflagset(FLB_NATB)) {<br>
> if(is_first_hop())<br>
> set_contact_alias();<br>
> }<br>
> }<br>
> #!endif<br>
> return;<br>
> }<br>
><br>
> Does anything jump out at you as being wrong?<br>
><br>
> My goal is to have linphone clients (android) with ICE enabled call<br>
> Groundwire clients (iOS) also with ICE enabled. Both are using the same<br>
> STUN server that sits on the same machine as Kamailio.<br>
> Ideally rtpengine wouldn't get involved at all and would ignore the SDP<br>
> since both UACs should be able to use ICE to negotiate a p2p connection<br>
> between them.<br>
> However, if one is behind symmetric NAT than rtpengine should be called<br>
> in to relay the media.<br>
><br>
> I've also tried the above config by<br>
> adding rtpengine_manage("replace-origin replace-session-connection<br>
> ICE=force-relay"); but I think that's made debugging even harder.<br>
><br>
> I'm not sure if the problem lies with kamailio/rtpengine (or my config<br>
> for them) or if it is the UACs that aren't playing nicely even though<br>
> they supposedly support SIP and ICE RFCs. It seems when they call each<br>
> other ICE isn't being used at all (at least linphone display shows ICE<br>
> not activated) even though the media is flowing normally.<br>
><br>
> Anyway, I don't need to be spoon fed, but a push in the right direction<br>
> would be much appreciated.<br>
<br>
</div></div>The best way to find out what could be going on is to post the complete<br>
log from rtpengine for one such call. This will show all the SDP bodies<br>
and everything else involved.<br>
<div class="HOEnZb"><div class="h5"><br>
cheers<br>
<br>
_______________________________________________<br>
sr-dev mailing list<br>
<a href="mailto:sr-dev@lists.sip-router.org">sr-dev@lists.sip-router.org</a><br>
<a href="http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev" target="_blank">http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev</a><br>
</div></div></blockquote></div><br></div>