Videobridge failover reconnection failure

Hello everyone :smiley:

We are currently testing different failure and failover cases, and are encountering issues troubleshooting issues with reconnecting to redundant videobridges. We are building our application using lib-jitsi-meet and react-native.

Our setup is such that we have multiple bridges on a shard. They are all in the same region, and linked with octo in the IntraRegionBridgeSelectionStrategy strategy.

We want to test resilience in case a videobridge shut down mid-call. For this we had two videobridges on a shard. Two users connected to a room on the same bridge. We ensured that p2p was not used.

It seems that the client should be able to automatically reconnect, but this was not the case. Here are the related logs excerpts.

Jicofo

Jicofo 2021-03-24 17:31:00.384 INFO: [62] org.jitsi.jicofo.xmpp.IqHandler.log() Logout IQ received: <iq to='focus.rolo.chat' from='3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com/3-0Rcid7' id='a7cf094a-534a-4a61-a2b8-7487ad95aff4:sendIQ' type='set'><conference xmlns='http://jitsi.org/protocol/focus' room='152591154[at]muc.domain.com' machine-uid='e7bf545df08cfd66d15cdee74e7bcc47'><property xmlns='http://jitsi.org/protocol/focus' name='disableRtx' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='enableLipSync' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='openSctp' value='false'/></conference></iq>
Jicofo 2021-03-24 17:31:00.384 INFO: [62] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: 152591154[at]muc.domain.com
Jicofo 2021-03-24 17:31:00.385 INFO: [62] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Authentication session created for 3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com SID: 9efa6960-8f3a-4f3d-b1e6-e112943491b0
Jicofo 2021-03-24 17:31:00.385 INFO: [62] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Authenticated jid: 3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com/3-0Rcid7 with session: AuthSession[ID=3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com, JID=3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com/3-0Rcid7, SID=9efa6960-8f3a-4f3d-b1e6-e112943491b0, MUID=e7bf545df08cfd66d15cdee74e7bcc47, LIFE_TM_SEC=0, R=152591154[at]muc.domain.com][at]777674878
Jicofo 2021-03-24 17:31:00.385 INFO: [62] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Jid 3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com/3-0Rcid7 authenticated as: 3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com
Jicofo 2021-03-24 17:31:00.385 INFO: [62] org.jitsi.jicofo.FocusManager.log() Created new focus for 152591154[at]muc.domain.com[at]auth.rolo.chat. Conference count 7,options: enableLipSync=false openSctp=false disableRtx=false 
Jicofo 2021-03-24 17:31:00.385 INFO: [62] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Joining the room: 152591154[at]muc.domain.com
Jicofo 2021-03-24 17:31:02.028 INFO: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl[at]79c39e68 member=ChatMember[152591154[at]muc.domain.com/3c4181fb, jid: null][at]953949166]
Jicofo 2021-03-24 17:31:02.028 WARNING: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Focus role unknown
Jicofo 2021-03-24 17:31:02.029 INFO: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Obtained focus role: OWNER
Jicofo 2021-03-24 17:31:02.033 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member 152591154[at]muc.domain.com/3c4181fb joined.
Jicofo 2021-03-24 17:31:02.435 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.013S. Sticky failure: false
Jicofo 2021-03-24 17:31:12.430 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.007S. Sticky failure: false
Jicofo 2021-03-24 17:31:22.435 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.013S. Sticky failure: false
Jicofo 2021-03-24 17:31:25.774 INFO: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberLeft sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl[at]79c39e68 member=ChatMember[152591154[at]muc.domain.com/3c4181fb, jid: 3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com/3-0Rcid7][at]953949166]
Jicofo 2021-03-24 17:31:25.774 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member 152591154[at]muc.domain.com/3c4181fb is leaving
Jicofo 2021-03-24 17:31:25.774 WARNING: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Participant not found for 152591154[at]muc.domain.com/3c4181fb terminated already or never started ?
Jicofo 2021-03-24 17:31:25.776 INFO: [29] org.jitsi.jicofo.FocusManager.log() Disposed conference for room: 152591154[at]muc.domain.com conference count: 6
Jicofo 2021-03-24 17:31:32.432 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.01S. Sticky failure: false
Jicofo 2021-03-24 17:31:37.397 INFO: [88] org.jitsi.jicofo.xmpp.IqHandler.log() Logout IQ received: <iq to='focus.rolo.chat' from='62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com/2WTv4Ddy' id='efc5c740-1567-45d8-82da-f777d724e4a6:sendIQ' type='set'><conference xmlns='http://jitsi.org/protocol/focus' room='1394202891[at]muc.domain.com' session-id='e8e7c63f-7fc1-4e5b-9206-0095e32fca07' machine-uid='4925d0145164e60bddb9ce1894804629'><property xmlns='http://jitsi.org/protocol/focus' name='disableRtx' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='enableLipSync' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='openSctp' value='false'/></conference></iq>
Jicofo 2021-03-24 17:31:37.397 INFO: [88] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: 1394202891[at]muc.domain.com
Jicofo 2021-03-24 17:31:38.601 INFO: [90] org.jitsi.jicofo.xmpp.IqHandler.log() Logout IQ received: <iq to='focus.rolo.chat' from='62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com/2WTv4Ddy' id='f91c586a-f191-46e7-83c1-ef81f5b8517b:sendIQ' type='set'><conference xmlns='http://jitsi.org/protocol/focus' room='1394202891[at]muc.domain.com' machine-uid='4925d0145164e60bddb9ce1894804629'><property xmlns='http://jitsi.org/protocol/focus' name='disableRtx' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='enableLipSync' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='openSctp' value='false'/></conference></iq>
Jicofo 2021-03-24 17:31:38.601 INFO: [90] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: 1394202891[at]muc.domain.com
Jicofo 2021-03-24 17:31:38.602 INFO: [90] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Authentication session created for 62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com SID: 71ddabb5-1202-40a6-b004-0e3a42ca4712
Jicofo 2021-03-24 17:31:38.602 INFO: [90] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Authenticated jid: 62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com/2WTv4Ddy with session: AuthSession[ID=62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com, JID=62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com/2WTv4Ddy, SID=71ddabb5-1202-40a6-b004-0e3a42ca4712, MUID=4925d0145164e60bddb9ce1894804629, LIFE_TM_SEC=0, R=1394202891[at]muc.domain.com][at]1180183418
Jicofo 2021-03-24 17:31:38.602 INFO: [90] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Jid 62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com/2WTv4Ddy authenticated as: 62897f5a-8f9a-486e-ad97-6951b0f3e340[at]domain.com
Jicofo 2021-03-24 17:31:38.605 INFO: [90] org.jitsi.jicofo.FocusManager.log() Created new focus for 1394202891[at]muc.domain.com[at]auth.rolo.chat. Conference count 7,options: enableLipSync=false openSctp=false disableRtx=false 
Jicofo 2021-03-24 17:31:38.605 INFO: [90] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Joining the room: 1394202891[at]muc.domain.com
Jicofo 2021-03-24 17:31:38.722 INFO: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl[at]6cb8aec7 member=ChatMember[1394202891[at]muc.domain.com/62897f5a, jid: null][at]1775699207]
Jicofo 2021-03-24 17:31:38.723 WARNING: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Focus role unknown
Jicofo 2021-03-24 17:31:38.723 INFO: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Obtained focus role: OWNER
Jicofo 2021-03-24 17:31:38.728 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member 1394202891[at]muc.domain.com/62897f5a joined.
Jicofo 2021-03-24 17:31:38.986 INFO: [94] org.jitsi.jicofo.xmpp.IqHandler.log() Logout IQ received: <iq to='focus.rolo.chat' from='b03ad2e8-c22c-44e7-8c2a-dedd945b7def[at]domain.com/GBWaNb-H' id='c5a1a6f5-2675-4309-93cd-437eb8fb52d3:sendIQ' type='set'><conference xmlns='http://jitsi.org/protocol/focus' room='1394202891[at]muc.domain.com' session-id='9efa6960-8f3a-4f3d-b1e6-e112943491b0' machine-uid='e7bf545df08cfd66d15cdee74e7bcc47'><property xmlns='http://jitsi.org/protocol/focus' name='disableRtx' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='enableLipSync' value='false'/><property xmlns='http://jitsi.org/protocol/focus' name='openSctp' value='false'/></conference></iq>
Jicofo 2021-03-24 17:31:38.986 INFO: [94] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: 1394202891[at]muc.domain.com
Jicofo 2021-03-24 17:31:38.986 INFO: [94] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Authenticated jid: b03ad2e8-c22c-44e7-8c2a-dedd945b7def[at]domain.com/GBWaNb-H with session: AuthSession[ID=3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com, JID=b03ad2e8-c22c-44e7-8c2a-dedd945b7def[at]domain.com/GBWaNb-H, SID=9efa6960-8f3a-4f3d-b1e6-e112943491b0, MUID=e7bf545df08cfd66d15cdee74e7bcc47, LIFE_TM_SEC=38, R=152591154[at]muc.domain.com][at]777674878
Jicofo 2021-03-24 17:31:38.987 INFO: [94] org.jitsi.jicofo.auth.AbstractAuthAuthority.log() Jid b03ad2e8-c22c-44e7-8c2a-dedd945b7def[at]domain.com/GBWaNb-H authenticated as: 3c4181fb-1ae5-48db-bdd9-31bce8f6d159[at]domain.com
Jicofo 2021-03-24 17:31:40.250 INFO: [29] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl[at]6cb8aec7 member=ChatMember[1394202891[at]muc.domain.com/b03ad2e8, jid: null][at]201516683]
Jicofo 2021-03-24 17:31:40.253 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member 1394202891[at]muc.domain.com/b03ad2e8 joined.
Jicofo 2021-03-24 17:31:40.281 INFO: [29] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s, relayId=10.64.3.2:4096, region=asia-east, stress=0.00] with reported stress=0.0 for participantRegion=null using strategy IntraRegionBridgeSelectionStrategy
Jicofo 2021-03-24 17:31:40.283 INFO: [29] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl[at]54599f8e
Jicofo 2021-03-24 17:31:40.284 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= 1394202891[at]muc.domain.com/b03ad2e8, bridge=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:31:40.284 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east, null]]
Jicofo 2021-03-24 17:31:40.286 INFO: [514] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:31:40.287 INFO: [29] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected bridge Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s, relayId=10.64.3.2:4096, region=asia-east, stress=0.01] with stress=0.0 for participantRegion=null
Jicofo 2021-03-24 17:31:40.287 INFO: [514] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for 1394202891[at]muc.domain.com/b03ad2e8 in 1
Jicofo 2021-03-24 17:31:40.288 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= 1394202891[at]muc.domain.com/62897f5a, bridge=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:31:40.288 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east, null, null]]
Jicofo 2021-03-24 17:31:40.289 INFO: [515] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:31:40.289 INFO: [515] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for 1394202891[at]muc.domain.com/62897f5a in 0
Jicofo 2021-03-24 17:31:40.290 INFO: [514] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s to allocate channels for: Participant[1394202891[at]muc.domain.com/b03ad2e8][at]1812668584
Jicofo 2021-03-24 17:31:40.290 INFO: [515] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s to allocate channels for: Participant[1394202891[at]muc.domain.com/62897f5a][at]1397016975
Jicofo 2021-03-24 17:31:42.428 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.006S. Sticky failure: false
Jicofo 2021-03-24 17:31:42.450 INFO: [515] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:31:42.450 INFO: [514] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:31:43.714 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:31:43.715 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from 1394202891[at]muc.domain.com/62897f5a with accepted sources:Sources{ audio: [ssrc=2081534090 ] }[at]796971512
Jicofo 2021-03-24 17:31:43.717 WARNING: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No jingle session yet for 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:31:43.942 WARNING: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No jingle session yet for 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:31:44.188 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:31:44.190 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from 1394202891[at]muc.domain.com/b03ad2e8 with accepted sources:Sources{ video: [ssrc=2918114196 ssrc=240572187 ssrc=3961817779 ssrc=3396344207 ssrc=857006151 ssrc=2912446216 ] audio: [ssrc=1185582403 ] }[at]618655009
Jicofo 2021-03-24 17:31:52.433 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.011S. Sticky failure: false
Jicofo 2021-03-24 17:32:02.444 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.02S. Sticky failure: false
Jicofo 2021-03-24 17:32:12.434 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.012S. Sticky failure: false
Jicofo 2021-03-24 17:32:22.438 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.016S. Sticky failure: false
Jicofo 2021-03-24 17:32:32.434 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.01S. Sticky failure: false
Jicofo 2021-03-24 17:32:42.428 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.006S. Sticky failure: false
Jicofo 2021-03-24 17:32:52.432 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.01S. Sticky failure: false
Jicofo 2021-03-24 17:33:02.430 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.008S. Sticky failure: false
Jicofo 2021-03-24 17:33:12.453 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.03S. Sticky failure: false
Jicofo 2021-03-24 17:33:22.430 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.007S. Sticky failure: false
Jicofo 2021-03-24 17:33:30.764 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-terminate from Participant[1394202891[at]muc.domain.com/62897f5a][at]1397016975, session: BridgeSession[id=95108_26f4d3, bridge=Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s, relayId=10.64.3.2:4096, region=asia-east, stress=0.00]][at]73328333, restart: true
Jicofo 2021-03-24 17:33:30.764 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Terminating Participant[1394202891[at]muc.domain.com/62897f5a][at]1397016975, reason: null, send st: false
Jicofo 2021-03-24 17:33:30.765 INFO: [29] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Terminate session: 1394202891[at]muc.domain.com/62897f5a, reason: null, send terminate: false
Jicofo 2021-03-24 17:33:30.766 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removing 1394202891[at]muc.domain.com/62897f5a sources Sources{ audio: [ssrc=2081534090 ] video: [ssrc=466755149 ssrc=541443171 ssrc=974930284 ssrc=1125948294 ssrc=3025582294 ssrc=3543892702 ] }[at]332160735
Jicofo 2021-03-24 17:33:30.767 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removed participant: true, 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:33:30.767 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east, null]]
Jicofo 2021-03-24 17:33:30.768 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Expiring channels for: 1394202891[at]muc.domain.com/62897f5a on: Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s, relayId=10.64.3.2:4096, region=asia-east, stress=0.00]
Jicofo 2021-03-24 17:33:30.769 SEVERE: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() One of our bridges failed: jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:33:30.770 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east]]
Jicofo 2021-03-24 17:33:30.771 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Expiring channels for: 1394202891[at]muc.domain.com/b03ad2e8 on: Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s, relayId=10.64.3.2:4096, region=asia-east, stress=0.00]
Jicofo 2021-03-24 17:33:30.772 INFO: [29] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk, relayId=10.64.7.110:4096, region=asia-east, stress=0.00] with reported stress=0.0 for participantRegion=null using strategy IntraRegionBridgeSelectionStrategy
Jicofo 2021-03-24 17:33:30.773 INFO: [29] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl[at]2274e2b7
Jicofo 2021-03-24 17:33:30.773 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= 1394202891[at]muc.domain.com/b03ad2e8, bridge=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk
Jicofo 2021-03-24 17:33:30.773 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east, null]]
Jicofo 2021-03-24 17:33:30.774 INFO: [29] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected bridge Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk, relayId=10.64.7.110:4096, region=asia-east, stress=0.01] with stress=0.0 for participantRegion=null
Jicofo 2021-03-24 17:33:30.775 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= 1394202891[at]muc.domain.com/62897f5a, bridge=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk
Jicofo 2021-03-24 17:33:30.775 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east, null, null]]
Jicofo 2021-03-24 17:33:30.775 INFO: [516] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:33:30.775 INFO: [516] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for 1394202891[at]muc.domain.com/b03ad2e8 in 0
Jicofo 2021-03-24 17:33:30.776 INFO: [516] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk to allocate channels for: Participant[1394202891[at]muc.domain.com/b03ad2e8][at]1812668584
Jicofo 2021-03-24 17:33:30.777 INFO: [517] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:33:30.777 INFO: [517] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for 1394202891[at]muc.domain.com/62897f5a in 0
Jicofo 2021-03-24 17:33:30.777 INFO: [517] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk to allocate channels for: Participant[1394202891[at]muc.domain.com/62897f5a][at]1397016975
Jicofo 2021-03-24 17:33:32.428 INFO: [39] org.jitsi.health.HealthChecker.log() Performed a successful health check in PT0.006S. Sticky failure: false
Jicofo 2021-03-24 17:33:32.996 INFO: [29] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:33:32.996 INFO: [29] org.jitsi.jicofo.xmpp.BaseBrewery.log() A bridge left the MUC: jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:33:32.996 INFO: [29] org.jitsi.jicofo.bridge.BridgeSelector.log() Removing JVB: jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:33:32.997 INFO: [29] org.jitsi.jicofo.bridge.JvbDoctor.log() Stopping health-check task for: jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-9c69s
Jicofo 2021-03-24 17:33:33.001 INFO: [32] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Creating an Octo participant for Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk, relayId=10.64.7.110:4096, region=asia-east, stress=0.02] in JitsiMeetConferenceImpl[gid=95108, name=1394202891[at]muc.domain.com]
Jicofo 2021-03-24 17:33:33.037 INFO: [519] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk to allocate channels for: OctoParticipant[relays=[]][at]1234190425
Jicofo 2021-03-24 17:33:33.793 INFO: [516] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending transport-replace to: 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:33:33.795 INFO: [516] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() RE-INVITE PEER: 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:33:33.876 INFO: [517] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:33:34.536 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: 1394202891[at]muc.domain.com/62897f5a
Jicofo 2021-03-24 17:33:34.555 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from 1394202891[at]muc.domain.com/62897f5a with accepted sources:Sources{ video: [ssrc=2632942473 ssrc=577040030 ssrc=2391927270 ssrc=3547541367 ssrc=4147391145 ssrc=3636742430 ] audio: [ssrc=9264667 ] }[at]398880079
Jicofo 2021-03-24 17:33:34.574 INFO: [29] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Ignored session-terminate for invalid session: Participant[1394202891[at]muc.domain.com/b03ad2e8][at]1812668584, bridge session ID: 95108_26f4d3 restart: true
Jicofo 2021-03-24 17:33:35.436 SEVERE: [516] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Unexpected response to 'transport-replace' from 1394202891[at]muc.domain.com/b03ad2e8: <iq to='focus[at]auth.rolo.chat/focus408992918768819' from='1394202891[at]muc.domain.com/b03ad2e8' id='Obwk5-180761' type='error'><error type='cancel'><item-not-found xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/><unknown-session xmlns='urn:xmpp:jingle:errors:1' xmlns:stream='http://etherx.jabber.org/streams'></unknown-session></error></iq>
Jicofo 2021-03-24 17:33:35.437 INFO: [516] org.jitsi.jicofo.ParticipantChannelAllocator.log() Expiring 1394202891[at]muc.domain.com/b03ad2e8 channels - no RESULT for transport-replace
Jicofo 2021-03-24 17:33:35.437 INFO: [516] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Terminating Participant[1394202891[at]muc.domain.com/b03ad2e8][at]1812668584, reason: general-error, send st: true
Jicofo 2021-03-24 17:33:35.437 INFO: [516] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Terminate session: 1394202891[at]muc.domain.com/b03ad2e8, reason: general-error, send terminate: true
Jicofo 2021-03-24 17:33:35.458 INFO: [516] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removing 1394202891[at]muc.domain.com/b03ad2e8 sources Sources{ video: [ssrc=2918114196 ssrc=240572187 ssrc=3961817779 ssrc=3396344207 ssrc=857006151 ssrc=2912446216 ] audio: [ssrc=1185582403 ] }[at]1170016095
Jicofo 2021-03-24 17:33:35.459 INFO: [516] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removed participant: true, 1394202891[at]muc.domain.com/b03ad2e8
Jicofo 2021-03-24 17:33:35.462 WARNING: [516] org.jitsi.jicofo.AbstractParticipant.log() Canceling ParticipantChannelAllocator[BridgeSession[id=95108_7fc293, bridge=Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk, relayId=10.64.7.110:4096, region=asia-east, stress=0.02]][at]829804971, Participant[1394202891[at]muc.domain.com/b03ad2e8][at]1812668584][at]1694478752
Jicofo 2021-03-24 17:33:35.463 INFO: [516] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=95108: [[asia-east, null]]
Jicofo 2021-03-24 17:33:35.463 INFO: [516] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Expiring channels for: 1394202891[at]muc.domain.com/b03ad2e8 on: Bridge[jid=jvbbrewery[at]internal-muc.rolo.chat/jitsi-dev-jvb-b4grh3qx-857d77f8c8-99rjk, relayId=10.64.7.110:4096, region=asia-east, stress=0.02]

