[jitsi-dev] Videobridge REST API Integration Questions


#1

Dear Jitsi Developers,

My company is trying to integrate the Jitsi videobridge into one of our
products, and I was hoping to get a little guidance. We are using the
REST API and have been following the REST API example available from ht
tps://github.com/jitsi/jitsi-videobridge/blob/master/doc/rest-
videobridge.md.

We've got code that generates an SDP blob that is accepted by Chrome
(sample below) and from which we are able to create a response. We take
that response and then translate it back to Colibri and use it to
update the Jitsi Videobridge (SDP and Colibri examples below).

ICE candidates are gathered (we actually gather the candidates and send
them to the signalling application before updating Colibri), and the
iceConnectionStatus changes to "checking", but the connection is never
made.

On the videobridge, we see the following errors, so we're confident
that the two are able to find one another and begin the connection
process.

JVB 2017-02-14 12:46:16.775 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=57459,localport=4443]:
End of stream!

and a few seconds later:

JVB 2017-02-14 12:46:30.141 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=57479,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=57479,localport=4443]

Is there anyone who might be able to provide insight as to what is
causing these errors? We've tried to run down the obvious issues:

1) The SDP we are generating is bad
2) The conversion from SDP back to Colibri is bad, and we are not
providing the connection candidates for the video bridge.
3) We're not correctly adding the ice candidates on the
RTCPeerConnection
4) There is a problem with the ufrag value

We would greatly appreciate any guidance.

Cheers,

Rob Oakes

{
	'channel-bundles': [{
	'id': u'81b6bbfd-aa11-440b-a697-572b0a715d16', 
	'transport': {
		'xmlns': 'urn:xmpp:jingle:transports:ice-udp:1',
		'rtcp-mux': True
	}}], 
	'id': u'ed6caf7fb7c64ed0',
	'contents': [{
		'channels': [{
			'rtp-level-relay-type': 'mixer', 
			'channel-bundle-id': u'81b6bbfd-aa11-440b-a697-572b0a715d16', 
			'initiator': True, 
			'endpoint': u'81b6bbfd-aa11-440b-a697-572b0a715d16', 
			'direction': 'sendrecv', 'expire': 10
		}],
		'name': 'audio'
		}, {
		'channels': [{
			'channel-bundle-id': u'81b6bbfd-aa11-440b-a697-572b0a715d16', 
		'initiator': True, 
		'endpoint': u'81b6bbfd-aa11-440b-a697-572b0a715d16', 
		'direction': 'sendrecv', 
		'last-n': 2, 'expire': 10}], 'name': 'video'}]}
v=0
o=- 3695777470 2 IN IP4 127.0.0.1
s=-
t=0 0
a=msid-semantic: WMS
a=group:BUNDLE audio video
m=audio 1 RTP/SAVPF 111 103 104 126
c=IN IP4 0.0.0.0
a=rtcp:1 IN IP4 0.0.0.0
a=ice-ufrag:464nj1b8v3uh7n
a=ice-pwd:4v6ani5kuehel655qbolgev56v
a=fingerprint:sha-1
3C:73:F6:BE:0E:A2:D1:D5:8C:49:FC:9B:12:B4:29:2F:75:A8:F1:D5
a=setup:actpass
a=recvonly
a=mid:audio
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10; useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=ssrc:3480057974 cname:HrPWqRhS08rzyMXc
a=ssrc:3480057974 msid:w0KGB1MSiN5gP61DjvuwtcG3lJ061UYAsbil 9a9bfbf3-
a668-4952-b283-b2f2733d6a42
a=candidate:1 1 ssltcp 2130706431 192.168.65.6 4443 typ host generation
0 network-id 0
a=candidate:2 1 udp 2130706431 192.168.65.6 10000 typ host generation 0
network-id 0
m=video 9 RTP/SAVPF 100 116 117
c=IN IP4 0.0.0.0
a=rtcp:1 IN IP4 0.0.0.0
a=ice-ufrag:464nj1b8v3uh7n
a=ice-pwd:4v6ani5kuehel655qbolgev56v
a=fingerprint:sha-1
3C:73:F6:BE:0E:A2:D1:D5:8C:49:FC:9B:12:B4:29:2F:75:A8:F1:D5
a=setup:actpass
a=sendrecv
a=mid:video
a=rtcp-mux
a=msid:w0KGB1MSiN5gP61DjvuwtcG3lJ061UYAsbil a0faf67d-6b50-4ac3-bf19-
7cbf603eb7d0
a=rtpmap:100 VP8/90000
a=rtcp-fb:100 ccm fir
a=rtcp-fb:100 nack
a=rtcp-fb:100 nack pli
a=rtcp-fb:100 goog-remb
a=rtpmap:116 red/90000
a=rtpmap:117 ulpfec/90000
a=extmap:2 urn:ietf:params:rtp-hdrext:toffset
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=ssrc:683076867 cname:HrPWqRhS08rzyMXc
a=ssrc:683076867 msid:w0KGB1MSiN5gP61DjvuwtcG3lJ061UYAsbil a0faf67d-
6b50-4ac3-bf19-7cbf603eb7d0
a=candidate:1 1 ssltcp 2130706431 192.168.65.6 4443 typ host generation
0 network-id 0
a=candidate:2 1 udp 2130706431 192.168.65.6 10000 typ host generation 0
network-id 0
v=0
o=- 1708303114506441058 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio video
a=msid-semantic: WMS
m=audio 9 RTP/SAVPF 111 103 104
c=IN IP4 0.0.0.0
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:Wbi2
a=ice-pwd:8hkzIeej9BNWiRfabvT7bSOV
a=fingerprint:sha-256
67:AD:33:17:B5:1E:61:1E:64:47:C8:20:5C:7F:A8:80:12:6B:04:FE:C6:47:1E:2A
:37:4C:6E:11:59:C9:2A:D4
a=setup:active
a=mid:audio
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=inactive
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
m=video 9 RTP/SAVPF 100 116 117
c=IN IP4 0.0.0.0
a=rtcp:9 IN IP4 0.0.0.0
a=ice-ufrag:Wbi2
a=ice-pwd:8hkzIeej9BNWiRfabvT7bSOV
a=fingerprint:sha-256
67:AD:33:17:B5:1E:61:1E:64:47:C8:20:5C:7F:A8:80:12:6B:04:FE:C6:47:1E:2A
:37:4C:6E:11:59:C9:2A:D4
a=setup:active
a=mid:video
a=extmap:2 urn:ietf:params:rtp-hdrext:toffset
a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=recvonly
a=rtcp-mux
a=rtpmap:100 VP8/90000
a=rtcp-fb:100 ccm fir
a=rtcp-fb:100 nack
a=rtcp-fb:100 nack pli
a=rtcp-fb:100 goog-remb
a=rtpmap:116 red/90000
a=rtpmap:117 ulpfec/90000
candidate:2430253621 1 udp 2122260223 192.168.10.1 59305 typ host
generation 0 ufrag Wbi2 network-id 4
candidate:2218135367 1 udp 2122194687 10.1.2.5 59306 typ host
generation 0 ufrag Wbi2 network-id 2
candidate:95425800 1 udp 2122129151 192.168.65.1 59307 typ host
generation 0 ufrag Wbi2 network-id 1
candidate:3323467922 1 udp 2122063615 10.2.3.112 59308 typ host
generation 0 ufrag Wbi2 network-id 3 network-cost 10
candidate:3142642542 1 udp 1685987071 40.141.117.2 59306 typ srflx
raddr 10.1.2.5 rport 59306 generation 0 ufrag Wbi2 network-id 2
candidate:624533118 1 udp 1685855999 40.141.117.2 59308 typ srflx raddr
10.2.3.112 rport 59308 generation 0 ufrag Wbi2 network-id 3 network-
cost 10
candidate:3730392773 1 tcp 1518280447 192.168.10.1 9 typ host tcptype
active generation 0 ufrag Wbi2 network-id 4
candidate:3400922039 1 tcp 1518214911 10.1.2.5 9 typ host tcptype
active generation 0 ufrag Wbi2 network-id 2
candidate:1261693432 1 tcp 1518149375 192.168.65.1 9 typ host tcptype
active generation 0 ufrag Wbi2 network-id 1
candidate:2291917922 1 tcp 1518083839 10.2.3.112 9 typ host tcptype
active generation 0 ufrag Wbi2 network-id 3 network-cost 10

