Jicofo cannot allocate channels for participants after some time

Developers
,
#1

Hi!

I’m investigating a strange case/bug that started to appear in the last 2 days:

  1. Users are joining their conference as usual in the morning.
  2. They have breaks so they leave the conference from time to time
  3. After second or third break, participants stop hearing and seeing each other

There are 2 strange things here:

  1. This only happens in one conference in the Jitsi Meet machine. Other conferences continue to function as normal and new conferences are created without problems
  2. It happens randomly in different conferences and machines

If I understand the flow correctly it goes like this:

  1. When the first participant joins → a new conference is created by Jicofo
  2. When second participant joins → a new conference is created in JVB
  3. Jicofo allocates channels in JVB for the participants
  4. If all the participants leave the conference + 20 seconds passes → conference is expired
  5. When there is a new request for join (to the same conference) → new conference is created by Jicofo
  6. When second participant join → a new conference is created in JVB
  7. Jicofo allocates channels in JVB for the participants
    … and so on

So if the above flow is correct as far as I see from the logs I think there is a problem with the Jicofo. Instead of creating a new conference it tries to allocate a channel from the expired channel:

Jicofo 2022-01-26 08:08:14.899 INFO: [376] [room=fb267a1e54de4c356bb78b8b8fa61cfbd44e9b796710610d5f7cd27901fc3e74@conference.my-jitsi-server.com meeting_id=977ad8bd-cb1d-4e2e-99cc-da5902f34606] AbstractChannelAllocator.allocateChannels#248: Using jvbbrewery@internal.auth.my-jitsi-server.com/5d031413-59cb-4aab-a5fe-ba3c3d269c12 to allocate channels for: Participant[fb267a1e54de4c356bb78b8b8fa61cfbd44e9b796710610d5f7cd27901fc3e74@conference.my-jitsi-server.com/9ee5e9fe]@708800679
Jicofo 2022-01-26 08:08:14.908 SEVERE: [376] [room=fb267a1e54de4c356bb78b8b8fa61cfbd44e9b796710610d5f7cd27901fc3e74@conference.my-jitsi-server.com meeting_id=977ad8bd-cb1d-4e2e-99cc-da5902f34606] AbstractChannelAllocator.allocateChannels#284: jvbbrewery@internal.auth.my-jitsi-server.com/5d031413-59cb-4aab-a5fe-ba3c3d269c12 - the bridge indicated bad-request: <iq xmlns='jabber:client' to='focus@auth.my-jitsi-server.com/focus' from='jvbbrewery@internal.auth.my-jitsi-server.com/5d031413-59cb-4aab-a5fe-ba3c3d269c12' id='WEZ98-16703' type='error'><error type='modify'><bad-request xmlns='urn:ietf:params:xml:ns:xmpp-stanzas'/><text xml:lang='en'>Conference not found for ID: 857659de1f6ddff8</text></error></iq>

Which causes Conference not found error from JVB.
I’m still unable to reproduce this problem and not sure what it is the root cause, so I’m curious if someone else had a similar issue? Also do you have any suggestions for debugging and/or fixing the problem?

I’m attaching logs from JVB and Jicofo (all IPs and Jitsi Meet FQDN are obscured):
jvb.log (1.9 MB)
jicofo.log (716.2 KB)

These are the versions of packages that we are currently using:

prosody: 0.11.11-1~focal1
jitsi-videobridge2: 2.1-570-gb802be83-1
jicofo: 1.0-813-1
jitsi-meet-web: 1.0.5415-1
jitsi-meet-web-config: 1.0.5415-1
jitsi-meet-prosody: 1.0.5415-1
jitsi-meet-turnserver: 1.0.5415-1
jitsi-meet: 2.0.6433-1

I also need to note that all the components (jicofo, jvb, prosody, nginx, coturn) are located in the same machine.

#2

Have you tried the latest stable? Do you reproduce it with it?

#3