It looks to me like the issue comes from the transport-replace message to which the client returns an error.

Here is the client related lines (full client logs attached)

ReactNativeJS: '2021-03-24T09:33:34.774Z', '[modules/xmpp/strophe.jingle.js]', 'on jingle transport-replace from 1394202891@muc.rolo.chat/focus', '<iq id="YjAzYWQyZTgtYzIyYy00NGU3LThjMmEtZGVkZDk0NWI3ZGVmQHJvbG8uY2hhdC9HQldhTmItSABPYndrNS0xODA3NjEAQPvMUWN3v0weENEj6YR/9w==" xmlns="jabber:client" to="b03ad2e8-c22c-44e7-8c2a-dedd945b7def@rolo.chat/GBWaNb-H" type="set" from="1394202891@muc.rolo.chat/focus"><jingle initiator="focus@auth.rolo.chat/focus408992918768819" action="transport-replace" sid="1f2sckoif5jvf" xmlns="urn:xmpp:jingle:1"><content creator="initiator" senders="both" name="audio"><description maxptime="60" media="audio" xmlns="urn:xmpp:jingle:apps:rtp:1"><payload-type id="111" clockrate="48000" name="opus" channels="2"><parameter name="minptime" value="10"/><parameter name="useinbandfec" value="1"/><rtcp-fb type="transport-cc" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/></payload-type><payload-type id="103" clockrate="16000" name="ISAC" xmlns="urn:xmpp:jingle:apps:rtp:1"/><payload-type id="104" clockrate="32000" name="ISAC"/><payload-type id="126" clockrate="8000" name="telephone-event"/><rtp-hdrext id="1" uri="urn:ietf:params:rtp-hdrext:ssrc-audio-level" xmlns="urn:xmpp:jingle:apps:rtp:rtp-hdrext:0"/><rtp-hdrext id="5" uri="http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01" xmlns="urn:xmpp:jingle:apps:rtp:rtp-hdrext:0"/><rtcp-mux xmlns="urn:xmpp:jingle:apps:rtp:1"/><source ssrc="3977070949" xmlns="urn:xmpp:jingle:apps:rtp:ssma:0"><parameter name="cname" value="mixed"/><parameter name="label" value="mixedlabelaudio0"/><parameter name="msid" value="mixedmslabel mixedlabelaudio0"/><parameter name="mslabel" value="mixedmslabel"/><ssrc-info owner="jvb" xmlns="http://jitsi.org/jitmeet"/></source></description><transport pwd="5171mq1qgp0kjbnrvthot5uc10" ufrag="1ion11f1hp9v1v" xmlns="urn:xmpp:jingle:transports:ice-udp:1"><web-socket url="wss://dev.api.rolo.chat/call/b4grh3qx/colibri-ws/99rjk/d37655eccad2f1a1/b03ad2e8?pwd=5171mq1qgp0kjbnrvthot5uc10" xmlns="http://jitsi.org/protocol/colibri"/><rtcp-mux xmlns="urn:xmpp:jingle:transports:ice-udp:1"/><fingerprint hash="sha-256" required="false" setup="actpass" xmlns="urn:xmpp:jingle:apps:dtls:0">0C:BB:2F:83:15:BF:86:31:73:BA:4A:48:88:14:85:E4:BA:E9:C3:63:6E:CB:24:57:3B:85:1F:51:7E:1C:7F:4D</fingerprint><candidate priority="2130706431" network="0" foundation="1" component="1" ip="10.64.7.110" generation="0" port="10000" protocol="udp" id="6fc593957a7fbdf30735e29ef" type="host" xmlns="urn:xmpp:jingle:transports:ice-udp:1"/><candidate priority="1694498815" network="0" rel-addr="10.64.7.110" foundation="2" component="1" ip="104.199.140.216" generation="0" rel-port="10000" port="10000" protocol="udp" id="5ab8ffe7a7fbdf30ffffffffd1e5af59" type="srflx"/></transport></content><content creator="initiator" senders="both" name="video" xmlns="urn:xmpp:jingle:1"><description media="video" xmlns="urn:xmpp:jingle:apps:rtp:1"><payload-type id="100" clockrate="90000" name="VP8"><rtcp-fb type="ccm" subtype="fir" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" subtype="pli" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><parameter name="x-google-start-bitrate" value="800" xmlns="urn:xmpp:jingle:apps:rtp:1"/><rtcp-fb type="transport-cc" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/></payload-type><payload-type id="107" clockrate="90000" name="H264" xmlns="urn:xmpp:jingle:apps:rtp:1"><rtcp-fb type="ccm" subtype="fir" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" subtype="pli" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><parameter name="x-google-start-bitrate" value="800" xmlns="urn:xmpp:jingle:apps:rtp:1"/><rtcp-fb type="transport-cc" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><parameter name="profile-level-id" value="42e01f;level-asymmetry-allowed=1;packetization-mode=1;" xmlns="urn:xmpp:jingle:apps:rtp:1"/></payload-type><payload-type id="101" clockrate="90000" name="VP9"><rtcp-fb
ReactNativeJS: '2021-03-24T09:33:34.776Z', '[modules/xmpp/strophe.jingle.js]', 'invalid session id', '<iq id="YjAzYWQyZTgtYzIyYy00NGU3LThjMmEtZGVkZDk0NWI3ZGVmQHJvbG8uY2hhdC9HQldhTmItSABPYndrNS0xODA3NjEAQPvMUWN3v0weENEj6YR/9w==" xmlns="jabber:client" to="b03ad2e8-c22c-44e7-8c2a-dedd945b7def@rolo.chat/GBWaNb-H" type="set" from="1394202891@muc.rolo.chat/focus"><jingle initiator="focus@auth.rolo.chat/focus408992918768819" action="transport-replace" sid="1f2sckoif5jvf" xmlns="urn:xmpp:jingle:1"><content creator="initiator" senders="both" name="audio"><description maxptime="60" media="audio" xmlns="urn:xmpp:jingle:apps:rtp:1"><payload-type id="111" clockrate="48000" name="opus" channels="2"><parameter name="minptime" value="10"/><parameter name="useinbandfec" value="1"/><rtcp-fb type="transport-cc" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/></payload-type><payload-type id="103" clockrate="16000" name="ISAC" xmlns="urn:xmpp:jingle:apps:rtp:1"/><payload-type id="104" clockrate="32000" name="ISAC"/><payload-type id="126" clockrate="8000" name="telephone-event"/><rtp-hdrext id="1" uri="urn:ietf:params:rtp-hdrext:ssrc-audio-level" xmlns="urn:xmpp:jingle:apps:rtp:rtp-hdrext:0"/><rtp-hdrext id="5" uri="http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01" xmlns="urn:xmpp:jingle:apps:rtp:rtp-hdrext:0"/><rtcp-mux xmlns="urn:xmpp:jingle:apps:rtp:1"/><source ssrc="3977070949" xmlns="urn:xmpp:jingle:apps:rtp:ssma:0"><parameter name="cname" value="mixed"/><parameter name="label" value="mixedlabelaudio0"/><parameter name="msid" value="mixedmslabel mixedlabelaudio0"/><parameter name="mslabel" value="mixedmslabel"/><ssrc-info owner="jvb" xmlns="http://jitsi.org/jitmeet"/></source></description><transport pwd="5171mq1qgp0kjbnrvthot5uc10" ufrag="1ion11f1hp9v1v" xmlns="urn:xmpp:jingle:transports:ice-udp:1"><web-socket url="wss://dev.api.rolo.chat/call/b4grh3qx/colibri-ws/99rjk/d37655eccad2f1a1/b03ad2e8?pwd=5171mq1qgp0kjbnrvthot5uc10" xmlns="http://jitsi.org/protocol/colibri"/><rtcp-mux xmlns="urn:xmpp:jingle:transports:ice-udp:1"/><fingerprint hash="sha-256" required="false" setup="actpass" xmlns="urn:xmpp:jingle:apps:dtls:0">0C:BB:2F:83:15:BF:86:31:73:BA:4A:48:88:14:85:E4:BA:E9:C3:63:6E:CB:24:57:3B:85:1F:51:7E:1C:7F:4D</fingerprint><candidate priority="2130706431" network="0" foundation="1" component="1" ip="10.64.7.110" generation="0" port="10000" protocol="udp" id="6fc593957a7fbdf30735e29ef" type="host" xmlns="urn:xmpp:jingle:transports:ice-udp:1"/><candidate priority="1694498815" network="0" rel-addr="10.64.7.110" foundation="2" component="1" ip="104.199.140.216" generation="0" rel-port="10000" port="10000" protocol="udp" id="5ab8ffe7a7fbdf30ffffffffd1e5af59" type="srflx"/></transport></content><content creator="initiator" senders="both" name="video" xmlns="urn:xmpp:jingle:1"><description media="video" xmlns="urn:xmpp:jingle:apps:rtp:1"><payload-type id="100" clockrate="90000" name="VP8"><rtcp-fb type="ccm" subtype="fir" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" subtype="pli" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><parameter name="x-google-start-bitrate" value="800" xmlns="urn:xmpp:jingle:apps:rtp:1"/><rtcp-fb type="transport-cc" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/></payload-type><payload-type id="107" clockrate="90000" name="H264" xmlns="urn:xmpp:jingle:apps:rtp:1"><rtcp-fb type="ccm" subtype="fir" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><rtcp-fb type="nack" subtype="pli" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><parameter name="x-google-start-bitrate" value="800" xmlns="urn:xmpp:jingle:apps:rtp:1"/><rtcp-fb type="transport-cc" xmlns="urn:xmpp:jingle:apps:rtp:rtcp-fb:0"/><parameter name="profile-level-id" value="42e01f;level-asymmetry-allowed=1;packetization-mode=1;" xmlns="urn:xmpp:jingle:apps:rtp:1"/></payload-type><payload-type id="101" clockrate="90000" name="VP9"><rtcp-fb type="ccm" subtype="fir" xmlns="urn:xmpp:jin

