[libnice] why is TURN prefered before STUN ?

Tue Nov 11 01:14:26 PST 2014

Drear Philip,
I get the gathering done signal only once.
Attached is a trace up to this point.

Rgds
Klaus

-----Original Message-----
From: Philip Withnall [mailto:philip at tecnocode.co.uk]
Sent: Montag, 10. November 2014 20:14
To: Klaus Kranz
Cc: nice at lists.freedesktop.org
Subject: Re: [libnice] why is TURN prefered before STUN ?

You’ve verified that all the local candidates on each peer are being
successfully set as remote candidates on the other peer?

Note that libnice will emit NiceAgent::candidate-gathering-done twice:
once for the STUN candidates, and a second time for the TURN candidates.

If it’s still chosen the TURN server at STATE_READY, there’s either a
problem with all of the non-TURN candidates, or a bug somewhere in your code
or libnice. Try running with NICE_DEBUG=all G_MESSAGES_DEBUG=all set in your
environment and see why libnice is rejecting the non-TURN candidates.

Philip

On Mon, 2014-11-10 at 17:27 +0100, Klaus Kranz wrote:
> Hi Philip,
> I wait until I get gathering_done callback. Then send the list of
> candidates to the other peer.
> At NICE_COMPONENT_STATE_READY event it has selected the "relay"
> instead of the "srflx" candidate, even though priorities are lower than
> the srflx ones.
> Rgds
> Klaus
>
>
> -----Original Message-----
> From: nice [mailto:nice-bounces at lists.freedesktop.org] On Behalf Of
> Philip Withnall
> Sent: Montag, 10. November 2014 16:11
> To: Klaus Kranz
> Cc: nice at lists.freedesktop.org
> Subject: Re: [libnice] why is TURN prefered before STUN ?
>
> Hi,
>
> On Mon, 2014-11-10 at 13:47 +0100, Klaus Kranz wrote:
>
> > in the hope not chasing a phantom, I am wondering that even though a
> > STUN srflx based connection is possible, libnice uses the TURN relay
> > path.
> >
> > Is there a way to let the library select relay as the last resort
> > only in the case that STUN srflx fails ?
>
> ICE assigns priorities to candidate pairs, and STUN is always
> prioritised above TURN — precisely because TURN is so slow and expensive.
>
> Are you using trickle ICE[1] or normal ICE? How are you checking which
> candidate pair libnice chooses to use? Are you waiting for the
> NiceAgent to reach NICE_COMPONENT_STATE_CONNECTED or
> NICE_COMPONENT_STATE_READY?
> The candidate pair selection isn’t final until STATE_READY.
>
> This kind of general question can go on the libnice mailing so that
> others can respond (and benefit from the answer!). :-)
>
> Philip
>
> [1]: https://tools.ietf.org/html/draft-ietf-mmusic-trickle-ice-01
>

-- 
.
-------------- next part --------------
TA_Setup(497CA9C563CDC437E5ECFF5199BEB11DBC80D4B5) posted
(process:21134): libnice-DEBUG: Agent 0xc700a0 : allocating stream id 1 (0x7feba4027bb0)
(process:21134): libnice-DEBUG: Agent 0xc700a0 : reliable stream
(process:21134): libnice-DEBUG: Agent 0xc700a0: Create Pseudo Tcp Socket for component 1
(process:21134): libnice-DEBUG: Agent 0xc700a0: added relay server [10.96.252.8]:3478 of type 0 to s/c 1/1 with user/pass : 7D3F3C3ED4F6A8A21AE7A272F676F32F72A6D18B -- zxcvb123
[09:58:29.140] [TWINE] twine_manager_handle_content_fetch(local,shrink) 
(process:21134): libnice-DEBUG: Agent 0xc700a0 : In ICE-FULL mode, starting candidate gathering.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : libnice compiled without UPnP support
(process:21134): libnice-DEBUG: Failed to convert address to string for interface ?lo?.
(process:21134): libnice-DEBUG: Failed to convert address to string for interface ?eth0?.
(process:21134): libnice-DEBUG: Interface:  lo
(process:21134): libnice-DEBUG: IP Address: 127.0.0.1
(process:21134): libnice-DEBUG: Ignoring loopback interface
(process:21134): libnice-DEBUG: Interface:  eth0
(process:21134): libnice-DEBUG: IP Address: 192.168.0.101
(process:21134): libnice-DEBUG: Interface:  lo
(process:21134): libnice-DEBUG: IP Address: ::1
(process:21134): libnice-DEBUG: Ignoring loopback interface
(process:21134): libnice-DEBUG: Interface:  eth0
(process:21134): libnice-DEBUG: IP Address: fe80::221:70ff:fed5:12c6%eth0
(process:21134): libnice-DEBUG: Agent 0xc700a0: Trying to create host candidate on port 0
(process:21134): libnice-DEBUG: Component 0x7feba4012770 (agent 0xc700a0): Attach source (stream 1).
(process:21134): libnice-DEBUG: Attaching source 0x7febac012a20 (socket 0x7feba4009de0, FD 27) to context 0xc68420
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Adding new srv-rflx candidate discovery 0x7febac022290