#2

Hi Rob,

Dear Jitsi Developers,

My company is trying to integrate the Jitsi videobridge into one of our
products, and I was hoping to get a little guidance. We are using the
REST API and have been following the REST API example available from ht
tps://github.com/jitsi/jitsi-videobridge/blob/master/doc/rest-
videobridge.md.

We've got code that generates an SDP blob that is accepted by Chrome
(sample below) and from which we are able to create a response. We take
that response and then translate it back to Colibri and use it to
update the Jitsi Videobridge (SDP and Colibri examples below).

ICE candidates are gathered (we actually gather the candidates and send
them to the signalling application before updating Colibri), and the
iceConnectionStatus changes to "checking", but the connection is never
made.

On the videobridge, we see the following errors, so we're confident
that the two are able to find one another and begin the connection
process.

JVB 2017-02-14 12:46:16.775 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=57459,localport=4443]:
End of stream!

This one means that the client closed the TCP connection before sending valid data (either the hard-coded "fake" SSL handshake, or a STUN packet).

and a few seconds later:

JVB 2017-02-14 12:46:30.141 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=57479,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=57479,localport=4443]

This means that the client sent a valid STUN message, and the bridge found the associated ICE Agent (which means the ufrag is correct, or at least recognized). I don't know why that would happen, though. Can you include more logs from the bridge?

Regards,
Boris

···

On 14/02/2017 14:21, Rob Oakes wrote:


#3

Hi Boris,

Thank you for getting back to me so quickly and for looking at this.

Hi Rob,

>
> On the videobridge, we see the following errors, so we're confident
> that the two are able to find one another and begin the connection
> process.
>
> JVB 2017-02-14 12:46:16.775 INFO: [51]
> org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed
> to
> handle TCP socket
> Socket[addr=/192.168.65.1,port=57459,localport=4443]:
> End of stream!
This one means that the client closed the TCP connection before
sending
valid data (either the hard-coded "fake" SSL handshake, or a STUN
packet).

Probably not related to the problem, then?

> and a few seconds later:
>
> JVB 2017-02-14 12:46:30.141 INFO: [51]
> org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed
> to
> handle TCP socket
> Socket[addr=/192.168.65.1,port=57479,localport=4443]:
> Failed to find the local candidate for socket:
> Socket[addr=/192.168.65.1,port=57479,localport=4443]

This means that the client sent a valid STUN message, and the bridge
found the associated ICE Agent (which means the ufrag is correct, or
at
least recognized). I don't know why that would happen, though. Can
you
include more logs from the bridge?

As you requested, below is the log output from the bridge for a "mostly
complete" session from the time the conference is allocated to when the
client connection fails.

I've come to the point where I have no idea what to look into next. Any
suggestions would be really appreciated.

Cheers,

Rob Oakes

