Unstable connections after some minutes

stagil · October 4, 2019, 11:06am

Hello Jitsi Community,

it’s my first message here.
I install an Jitsi-Meet to an AWS EC2 instance. The installation was fine and the web interface is also functional. It’s possible to meet with other participants in the session, but the connection will be closed after some minutes / sometimes over an hour.
In the jvb.log is something like: “org.ice4j.socket.MergingDatagramSocket.log() Removing the active socket. Won’t be able to send until a new one is elected.” and “org.ice4j.stack.Connector.run() Connector died”.

Any help would be appreciated!

Thank in advance,
Max

stagil · October 7, 2019, 12:15pm

Here’s an extraction of the jvb.log (because i couldn’t upload files as a new users) where a session crashed:

JVB 2019-10-07 14:05:37.779 FINE: [132] org.jitsi.videobridge.xmpp.ComponentImpl.processIQRequest() (serving component 'JitsiVideobridge') Processing IQ request (packetId 5focs-197012).
JVB 2019-10-07 14:05:37.780 FINE: [132] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Responding to IQ (packetId 5focs-197012) with: <iq to="focus@auth.meet.stagil.com/focus339710841211865" from="jitsi-videobridge.meet.stagil.com" id="5focs-197012" type="result"/>
JVB 2019-10-07 14:05:40.109 FINE: [134] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId W3omI-107328): <iq id="W3omI-107328" type="result" to="jitsi-videobridge.meet.stagil.com" from="meet.stagil.com"/>
JVB 2019-10-07 14:05:45.052 INFO: [18] org.jitsi.videobridge.Videobridge.log() CAT=stat create_conf,conf_id=5b5f0564191d2e47 conf_name=null,logging=false,conf_count=2,ch_count=9,v_streams=9
JVB 2019-10-07 14:05:45.062 INFO: [18] org.jitsi.videobridge.health.Health.log() Performed a successful health check in 10ms. Sticky failure: false
JVB 2019-10-07 14:05:47.779 FINE: [136] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId 5focs-197019): <iq type="get" to="jitsi-videobridge.meet.stagil.com" from="focus@auth.meet.stagil.com/focus339710841211865" id="5focs-197019"><healthcheck xml
ns="http://jitsi.org/protocol/healthcheck"/></iq>
JVB 2019-10-07 14:05:47.779 FINE: [136] org.jitsi.videobridge.xmpp.ComponentImpl.processIQRequest() (serving component 'JitsiVideobridge') Processing IQ request (packetId 5focs-197019).
JVB 2019-10-07 14:05:47.780 FINE: [136] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Responding to IQ (packetId 5focs-197019) with: <iq to="focus@auth.meet.stagil.com/focus339710841211865" from="jitsi-videobridge.meet.stagil.com" id="5focs-197019" type="result"/>
JVB 2019-10-07 14:05:48.328 FINE: [159] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId 5focs-197023): <iq type="get" to="jitsi-videobridge.meet.stagil.com" from="focus@auth.meet.stagil.com/focus339710841211865" id="5focs-197023"><query xmlns="ht
tp://jabber.org/protocol/disco#info"/></iq>
JVB 2019-10-07 14:05:48.328 FINE: [159] org.jitsi.videobridge.xmpp.ComponentImpl.processIQRequest() (serving component 'JitsiVideobridge') Processing IQ request (packetId 5focs-197023).
JVB 2019-10-07 14:05:48.328 FINE: [159] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Responding to IQ (packetId 5focs-197023) with: <iq type="result" id="5focs-197023" from="jitsi-videobridge.meet.stagil.com" to="focus@auth.meet.stagil.com/focus339710841211865"><quer
y xmlns="http://jabber.org/protocol/disco#info"><identity category="component" type="conference" name="JitsiVideobridge"/><feature var="http://jabber.org/protocol/disco#info"/><feature var="urn:xmpp:ping"/><feature var="jabber:iq:last"/><feature var="urn:xmpp:time"/><feature var="http://jitsi.org/protocol/colibri
"/><feature var="http://jitsi.org/protocol/healthcheck"/><feature var="urn:xmpp:jingle:apps:dtls:0"/><feature var="urn:xmpp:jingle:transports:ice-udp:1"/><feature var="urn:xmpp:jingle:transports:raw-udp:1"/><feature var="jabber:iq:version"/></query></iq>
JVB 2019-10-07 14:05:50.110 FINE: [165] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId W3omI-107332): <iq id="W3omI-107332" type="result" to="jitsi-videobridge.meet.stagil.com" from="meet.stagil.com"/>
JVB 2019-10-07 14:05:51.796 WARNING: [569550] org.ice4j.stack.Connector.run() Connector died: <internal_ip>:4443/tcp -> <public_ip>:64741/tcp
java.net.SocketException: Failed to receive data from socket.
        at org.ice4j.socket.DelegatingSocket.receiveFromChannel(DelegatingSocket.java:686)
        at org.ice4j.socket.DelegatingSocket.receive(DelegatingSocket.java:648)
        at org.ice4j.socket.MultiplexingSocket.multiplexingXXXSocketSupportDoReceive(MultiplexingSocket.java:339)
        at org.ice4j.socket.MultiplexingSocket.access$000(MultiplexingSocket.java:34)
        at org.ice4j.socket.MultiplexingSocket$1.doReceive(MultiplexingSocket.java:77)
        at org.ice4j.socket.MultiplexingXXXSocketSupport.receive(MultiplexingXXXSocketSupport.java:649)
        at org.ice4j.socket.MultiplexingSocket.receive(MultiplexingSocket.java:419)
        at org.ice4j.socket.MultiplexedSocket.receive(MultiplexedSocket.java:161)
        at org.ice4j.socket.IceTcpSocketWrapper.receive(IceTcpSocketWrapper.java:146)
        at org.ice4j.ice.harvest.AbstractTcpListener$PushBackIceSocketWrapper.receive(AbstractTcpListener.java:775)
        at org.ice4j.stack.Connector.run(Connector.java:207)
        at java.base/java.lang.Thread.run(Thread.java:834)