(process:21134): libnice-DEBUG: Agent 0xc700a0 : Adding new relay-rflx candidate discovery 0x7febac035ad0

(process:21134): libnice-DEBUG: Agent 0xc700a0: Trying to create host candidate on port 0
(process:21134): libnice-DEBUG: Agent 0xc700a0: Trying to create host candidate on port 0
(process:21134): libnice-DEBUG: Component 0x7feba4012770 (agent 0xc700a0): Attach source (stream 1).
(process:21134): libnice-DEBUG: Attaching source 0x7febac0128f0 (socket 0x7febac011040, FD 28) to context 0xc68420
(process:21134): libnice-DEBUG: Agent 0xc700a0: Trying to create host candidate on port 0
(process:21134): libnice-DEBUG: Agent 0xc700a0: Could not set IPV6 socket ToS: Protocol not available
(process:21134): libnice-DEBUG: Component 0x7feba4012770 (agent 0xc700a0): Attach source (stream 1).
(process:21134): libnice-DEBUG: Attaching source 0x7febac012980 (socket 0x7febac0110b0, FD 29) to context 0xc68420
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Adding new srv-rflx candidate discovery 0x7febac049310

(process:21134): libnice-DEBUG: Agent 0xc700a0 : Adding new relay-rflx candidate discovery 0x7febac05cb50