JVB 2017-02-14 15:23:39.915 INFO: [30]
org.jitsi.videobridge.Videobridge.log() CAT=stat
create_conf,conf_id=bfe66a1629eda5fd
conf_name=null,logging=true,conf_count=1,ch_count=0,v_streams=0
JVB 2017-02-14 15:23:39.953 INFO: [28]
org.jitsi.videobridge.Conference.log() CAT=stat
create_content,conf_id=bfe66a1629eda5fd,content=audio
conf_count=1,ch_count=0,v_streams=0
JVB 2017-02-14 15:23:39.955 INFO: [28] org.ice4j.ice.Agent.log()
Gathering candidates for component stream.RTP. Local ufrag
6o9fb1b8vbindj
JVB 2017-02-14 15:23:39.956 INFO: [28]
org.jitsi.videobridge.Conference.log() CAT=stat
create_ice_tm,conf_id=bfe66a1629eda5fd
ufrag=6o9fb1b8vbindj,bundle=6816c5c7-a493-49d2-99fe-
88d589420b09,initiator=true
JVB 2017-02-14 15:23:39.956 INFO: [28]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
create_stream,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4b0
10ce,endp_id=null,stream=1957933470
JVB 2017-02-14 15:23:39.957 INFO: [28]
org.jitsi.videobridge.Content.log() CAT=stat
create_channel,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4b
010ce,endp_id=null,stream=1957933470 transport=default,bundle=6816c5c7-
a493-49d2-99fe-
88d589420b09,initiator=true,media_type=audio,relay_type=mixer
JVB 2017-02-14 15:23:39.961 INFO: [28]
org.jitsi.videobridge.Conference.log() CAT=stat
create_content,conf_id=bfe66a1629eda5fd,content=video
conf_count=1,ch_count=1,v_streams=0
JVB 2017-02-14 15:23:39.964 INFO: [28]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
create_stream,conf_id=bfe66a1629eda5fd,content=video,ch_id=5df1b0b04ba0
2fc5,endp_id=null,stream=1016491594
JVB 2017-02-14 15:23:39.965 INFO: [28]
org.jitsi.videobridge.Content.log() CAT=stat
create_channel,conf_id=bfe66a1629eda5fd,content=video,ch_id=5df1b0b04ba
02fc5,endp_id=null,stream=1016491594 transport=default,bundle=6816c5c7-
a493-49d2-99fe-
88d589420b09,initiator=true,media_type=video,relay_type=null
JVB 2017-02-14 15:23:40.121 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56674,localport=4443]:
End of stream!
JVB 2017-02-14 15:23:40.121 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56673,localport=4443]:
End of stream!
JVB 2017-02-14 15:23:40.221 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56676,localport=4443]:
End of stream!
JVB 2017-02-14 15:23:44.592 INFO: [87]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4045" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:23:54.624 INFO: [37]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4046" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:23:55.426 WARNING: [34]
org.jitsi.videobridge.Endpoint.log() No SCTP connection with 6816c5c7-
a493-49d2-99fe-88d589420b09.
JVB 2017-02-14 15:24:04.593 INFO: [39]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4047" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:24:14.592 INFO: [41]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4048" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:24:24.593 INFO: [44]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4049" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:24:28.044 INFO: [14]
org.jitsi.videobridge.Channel.log() CAT=stat
expire_ch,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4b010ce
,endp_id=6816c5c7-a493-49d2-99fe-88d589420b09,stream=1957933470
JVB 2017-02-14 15:24:28.044 INFO: [14]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
expire_ch_stats,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4
b010ce,endp_id=6816c5c7-a493-49d2-99fe-88d589420b09,stream=1957933470
bRecv=0,bSent=0,pRecv=0,pSent=0,bRetr=0,bNotRetr=0,pRetr=0,pNotRetr=0,p
Miss=0
JVB 2017-02-14 15:24:28.104 INFO: [14] org.ice4j.ice.Agent.log() ICE
state changed from Waiting to Terminated. Local ufrag 6o9fb1b8vbindj
JVB 2017-02-14 15:24:28.105 WARNING: [1187]
org.jitsi.videobridge.IceUdpTransportManager.log() Cannot get transport
type.
JVB 2017-02-14 15:24:28.112 INFO: [14]
org.ice4j.socket.MergingDatagramSocket.log() Closing.
JVB 2017-02-14 15:24:28.113 INFO: [1189]
org.ice4j.socket.MergingDatagramSocket.log() Failed to receive:
java.net.SocketException: Socket closed
JVB 2017-02-14 15:24:28.115 INFO: [14]
org.jitsi.videobridge.Channel.log() CAT=stat
expire_ch,conf_id=bfe66a1629eda5fd,content=video,ch_id=5df1b0b04ba02fc5
,endp_id=6816c5c7-a493-49d2-99fe-88d589420b09,stream=1016491594
JVB 2017-02-14 15:24:28.115 INFO: [1192]
org.ice4j.socket.MergingDatagramSocket.log() Failed to receive:
java.nio.channels.ClosedChannelException
JVB 2017-02-14 15:24:28.116 INFO: [14]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
expire_ch_stats,conf_id=bfe66a1629eda5fd,content=video,ch_id=5df1b0b04b
a02fc5,endp_id=6816c5c7-a493-49d2-99fe-88d589420b09,stream=1016491594
bRecv=0,bSent=0,pRecv=0,pSent=0,bRetr=0,bNotRetr=0,pRetr=0,pNotRetr=0,p
Miss=0
JVB 2017-02-14 15:24:28.444 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56747,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56747,localport=4443]
JVB 2017-02-14 15:24:28.738 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56750,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56750,localport=4443]
JVB 2017-02-14 15:24:29.031 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56751,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56751,localport=4443]
JVB 2017-02-14 15:24:29.325 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56752,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56752,localport=4443]
JVB 2017-02-14 15:24:29.619 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56755,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56755,localport=4443]
JVB 2017-02-14 15:24:29.913 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56756,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56756,localport=4443]
JVB 2017-02-14 15:24:30.208 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56757,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56757,localport=4443]
JVB 2017-02-14 15:24:30.502 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56758,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56758,localport=4443]
JVB 2017-02-14 15:24:30.794 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56759,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56759,localport=4443]
JVB 2017-02-14 15:24:31.090 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56760,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56760,localport=4443]
JVB 2017-02-14 15:24:31.382 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56761,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56761,localport=4443]
JVB 2017-02-14 15:24:31.677 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56764,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56764,localport=4443]
JVB 2017-02-14 15:24:31.975 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56765,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56765,localport=4443]
JVB 2017-02-14 15:24:32.167 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56766,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56766,localport=4443]
JVB 2017-02-14 15:24:32.461 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56767,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56767,localport=4443]
JVB 2017-02-14 15:24:32.754 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56770,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56770,localport=4443]
JVB 2017-02-14 15:24:33.047 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56771,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=56771,localport=4443]
JVB 2017-02-14 15:24:34.596 INFO: [63]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4050" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>

