Hi,
I just updated to 4.2 stable along with latest rtpengine module compiled today from git.
I'm also running latest (compiled today) RFC5766 turn server on the same Debian 7 host.
I noticed that sometimes I get one way audio with linphone client in Android, and looking through the logs I see these STUN error messages:
rtpengine[4633]: [port 10448] Not handling potential STUN packet from 85.xx.xx.xx:7076: FINGERPRINT attribute missing
That 85.xx.xx.xx address is indeed the public IP of the linphone client.
Looking further in the RTP engine logs you can see it's not getting the IP which I believe would explain the 1 way audio issues.
Media #1, port 10468 <> [::]:0 , 0 p, 0 b, 0 e
Now why would rtpengine be dealing with STUN packets at all? I imagine the RFC5766 stun server would handle that completely.
I guess the more I dig, the more confused I get. Has anything changed recently in rtpengine or kamailio 4.2 to produce this behavior?
Thanks
On 10/22/14 15:48, Peter Villeneuve wrote:
Hi,
I just updated to 4.2 stable along with latest rtpengine module compiled today from git.
I'm also running latest (compiled today) RFC5766 turn server on the same Debian 7 host.
I noticed that sometimes I get one way audio with linphone client in Android, and looking through the logs I see these STUN error messages:
rtpengine[4633]: [port 10448] Not handling potential STUN packet from 85.xx.xx.xx:7076: FINGERPRINT attribute missing
That 85.xx.xx.xx address is indeed the public IP of the linphone client.
Looking further in the RTP engine logs you can see it's not getting the IP which I believe would explain the 1 way audio issues.
Media #1, port 10468 <> [::]:0 , 0 p, 0 b, 0 e
Now why would rtpengine be dealing with STUN packets at all? I imagine the RFC5766 stun server would handle that completely.
I guess the more I dig, the more confused I get. Has anything changed recently in rtpengine or kamailio 4.2 to produce this behavior?
This is part of ICE (RFC 5245 and RFC 5389). If ICE is enabled, rtpengine will listen for and handle STUN packets, which in this context require the fingerprint attribute.
I don't think this explains your 1-way audio issue though. From the log message you posted, I suspect that no "answer" was received by rtpengine.
cheers
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.
Thanks,
Peter
On Wed, Oct 22, 2014 at 9:00 PM, Richard Fuchs rfuchs@sipwise.com wrote:
On 10/22/14 15:48, Peter Villeneuve wrote:
Hi,
I just updated to 4.2 stable along with latest rtpengine module compiled today from git.
I'm also running latest (compiled today) RFC5766 turn server on the same Debian 7 host.
I noticed that sometimes I get one way audio with linphone client in Android, and looking through the logs I see these STUN error messages:
rtpengine[4633]: [port 10448] Not handling potential STUN packet from 85.xx.xx.xx:7076: FINGERPRINT attribute missing
That 85.xx.xx.xx address is indeed the public IP of the linphone client.
Looking further in the RTP engine logs you can see it's not getting the IP which I believe would explain the 1 way audio issues.
Media #1, port 10468 <> [::]:0 , 0 p, 0 b, 0 e
Now why would rtpengine be dealing with STUN packets at all? I imagine the RFC5766 stun server would handle that completely.
I guess the more I dig, the more confused I get. Has anything changed recently in rtpengine or kamailio 4.2 to produce this behavior?
This is part of ICE (RFC 5245 and RFC 5389). If ICE is enabled, rtpengine will listen for and handle STUN packets, which in this context require the fingerprint attribute.
I don't think this explains your 1-way audio issue though. From the log message you posted, I suspect that no "answer" was received by rtpengine.
cheers
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
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
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
On 10/23/14 13:44, Peter Villeneuve wrote:
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.
I don't really see anything wrong with this call and it doesn't seem to exhibit the issues you've mentioned, as there are no error messages or anything else strange. Both clients are ICE and you're using ICE=force-relay, so I'm guessing that the clients have established communications outside of rtpengine's path, which is why it closes the call with a timeout (no packets received).
cheers
You're right. That call went through without any problems.
Here are the logs for 2 more calls. One from 1000 (Linphone on Android with ICE enabled) to 1010 (Groundwire on iOS with ICE enabled), resulting in no audio in either direction.
And call 2 from 1000 to 1104 (Linphone on Android with ICE enabled). This resulted in 1 way audio.
Both of these calls had the ICE=force-relay flag set
I then tried the same exact calls, this time without ICE=force-relay, and both calls went through fine. Also, I don't see that Missing STUN fingerprint that shows up once in awhile
Weird.
I hope you can make some sense of this.
Cheers,
Peter
Here are the logs
rtpengine_manage("replace-origin replace-session-connection ICE=force-relay");
Oct 23 18:23:36 pbx rtpengine[4633]: Got valid command from 127.0.0.1:58816: offer - { "sdp": "v=0#015#012o=1000 2180 1168 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:fc97aefa4dc375ac8b8eb358#015#012a=ice-ufrag:97dc6a58#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 ... Oct 23 18:23:36 pbx rtpengine[4633]: ... #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.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": "3FPovr0noK", "receive ... Oct 23 18:23:36 pbx rtpengine[4633]: ... d-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "ypjpPM5OI", "command": "offer" } Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] Creating new call Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] Returning to SIP proxy: d3:sdp1001:v=0#015#012o=1000 2180 1168 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:fc97aefa4dc375ac8b8eb358#015#012a=ice-ufrag:97dc6a58#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/800 ... Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] ... 0#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 12230 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777 ... Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] ... 214 79.xx.xx.153 12231 typ relay#015#0126:result2:oke Oct 23 18:23:36 pbx rtpengine[4633]: Got valid command from 127.0.0.1:58816: offer - { "sdp": "v=0#015#012o=1000 2180 1168 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:fc97aefa4dc375ac8b8eb358#015#012a=ice-ufrag:97dc6a58#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 ... Oct 23 18:23:36 pbx rtpengine[4633]: ... #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.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": "3FPovr0noK", "receive ... Oct 23 18:23:36 pbx rtpengine[4633]: ... d-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "ypjpPM5OI", "command": "offer" } Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] Returning to SIP proxy: d3:sdp1001:v=0#015#012o=1000 2180 1168 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:fc97aefa4dc375ac8b8eb358#015#012a=ice-ufrag:97dc6a58#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/800 ... Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] ... 0#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 12230 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777 ... Oct 23 18:23:36 pbx rtpengine[4633]: [3FPovr0noK] ... 214 79.xx.xx.153 12231 typ relay#015#0126:result2:oke Oct 23 18:23:49 pbx rtpengine[4633]: Got valid command from 127.0.0.1:42531: answer - { "sdp": "v=0#015#012o=- 18970 59662 IN IP4 85.xx.xx.247#015#012s=wpxmvks#015#012c=IN IP4 85.xx.xx.247#015#012t=0 0#015#012m=audio 48886 RTP/AVP 124 101#015#012a=rtpmap:101 TELEPHONE-EVENT/8000#015#012a=rtpmap:124 OPUS/48000/2#015#012a=fmtp:101 0-15#015#012a=fmtp:124 maxplaybackrate=16000;useinbandfec=1#015#012a=ice-ufrag:B6427B#015#012a=ice-pwd:A0342B9F09BCB4AE207C5A8A146321BF#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 1 UDP 2130706431 192.168.1.3 48886 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 1 UDP 169449 ... Oct 23 18:23:49 pbx rtpengine[4633]: ... 8815 85.xx.xx.247 48886 typ srflx raddr 192.168.1.3 rport 48886#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 2 UDP 2130706430 192.168.1.3 48887 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 2 UDP 1694498814 85.xx.xx.247 48887 typ srflx raddr 192.168.1.3 rport 48887#015#012a=ptime:20#015#012a=sendrecv#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "3FPovr0noK", "received-from": [ "IP4", "162.243.35.55" ], "from-tag": "ypjpPM5OI", "to-tag": "1A19A9FE28B2BBC914495C1A3B5ACA0F" ... Oct 23 18:23:49 pbx rtpengine[4633]: ... , "command": "answer" } Oct 23 18:23:49 pbx rtpengine[4633]: [3FPovr0noK] Returning to SIP proxy: d3:sdp882:v=0#015#012o=- 18970 59662 IN IP4 85.xx.xx.247#015#012s=wpxmvks#015#012c=IN IP4 85.xx.xx.247#015#012t=0 0#015#012m=audio 48886 RTP/AVP 124 101#015#012a=rtpmap:101 TELEPHONE-EVENT/8000#015#012a=rtpmap:124 OPUS/48000/2#015#012a=fmtp:101 0-15#015#012a=fmtp:124 maxplaybackrate=16000;useinbandfec=1#015#012a=ice-ufrag:B6427B#015#012a=ice-pwd:A0342B9F09BCB4AE207C5A8A146321BF#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 1 UDP 2130706431 192.168.1.3 48886 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 1 UDP 1694498815 85.xx.xx.247 48886 ... Oct 23 18:23:49 pbx rtpengine[4633]: [3FPovr0noK] ... typ srflx raddr 192.168.1.3 rport 48886#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 2 UDP 2130706430 192.168.1.3 48887 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 2 UDP 1694498814 85.xx.xx.247 48887 typ srflx raddr 192.168.1.3 rport 48887#015#012a=ptime:20#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12250 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777214 79.xx.xx.153 12251 typ relay#015#0126:result2:oke Oct 23 18:24:19 pbx rtpengine[4633]: Got valid command from 127.0.0.1:59621: delete - { "ICE": "force-relay", "call-id": "3FPovr0noK", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "ypjpPM5OI", "command": "delete" } Oct 23 18:24:19 pbx rtpengine[4633]: [3FPovr0noK] Scheduling deletion of call branch 'ypjpPM5OI' in 30 seconds Oct 23 18:24:19 pbx rtpengine[4633]: [3FPovr0noK] Returning to SIP proxy: d7:createdi1414088616e11:last signali1414088629e4:tagsd9:ypjpPM5OId3:tag9:ypjpPM5OI7:createdi1414088616e16:in dialogue with32:1A19A9FE28B2BBC914495C1A3B5ACA0F6:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti12250e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee11:last packeti1414088616e5:flagsl3:RTP6:fillede5:statsd7:packetsi0e5:bytesi0e6:errorsi0eeed10: ... Oct 23 18:24:19 pbx rtpengine[4633]: [3FPovr0noK] ... local porti12251e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee11:last packeti1414088616e5:flagsl4:RTCP6:fillede5:statsd7:packetsi0e5:bytesi0e6:errorsi0eeee5:flagsl11:initialized11:passthrough3:ICEeeee32:1A19A9FE28B2BBC914495C1A3B5ACA0Fd3:tag32:1A19A9FE28B2BBC914495C1A3B5ACA0F7:createdi1414088616e16:in dialogue with9:ypjpPM5OI6:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti1 ... Oct 23 18:24:19 pbx rtpengine[4633]: [3FPovr0noK] ... 2230e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti48886ee19:advertised endpointd6:family4:IPv47:address13:162.243.35.554:porti48886ee11:last packeti1414088631e5:flagsl3:RTP6:fillede5:statsd7:packetsi5e5:bytesi460e6:errorsi0eeed10:local porti12231e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti48887ee19:advertised endpointd6:family4:IPv47:address13:162.243.35.554:porti48887ee11:last packeti1414088632e5:flagsl4:RTCP6:fillede5:statsd7:packetsi5e5:bytesi460e6:errorsi0eeee5:fl ... Oct 23 18:24:19 pbx rtpengine[4633]: [3FPovr0noK] ... agsl11:initialized11:passthrough3:ICEeeeee6:totalsd3:RTPd7:packetsi5e5:bytesi460e6:errorsi0ee4:RTCPd7:packetsi5e5:bytesi460e6:errorsi0eee6:result2:oke Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] Call branch 'ypjpPM5OI' deleted, no more branches remaining Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] Final packet stats: Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] --- Tag '1A19A9FE28B2BBC914495C1A3B5ACA0F', created 1:13 ago, in dialogue with 'ypjpPM5OI' Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] ------ Media #1, port 12230 <> 85.xx.xx.247:48886, 5 p, 460 b, 0 e Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] ------ Media #1, port 12231 <> 85.xx.xx.247:48887 (RTCP), 5 p, 460 b, 0 e Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] --- Tag 'ypjpPM5OI', created 1:13 ago, in dialogue with '1A19A9FE28B2BBC914495C1A3B5ACA0F' Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] ------ Media #1, port 12250 <> 85.xx.xx.247:7076 , 0 p, 0 b, 0 e Oct 23 18:24:49 pbx rtpengine[4633]: [3FPovr0noK] ------ Media #1, port 12251 <> 85.xx.xx.247:7077 (RTCP), 0 p, 0 b, 0 e Oct 23 18:25:11 pbx rtpengine[4633]: Got valid command from 127.0.0.1:59621: offer - { "sdp": "v=0#015#012o=1000 2963 761 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:da4ac4e59c3fbbde88b55a6d#015#012a=ice-ufrag:2a32181a#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 18:25:11 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": "6bRH2rngPS", "received ... Oct 23 18:25:11 pbx rtpengine[4633]: ... -from": [ "IP4", "85.xx.xx.247" ], "from-tag": "x9WGjS4~9", "command": "offer" } Oct 23 18:25:11 pbx rtpengine[4633]: [6bRH2rngPS] Creating new call Oct 23 18:25:11 pbx rtpengine[4633]: [6bRH2rngPS] Returning to SIP proxy: d3:sdp1000:v=0#015#012o=1000 2963 761 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:da4ac4e59c3fbbde88b55a6d#015#012a=ice-ufrag:2a32181a#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 18:25:11 pbx rtpengine[4633]: [6bRH2rngPS] ... #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 12268 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 167772 ... Oct 23 18:25:11 pbx rtpengine[4633]: [6bRH2rngPS] ... 14 79.xx.xx.153 12269 typ relay#015#0126:result2:oke Oct 23 18:25:14 pbx rtpengine[4633]: Got valid command from 127.0.0.1:42531: answer - { "sdp": "v=0#015#012o=1104 2835 2386 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:57046d3e78d22a34b13ce526#015#012a=ice-ufrag:5b4f3e35#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 1051 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 18:25:14 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 1051 typ srflx raddr 192.168.1.16 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 1052 typ srflx raddr 192.168.1.16 rport 7077#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "6bRH2rngPS", " ... Oct 23 18:25:14 pbx rtpengine[4633]: ... received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "x9WGjS4~9", "to-tag": "nfaREr4", "command": "answer" } Oct 23 18:25:14 pbx rtpengine[4633]: [6bRH2rngPS] Returning to SIP proxy: d3:sdp1007:v=0#015#012o=1104 2835 2386 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:57046d3e78d22a34b13ce526#015#012a=ice-ufrag:5b4f3e35#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 1051 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 18:25:14 pbx rtpengine[4633]: [6bRH2rngPS] ... 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 1051 typ srflx raddr 192.168.1.16 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 1052 typ srflx raddr 192.168.1.16 rport 7077#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12278 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP ... Oct 23 18:25:14 pbx rtpengine[4633]: [6bRH2rngPS] ... 16777214 79.xx.xx.153 12279 typ relay#015#0126:result2:oke Oct 23 18:25:18 pbx rtpengine[4633]: [6bRH2rngPS port 12268] Confirmed peer address as 85.xx.xx.247:7076 Oct 23 18:25:18 pbx rtpengine[4633]: [6bRH2rngPS port 12278] Confirmed peer address as 85.xx.xx.247:7076 Oct 23 18:25:18 pbx rtpengine[4633]: [6bRH2rngPS port 12278] Kernelizing media stream Oct 23 18:25:18 pbx rtpengine[4633]: [6bRH2rngPS port 12269] Confirmed peer address as 85.xx.xx.247:7077 Oct 23 18:25:18 pbx rtpengine[4633]: [6bRH2rngPS port 12279] Confirmed peer address as 85.xx.xx.247:7077 Oct 23 18:25:21 pbx rtpengine[4633]: [6bRH2rngPS port 12268] Kernelizing media stream Oct 23 18:25:27 pbx rtpengine[4633]: Got valid command from 127.0.0.1:59621: offer - { "sdp": "v=0#015#012o=1000 2963 762 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:da4ac4e59c3fbbde88b55a6d#015#012a=ice-ufrag:2a32181a#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 18:25:27 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=rtcp:7077 IN IP4 192.168.1.4#015#012a=nortpproxy:yes#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=remote-candidates:1 192.168.1.1 7076 2 192.168.1.16 7077#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "6bRH2rngPS", "received-from": [ "IP4", "85.xx.xx.247" ], "fr ... Oct 23 18:25:27 pbx rtpengine[4633]: ... om-tag": "x9WGjS4~9", "to-tag": "nfaREr4", "command": "offer" } Oct 23 18:25:27 pbx rtpengine[4633]: [6bRH2rngPS] Returning to SIP proxy: d3:sdp960:v=0#015#012o=1000 2963 762 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:da4ac4e59c3fbbde88b55a6d#015#012a=ice-ufrag:2a32181a#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 18:25:27 pbx rtpengine[4633]: [6bRH2rngPS] ... a=fmtp:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=rtcp:7077 IN IP4 192.168.1.4#015#012a=nortpproxy:yes#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=remote-candidates:1 192.168.1.1 7076 2 192.168.1.16 7077#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12268 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777214 79.xx.xx.153 12269 typ relay#015#0126:resu ... Oct 23 18:25:27 pbx rtpengine[4633]: [6bRH2rngPS] ... lt2:oke Oct 23 18:25:27 pbx rtpengine[4633]: Got valid command from 127.0.0.1:42531: answer - { "sdp": "v=0#015#012o=1104 2835 2388 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:57046d3e78d22a34b13ce526#015#012a=ice-ufrag:5b4f3e35#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 18:25:27 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=rtcp:7077 IN IP4 192.168.1.16#015#012a=nortpproxy:yes#015#012a=candidate:1 2 UDP 2130706430 192.168.1.16 7077 typ host#015#012a=candidate:3 1 UDP 1862270975 192.168.1.1 7076 typ prflx raddr 192.168.1.16 rport 7076#015#012", "ICE": "force-relay", "replace": [ "origin", "session-connection" ], "call-id": "6bRH2rngPS", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "x9WGjS4~9", "to-tag": "nfaREr4", "command": "answer" } Oct 23 18:25:27 pbx rtpengine[4633]: [6bRH2rngPS] Returning to SIP proxy: d3:sdp895:v=0#015#012o=1104 2835 2388 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:57046d3e78d22a34b13ce526#015#012a=ice-ufrag:5b4f3e35#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 18:25:27 pbx rtpengine[4633]: [6bRH2rngPS] ... p:110 vbr=on#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=rtcp:7077 IN IP4 192.168.1.16#015#012a=nortpproxy:yes#015#012a=candidate:1 2 UDP 2130706430 192.168.1.16 7077 typ host#015#012a=candidate:3 1 UDP 1862270975 192.168.1.1 7076 typ prflx raddr 192.168.1.16 rport 7076#015#012a=sendrecv#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 16777215 79.xx.xx.153 12290 typ relay#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 16777214 79.xx.xx.153 12291 typ relay#015#0126:result2:oke Oct 23 18:26:23 pbx rtpengine[4633]: Got valid command from 127.0.0.1:58816: delete - { "ICE": "force-relay", "call-id": "6bRH2rngPS", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "nfaREr4", "command": "delete" } Oct 23 18:26:23 pbx rtpengine[4633]: [6bRH2rngPS] Scheduling deletion of call branch 'nfaREr4' in 30 seconds Oct 23 18:26:23 pbx rtpengine[4633]: [6bRH2rngPS] Returning to SIP proxy: d7:createdi1414088711e11:last signali1414088727e4:tagsd7:nfaREr4d3:tag7:nfaREr47:createdi1414088711e16:in dialogue with9:x9WGjS4~96:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti12268e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee11:last packeti1414088727e5:flagsl3:RTP6:fillede5:statsd7:packetsi22e5:bytesi2272e6:errorsi0eeed10:local porti12269e8:endpo ... Oct 23 18:26:23 pbx rtpengine[4633]: [6bRH2rngPS] ... intd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee11:last packeti1414088727e5:flagsl4:RTCP6:filled10:kernelized17:no kernel supporte5:statsd7:packetsi23e5:bytesi1664e6:errorsi0eeee5:flagsl11:initialized11:passthrough3:ICEeeee9:x9WGjS4~9d3:tag9:x9WGjS4~97:createdi1414088711e16:in dialogue with7:nfaREr46:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti12290e8:endpointd6:family4:IPv47:addre ... Oct 23 18:26:23 pbx rtpengine[4633]: [6bRH2rngPS] ... ss14:85.xx.xx.2474:porti7076ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee11:last packeti1414088727e5:flagsl3:RTP6:fillede5:statsd7:packetsi25e5:bytesi2628e6:errorsi0eeed10:local porti12291e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee11:last packeti1414088726e5:flagsl4:RTCP6:filled10:kernelized17:no kernel supporte5:statsd7:packetsi25e5:bytesi2208e6:errorsi0eeee5:flag ... Oct 23 18:26:23 pbx rtpengine[4633]: [6bRH2rngPS] ... sl11:initialized11:passthrough3:ICEeeeee6:totalsd3:RTPd7:packetsi47e5:bytesi4900e6:errorsi0ee4:RTCPd7:packetsi48e5:bytesi3872e6:errorsi0eee6:result2:oke Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] Closing call due to timeout Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] Final packet stats: Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] --- Tag 'nfaREr4', created 1:16 ago, in dialogue with 'x9WGjS4~9' Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] ------ Media #1, port 12268 <> 85.xx.xx.247:7076 , 22 p, 2272 b, 0 e Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] ------ Media #1, port 12269 <> 85.xx.xx.247:7077 (RTCP), 23 p, 1664 b, 0 e Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] --- Tag 'x9WGjS4~9', created 1:16 ago, in dialogue with 'nfaREr4' Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] ------ Media #1, port 12290 <> 85.xx.xx.247:7076 , 25 p, 2628 b, 0 e Oct 23 18:26:27 pbx rtpengine[4633]: [6bRH2rngPS] ------ Media #1, port 12291 <> 85.xx.xx.247:7077 (RTCP), 25 p, 2208 b, 0 e
And the logs for the successful calls: rtpengine_manage("replace-origin replace-session-connection");
Oct 23 18:36:19 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35930: offer - { "sdp": "v=0#015#012o=1000 2738 4037 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:4ae5f0906c058b88649af65f#015#012a=ice-ufrag:bd451de7#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 ... Oct 23 18:36:19 pbx rtpengine[4633]: ... #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.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", "replace": [ "origin", "session-connection" ], "call-id": "JnnNxMkapj", "received-from": [ "IP4", "85. ... Oct 23 18:36:19 pbx rtpengine[4633]: ... 138.120.247" ], "from-tag": "lL2Xy9ZAn", "command": "offer" } Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] Creating new call Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] Returning to SIP proxy: d3:sdp1024:v=0#015#012o=1000 2738 4037 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:4ae5f0906c058b88649af65f#015#012a=ice-ufrag:bd451de7#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12356 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 79.xx.xx.153#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 sp ... Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] ... eex/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#012a=sendrecv#015#012a=rtcp:12357#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12356 typ host#015#012a=candidate:GGlJTG ... Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] ... IsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12357 typ host#015#0126:result2:oke Oct 23 18:36:19 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35930: offer - { "sdp": "v=0#015#012o=1000 2738 4037 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:4ae5f0906c058b88649af65f#015#012a=ice-ufrag:bd451de7#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 ... Oct 23 18:36:19 pbx rtpengine[4633]: ... #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.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", "replace": [ "origin", "session-connection" ], "call-id": "JnnNxMkapj", "received-from": [ "IP4", "85. ... Oct 23 18:36:19 pbx rtpengine[4633]: ... 138.120.247" ], "from-tag": "lL2Xy9ZAn", "command": "offer" } Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] Returning to SIP proxy: d3:sdp1024:v=0#015#012o=1000 2738 4037 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:4ae5f0906c058b88649af65f#015#012a=ice-ufrag:bd451de7#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12356 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 79.xx.xx.153#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 sp ... Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] ... eex/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#012a=sendrecv#015#012a=rtcp:12357#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12356 typ host#015#012a=candidate:GGlJTG ... Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] ... IsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12357 typ host#015#0126:result2:oke Oct 23 18:36:19 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35930: offer - { "sdp": "v=0#015#012o=1000 2738 4037 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:4ae5f0906c058b88649af65f#015#012a=ice-ufrag:bd451de7#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 ... Oct 23 18:36:19 pbx rtpengine[4633]: ... #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.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", "replace": [ "origin", "session-connection" ], "call-id": "JnnNxMkapj", "received-from": [ "IP4", "85. ... Oct 23 18:36:19 pbx rtpengine[4633]: ... 138.120.247" ], "from-tag": "lL2Xy9ZAn", "command": "offer" } Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] Returning to SIP proxy: d3:sdp1024:v=0#015#012o=1000 2738 4037 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:4ae5f0906c058b88649af65f#015#012a=ice-ufrag:bd451de7#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12356 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 79.xx.xx.153#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 sp ... Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] ... eex/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#012a=sendrecv#015#012a=rtcp:12357#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12356 typ host#015#012a=candidate:GGlJTG ... Oct 23 18:36:19 pbx rtpengine[4633]: [JnnNxMkapj] ... IsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12357 typ host#015#0126:result2:oke Oct 23 18:36:28 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35845: answer - { "sdp": "v=0#015#012o=- 63734 35532 IN IP4 85.xx.xx.247#015#012s=zctlrun#015#012c=IN IP4 85.xx.xx.247#015#012t=0 0#015#012m=audio 33572 RTP/AVP 124 101#015#012a=rtpmap:101 TELEPHONE-EVENT/8000#015#012a=rtpmap:124 OPUS/48000/2#015#012a=fmtp:101 0-15#015#012a=fmtp:124 maxplaybackrate=16000;useinbandfec=1#015#012a=ice-ufrag:F4BB5A#015#012a=ice-pwd:B98DAF9CB90133B8671D3465AE88B9BD#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 1 UDP 2130706431 192.168.1.3 33572 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 1 UDP 169449 ... Oct 23 18:36:28 pbx rtpengine[4633]: ... 8815 85.xx.xx.247 33572 typ srflx raddr 192.168.1.3 rport 33572#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 2 UDP 2130706430 192.168.1.3 33573 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 2 UDP 1694498814 85.xx.xx.247 33573 typ srflx raddr 192.168.1.3 rport 33573#015#012a=ptime:20#015#012a=sendrecv#015#012", "replace": [ "origin", "session-connection" ], "call-id": "JnnNxMkapj", "received-from": [ "IP4", "162.243.35.55" ], "from-tag": "lL2Xy9ZAn", "to-tag": "CAACC2884F8BF08C0E972BCFBCD89F09", "command": "answer" ... Oct 23 18:36:28 pbx rtpengine[4633]: ... } Oct 23 18:36:28 pbx rtpengine[4633]: [JnnNxMkapj] Returning to SIP proxy: d3:sdp898:v=0#015#012o=- 63734 35532 IN IP4 79.xx.xx.153#015#012s=zctlrun#015#012c=IN IP4 79.xx.xx.153#015#012t=0 0#015#012m=audio 12376 RTP/AVP 124 101#015#012a=rtpmap:101 TELEPHONE-EVENT/8000#015#012a=rtpmap:124 OPUS/48000/2#015#012a=fmtp:101 0-15#015#012a=fmtp:124 maxplaybackrate=16000;useinbandfec=1#015#012a=ice-ufrag:F4BB5A#015#012a=ice-pwd:B98DAF9CB90133B8671D3465AE88B9BD#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 1 UDP 2130706431 192.168.1.3 33572 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 1 UDP 1694498815 85.xx.xx.247 33572 ... Oct 23 18:36:28 pbx rtpengine[4633]: [JnnNxMkapj] ... typ srflx raddr 192.168.1.3 rport 33572#015#012a=candidate:z326/PkxOom7UM/yh6QLaQ== 2 UDP 2130706430 192.168.1.3 33573 typ host#015#012a=candidate:9ZWlDYzRLqo8Q4979OwFlQ== 2 UDP 1694498814 85.xx.xx.247 33573 typ srflx raddr 192.168.1.3 rport 33573#015#012a=ptime:20#015#012a=sendrecv#015#012a=rtcp:12377#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12376 typ host#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12377 typ host#015#0126:result2:oke Oct 23 18:36:32 pbx rtpengine[4633]: [JnnNxMkapj port 12376] Confirmed peer address as 85.xx.xx.247:7076 Oct 23 18:36:32 pbx rtpengine[4633]: [JnnNxMkapj port 12356] Confirmed peer address as 85.xx.xx.247:33572 Oct 23 18:36:32 pbx rtpengine[4633]: [JnnNxMkapj port 12356] Kernelizing media stream Oct 23 18:36:32 pbx rtpengine[4633]: [JnnNxMkapj port 12376] Kernelizing media stream Oct 23 18:36:32 pbx rtpengine[4633]: [JnnNxMkapj port 12357] Confirmed peer address as 85.xx.xx.247:33573 Oct 23 18:36:33 pbx rtpengine[4633]: [JnnNxMkapj port 12377] Confirmed peer address as 85.xx.xx.247:7077 Oct 23 18:36:49 pbx rtpengine[4633]: Got valid command from 127.0.0.1:46214: delete - { "call-id": "JnnNxMkapj", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "lL2Xy9ZAn", "command": "delete" } Oct 23 18:36:49 pbx rtpengine[4633]: [JnnNxMkapj] Scheduling deletion of call branch 'lL2Xy9ZAn' in 30 seconds Oct 23 18:36:49 pbx rtpengine[4633]: [JnnNxMkapj] Returning to SIP proxy: d7:createdi1414089379e11:last signali1414089388e4:tagsd9:lL2Xy9ZAnd3:tag9:lL2Xy9ZAn7:createdi1414089379e16:in dialogue with32:CAACC2884F8BF08C0E972BCFBCD89F096:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti12376e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee11:last packeti1414089409e5:flagsl3:RTP6:filled9:confirmed10:kernelizede5:statsd7:packetsi1015e ... Oct 23 18:36:49 pbx rtpengine[4633]: [JnnNxMkapj] ... 5:bytesi133416e6:errorsi0eeed10:local porti12377e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee11:last packeti1414089409e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel supporte5:statsd7:packetsi7e5:bytesi916e6:errorsi0eeee5:flagsl11:initialized11:passthrough3:ICEeeee32:CAACC2884F8BF08C0E972BCFBCD89F09d3:tag32:CAACC2884F8BF08C0E972BCFBCD89F097:createdi1414089379e16:in dialogue with9:lL2Xy9ZAn ... Oct 23 18:36:49 pbx rtpengine[4633]: [JnnNxMkapj] ... 6:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti12356e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti33572ee19:advertised endpointd6:family4:IPv47:address13:162.243.35.554:porti33572ee11:last packeti1414089409e5:flagsl3:RTP6:filled9:confirmed10:kernelizede5:statsd7:packetsi1008e5:bytesi98393e6:errorsi0eeed10:local porti12357e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti33573ee19:advertised endpointd6:family4:IPv47:address13:162.243.35.554:port ... Oct 23 18:36:49 pbx rtpengine[4633]: [JnnNxMkapj] ... i33573ee11:last packeti1414089408e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel supporte5:statsd7:packetsi10e5:bytesi1072e6:errorsi0eeee5:flagsl11:initialized11:passthrough3:ICEeeeee6:totalsd3:RTPd7:packetsi2023e5:bytesi231809e6:errorsi0ee4:RTCPd7:packetsi17e5:bytesi1988e6:errorsi0eee6:result2:oke Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] Call branch 'lL2Xy9ZAn' deleted, no more branches remaining Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] Final packet stats: Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] --- Tag 'CAACC2884F8BF08C0E972BCFBCD89F09', created 1:00 ago, in dialogue with 'lL2Xy9ZAn' Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] ------ Media #1, port 12356 <> 85.xx.xx.247:33572, 1035 p, 101446 b, 0 e Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] ------ Media #1, port 12357 <> 85.xx.xx.247:33573 (RTCP), 10 p, 1072 b, 0 e Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] --- Tag 'lL2Xy9ZAn', created 1:00 ago, in dialogue with 'CAACC2884F8BF08C0E972BCFBCD89F09' Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] ------ Media #1, port 12376 <> 85.xx.xx.247:7076 , 1031 p, 135562 b, 0 e Oct 23 18:37:19 pbx rtpengine[4633]: [JnnNxMkapj] ------ Media #1, port 12377 <> 85.xx.xx.247:7077 (RTCP), 7 p, 916 b, 0 e Oct 23 18:37:57 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35930: offer - { "sdp": "v=0#015#012o=1000 997 1935 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:4dcbb6c73e2764eb41a68c00#015#012a=ice-ufrag:b0b8eaf0#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 18:37:57 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", "replace": [ "origin", "session-connection" ], "call-id": "DZt4oR7o~2", "received-from": [ "IP4", "85.1 ... Oct 23 18:37:57 pbx rtpengine[4633]: ... 38.120.247" ], "from-tag": "yFZte-7q7", "command": "offer" } Oct 23 18:37:57 pbx rtpengine[4633]: [DZt4oR7o~2] Creating new call Oct 23 18:37:57 pbx rtpengine[4633]: [DZt4oR7o~2] Returning to SIP proxy: d3:sdp1023:v=0#015#012o=1000 997 1935 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:4dcbb6c73e2764eb41a68c00#015#012a=ice-ufrag:b0b8eaf0#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12392 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 79.xx.xx.153#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 spe ... Oct 23 18:37:57 pbx rtpengine[4633]: [DZt4oR7o~2] ... ex/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#012a=sendrecv#015#012a=rtcp:12393#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12392 typ host#015#012a=candidate:GGlJTGI ... Oct 23 18:37:57 pbx rtpengine[4633]: [DZt4oR7o~2] ... sZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12393 typ host#015#0126:result2:oke Oct 23 18:38:00 pbx rtpengine[4633]: Got valid command from 127.0.0.1:42804: answer - { "sdp": "v=0#015#012o=1104 3139 3667 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:ea415569407247b0fb0310ee#015#012a=ice-ufrag:d0a39941#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 1052 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 18:38:00 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 1052 typ srflx raddr 192.168.1.16 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 1053 typ srflx raddr 192.168.1.16 rport 7077#015#012", "replace": [ "origin", "session-connection" ], "call-id": "DZt4oR7o~2", "received-from": [ "IP4 ... Oct 23 18:38:00 pbx rtpengine[4633]: ... ", "85.xx.xx.247" ], "from-tag": "yFZte-7q7", "to-tag": "U6V4a7v", "command": "answer" } Oct 23 18:38:00 pbx rtpengine[4633]: [DZt4oR7o~2] Returning to SIP proxy: d3:sdp1028:v=0#015#012o=1104 3139 3667 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=ice-pwd:ea415569407247b0fb0310ee#015#012a=ice-ufrag:d0a39941#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12412 RTP/AVP 124 120 111 110 0 8 101#015#012c=IN IP4 79.xx.xx.153#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 sp ... Oct 23 18:38:00 pbx rtpengine[4633]: [DZt4oR7o~2] ... eex/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 1052 typ srflx raddr 192.168.1.16 rport 7076#015#012a=candidate:2 2 UDP 1694498814 85.xx.xx.247 1053 typ srflx raddr 192.168.1.16 rport 7077#015#012a=sendrecv#015#012a=rtcp:12413#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12412 typ host#015#012a=candidate:GG ... Oct 23 18:38:00 pbx rtpengine[4633]: [DZt4oR7o~2] ... lJTGIsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12413 typ host#015#0126:result2:oke Oct 23 18:38:03 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35930: offer - { "sdp": "v=0#015#012o=1000 997 1936 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=nortpproxy:yes#015#012a=ice-pwd:4dcbb6c73e2764eb41a68c00#015#012a=ice-ufrag:b0b8eaf0#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=rtpma ... Oct 23 18:38:03 pbx rtpengine[4633]: ... p: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: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=remote-candidates:1 192.168.1.16 7076 2 192.168.1.16 7077#015#012", "replace": [ "origin", "session-connection" ], "call-id": "DZt4oR7o~2", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "yFZte-7q7", "to-tag": "U6V4a7v", "command": "offer" } Oct 23 18:38:03 pbx rtpengine[4633]: [DZt4oR7o~2] Returning to SIP proxy: d3:sdp913:v=0#015#012o=1000 997 1936 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=nortpproxy:yes#015#012a=ice-pwd:4dcbb6c73e2764eb41a68c00#015#012a=ice-ufrag:b0b8eaf0#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12392 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 ... Oct 23 18:38:03 pbx rtpengine[4633]: [DZt4oR7o~2] ... #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: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=remote-candidates:1 192.168.1.16 7076 2 192.168.1.16 7077#015#012a=sendrecv#015#012a=rtcp:12393#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12392 typ host#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12393 typ host#015#0126:result2:oke Oct 23 18:38:04 pbx rtpengine[4633]: Got valid command from 127.0.0.1:42804: answer - { "sdp": "v=0#015#012o=1104 3139 3669 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=nortpproxy:yes#015#012a=ice-pwd:ea415569407247b0fb0310ee#015#012a=ice-ufrag:d0a39941#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=r ... Oct 23 18:38:04 pbx rtpengine[4633]: ... tpmap: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: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#012", "replace": [ "origin", "session-connection" ], "call-id": "DZt4oR7o~2", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "yFZte-7q7", "to-tag": "U6V4a7v", "command": "answer" } Oct 23 18:38:04 pbx rtpengine[4633]: [DZt4oR7o~2] Returning to SIP proxy: d3:sdp855:v=0#015#012o=1104 3139 3669 IN IP4 79.xx.xx.153#015#012s=Talk#015#012c=IN IP4 79.xx.xx.153#015#012b=AS:1024#015#012t=0 0#015#012a=nortpproxy:yes#015#012a=ice-pwd:ea415569407247b0fb0310ee#015#012a=ice-ufrag:d0a39941#015#012a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics#015#012m=audio 12422 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 ... Oct 23 18:38:04 pbx rtpengine[4633]: [DZt4oR7o~2] ... #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: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=sendrecv#015#012a=rtcp:12423#015#012a=candidate:GGlJTGIsZALVPUmm 1 UDP 2130706175 79.xx.xx.153 12422 typ host#015#012a=candidate:GGlJTGIsZALVPUmm 2 UDP 2130706174 79.xx.xx.153 12423 typ host#015#0126:result2:oke Oct 23 18:38:08 pbx rtpengine[4633]: [DZt4oR7o~2 port 12422] Confirmed peer address as 85.xx.xx.247:7076 Oct 23 18:38:08 pbx rtpengine[4633]: [DZt4oR7o~2 port 12392] Confirmed peer address as 85.xx.xx.247:7076 Oct 23 18:38:08 pbx rtpengine[4633]: [DZt4oR7o~2 port 12392] Kernelizing media stream Oct 23 18:38:08 pbx rtpengine[4633]: [DZt4oR7o~2 port 12422] Kernelizing media stream Oct 23 18:38:08 pbx rtpengine[4633]: [DZt4oR7o~2 port 12423] Confirmed peer address as 85.xx.xx.247:7077 Oct 23 18:38:08 pbx rtpengine[4633]: [DZt4oR7o~2 port 12393] Confirmed peer address as 85.xx.xx.247:7077 Oct 23 18:38:20 pbx rtpengine[4633]: Got valid command from 127.0.0.1:35845: delete - { "call-id": "DZt4oR7o~2", "received-from": [ "IP4", "85.xx.xx.247" ], "from-tag": "U6V4a7v", "command": "delete" } Oct 23 18:38:20 pbx rtpengine[4633]: [DZt4oR7o~2] Scheduling deletion of call branch 'U6V4a7v' in 30 seconds Oct 23 18:38:20 pbx rtpengine[4633]: [DZt4oR7o~2] Returning to SIP proxy: d7:createdi1414089477e11:last signali1414089484e4:tagsd7:U6V4a7vd3:tag7:U6V4a7v7:createdi1414089477e16:in dialogue with9:yFZte-7q76:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti12392e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee11:last packeti1414089500e5:flagsl3:RTP6:filled9:confirmed10:kernelizede5:statsd7:packetsi877e5:bytesi110156e6:errorsi0eeed ... Oct 23 18:38:20 pbx rtpengine[4633]: [DZt4oR7o~2] ... 10:local porti12393e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee11:last packeti1414089497e5:flagsl4:RTCP6:filled9:confirmed10:kernelized17:no kernel supporte5:statsd7:packetsi8e5:bytesi1500e6:errorsi0eeee5:flagsl11:initialized11:passthrough3:ICEeeee9:yFZte-7q7d3:tag9:yFZte-7q77:createdi1414089477e16:in dialogue with7:U6V4a7v6:mediasld5:indexi1e4:type5:audio8:protocol7:RTP/AVP7:streamsld10:local porti1 ... Oct 23 18:38:20 pbx rtpengine[4633]: [DZt4oR7o~2] ... 2422e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7076ee11:last packeti1414089500e5:flagsl3:RTP6:filled9:confirmed10:kernelizede5:statsd7:packetsi970e5:bytesi121770e6:errorsi0eeed10:local porti12423e8:endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee19:advertised endpointd6:family4:IPv47:address14:85.xx.xx.2474:porti7077ee11:last packeti1414089500e5:flagsl4:RTCP6:filled9:confirmed10:kernelized ... Oct 23 18:38:20 pbx rtpengine[4633]: [DZt4oR7o~2] ... 17:no kernel supporte5:statsd7:packetsi12e5:bytesi1936e6:errorsi0eeee5:flagsl11:initialized11:passthrough3:ICEeeeee6:totalsd3:RTPd7:packetsi1847e5:bytesi231926e6:errorsi0ee4:RTCPd7:packetsi20e5:bytesi3436e6:errorsi0eee6:result2:oke
On Thu, Oct 23, 2014 at 7:14 PM, Richard Fuchs rfuchs@sipwise.com wrote:
On 10/23/14 13:44, Peter Villeneuve wrote:
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.
I don't really see anything wrong with this call and it doesn't seem to exhibit the issues you've mentioned, as there are no error messages or anything else strange. Both clients are ICE and you're using ICE=force-relay, so I'm guessing that the clients have established communications outside of rtpengine's path, which is why it closes the call with a timeout (no packets received).
cheers
sr-dev mailing list sr-dev@lists.sip-router.org http://lists.sip-router.org/cgi-bin/mailman/listinfo/sr-dev
-
Peter Villeneuve -
Richard Fuchs