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.
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