···

On Tue, 2017-02-14 at 16:02 -0600, Boris Grozev wrote:

On 14/02/2017 14:21, Rob Oakes wrote:


#4

Hi Boris,

Thank you for getting back to me so quickly and for looking at this.

Hi Rob,

On the videobridge, we see the following errors, so we're confident
that the two are able to find one another and begin the connection
process.

JVB 2017-02-14 12:46:16.775 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed
to
handle TCP socket
Socket[addr=/192.168.65.1,port=57459,localport=4443]:
End of stream!

This one means that the client closed the TCP connection before
sending
valid data (either the hard-coded "fake" SSL handshake, or a STUN
packet).

Probably not related to the problem, then?

Correct.

and a few seconds later:

JVB 2017-02-14 12:46:30.141 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed
to
handle TCP socket
Socket[addr=/192.168.65.1,port=57479,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=57479,localport=4443]

This means that the client sent a valid STUN message, and the bridge
found the associated ICE Agent (which means the ufrag is correct, or
at
least recognized). I don't know why that would happen, though. Can
you
include more logs from the bridge?

As you requested, below is the log output from the bridge for a "mostly
complete" session from the time the conference is allocated to when the
client connection fails.

I've come to the point where I have no idea what to look into next. Any
suggestions would be really appreciated.

Cheers,

Rob Oakes

JVB 2017-02-14 15:23:39.915 INFO: [30]
org.jitsi.videobridge.Videobridge.log() CAT=stat
create_conf,conf_id=bfe66a1629eda5fd
conf_name=null,logging=true,conf_count=1,ch_count=0,v_streams=0
JVB 2017-02-14 15:23:39.953 INFO: [28]
org.jitsi.videobridge.Conference.log() CAT=stat
create_content,conf_id=bfe66a1629eda5fd,content=audio
conf_count=1,ch_count=0,v_streams=0
JVB 2017-02-14 15:23:39.955 INFO: [28] org.ice4j.ice.Agent.log()
Gathering candidates for component stream.RTP. Local ufrag
6o9fb1b8vbindj
JVB 2017-02-14 15:23:39.956 INFO: [28]
org.jitsi.videobridge.Conference.log() CAT=stat
create_ice_tm,conf_id=bfe66a1629eda5fd
ufrag=6o9fb1b8vbindj,bundle=6816c5c7-a493-49d2-99fe-
88d589420b09,initiator=true
JVB 2017-02-14 15:23:39.956 INFO: [28]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
create_stream,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4b0
10ce,endp_id=null,stream=1957933470
JVB 2017-02-14 15:23:39.957 INFO: [28]
org.jitsi.videobridge.Content.log() CAT=stat
create_channel,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4b
010ce,endp_id=null,stream=1957933470 transport=default,bundle=6816c5c7-
a493-49d2-99fe-
88d589420b09,initiator=true,media_type=audio,relay_type=mixer
JVB 2017-02-14 15:23:39.961 INFO: [28]
org.jitsi.videobridge.Conference.log() CAT=stat
create_content,conf_id=bfe66a1629eda5fd,content=video
conf_count=1,ch_count=1,v_streams=0
JVB 2017-02-14 15:23:39.964 INFO: [28]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
create_stream,conf_id=bfe66a1629eda5fd,content=video,ch_id=5df1b0b04ba0
2fc5,endp_id=null,stream=1016491594
JVB 2017-02-14 15:23:39.965 INFO: [28]
org.jitsi.videobridge.Content.log() CAT=stat
create_channel,conf_id=bfe66a1629eda5fd,content=video,ch_id=5df1b0b04ba
02fc5,endp_id=null,stream=1016491594 transport=default,bundle=6816c5c7-
a493-49d2-99fe-
88d589420b09,initiator=true,media_type=video,relay_type=null
JVB 2017-02-14 15:23:40.121 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56674,localport=4443]:
End of stream!
JVB 2017-02-14 15:23:40.121 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56673,localport=4443]:
End of stream!
JVB 2017-02-14 15:23:40.221 INFO: [51]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=56676,localport=4443]:
End of stream!
JVB 2017-02-14 15:23:44.592 INFO: [87]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4045" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:23:54.624 INFO: [37]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4046" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:23:55.426 WARNING: [34]
org.jitsi.videobridge.Endpoint.log() No SCTP connection with 6816c5c7-
a493-49d2-99fe-88d589420b09.
JVB 2017-02-14 15:24:04.593 INFO: [39]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4047" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:24:14.592 INFO: [41]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4048" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:24:24.593 INFO: [44]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="QKR6Q-
4049" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-14 15:24:28.044 INFO: [14]
org.jitsi.videobridge.Channel.log() CAT=stat
expire_ch,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4b010ce
,endp_id=6816c5c7-a493-49d2-99fe-88d589420b09,stream=1957933470
JVB 2017-02-14 15:24:28.044 INFO: [14]
org.jitsi.videobridge.RtpChannel.log() CAT=stat
expire_ch_stats,conf_id=bfe66a1629eda5fd,content=audio,ch_id=6fe35e39e4
b010ce,endp_id=6816c5c7-a493-49d2-99fe-88d589420b09,stream=1957933470
bRecv=0,bSent=0,pRecv=0,pSent=0,bRetr=0,bNotRetr=0,pRetr=0,pNotRetr=0,p
Miss=0
JVB 2017-02-14 15:24:28.104 INFO: [14] org.ice4j.ice.Agent.log() ICE
state changed from Waiting to Terminated. Local ufrag 6o9fb1b8vbindj