JVB 2019-10-07 14:05:51.797 WARNING: [569550] org.ice4j.stack.NetAccessManager.handleFatalError() Removing connector:ice4j.Connector@<internal_ip>:4443/tcp status:  running
java.net.SocketException: Failed to receive data from socket.
        at org.ice4j.socket.DelegatingSocket.receiveFromChannel(DelegatingSocket.java:686)
        at org.ice4j.socket.DelegatingSocket.receive(DelegatingSocket.java:648)
        at org.ice4j.socket.MultiplexingSocket.multiplexingXXXSocketSupportDoReceive(MultiplexingSocket.java:339)
        at org.ice4j.socket.MultiplexingSocket.access$000(MultiplexingSocket.java:34)
        at org.ice4j.socket.MultiplexingSocket$1.doReceive(MultiplexingSocket.java:77)
        at org.ice4j.socket.MultiplexingXXXSocketSupport.receive(MultiplexingXXXSocketSupport.java:649)
        at org.ice4j.socket.MultiplexingSocket.receive(MultiplexingSocket.java:419)
        at org.ice4j.socket.MultiplexedSocket.receive(MultiplexedSocket.java:161)
        at org.ice4j.socket.IceTcpSocketWrapper.receive(IceTcpSocketWrapper.java:146)
        at org.ice4j.ice.harvest.AbstractTcpListener$PushBackIceSocketWrapper.receive(AbstractTcpListener.java:775)
        at org.ice4j.stack.Connector.run(Connector.java:207)
        at java.base/java.lang.Thread.run(Thread.java:834)
JVB 2019-10-07 14:05:52.658 INFO: [569551] org.ice4j.socket.MergingDatagramSocket.log() Failed to receive: java.net.SocketException: Failed to receive data from socket.
JVB 2019-10-07 14:05:54.764 INFO: [571574] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=9
JVB 2019-10-07 14:05:55.050 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=8
JVB 2019-10-07 14:05:55.062 INFO: [18] org.jitsi.videobridge.Videobridge.log() CAT=stat create_conf,conf_id=54e43cbfd8005ef5 conf_name=null,logging=false,conf_count=2,ch_count=9,v_streams=9
JVB 2019-10-07 14:05:55.070 INFO: [18] org.jitsi.videobridge.health.Health.log() Performed a successful health check in 8ms. Sticky failure: false
JVB 2019-10-07 14:05:55.350 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=7
JVB 2019-10-07 14:05:55.650 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=6
JVB 2019-10-07 14:05:55.944 INFO: [572752] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 3.122.236.158:10000/udp/srflx -> <public_ip>:63010/udp/prflx (stream.RTP), failing.
JVB 2019-10-07 14:05:55.950 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=5
JVB 2019-10-07 14:05:56.250 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=4
JVB 2019-10-07 14:05:56.550 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=3
JVB 2019-10-07 14:05:56.850 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=2
JVB 2019-10-07 14:05:57.150 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=1
JVB 2019-10-07 14:05:57.450 INFO: [569597] org.jitsi.impl.neomedia.rtp.translator.RTCPFeedbackMessageSender.log() Sending a FIR to ssrc=2763706539 remainingRetries=0
JVB 2019-10-07 14:05:57.780 FINE: [185] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId 5focs-197033): <iq type="get" to="jitsi-videobridge.meet.stagil.com" from="focus@auth.meet.stagil.com/focus339710841211865" id="5focs-197033"><healthcheck xmlns="http://jitsi.org/protocol/healthcheck"/></iq>
JVB 2019-10-07 14:05:57.780 FINE: [185] org.jitsi.videobridge.xmpp.ComponentImpl.processIQRequest() (serving component 'JitsiVideobridge') Processing IQ request (packetId 5focs-197033).
JVB 2019-10-07 14:05:57.780 FINE: [185] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Responding to IQ (packetId 5focs-197033) with: <iq to="focus@auth.meet.stagil.com/focus339710841211865" from="jitsi-videobridge.meet.stagil.com" id="5focs-197033" type="result"/>
JVB 2019-10-07 14:05:58.944 INFO: [572752] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 3.122.236.158:10000/udp/srflx -> <public_ip>:63010/udp/prflx (stream.RTP), failing.
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Total packets added: 1
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Times reset() called: 1
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Times grow() called: 0
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because full: 0
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Packets dropped while shrinking: 0
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because they were late: 0
JVB 2019-10-07 14:05:59.482 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Packets dropped because they were late by more than MAX_SIZE: 0
JVB 2019-10-07 14:05:59.483 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Packets dropped in reset(): 0
JVB 2019-10-07 14:05:59.483 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Max size reached: 4
JVB 2019-10-07 14:05:59.483 INFO: [569576] net.sf.fmj.media.Log.info() net.sf.fmj.media.rtp.RTPSourceStream Adaptive jitter buffer mode was enabled
JVB 2019-10-07 14:05:59.483 INFO: [569576] net.sf.fmj.media.Log.info() Stopping RTPSourceStream.
JVB 2019-10-07 14:06:00.110 FINE: [179] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId W3omI-107336): <iq id="W3omI-107336" type="result" to="jitsi-videobridge.meet.stagil.com" from="meet.stagil.com"/>
JVB 2019-10-07 14:06:01.945 INFO: [572752] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 3.122.236.158:10000/udp/srflx -> <public_ip>:63010/udp/prflx (stream.RTP), failing.
JVB 2019-10-07 14:06:04.945 INFO: [572752] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: 3.122.236.158:10000/udp/srflx -> <public_ip>:63010/udp/prflx (stream.RTP), failing.
JVB 2019-10-07 14:06:05.070 INFO: [18] org.jitsi.videobridge.Videobridge.log() CAT=stat create_conf,conf_id=74d4ba370ca437d5 conf_name=null,logging=false,conf_count=2,ch_count=9,v_streams=9
JVB 2019-10-07 14:06:05.081 INFO: [18] org.jitsi.videobridge.health.Health.log() Performed a successful health check in 11ms. Sticky failure: false
JVB 2019-10-07 14:06:07.779 FINE: [183] org.jitsi.videobridge.xmpp.ComponentImpl.processIQ() (serving component 'JitsiVideobridge') Processing IQ (packetId 5focs-197038): <iq type="get" to="jitsi-videobridge.meet.stagil.com" from="focus@auth.meet.stagil.com/focus339710841211865" id="5focs-197038"><healthcheck xmlns="http://jitsi.org/protocol/healthcheck"/></iq>

stagil · October 14, 2019, 11:28am

Hello Jitsi community,

i want to push this answer, because we are on the edge to decide for or against jitsi and want look for other alternatives if it won’t work. We did a lot of testing and it would be a Bummer if it’s blocked by a problem like this momentary.

Best,
Max

NathanDo · January 15, 2020, 2:26pm

I have the same issue, any one encounter this ? Once this happens, how to recover or at least retry ?

amritanshtambi · February 11, 2020, 10:29am

I am experiencing similar issue with same message in log. Please advice, what does this message mean?

wwuu · February 11, 2020, 11:18pm

We got similar issue as well. Any thoughts from the jitsi team?

damencho · February 12, 2020, 8:02am

What is the issue you see? As these logs can be normal.

stagil · February 13, 2020, 3:46pm

For me the log entry occurs at the time when our Jitsi video conferencing is unstable and the connection break

wwuu · March 14, 2020, 7:12pm

We got hit again last night on one of our jvbs.

The symptom was that everyone’s audio and video dropped off. But the signaling server remains connected as they can still txt chat. So they hangup and tried to rejoin, but the jvb was probably in a bad state, so that also failed.

This morning the same jvb seems be recovered by itself. Not sure how frequent this happens. We know this because that was a meeting held by one of my friend.

We’ve got the log from both jvb, jicofo. We saw log like those attached below in jvb log when this happened.

201 JVB 2020-03-14 06:30:15.628 INFO: [1213350] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: XXXX:10000 /udp/srflx -> YYYY:5521/udp/prflx (stream.RTP), failing.
202 JVB 2020-03-14 06:30:15.673 INFO: [1213267] org.ice4j.ice.ConnectivityCheckClient.log() timeout for pair: XXXX:10000 /udp/srflx -> ZZZZ:20181/udp/prflx (stream.RTP), failing.
203 JVB 2020-03-14 06:30:15.752 INFO: [1215704] org.ice4j.ice.Agent.log() Stop periodic Stun Keep Alive.
204 JVB 2020-03-14 06:30:15.754 INFO: [1219445] org.ice4j.socket.MergingDatagramSocket.log() Failed to receive: java.net.SocketEx ception: Socket closed
205 JVB 2020-03-14 06:30:15.754 INFO: [1215704] org.ice4j.socket.MergingDatagramSocket.log() Closing.
206 JVB 2020-03-14 06:30:15.754 WARNING: [1219445] org.ice4j.socket.MergingDatagramSocket.log() Removing the active socket. Won’t be able to send until a new one is elected.