(process:21134): libnice-DEBUG: Agent 0xc700a0: Trying to create host candidate on port 0
(process:21134): libnice-DEBUG: Agent 0xc700a0: Trying to create host candidate on port 0
(process:21134): libnice-DEBUG: Agent 0xc700a0: Could not set IPV6 socket ToS: Protocol not available
(process:21134): libnice-DEBUG: Component 0x7feba4012770 (agent 0xc700a0): Attach source (stream 1).
(process:21134): libnice-DEBUG: Attaching source 0x7febac012df0 (socket 0x7febac011190, FD 30) to context 0xc68420
(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery tick #1 with list 0x7febac00b5a0 (1)
(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery - scheduling cand type 1 addr 10.96.252.8.

(process:21134): libnice-DEBUG: Agent 0xc700a0 : stream 1 component 1 STATE-CHANGE disconnected -> gathering.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery - scheduling cand type 3 addr 10.96.252.8.

(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery - scheduling cand type 1 addr 10.96.252.8.

(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery - scheduling cand type 3 addr 10.96.252.8.

SIGNAL: state changed stream:1 component:1 gathering[1]
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Received 1 valid messages of length 32 from base socket 0x7febac0110b0.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Packet received on local socket 29 from [10.96.252.8]:8887 (32 octets).
(process:21134): libnice-DEBUG: compact_input_message: **WARNING: SLOW PATH**
(process:21134): libnice-DEBUG: Message 0x7febb27ebbe0 (from: 0x7febb27ebae0, length: 32)
(process:21134): libnice-DEBUG: 	Buffer 0x7febb27ebc00 (length: 24)
(process:21134): libnice-DEBUG: 	Buffer 0x7febb27ebc20 (length: 65535)
(process:21134): libnice-DEBUG: Agent 0xc700a0: inbound STUN packet for 1/1 (stream/component) from [10.96.252.8]:8887 (32 octets) :
(process:21134): libnice-stun-DEBUG: STUN demux error: no cookie!
(process:21134): libnice-stun-DEBUG: STUN unknown: 0 mandatory attribute(s)!
(process:21134): libnice-stun-DEBUG: Received 32-bytes STUN message
(process:21134): libnice-stun-DEBUG:  No XOR-MAPPED-ADDRESS: 1
(process:21134): libnice-stun-DEBUG:  Mapped address found!
(process:21134): libnice-DEBUG: Agent 0xc700a0 : stun_bind_process/disc for 0x7febac049310 res 0.
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Valid STUN packet received.
(process:21134): libnice-DEBUG: component_io_cb: 0xc700a0: received 0 valid messages with 32 bytes
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Received 1 valid messages of length 132 from base socket 0x7febac0110b0.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Packet received on local socket 29 from [10.96.252.8]:3478 (132 octets).
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Packet received from TURN server candidate.
(process:21134): libnice-DEBUG: compact_input_message: **WARNING: SLOW PATH**
(process:21134): libnice-DEBUG: Message 0x7febb27ebbe0 (from: 0x7febb27ebae0, length: 132)
(process:21134): libnice-DEBUG: 	Buffer 0x7febb27ebc00 (length: 24)
(process:21134): libnice-DEBUG: 	Buffer 0x7febb27ebc20 (length: 65535)
(process:21134): libnice-DEBUG: Agent 0xc700a0: inbound STUN packet for 1/1 (stream/component) from [10.96.252.8]:3478 (132 octets) :
(process:21134): libnice-stun-DEBUG: STUN demux: OK!
(process:21134): libnice-stun-DEBUG: STUN unknown: 0 mandatory attribute(s)!
(process:21134): libnice-stun-DEBUG:  STUN error message received (code: 401)
(process:21134): libnice-DEBUG: Agent 0xc700a0 : stun_turn_process/disc for 0x7febac05cb50 res 2.
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Valid STUN packet received.
(process:21134): libnice-DEBUG: component_io_cb: 0xc700a0: received 0 valid messages with 132 bytes
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Received 0 valid messages of length 0 from base socket 0x7febac0110b0.
(process:21134): libnice-DEBUG: component_io_cb: 0xc700a0: received -1 valid messages with 0 bytes
(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery - scheduling cand type 3 addr 10.96.252.8.

(process:21134): libnice-stun-DEBUG:  Message HMAC-SHA1 message integrity:
(process:21134): libnice-stun-DEBUG:   key     : 0x7a78637662313233
(process:21134): libnice-stun-DEBUG:   sent    : 0x2bb34fd69a97815fa827c2cf7f0f92cf7d3a40d1
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Received 1 valid messages of length 104 from base socket 0x7febac0110b0.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Packet received on local socket 29 from [10.96.252.8]:3478 (104 octets).
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Packet received from TURN server candidate.
(process:21134): libnice-DEBUG: compact_input_message: **WARNING: SLOW PATH**
(process:21134): libnice-DEBUG: Message 0x7febb27ebbe0 (from: 0x7febb27ebae0, length: 104)
(process:21134): libnice-DEBUG: 	Buffer 0x7febb27ebc00 (length: 24)
(process:21134): libnice-DEBUG: 	Buffer 0x7febb27ebc20 (length: 65535)
(process:21134): libnice-DEBUG: Agent 0xc700a0: inbound STUN packet for 1/1 (stream/component) from [10.96.252.8]:3478 (104 octets) :
(process:21134): libnice-stun-DEBUG: STUN demux: OK!
(process:21134): libnice-stun-DEBUG:  Message HMAC-SHA1 fingerprint:
(process:21134): libnice-stun-DEBUG:   key     : 0x7a78637662313233
(process:21134): libnice-stun-DEBUG:   expected: 0xb4a4afb0a745225ee6b50de2304a71864e697747
(process:21134): libnice-stun-DEBUG:   received: 0xb4a4afb0a745225ee6b50de2304a71864e697747
(process:21134): libnice-stun-DEBUG: STUN auth: OK!
(process:21134): libnice-stun-DEBUG: STUN unknown: 0 mandatory attribute(s)!
(process:21134): libnice-stun-DEBUG: Received 104-bytes STUN message
(process:21134): libnice-stun-DEBUG:  Mapped address found!
(process:21134): libnice-DEBUG: Agent 0xc700a0 : stun_turn_process/disc for 0x7febac05cb50 res 1.
(process:21134): libnice-DEBUG: Candidate 0x7febac0149f0 (component-id 1) redundant, ignoring.
(process:21134): libnice-DEBUG: Candidate 0x7febac014a80 (component-id 1) redundant, ignoring.
(process:21134): libnice-DEBUG: Candidate 0x7febac014b10 (component-id 1) redundant, ignoring.
(process:21134): libnice-DEBUG: Component 0x7feba4012770 (agent 0xc700a0): Attach source (stream 1).
(process:21134): libnice-DEBUG: Attaching source 0x7febac0185a0 (socket 0x7febac011200, FD 29) to context 0xc68420
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Adding new refresh candidate 0x7febac070390 with timeout 1740000
(process:21134): libnice-DEBUG: timer source is : 0x7febac018690
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Valid STUN packet received.
(process:21134): libnice-DEBUG: component_io_cb: 0xc700a0: received 0 valid messages with 104 bytes
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Packet received from a TURN socket.
(process:21134): libnice-DEBUG: received message on TURN socket
(process:21134): libnice-DEBUG: agent_recv_message_unlocked: Received 0 valid messages of length 0 from base socket 0x7febac011200.
(process:21134): libnice-DEBUG: component_io_cb: 0xc700a0: received -1 valid messages with 0 bytes
(process:21134): libnice-stun-DEBUG: STUN transaction retransmitted (timeout 397ms).
(process:21134): libnice-stun-DEBUG: STUN transaction retransmitted (timeout 397ms).
(process:21134): libnice-stun-DEBUG: STUN transaction retransmitted (timeout 792ms).
(process:21134): libnice-stun-DEBUG: STUN transaction retransmitted (timeout 792ms).
(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery tick #51 with list 0x7febac00b5a0 (1)
(process:21134): libnice-stun-DEBUG: STUN transaction retransmitted (timeout 1585ms).
(process:21134): libnice-stun-DEBUG: STUN transaction retransmitted (timeout 1585ms).
(process:21134): libnice-DEBUG: Agent 0xc700a0 : discovery tick #101 with list 0x7febac00b5a0 (1)
(process:21134): libnice-DEBUG: Agent 0xc700a0 : bind discovery timed out, aborting discovery item.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : bind discovery timed out, aborting discovery item.
(process:21134): libnice-DEBUG: Agent 0xc700a0 : Candidate gathering FINISHED, stopping discovery timer.
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered UDP local candidate : [fe80::221:70ff:fed5:12c6]:33223 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered TCP-ACT local candidate : [fe80::221:70ff:fed5:12c6]:0 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered TCP-PASS local candidate : [fe80::221:70ff:fed5:12c6]:56430 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered UDP local candidate : [192.168.0.101]:58601 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered TCP-ACT local candidate : [192.168.0.101]:0 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered TCP-PASS local candidate : [192.168.0.101]:53609 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered UDP local candidate : [10.96.20.73]:58601 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered TCP-ACT local candidate : [10.96.20.73]:0 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered TCP-PASS local candidate : [10.96.20.73]:53609 for s1/c1. U/P '(null)'/'(null)'
(process:21134): libnice-DEBUG: Agent 0xc700a0: gathered UDP local candidate : [10.96.252.8]:62957 for s1/c1. U/P '(null)'/'(null)'
[09:58:32.156] [RA] SIGNAL:  candidate gathering done
SDP:m=- 62957 ICE/SDP
c=IN IP4 10.96.252.8
a=ice-ufrag:tBmU
a=ice-pwd:2pb+FfOzC3xhEWwT3lQnYB
a=candidate:1 1 UDP 1006633471 fe80::221:70ff:fed5:12c6 33223 typ host
a=candidate:2 1 TCP 2025849343 fe80::221:70ff:fed5:12c6 9 typ host tcptype active
a=candidate:3 1 TCP 2021655039 fe80::221:70ff:fed5:12c6 56430 typ host tcptype passive
a=candidate:4 1 UDP 1006633471 192.168.0.101 58601 typ host
a=candidate:5 1 TCP 2025849343 192.168.0.101 9 typ host tcptype active
a=candidate:6 1 TCP 2021655039 192.168.0.101 53609 typ host tcptype passive
a=candidate:7 1 UDP 838861311 10.96.20.73 58601 typ srflx raddr 192.168.0.101 rport 58601
a=candidate:8 1 TCP 1686110719 10.96.20.73 9 typ srflx raddr 192.168.0.101 rport 9 tcptype active
a=candidate:9 1 TCP 1681916415 10.96.20.73 53609 typ srflx raddr 192.168.0.101 rport 53609 tcptype passive
a=candidate:10 1 UDP 83886591 10.96.252.8 62957 typ relay raddr 192.168.0.101 rport 62957