This is quite interesting. It is not a valid ICE state transition, and AFAICT only happens if someone calls Agent.free() before the agent is started.

I see two possibilities here: either something caused free() to be called early on, or it was called normally when channels expired, but for some reason the Agent was never started. I think either of these would explain the rest of the behavior (ICE failing, the logs from the TCP harvester).

I don't think we've ever seen this problem with jicofo/jitsi-meet, although other people have reported it. So I suspect that what triggers it is something in the way you are using COLIBRI. I'll take another look at the json you sent later.

Regards,
Boris

···

On 14/02/2017 16:30, Rob Oakes wrote:

On Tue, 2017-02-14 at 16:02 -0600, Boris Grozev wrote:

On 14/02/2017 14:21, Rob Oakes wrote:


#5

This is quite intersting. It is not a valid ICE state transition,
and
AFAICT only happens if someone calls Agent.free() before the agent
is
started.

Interesting. So what do you think would be the most likely cause of the
problem? Is it an issue with the SDP offer that we are generating from
the Colibri sent back by the videobridge or an issue with timing?

(Literally everything that we know about the video bridge has been
learned from the online docs. The procedure we are using to connect is
from the REST interface page.)

Here's what we're doing (trying?):

1) When a new user joins a specific room/channel, we contact the
videobridge to (try and) allocate channels. Requests are sent via HTTP
to a web application that . The first HTTP response includes the SDP.
In this SDP response, we include the videobridge ICE candidates.

2) The SDP is used to generate an answer from the client. We then wait
for the ICE candidates to be gathered. When that is complete, se wend
the client answer SDP and client list back to the web application.

3) Colibri intended to patch the conference is created from the client
SDP by the web application, which is sent to the video bridge (PATCH)
to update the endpoint about codecs, and other client details.

4) The PATCH response is then parsed, the ICE andidate list compiled a
second time, and returned to the client.

5) We then call addIceCandidate to the RTCPeerConnection for the
candidate list generated by the video bridge.

Can you see anything important that we might be missing, or details
that we should be incorporating?

I'm more than a little nervous about the SDP that we are sending to the
client, as it's mostly been clobbed together from random resources on
the Internet and a rather significant bit of trial and error. Is there
a place we could get a sample of working SDP intended for the video
bridge? Ultimately, though they were helpful for general structure, all
of the samples we found (usually on Stack Overflow), were all
problematic.

I see two possibilities here: either something caused free() to be
called early on, or it was called normally when channels expired,
but
for some reason the Agent was never started. I think either of these
would explain the rest of the behavior (ICE failing, the logs from
the
TCP harvester).

I don't think we've ever seen this problem with jicofo/jitsi-meet,
although other people have reported it. So I suspect that what
triggers
it is something in the way you are using COLIBRI. I'll take another
look
at the json you sent later.

Again, thank you very much for your help. I look forward to your next
response.

Cheers,

Rob Oakes

···

On Wed, 2017-02-15 at 09:14 -0600, Boris Grozev wrote:

On 14/02/2017 16:30, Rob Oakes wrote:


#6

##SELECTION_END##Dear Jitsi Developers,

Here is a full set of session data for the problems that we are seeing.
I'm going to send two different emails, one with just a data channel,
and one with a full set of video, audio, and data channels. We are
seeing the same set of problems with both, SDP is generated and
accepted, but ICE connections fail. (The full session log from the
videobridge will be at the end of the email.)

(Please forgive some of the formatting issues, it's partially an
artifact of the way this was acquired and formatted for this email. All
of the JSON is valid.)


{'channel-bundles': [{'id': u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                      'transport': {'rtcp-mux': True,
                                    'xmlns':
'urn:xmpp:jingle:transports:ice-udp:1'}}],
 'contents': [{'name': 'data',
               'sctpconnections': [{'channel-bundle-id': u'dcdf3437-
6fbc-4657-b7f3-55a7940a7dee',
                                    'endpoint': u'dcdf3437-6fbc-4657-
b7f3-55a7940a7dee',
                                    'expire': 20,
                                    'initiator': True,
                                    'port': 5000}]}],
 'id': u'cd39cc9bbeae6d00'}