log.txt (232.4 KB)

Please let me know if you have any hint on what exactly could be the issue here, and if we have any ways of preventing it.

Let me know if you need any additional information :slight_smile:

Thanks for your help @damencho :slight_smile:

We have been investigating more into this. As we are not using jitsi-meet directly but lib-jitsi-meet.

From our understanding, the way to handle it would be to listen to the CONFERENCE_RESTARTED error, and then to restart the whole flow.

We’re however unable to get the CONFERENCE_RESTARTED error to happen right now on the CONFERENCE_FAILED event.

We have the latest (Jan 12) release on the backend, and are using 4848.1475 for lib-jitsi-meet. Is there anything that we are missing to get it happen ?

I haven’t seen this versioning scheme before and thus don’t know which version you are using, but just to double check, the CONFERENCE_RESTARTED event is available since Release 1083 · jitsi/lib-jitsi-meet · GitHub

Alright,

Just ran some more test, can confirm that we are encountering the issue with release 1125 on lib-jitsi-meet, and 5390-3 on the backend stack.

No CONFERENCE_FAILED event were triggered when Jicofo re-scheduled the call on another bridge.

We also always have the transport-replace XMPP message that gets rejected by the client with “invalid session id” as in the logs in my first post.

We figured out the issue on our side, thanks for your help everyone.

Actually we are using the react-native implementation, the library was trying to access the allSettled function of the Promise API which is not available in that environment.

We had to do a simple polyfill for it and everything is fine now.