No, I didn’t try yet. Do you know if something was improved in this area since 2.0.6433? Maybe this PR is related but I cannot find any details/description and don’t understand how adding a log is helpful to the problem. @Boris_Grozev is there something I’m missing?

#4

Yep, many changes since then.

#5

Dear all, i am having the same issue.

Jicofo 2022-02-04 19:44:45.731 INFO: [492] [room=global-web220207-1486@conference.meet.mydomain.com meeting_id=361c024a-0a0e-431d-b337-bdfcea37ccd2] ColibriV1SessionManager.allocate#145: Added participant id=bf749e4e, bridge=jvbbrewery@internal.auth.meet.mydomain.com/jvbbrewery@internal.auth.meet.mydomain.com
Jicofo 2022-02-04 19:44:45.731 INFO: [492] [room=global-web220207-1486@conference.meet.mydomain.com meeting_id=361c024a-0a0e-431d-b337-bdfcea37ccd2] ColibriV1SessionManager.allocateChannels#165: Using Bridge[jid=jvbbrewery@internal.auth.meet.mydomain.com/jvbbrewery@internal.auth.meet.mydomain.com, relayId=null, region=null, stress=0.19] to allocate channels for: Participant[global-web220207-1486@conference.meet.mydomain.com/bf749e4e]@699813868
Jicofo 2022-02-04 19:44:58.387 SEVERE: [489] [room=global-web220207-1486@conference.meet.mydomain.com meeting_id=361c024a-0a0e-431d-b337-bdfcea37ccd2] ColibriV1SessionManager.allocateChannels#214: Bridge[jid=jvbbrewery@internal.auth.meet.mydomain.com/jvbbrewery@internal.auth.meet.mydomain.com, relayId=null, region=null, stress=0.17] - failed to allocate channels, will consider the bridge faulty: Timed out waiting for a response for A4UR1-5854
Jicofo 2022-02-04 19:44:58.387 SEVERE: [489] [room=global-web220207-1486@conference.meet.mydomain.com meeting_id=361c024a-0a0e-431d-b337-bdfcea37ccd2 participant=1e336290] ParticipantInviteRunnable.doRun#223: Canceling due to
Jicofo 2022-02-04 19:44:58.387 SEVERE: [476] [room=global-web220207-1486@conference.meet.mydomain.com meeting_id=361c024a-0a0e-431d-b337-bdfcea37ccd2] ColibriV1SessionManager.allocateChannels#214: Bridge[jid=jvbbrewery@internal.auth.meet.mydomain.com/jvbbrewery@internal.auth.meet.mydomain.com, relayId=null, region=null, stress=0.17] - failed to allocate channels, will consider the bridge faulty: Timed out waiting for a response for A4UR1-5855

The above is the first failure followed by the existing connected user XMPP connection drop and the conference failed.

rc jitsi-meet 2.0.6293-1 all WebRTC JavaScript video conferences
ii jitsi-meet-prosody 1.0.5818-1 all Prosody configuration for Jitsi Meet
ii jitsi-meet-turnserver 1.0.5818-1 all Configures coturn to be used with Jitsi Meet
ii jitsi-meet-web 1.0.5818-1 all WebRTC JavaScript video conferences
ii jitsi-meet-web-config 1.0.5818-1 all Configuration for web serving of Jitsi Meet
ii jitsi-videobridge2 2.1-617-ga8b39c3f-1 all WebRTC compatible Selective Forwarding Unit (SFU)
ii prosody 0.11.4-1 amd64 Lightweight Jabber/XMPP server

The above are my server components.

Can anybody help ?

Thanks in advance :slight_smile:

#6

Check out the bridge logs, seems the bridge is not responding

#7

Hi Thanks for the quick reply,

JVB 2022-02-04 19:44:44.783 INFO: [349] [confId=92cb8abacf5d7f63 gid=67153812 stats_id=Narciso-z7K conf_name=global-room-1486@conference.meet.mydomain.com ufrag=92klm1fr28nr7m epId=b8643d44 local_ufrag=92klm1fr28nr7m] ConnectivityCheckClient.processTimeout#880: timeout for pair: x.x.x.x:10000/udp/srflx → 192.168.2.1:21741/udp/prflx (stream-b8643d44.RTP), failing.
JVB 2022-02-04 19:44:44.881 SEVERE: [30] [confId=92cb8abacf5d7f63 epId=f28c8277 gid=67153812 stats_id=Deanna-zx9 conf_name=global-room-1486@conference.meet.mydomain.com] Endpoint.scheduleEndpointMessageTransportTimeout$lambda-20#617: EndpointMessageTransport still not connected.
JVB 2022-02-04 19:44:44.891 SEVERE: [30] [confId=92cb8abacf5d7f63 epId=8b6f6be8 gid=67153812 stats_id=Americo-UAw conf_name=global-room-1486@conference.meet.mydomain.com] Endpoint.scheduleEndpointMessageTransportTimeout$lambda-20#617: EndpointMessageTransport still not connected.
JVB 2022-02-04 19:44:45.133 INFO: [106] [confId=77f9901b425bea3a gid=67153812 stats_id=Dominique-2Rx conf_name=global-room-1486@conference.meet.mydomain.com ufrag=ikir1fr28pd15 epId=ab61e9df local_ufrag=ikir1fr28pd15] Agent.setState#948: ICE state changed from Completed to Terminated.
JVB 2022-02-04 19:44:45.133 INFO: [106] [confId=77f9901b425bea3a epId=ab61e9df local_ufrag=ikir1fr28pd15 gid=67153812 stats_id=Dominique-2Rx conf_name=global-room-1486@conference.meet.mydomain.com] IceTransport.iceStateChanged#340: ICE state changed old=Completed new=Terminated
JVB 2022-02-04 19:44:45.161 INFO: [349] [confId=92cb8abacf5d7f63 gid=67153812 stats_id=Zachariah-mTU conf_name=global-room-1486@conference.meet.mydomain.com ufrag=6g1101fr28o1o7 epId=a6e1bd8a local_ufrag=6g1101fr28o1o7] ConnectivityCheckClient.processTimeout#880: timeout for pair: x.x.x.x:10000/udp/srflx → 109.159.112.236:64400/udp/prflx (stream-a6e1bd8a.RTP), failing.
JVB 2022-02-04 19:44:45.183 INFO: [349] [confId=92cb8abacf5d7f63 gid=67153812 stats_id=Kiley-ggZ conf_name=global-room-1486@conference.meet.mydomain.com ufrag=7al8l1fr28o1oi epId=a9091a1f local_ufrag=7al8l1fr28o1oi] ConnectivityCheckClient.processTimeout#880: timeout for pair: x.x.x.x:10000/udp/srflx → 192.168.2.1:22780/udp/prflx (stream-a9091a1f.RTP), failing.
JVB 2022-02-04 19:44:45.190 INFO: [349] [confId=92cb8abacf5d7f63 gid=67153812 stats_id=Lemuel-sZK conf_name=global-room-1486@conference.meet.mydomain.com ufrag=2a0f91fr28o1od epId=0c0b0f4e local_ufrag=2a0f91fr28o1od] ConnectivityCheckClient.processTimeout#880: timeout for pair: x.x.x.x:10000/udp/srflx → 86.138.181.160:51260/udp/prflx (stream-0c0b0f4e.RTP), failing.
JVB 2022-02-04 19:44:46.896 INFO: [349] [confId=92cb8abacf5d7f63 gid=67153812 stats_id=Deanna-zx9 conf_name=global-room-1486@conference.meet.mydomain.com ufrag=6qitn1fr28o8se epId=f28c8277 local_ufrag=6qitn1fr28o8se] ConnectivityCheckClient.processTimeout#880: timeout for pair: x.x.x.x:10000/udp/srflx → 192.168.2.1:29597/udp/prflx (stream-f28c8277.RTP), failing.
JVB 2022-02-04 19:44:46.906 INFO: [349] [confId=92cb8abacf5d7f63 gid=67153812 stats_id=Americo-UAw conf_name=global-room-1486@conference.meet.mydomain.com ufrag=42kci1fr28o8sa epId=8b6f6be8 local_ufrag=42kci1fr28o8sa] ConnectivityCheckClient.processTimeout#880: timeout for pair: x.x.x.x:10000/udp/srflx → 192.168.2.1:29695/udp/prflx (stream-8b6f6be8.RTP), failing.

this is the relevant log closed to same time

What else i can check add for u to troubleshoot ?

#8

Seems the bridge lost connectivity and jicofo and clients were not reaching it

#9

Hi,

how can i solve this issue ?

My environment all components in same machine

I have more than enough RAM, CPU power.

I have recently rebuild the whole server Ubuntu 20 did a fresh reinstallation.

These error i get during prosody startup
Feb 04 21:41:41 mod_posix error Failed to daemonize: already-daemonized
Feb 04 21:41:41 mod_limits error Unable to parse burst for s2sin: “nil”, using default burst interval (2s)
Feb 04 21:41:41 mod_limits error Unable to parse burst for c2s: “nil”, using default burst interval (2s)

Thank again.

#10

Then that is strange. How many participants were there on the server, and what was the spec of the machine? Try monitoring the prosody process CPU usage.
Do you experience this regularly?

#11

Hi,

Today about 30 peoples in 4 separate room, with all audio/video (Thumbnail)

Yes most of the time.

I don’t see any error in prosody error.

Attached my jvb.conf.

Below is prosody log same time

Feb 04 19:44:36 c2s562920a624b0 info Client connected
Feb 04 19:44:37 c2s5628ef1c0a70 info Authenticated as jeya@meet.mydomain.com
Feb 04 19:44:38 c2s562949dc18e0 info Client disconnected: connection closed
Feb 04 19:44:41 c2s562962ce4ff0 warn User has too much hibernated sessions, removing oldest session (token: d8143f48-6deb-4aa0-9534-e14017d02d49)
Feb 04 19:44:41 c2s562916ae08e0 warn User has too much hibernated sessions, removing oldest session (token: b172fc98-4025-42a6-b9c0-67301f5b35fd)
Feb 04 19:44:41 c2s5628ebcd39e0 warn User has too much hibernated sessions, removing oldest session (token: 861eaa24-8a7a-498c-be89-af64a32ab4fe)
Feb 04 19:44:41 c2s5628c4d4f160 warn User has too much hibernated sessions, removing oldest session (token: 24fd5a38-d98d-49dc-971e-5f3b82bd2c2a)
Feb 04 19:44:41 c2s5628f8d3ad10 warn User has too much hibernated sessions, removing oldest session (token: 375c28d7-daed-4372-804e-29d9b8db5939)
Feb 04 19:44:41 c2s5629285ee6b0 warn User has too much hibernated sessions, removing oldest session (token: 6d7507dc-772a-456c-a375-dad719ec7c4d)
Feb 04 19:44:41 c2s5628ae1978a0 warn User has too much hibernated sessions, removing oldest session (token: 5cda925c-ad92-4b8a-9d4a-6b848f32036a)
Feb 04 19:44:41 c2s562941d5e990 warn User has too much hibernated sessions, removing oldest session (token: b49c1a28-85dd-411d-9299-d7de9c7b9889)
Feb 04 19:44:41 c2s562941d5bfe0 warn User has too much hibernated sessions, removing oldest session (token: 7522b9d2-936c-426b-a434-956cd07a372e)
Feb 04 19:44:41 c2s5629147e7730 warn User has too much hibernated sessions, removing oldest session (token: 9a39baa7-9a0e-4a64-8386-1d9169fbf787)
Feb 04 19:44:41 c2s562900388e80 warn User has too much hibernated sessions, removing oldest session (token: 827f71ba-a366-47ba-b635-2530db692e9e)
Feb 04 19:44:41 c2s56291cd39b70 warn User has too much hibernated sessions, removing oldest session (token: 5dc28c57-daa5-4552-80e7-6a2f78310742)
Feb 04 19:44:41 c2s562933f44170 warn User has too much hibernated sessions, removing oldest session (token: f59dde0c-a656-46fa-84a1-0c403c7faf2c)
Feb 04 19:44:41 c2s5629ad904c60 info Client disconnected: connection closed
Feb 04 19:44:42 c2s5628a5a170c0 warn User has too much hibernated sessions, removing oldest session (token: 6d173435-70ba-4997-bab3-3071f620e44f)
Feb 04 19:44:42 c2s5628fb638180 warn User has too much hibernated sessions, removing oldest session (token: e8697266-9930-44f5-9f86-17dbc378598b)
Feb 04 19:44:42 c2s5628c281ed30 warn User has too much hibernated sessions, removing oldest session (token: 57412e42-940a-44f2-a970-075069fdaf31)
Feb 04 19:44:42 c2s5628a96eb350 warn User has too much hibernated sessions, removing oldest session (token: ce8e939d-1589-4c58-baea-316b69807ad8)
Feb 04 19:44:42 c2s5628ff3f3b90 warn User has too much hibernated sessions, removing oldest session (token: cf5fd866-4376-43d4-bfa6-7f909e1db73c)
Feb 04 19:44:42 c2s5628c750d3c0 warn User has too much hibernated sessions, removing oldest session (token: 8ede99f3-8172-47ba-8c03-7470af7fae83)
Feb 04 19:44:42 c2s562934ab6bd0 warn User has too much hibernated sessions, removing oldest session (token: ead1bf0a-3982-49b5-8b11-0b1bd3be8cdf)
Feb 04 19:44:42 c2s5629269501e0 warn User has too much hibernated sessions, removing oldest session (token: b64f8faa-7637-4aaf-a167-39497f5d3e2d)
Feb 04 19:44:42 c2s5628ba3080b0 warn User has too much hibernated sessions, removing oldest session (token: 9da747d4-c6ab-4d3a-8b75-aa864043deef)
Feb 04 19:44:42 c2s5628bf5dbbb0 info Authenticated as jeya@meet.mydomain.com
Feb 04 19:44:42 c2s562920a624b0 info Authenticated as jeya@meet.mydomain.com
Feb 04 19:44:42 c2s5629b9cff0c0 info Client connected
Feb 04 19:44:43 c2s5628ffa85c40 warn User has too much hibernated sessions, removing oldest session (token: f5016b9e-f4a5-4e9d-a930-e07f1266b8ab)

jvb.con.txt (6.2 KB)

#12

CPU usage hit you will not see an error, it will be just busy processing taking one of your CPU cores at 100%.

#13

Hi,

oh yes, i have seen that,

Regards.

#14

hi, sorry i missed system configuration,

Processor: Dual CPU Intel(R) Xeon(R) CPU E5-2640 0 @ 2.50GHz
Memory : 60GiB
Network Card : 1Gbit/s

Regards.

#15

your jitsi-meet package is not in normal state, your install is not correct. It should be
dpkg -l | grep jitsi
ii jitsi-meet

so purge everything and do a fresh install from scratch will be my attempt at helping you :slight_smile:

#16

hi that is what i did finally need to test will update once the test done.

ii jitsi-meet 2.0.6865-2 all WebRTC JavaScript video conferences
ii jitsi-meet-prosody 1.0.5818-1 all Prosody configuration for Jitsi Meet
ii jitsi-meet-turnserver 1.0.5818-1 all Configures coturn to be used with Jitsi Meet
ii jitsi-meet-web 1.0.5818-1 all WebRTC JavaScript video conferences
ii jitsi-meet-web-config 1.0.5818-1 all Configuration for web serving of Jitsi Meet
ii jitsi-videobridge2 2.1-617-ga8b39c3f-1 all WebRTC compatible Selective Forwarding Unit (SFU)
ii prosody 0.11.4-1 amd64 Lightweight Jabber/XMPP server

This is new one.

Thanks for your time answering.