{u'channel-bundles': [{u'id': u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                       u'transport': {u'candidates': [{u'component': 1,
                                                       u'foundation':
u'1',
                                                       u'generation':
0,
                                                       u'id':
u'cd39cc9bbeae6d002bc1a99545456e100ffffffffecb9f8b7',
                                                       u'ip':
u'192.168.65.6',
                                                       u'network': 0,
                                                       u'port': 4443,
                                                       u'priority':
2130706431,
                                                       u'protocol':
u'ssltcp',
                                                       u'tcptype':
u'passive',
                                                       u'type':
u'host'},
                                                      {u'component': 1,
                                                       u'foundation':
u'2',
                                                       u'generation':
0,
                                                       u'id':
u'cd39cc9bbeae6d002bc1a99545456e100ffffffffecba0e6c',
                                                       u'ip':
u'192.168.65.6',
                                                       u'network': 0,
                                                       u'port': 10000,
                                                       u'priority':
2130706431,
                                                       u'protocol':
u'udp',
                                                       u'type':
u'host'}],
                                      u'fingerprints':
[{u'fingerprint':
u'65:86:A2:F3:84:16:C8:05:16:41:82:0E:7F:40:29:A3:CD:DC:E3:5C',
                                                         u'hash':
u'sha-1',
                                                         u'setup':
u'actpass'}],
                                      u'pwd':
u'6odk7oq2ffoekcot7sbfc8bhe9',
                                      u'rtcp-mux': True,
                                      u'ufrag': u'are0b1b94a7kl3',
                                      u'xmlns':
u'urn:xmpp:jingle:transports:ice-udp:1'}}],
 u'contents': [{u'name': u'data',
                u'sctpconnections': [{u'channel-bundle-id': u'dcdf3437-
6fbc-4657-b7f3-55a7940a7dee',
                                      u'endpoint': u'dcdf3437-6fbc-
4657-b7f3-55a7940a7dee',
                                      u'expire': 60,
                                      u'id': u'5887515ec64491d1',
                                      u'initiator': True,
                                      u'port': 5000}]}],
 u'id': u'cd39cc9bbeae6d00'}

v=0
o=- 3695822892 2 IN IP4 127.0.0.1
s=-
t=0 0
a=msid-semantic: WMS
a=group:BUNDLE data
m=application 1 DTLS/SCTP 5000
c=IN IP4 0.0.0.0
a=ice-ufrag:are0b1b94a7kl3
a=ice-pwd:6odk7oq2ffoekcot7sbfc8bhe9
a=fingerprint:sha-1
65:86:A2:F3:84:16:C8:05:16:41:82:0E:7F:40:29:A3:CD:DC:E3:5C
a=setup:actpass
a=sctpmap:5000 webrtc-datachannel 1024
a=mid:data
bridge)

v=0
o=- 2195412144308035748 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE data
a=msid-semantic: WMS
m=application 9 DTLS/SCTP 5000
c=IN IP4 0.0.0.0
b=AS:30
a=ice-ufrag:04yX
a=ice-pwd:A5Ab8f8iO3KNsO44UWXiECOb
a=fingerprint:sha-256
C7:9F:17:2B:70:52:EE:4A:B9:1F:13:E8:95:9E:9E:17:FD:B7:60:16:F0:01:58:78
:BD:DB:EA:80:0C:15:45:41
a=setup:active
a=mid:data
a=sctpmap:5000 webrtc-datachannel 1024
one by one using the remote-candidate property)

candidate:2430253621 1 udp 2122260223 192.168.10.1 51581 typ host
generation 0 ufrag 04yX network-id 4
candidate:2218135367 1 udp 2122194687 10.1.2.5 51582 typ host
generation 0 ufrag 04yX network-id 2
candidate:95425800 1 udp 2122129151 192.168.65.1 51583 typ host
generation 0 ufrag 04yX network-id 1
candidate:3323467922 1 udp 2122063615 10.2.3.112 51584 typ host
generation 0 ufrag 04yX network-id 3 network-cost 10
candidate:3730392773 1 tcp 1518280447 192.168.10.1 9 typ host tcptype
active generation 0 ufrag 04yX network-id 4
candidate:3400922039 1 tcp 1518214911 10.1.2.5 9 typ host tcptype
active generation 0 ufrag 04yX network-id 2
candidate:1261693432 1 tcp 1518149375 192.168.65.1 9 typ host tcptype
active generation 0 ufrag 04yX network-id 1
candidate:2291917922 1 tcp 1518083839 10.2.3.112 9 typ host tcptype
active generation 0 ufrag 04yX network-id 3 network-cost 1
update)

