Thanks again for your help Richard.

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.
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.
You'll also notice I have tried adding ICE=force-relay and indeed it seems to be creating the proper relay candidates.

Thanks again,
Peter



Oct 23 17:35:50 pbx rtpengine[4633]: Got valid command from 127.0.0.1:55139: 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 ...
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 ...
Oct 23 17:35:50 pbx rtpengine[4633]: ... -from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "command": "offer" }
Oct 23 17:35:50 pbx rtpengine[4633]: [gBRbDZzJvq] Creating new call
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 ...
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 ...
Oct 23 17:35:50 pbx rtpengine[4633]: [gBRbDZzJvq] ... 14 79.xx.xx.153 12007 typ relay#015#0126:result2:oke
Oct 23 17:35:53 pbx rtpengine[4633]: Got valid command from 127.0.0.1:46671: 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= ...
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", " ...
Oct 23 17:35:53 pbx rtpengine[4633]: ... received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "to-tag": "--XZThM", "command": "answer" }
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 ...
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 ...
Oct 23 17:35:53 pbx rtpengine[4633]: [gBRbDZzJvq] ...  16777214 79.xx.xx.153 12021 typ relay#015#0126:result2:oke
Oct 23 17:35:56 pbx rtpengine[4633]: Got valid command from 127.0.0.1:55139: 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 ...
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 ...
Oct 23 17:35:56 pbx rtpengine[4633]: ... om-tag": "R7wGZh8mM", "to-tag": "--XZThM", "command": "offer" }
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 ...
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 ...
Oct 23 17:35:56 pbx rtpengine[4633]: [gBRbDZzJvq] ... lt2:oke
Oct 23 17:35:56 pbx rtpengine[4633]: Got valid command from 127.0.0.1:46671: 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 ...
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" }
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 ...
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
Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] Closing call due to timeout
Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] Final packet stats:
Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] --- Tag '--XZThM', created 1:05 ago, in dialogue with 'R7wGZh8mM'
Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] ------ Media #1, port 12006 <>  85.xx.xx.247:7076 , 3 p, 256 b, 0 e
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
Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] --- Tag 'R7wGZh8mM', created 1:05 ago, in dialogue with '--XZThM'
Oct 23 17:36:55 pbx rtpengine[4633]: [gBRbDZzJvq] ------ Media #1, port 12036 <>  85.xx.xx.247:7076 , 4 p, 352 b, 0 e
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
Oct 23 17:37:02 pbx rtpengine[4633]: Got valid command from 127.0.0.1:46671: delete - { "ICE": "force-relay", "call-id": "gBRbDZzJvq", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "R7wGZh8mM", "command": "delete" }
Oct 23 17:37:02 pbx rtpengine[4633]: [gBRbDZzJvq] Call-ID to delete not found
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

On Wed, Oct 22, 2014 at 11:04 PM, Richard Fuchs <rfuchs@sipwise.com> wrote:
On 10/22/14 16:53, Peter Villeneuve wrote:
> Thanks Richard.
>
> I guess I'll have to keep looking then.
>
> Have there been any changes in the syntax for rtpengine and its
> integration with Kamailio 4.2 lately?
>
> I have quite a few of those "empty IPs" (for lack of a better word)  in
> the rtpengine logs and I can't figure out why they occur.
>
> I have the following in my kamailio config
>
> # RTPProxy control
> route[NATMANAGE] {
> #!ifdef WITH_NAT
> if (is_request()) {
> if(has_totag()) {
> if(check_route_param("nat=yes")) {
> setbflag(FLB_NATB);
> }
> }
> }
> if (!(isflagset(FLT_NATS) || isbflagset(FLB_NATB)))
> return;
>
> rtpengine_manage("replace-origin replace-session-connection");
>
> if (is_request()) {
> if (!has_totag()) {
> if(t_is_branch_route()) {
> add_rr_param(";nat=yes");
> }
> }
> }
> if (is_reply()) {
> if(isbflagset(FLB_NATB)) {
> if(is_first_hop())
> set_contact_alias();
> }
> }
> #!endif
> return;
> }
>
> Does anything jump out at you as being wrong?
>
> My goal is to have linphone clients (android) with ICE enabled call
> Groundwire clients (iOS) also with ICE enabled. Both are using the same
> STUN server that sits on the same machine as Kamailio.
> Ideally rtpengine wouldn't get involved at all and would ignore the SDP
> since both UACs should be able to use ICE to negotiate a p2p connection
> between them.
> However, if one is behind symmetric NAT than rtpengine should be called
> in to relay the media.
>
> I've also tried the above config by
> adding rtpengine_manage("replace-origin replace-session-connection
> ICE=force-relay"); but I think that's made debugging even harder.
>
> I'm not sure if the problem lies with kamailio/rtpengine (or my config
> for them) or if it is the UACs that aren't playing nicely even though
> they supposedly support SIP and ICE RFCs. It seems when they call each
> other ICE isn't being used at all (at least linphone display shows ICE
> not activated) even though the media is flowing normally.
>
> Anyway, I don't need to be spoon fed, but a push in the right direction
> would be much appreciated.

The best way to find out what could be going on is to post the complete
log from rtpengine for one such call. This will show all the SDP bodies
and everything else involved.

cheers

_______________________________________________
sr-dev mailing list
sr-dev@lists.sip-router.org
http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev