JVB Randomly getting disconnected after working for several days and kicks off participants out of meeting

Install & Config
,
#1

Hello guys,

Recently, I have been facing JVB randomly loosing connectivity with Jicofo. Things went fine for several months and then recently, I am seeing below errors on Jitsi and JVB end and kicks off participants out from the meeting:

JVB version:
ii jitsi-videobridge2 2.1-304-g8488f77d-1 all WebRTC compatible Selective Forwarding Unit (SFU)

Jicofo error logs:

Jicofo logs

Jicofo 2021-04-08 14:35:26.914 SEVERE: [35549] org.jitsi.jicofo.AbstractChannelAllocator.log() jvbbrewery@internal.auth.domain.com/prod2-jvb1 - failed to allocate channels, will consider the bridge faulty: XMPP error:
org.jitsi.protocol.xmpp.colibri.exception.ColibriException: XMPP error:
at org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl.maybeThrowOperationFailed(ColibriConferenceImpl.java:378)
at org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl.createColibriChannels(ColibriConferenceImpl.java:282)
at org.jitsi.protocol.xmpp.colibri.ColibriConference.createColibriChannels(ColibriConference.java:112)
at org.jitsi.jicofo.ParticipantChannelAllocator.doAllocateChannels(ParticipantChannelAllocator.java:111)
at org.jitsi.jicofo.AbstractChannelAllocator.allocateChannels(AbstractChannelAllocator.java:271)
at org.jitsi.jicofo.AbstractChannelAllocator.doRun(AbstractChannelAllocator.java:190)
at org.jitsi.jicofo.AbstractChannelAllocator.run(AbstractChannelAllocator.java:150)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
at java.base/java.lang.Thread.run(Thread.java:834)
Jicofo 2021-04-08 14:35:26.914 SEVERE: [35549] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() One of our bridges failed: jvbbrewery@internal.auth.domain.com/prod2-jvb1
Jicofo 2021-04-08 14:35:26.914 INFO: [35549] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=44099 octo_enabled= false: [[null, null]]
Jicofo 2021-04-08 14:35:26.914 WARNING: [35549] org.jitsi.jicofo.AbstractParticipant.log() Canceling ParticipantChannelAllocator[BridgeSession[id=44099_63c420, bridge=Bridge[jid=jvbbrewery@internal.auth.domain.com/prod2-jvb1, relayId=null, region=null, stress=0.03]]@681790900, Participant[5a836218-7624-11eb-8b8f-02fca26ac9c6@conference.domain.com/633eb26a]@1395261742]@1506962014
Jicofo 2021-04-08 14:35:26.915 INFO: [35549] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=44099 octo_enabled= false: [[null]]
Jicofo 2021-04-08 14:35:26.915 WARNING: [35549] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Failed to select initial bridge for participantRegion=null
Jicofo 2021-04-08 14:35:26.915 SEVERE: [35549] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Can not invite participant – no bridge available.
Jicofo 2021-04-08 14:35:26.915 WARNING: [35549] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Failed to select initial bridge for participantRegion=null
Jicofo 2021-04-08 14:35:26.915 SEVERE: [35549] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Can not invite participant – no bridge available.
Jicofo 2021-04-08 14:35:27.096 INFO: [31] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberLeft sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@18a299a9 member=ChatMember[5a836218-7624-11eb-8b8f-02fca26ac9c6@conference.domain.com/0086944a, jid: 0086944a-ce02-4f16-a24c-aeca514b2246@domain.com/5rd36LQb]@589788786]

JVB error logs:

JVB logs

2021-04-08 14:35:26.628 INFO: [117010] [confId=deb287aafbfcbcc9 gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6 ufrag=60m511f2pc8foh epId=633eb26a local_ufrag=60m511f2pc8foh] Agent.checkListStatesUpdated#1949: ICE state is FAILED
2021-04-08 14:35:26.914 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] AbstractEndpoint.expire#233: Expiring.
2021-04-08 14:35:26.914 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] Transceiver.teardown#319: Tearing down
2021-04-08 14:35:26.914 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] RtpReceiverImpl.tearDown#299: Tearing down
2021-04-08 14:35:26.914 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] RtpSenderImpl.tearDown#271: Tearing down
2021-04-08 14:35:26.914 SEVERE: [117036] XmppCommon.handleIQRequest#177: Exception handling IQ request

I checked the ports are open and things are working fine for several months. Also, I have done the NAT configuration on JVB end.

Any idea what might be going wrong? Thanks.

#2

Is there a stack trace and more info for this exception?

#3

I don’t see any trace for the error logs I sent you. These are the logs after above exception on jvb end:

Summary

2021-04-08 14:35:26.914 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] DtlsTransport.stop#184: Stopping
2021-04-08 14:35:26.915 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a local_ufrag=60m511f2pc8foh gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] IceTransport.stop#235: Stopping
2021-04-08 14:35:26.915 INFO: [117046] [confId=deb287aafbfcbcc9 gid=278681 stats_id=Augustine-Jjh componentId=1 conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6 ufrag=60m511f2pc8foh name=stream-633eb26a epId=633eb26a local_ufrag=60m511f2pc8foh] MergingDatagramSocket$SocketContainer.runInReaderThread#770: Failed to receive: java.net.SocketException: Socket closed
2021-04-08 14:35:26.916 INFO: [116993] [confId=deb287aafbfcbcc9 gid=278681 stats_id=Augustine-Jjh componentId=1 conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6 ufrag=60m511f2pc8foh name=stream-633eb26a epId=633eb26a local_ufrag=60m511f2pc8foh] MergingDatagramSocket.close#142: Closing.
2021-04-08 14:35:26.916 INFO: [116993] [confId=deb287aafbfcbcc9 epId=633eb26a gid=278681 stats_id=Augustine-Jjh conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] Endpoint.expire#778: Expired.
2021-04-08 14:35:27.118 INFO: [116798] [confId=deb287aafbfcbcc9 epId=0086944a gid=278681 stats_id=Felton-RUa conf_name=5a836218-7624-11eb-8b8f-02fca26ac9c6] TlsServerImpl.notifyAlertReceived#239: close_notify received, connection closing

However, similar thing just happened now and I see some trace for that event which is as below:

Similar issue JVB logs

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 epId=343e3343 gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6] AbstractEndpoint.expire#233: Expiring.

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 epId=343e3343 gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6] Transceiver.teardown#319: Tearing down

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 epId=343e3343 gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6] RtpReceiverImpl.tearDown#299: Tearing down

2021-04-08 16:31:26.137 SEVERE: [116865] XmppCommon.handleIQRequest#177: Exception handling IQ request

java.lang.NullPointerException

at org.jitsi.videobridge.shim.ChannelShim.(ChannelShim.java:163)

at org.jitsi.videobridge.shim.ContentShim.createRtpChannel(ContentShim.java:135)

at org.jitsi.videobridge.shim.ContentShim.getOrCreateChannelShim(ContentShim.java:276)

at org.jitsi.videobridge.shim.VideobridgeShim.processChannels(VideobridgeShim.java:141)

at org.jitsi.videobridge.shim.VideobridgeShim.handleColibriConferenceIQ(VideobridgeShim.java:313)

at org.jitsi.videobridge.Videobridge.handleColibriConferenceIQ(Videobridge.java:427)

at org.jitsi.videobridge.xmpp.XmppCommon.handleIQRequest(XmppCommon.java:158)

at org.jitsi.videobridge.xmpp.XmppCommon.handleIQInternal(XmppCommon.java:116)

at org.jitsi.videobridge.xmpp.XmppCommon.handleIQ(XmppCommon.java:87)

at org.jitsi.videobridge.xmpp.ClientConnectionImpl.handleIq(ClientConnectionImpl.java:97)

at org.jitsi.xmpp.mucclient.IQListener.handleIq(IQListener.java:50)

at org.jitsi.xmpp.mucclient.MucClient.handleIq(MucClient.java:566)

at org.jitsi.xmpp.mucclient.MucClient.access$700(MucClient.java:50)

at org.jitsi.xmpp.mucclient.MucClient$2.handleIQRequest(MucClient.java:530)

at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)

at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)

at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)

at java.base/java.lang.Thread.run(Thread.java:834)

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 epId=343e3343 gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6] RtpSenderImpl.tearDown#271: Tearing down

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 epId=343e3343 gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6] DtlsTransport.stop#184: Stopping

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 epId=343e3343 local_ufrag=b57np1f2pisrku gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6] IceTransport.stop#235: Stopping

2021-04-08 16:31:26.137 INFO: [117205] [confId=c72fa97e238dea22 gid=350339 stats_id=Laura-yTr conf_name=d8959fe7-e653-11ea-ac19-02fca26ac9c6 ufrag=b57np1f2pisrku epId=343e3343 local_ufrag=b57np1f2pisrku] Agent.setState#963: ICE state changed from Running to Terminated.

#4

O that is pretty old jvb, I think this was fixed at some point try the latest versions.

1 Like