{'channel-bundles': [{'transport': {'fingerprints': [{'fingerprint':
u'C7:9F:17:2B:70:52:EE:4A:B9:1F:13:E8:95:9E:9E:17:FD:B7:60:16:F0:01:58:
78:BD:DB:EA:80:0C:15:45:41',
                                                      'hash': u'sha-
256'}],
                                    'id': u'dcdf3437-6fbc-4657-b7f3-
55a7940a7dee',
                                    'pwd': u'A5Ab8f8iO3KNsO44UWXiECOb',
                                    'ufrag': u'04yX',
                                    'xmlns':
'urn:xmpp:jingle:transports:ice-udp:1'}}],
 'contents': [{'name': 'data',
               'sctpconnections': [{'channel-bundle-id': u'dcdf3437-
6fbc-4657-b7f3-55a7940a7dee',
                                    'endpoint': u'dcdf3437-6fbc-4657-
b7f3-55a7940a7dee',
                                    'expire': 60,
                                    'id': u'5887515ec64491d1',
                                    'initiator': True,
                                    'port': 5000}]}],
 'id': u'cd39cc9bbeae6d00'}
RTCPeerConnection via addIceCandidate

candidate:1 1 ssltcp 2130706431 192.168.65.6 4443 typ host generation 0
 candidate:2 1 udp 2130706431 192.168.65.6 10000 typ host generation 0

JVB 2017-02-16 13:36:20.254 INFO: [24]
org.jitsi.videobridge.Conference.log() CAT=stat
create_content,conf_id=cd39cc9bbeae6d00,content=data
conf_count=1,ch_count=0,v_streams=0
JVB 2017-02-16 13:36:20.259 INFO: [24] org.ice4j.ice.Agent.log()
Gathering candidates for component stream.RTP. Local ufrag
are0b1b94a7kl3
JVB 2017-02-16 13:36:20.260 INFO: [24]
org.jitsi.videobridge.Conference.log() CAT=stat
create_ice_tm,conf_id=cd39cc9bbeae6d00
ufrag=are0b1b94a7kl3,bundle=dcdf3437-6fbc-4657-b7f3-
55a7940a7dee,initiator=true
JVB 2017-02-16 13:36:20.726 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53111,localport=4443]:
End of stream!
JVB 2017-02-16 13:36:20.826 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53112,localport=4443]:
End of stream!
JVB 2017-02-16 13:36:20.840 INFO: [91]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2940" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:36:23.717 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53109,localport=4443]:
End of stream!
JVB 2017-02-16 13:36:23.718 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53114,localport=4443]:
End of stream!
JVB 2017-02-16 13:36:30.836 INFO: [93]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2941" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:36:35.600 WARNING: [28]
org.jitsi.videobridge.Endpoint.log() SCTP connection with dcdf3437-
6fbc-4657-b7f3-55a7940a7dee not ready yet.
JVB 2017-02-16 13:36:38.786 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.cleanup() Read timeout for
socket: Socket[addr=/192.168.65.1,port=53110,localport=4443]
JVB 2017-02-16 13:36:40.850 INFO: [95]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2942" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:36:50.844 INFO: [97]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2943" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:00.845 INFO: [109]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2944" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:10.845 INFO: [37]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2945" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:20.850 INFO: [40]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2946" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:30.845 INFO: [59]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2947" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:40.846 INFO: [61]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2948" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:50.846 INFO: [63]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2949" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:37:56.984 INFO: [14] org.ice4j.ice.Agent.log() ICE
state changed from Waiting to Terminated. Local ufrag are0b1b94a7kl3
JVB 2017-02-16 13:37:56.985 WARNING: [494]
org.jitsi.videobridge.IceUdpTransportManager.log() Cannot get transport
type.
JVB 2017-02-16 13:37:56.988 INFO: [14]
org.ice4j.socket.MergingDatagramSocket.log() Closing.
JVB 2017-02-16 13:37:56.988 INFO: [496]
org.ice4j.socket.MergingDatagramSocket.log() Failed to receive:
java.net.SocketException: Socket closed
JVB 2017-02-16 13:37:56.990 INFO: [499]
org.ice4j.socket.MergingDatagramSocket.log() Failed to receive:
java.nio.channels.ClosedChannelException
JVB 2017-02-16 13:37:56.992 INFO: [14]
org.jitsi.videobridge.Channel.log() CAT=stat
expire_ch,conf_id=cd39cc9bbeae6d00,content=data,ch_id=5887515ec64491d1,
endp_id=dcdf3437-6fbc-4657-b7f3-55a7940a7dee
JVB 2017-02-16 13:37:57.752 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53246,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=53246,localport=4443]
JVB 2017-02-16 13:37:58.044 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53247,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=53247,localport=4443]
JVB 2017-02-16 13:37:58.335 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53248,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=53248,localport=4443]
JVB 2017-02-16 13:37:58.635 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53251,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=53251,localport=4443]
JVB 2017-02-16 13:38:00.847 INFO: [77]
org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV: <iq id="o3jmM-
2950" type="result" to="jitsi-videobridge.jitsi.gurulabs.com"
from="jitsi.gurulabs.com"/>
JVB 2017-02-16 13:38:01.574 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53252,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=53252,localport=4443]
JVB 2017-02-16 13:38:01.866 INFO: [47]
org.ice4j.ice.harvest.AbstractTcpListener.readFromChannel() Failed to
handle TCP socket Socket[addr=/192.168.65.1,port=53257,localport=4443]:
Failed to find the local candidate for socket:
Socket[addr=/192.168.65.1,port=53257,localport=4443]

Any thoughts on what to look at next would be greatly appreciated.


#7

Hi Boris,

Sorry for the delay. I got sidetracked into a different project for a
few weeks and have only been able to get back to this now.

Which version is this?

We are running version 879-1 of the videobridge alongside 1.0.1622-1 of
Jitsi meet. Connections setup via our application fail, but connections
setup via Jitsi meet work.

Any thoughts on what we should look at next?

Cheers,

Rob Oakes


#8

Hi Rob,

See one observation below. I will take a closer look later on.

···

On 16/02/2017 14:54, Rob Oakes wrote:

Dear Jitsi Developers,

Here is a full set of session data for the problems that we are seeing.
I'm going to send two different emails, one with just a data channel,
and one with a full set of video, audio, and data channels. We are
seeing the same set of problems with both, SDP is generated and
accepted, but ICE connections fail. (The full session log from the
videobridge will be at the end of the email.)

(Please forgive some of the formatting issues, it's partially an
artifact of the way this was acquired and formatted for this email. All
of the JSON is valid.)


{'channel-bundles': [{'id': u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                      'transport': {'rtcp-mux': True,
                                    'xmlns':
'urn:xmpp:jingle:transports:ice-udp:1'}}],
 'contents': [{'name': 'data',
               'sctpconnections': [{'channel-bundle-id':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                    'endpoint':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                    'expire': 20,
                                    'initiator': True,
                                    'port': 5000}]}],
 'id': u'cd39cc9bbeae6d00'}

{u'channel-bundles': [{u'id': u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                       u'transport': {u'candidates': [{u'component': 1,
                                                       u'foundation': u'1',
                                                       u'generation': 0,
                                                       u'id':
u'cd39cc9bbeae6d002bc1a99545456e100ffffffffecb9f8b7',
                                                       u'ip':
u'192.168.65.6',
                                                       u'network': 0,
                                                       u'port': 4443,
                                                       u'priority':
2130706431,
                                                       u'protocol':
u'ssltcp',
                                                       u'tcptype':
u'passive',
                                                       u'type': u'host'},
                                                      {u'component': 1,
                                                       u'foundation': u'2',
                                                       u'generation': 0,
                                                       u'id':
u'cd39cc9bbeae6d002bc1a99545456e100ffffffffecba0e6c',
                                                       u'ip':
u'192.168.65.6',
                                                       u'network': 0,
                                                       u'port': 10000,
                                                       u'priority':
2130706431,
                                                       u'protocol': u'udp',
                                                       u'type': u'host'}],
                                      u'fingerprints': [{u'fingerprint':
u'65:86:A2:F3:84:16:C8:05:16:41:82:0E:7F:40:29:A3:CD:DC:E3:5C',
                                                         u'hash': u'sha-1',
                                                         u'setup':
u'actpass'}],
                                      u'pwd': u'6odk7oq2ffoekcot7sbfc8bhe9',
                                      u'rtcp-mux': True,
                                      u'ufrag': u'are0b1b94a7kl3',
                                      u'xmlns':
u'urn:xmpp:jingle:transports:ice-udp:1'}}],
 u'contents': [{u'name': u'data',
                u'sctpconnections': [{u'channel-bundle-id':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                      u'endpoint':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                      u'expire': 60,
                                      u'id': u'5887515ec64491d1',
                                      u'initiator': True,
                                      u'port': 5000}]}],
 u'id': u'cd39cc9bbeae6d00'}

v=0
o=- 3695822892 2 IN IP4 127.0.0.1
s=-
t=0 0
a=msid-semantic: WMS
a=group:BUNDLE data
m=application 1 DTLS/SCTP 5000
c=IN IP4 0.0.0.0
a=ice-ufrag:are0b1b94a7kl3
a=ice-pwd:6odk7oq2ffoekcot7sbfc8bhe9
a=fingerprint:sha-1
65:86:A2:F3:84:16:C8:05:16:41:82:0E:7F:40:29:A3:CD:DC:E3:5C
a=setup:actpass
a=sctpmap:5000 webrtc-datachannel 1024
a=mid:data

v=0
o=- 2195412144308035748 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE data
a=msid-semantic: WMS
m=application 9 DTLS/SCTP 5000
c=IN IP4 0.0.0.0
b=AS:30
a=ice-ufrag:04yX
a=ice-pwd:A5Ab8f8iO3KNsO44UWXiECOb
a=fingerprint:sha-256
C7:9F:17:2B:70:52:EE:4A:B9:1F:13:E8:95:9E:9E:17:FD:B7:60:16:F0:01:58:78:BD:DB:EA:80:0C:15:45:41
a=setup:active
a=mid:data
a=sctpmap:5000 webrtc-datachannel 1024
one by one using the remote-candidate property)

candidate:2430253621 1 udp 2122260223 192.168.10.1 51581 typ host
generation 0 ufrag 04yX network-id 4
candidate:2218135367 1 udp 2122194687 10.1.2.5 51582 typ host generation
0 ufrag 04yX network-id 2
candidate:95425800 1 udp 2122129151 192.168.65.1 51583 typ host
generation 0 ufrag 04yX network-id 1
candidate:3323467922 1 udp 2122063615 10.2.3.112 51584 typ host
generation 0 ufrag 04yX network-id 3 network-cost 10
candidate:3730392773 1 tcp 1518280447 192.168.10.1 9 typ host tcptype
active generation 0 ufrag 04yX network-id 4
candidate:3400922039 1 tcp 1518214911 10.1.2.5 9 typ host tcptype active
generation 0 ufrag 04yX network-id 2
candidate:1261693432 1 tcp 1518149375 192.168.65.1 9 typ host tcptype
active generation 0 ufrag 04yX network-id 1
candidate:2291917922 1 tcp 1518083839 10.2.3.112 9 typ host tcptype
active generation 0 ufrag 04yX network-id 3 network-cost 1

{'channel-bundles': [{'transport': {'fingerprints': [{'fingerprint':
u'C7:9F:17:2B:70:52:EE:4A:B9:1F:13:E8:95:9E:9E:17:FD:B7:60:16:F0:01:58:78:BD:DB:EA:80:0C:15:45:41',
                                                      'hash': u'sha-256'}],
                                    'id':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                    'pwd': u'A5Ab8f8iO3KNsO44UWXiECOb',
                                    'ufrag': u'04yX',
                                    'xmlns':
'urn:xmpp:jingle:transports:ice-udp:1'}}],
 'contents': [{'name': 'data',
               'sctpconnections': [{'channel-bundle-id':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                    'endpoint':
u'dcdf3437-6fbc-4657-b7f3-55a7940a7dee',
                                    'expire': 60,
                                    'id': u'5887515ec64491d1',
                                    'initiator': True,
                                    'port': 5000}]}],
 'id': u'cd39cc9bbeae6d00'}

This is strange. AFAICT this JSON should have resulted in the ICE agent being started, but the logs indicate that it didn't (they would have contained "Starting ICE agent without remote candidates.").

Regards,
Boris


#9

This is strange. AFAICT this JSON should have resulted in the ICE agent being started, but the logs indicate that it didn't (they would have contained "Starting ICE agent without remote candidates.").

Could we have a timing issue? Are we returning the candidate list to the client too quickly without allowing time for the VideoBridge to allocate the resources for the ICE agent?

Or maybe a versioning thing? I'm using the version of the video bridge available through the Ubuntu repository? Should I update to a more recent build?


#10

This is strange. AFAICT this JSON should have resulted in the ICE
agent being started, but the logs indicate that it didn't (they
would have contained "Starting ICE agent without remote
candidates.").

Could we have a timing issue? Are we returning the candidate list to
the client too quickly without allowing time for the VideoBridge to
allocate the resources for the ICE agent?

I don't suspect timing. It should be fine as long as you wait for the REST response before sending a new request (which you have to do is most cases, because you need the conference ID).

Or maybe a versioning thing? I'm using the version of the video
bridge available through the Ubuntu repository? Should I update to a
more recent build?

Which version is this?

Regards,
Boris

···

On 18/02/2017 11:29, Rob Oakes wrote: