Ghosts users in some rooms

yves-d · May 14, 2020, 5:04pm

Hello,

I have an issue with ghosts users and tried everything that I found on the community forum.
I upgraded prosody to 0.11.5 but it is still happening.

The configuration:
Server #1 / 16 CPU, 32G RAM, 4Gb/s
debian 9.12
nginx 1.10.3
jitsi-meet 2.0.4548
jitsi-meet-prosody 1.0.4074
jitsi-meet-web 1.0.4074
jitsi-meet-web-config 1.0.4074
jicofo 1.0-567
openjdk-8-jre-headless

Servers #2 #3 #4 #5 / 16 CPU, 32G RAM, 4Gb/s
debian 9.12
nginx 1.10.3
jitsi-videobridge2 2.1-197-g38256192
openjdk-8-jre-headless

I have configured Websockets in nginx, in the Jitsi meet config.js and in prosody.
The prosody storage is set to « memory », the secure domain is set.

/etc/systemd/system.conf set with:
DefaultLimitNOFILE=65000
DefaultLimitNPROC=65000
DefaultTasksMax=65000

Prosody config has:
cross_domain_bosh = false;
consider_bosh_secure = true;
cross_domain_websocket = true;
consider_websocket_secure = true;

The issue:
When we have a lot of users using the service (around 1000 at the same minute on 4 videobridges - 250 users per videobridge), some rooms are never shutting down because of some « ghosts » users remaining.
In those rooms, when refreshing the page, another user appears.
Writing a message into the Chat refreshes the connections and ghosts disappear. It doesn’t solve the problem because all of the users that are still in the room will be ghosts when they leave.

More information:
I think that the videobridge has made the disconnection (the rooms occupation in colibri stats seems to be OK) but jicofo / prosody still try to use the disconnected JID.
Restarting prosody solves the issue but it starts over each day.
These are the logs that I can see in /var/log/prosody/prosody.err. We have the same logs in /var/log/prosody/prosody.log. They continue periodically and never end:
May 14 14:41:22 c2s55598c5bbe90 error Traceback[c2s]: …itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: attempt to index field ‘speakerStats’ (a nil value)
stack traceback:
…itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: in function ‘?’
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/modules/muc/muc.lib.lua:561: in function </usr/lib/prosody/modules/muc/muc.lib.lua:498>
(…tail calls…)
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/core/stanza_router.lua:180: in function ‘core_post_stanza’
/usr/lib/prosody/core/stanza_router.lua:127: in function ‘core_process_stanza’
/usr/lib/prosody/modules/mod_c2s.lua:275: in function ‘func’
/usr/lib/prosody/util/async.lua:127: in function </usr/lib/prosody/util/async.lua:125>
May 14 14:41:26 c2s55598403cde0 error Traceback[c2s]: …itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: attempt to index field ‘speakerStats’ (a nil value)
stack traceback:
…itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: in function ‘?’
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/modules/muc/muc.lib.lua:561: in function </usr/lib/prosody/modules/muc/muc.lib.lua:498>
(…tail calls…)
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/core/stanza_router.lua:180: in function ‘core_post_stanza’
/usr/lib/prosody/modules/mod_presence.lua:109: in function ‘handle_normal_presence’
/usr/lib/prosody/modules/mod_presence.lua:304: in function ‘?’
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/core/stanza_router.lua:180: in function ‘core_post_stanza’
/usr/lib/prosody/core/stanza_router.lua:127: in function ‘core_process_stanza’
/usr/lib/prosody/modules/mod_c2s.lua:275: in function ‘func’
/usr/lib/prosody/util/async.lua:127: in function </usr/lib/prosody/util/async.lua:125>
May 14 14:41:27 mod_bosh error Traceback[bosh]: …itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: attempt to index field ‘speakerStats’ (a nil value)
stack traceback:
…itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: in function ‘?’
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/modules/muc/muc.lib.lua:561: in function </usr/lib/prosody/modules/muc/muc.lib.lua:498>
(…tail calls…)
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/core/stanza_router.lua:180: in function ‘core_post_stanza’
/usr/lib/prosody/core/stanza_router.lua:127: in function ‘dispatch_stanza’
/usr/lib/prosody/modules/mod_bosh.lua:305: in function ‘func’
/usr/lib/prosody/util/async.lua:127: in function </usr/lib/prosody/util/async.lua:125>
stack traceback:
/usr/lib/prosody/util/async.lua:211: in function ‘run’
/usr/lib/prosody/modules/mod_bosh.lua:447: in function ‘cb_handlestanza’
/usr/lib/prosody/util/xmppstream.lua:182: in function </usr/lib/prosody/util/xmppstream.lua:162>
[C]: in function ‘parse’
/usr/lib/prosody/util/xmppstream.lua:282: in function ‘feed’
/usr/lib/prosody/modules/mod_bosh.lua:133: in function ‘?’
/usr/lib/prosody/util/events.lua:79: in function </usr/lib/prosody/util/events.lua:75>
(…tail calls…)
/usr/lib/prosody/net/http/server.lua:228: in function </usr/lib/prosody/net/http/server.lua:176>
[C]: in function ‘xpcall’
/usr/lib/prosody/net/http/server.lua:108: in function ‘process_next’
/usr/lib/prosody/net/http/server.lua:124: in function ‘success_cb’
/usr/lib/prosody/net/http/parser.lua:177: in function ‘feed’
/usr/lib/prosody/net/http/server.lua:155: in function </usr/lib/prosody/net/http/server.lua:154>
(…tail calls…)
/usr/lib/prosody/net/server_select.lua:915: in function </usr/lib/prosody/net/server_select.lua:899>
[C]: in function ‘xpcall’
/usr/bin/prosody:76: in function ‘loop’
/usr/bin/prosody:86: in main chunk
[C]: in ?

The line quoted in /usr/share/jitsi-meet/prosody-plugins/mod_speakerstats_component.lua is:
local speakerStatsForOccupant = room.speakerStats [occupant.jid];

It seems that the occupant exists but the jid is not in room.speakerStats anymore (because he has disconnected, but somehow, he is still kept somewhere).

Do you have some clues about how to solve this issue and make the ghosts disappear?
Can I use something to force jicofo/prosody to purge these connections without restarting prosody?

Thank you for any help you can give. I can send more info / complete files if needed. Everything works fine for us except this issue.

damencho · May 15, 2020, 2:01am

Seems there is a bug in the code, we had not seen this with same prosody … I suspect hooking on some event using same priority … And it sometimes happen and sometimes not. We need to investigate …

damencho · May 15, 2020, 2:01am

Thanks for the report

yves-d · May 15, 2020, 7:07am

Thank you for the answer.
It happened also with prosody 0.11.2.
Don’t hesitate if I can help you with more information.

damencho · May 15, 2020, 3:31pm

What is your prosody config, is it like the default one https://github.com/jitsi/jitsi-meet/blob/master/doc/debian/jitsi-meet-prosody/prosody.cfg.lua-jvb.example
Are you using storage = "memory"?

damencho · May 15, 2020, 3:38pm

The error is on event muc-occupant-pre-leave and it is trying to use room.speakerStats which is nil. We do not clear it, as the room is being destroyed and freed from memory … I don’t see how you will get muc-occupant-pre-leave after muc-room-destroyed.
Maybe you need to check whether you see https://github.com/jitsi/jitsi-meet/blob/3b4037553a941f9502075b4cb474fd706c144da5/resources/prosody-plugins/ext_events.lib.lua#L44 for the same room before the error, in prosody logs. But this means small modifications in log messages there on your deployment to print and room name before the error and in that ext_events …

ptualek · May 15, 2020, 4:28pm

@yves-d I had same problem. So I searched and found a workaround that can resolve this Ghost Participant.

By enable this mod in prosody https://modules.prosody.im/mod_pinger.html

This is very simple mod just enable by add it in your prosody.cfg.lua.

Basically Pinger will create watch dog for every participant and ping client. If client didn’t reply in x seconds it will consider client timeout and kick that client out of prosody.

I have used this plugin for a weeks and everything work fine no more ghost in our server.

by the way for error from speakerStat I just disable speakerStat from prosody and error is gone.

yves-d · May 15, 2020, 6:38pm

@damencho Here are my answers. Thank you again.

Prosody config
Same as the link except that I have added the following lines. The storage is set to “memory”:

+cross_domain_websocket = true;
+consider_websocket_secure = true;

VirtualHost "example.com"
    +authentication = "internal_hashed"
    modules_enabled = {
            +"websocket";
	        +"smacks"; -- enabled yesterday for testing but it doesn’t solve or cause the issue
    }

VirtualHost "auth.example.com"
    +ssl = {
    +    key = "/etc/prosody/certs/auth.example.com.key";
    +    certificate = "/etc/prosody/certs/auth.example.com.crt";
    +}
    +authentication = "internal_hashed"

+VirtualHost "guest.example.com"
    +authentication = "anonymous"

    +speakerstats_component = "speakerstats.example.com"
    +conference_duration_component = "conferenceduration.example.com"

    +modules_enabled = {
            +"turncredentials";
            +"conference_duration";
    +}
    +c2s_require_encryption = false

Ext_events.lib.lua
I can add room with the “warn” log line 46.
Is it OK if I replace the line with the following:
room.jid .. " : A module has been configured that triggers external events."
Do I understand correctly?

I don’t know if it helps, but I retrieved the first error of the day:

May 11 07:32:23 conference.example.com:muc_domain_mapper warn Session filters applied
May 11 07:32:23 c2s55994668a210 info Client connected
May 11 07:32:23 conference.example.com:muc_domain_mapper warn Session filters applied
May 11 07:32:23 c2s559947d0dc60 info Client connected
May 11 07:32:23 c2s55994757d1d0 info Client disconnected: closed
May 11 07:32:23 speakerstats.example.com:speakerstats_component warn A module has been configured that triggers external events.
May 11 07:32:23 speakerstats.example.com:speakerstats_component warn Implement this lib to trigger external events.
May 11 07:32:23 c2s55994668a210 info Authenticated as jx8wd8kjwmalme4j@guest.example.com
May 11 07:32:24 c2s559945b8c9c0 info Client disconnected: connection closed
May 11 07:32:25 c2s559947d0dc60 info Authenticated as l8omv_aa-e3b0gq2@guest.example.com
May 11 07:32:26 c2s559947d8a580 error Traceback[c2s]: …itsi-meet/prosody-plugins/mod_speakerstats_component.lua:193: attempt to index field ‘speakerStats’ (a nil value)
May 11 07:32:26 c2s559947d8a580 info Client disconnected: connection closed

@ptualek Thank you, I will try the plugin as countermeasures

damencho · May 16, 2020, 3:57pm

module:log(
        "warn",
        "A module has been configured that triggers external events. Room: %s", room.jid
    )

And maybe here https://github.com/jitsi/jitsi-meet/blob/3b4037553a941f9502075b4cb474fd706c144da5/resources/prosody-plugins/mod_speakerstats_component.lua#L122

if room.speakerStats == nil then
module:log('warn', 'Speaker stats is nil for: %s', room.jid)
end

This way you will see when it is nil for which room and with the first change you will see whether room was destroyed before that …
You can even fix your problem with

if room.speakerStats == nil then
module:log('warn', 'Speaker stats is nil for: %s', room.jid)
return
end

You will skip the error.

yves-d · May 16, 2020, 4:58pm

OK, it is implemented. I will let you know the content of the logs on Monday: we will not have much traffic on Saturday and Sunday.

yves-d · May 18, 2020, 8:25am

Here are the logs:

prosody.log

May 18 07:31:23 speakerstats.example.com:speakerstats_component warn Speaker stats is nil for: ROOMNAME01@conference.example.com
May 18 07:31:23 c2s56164f6ed0d0 info Client disconnected: connection closed
May 18 07:31:23 speakerstats.example.com:speakerstats_component warn Speaker stats is nil for: ROOMNAME01@conference.example.com
May 18 07:31:23 speakerstats.example.com:speakerstats_component warn A module has been configured that triggers external events. Room ROOMNAME01@conference.example.com
May 18 07:31:23 speakerstats.example.com:speakerstats_component warn Implement this lib to trigger external events.

jicofo.log

Jicofo 2020-05-18 07:31:23.157 INFO: [39] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberLeft sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@24e15e64 member=ChatMember[ROOMNAME01@conference.example.com/76060a80, jid: qp-tkxlrtjrnthfm@guest.example.com/sL7HRnIK]@1454214250]
Jicofo 2020-05-18 07:31:23.157 INFO: [39] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member ROOMNAME01@conference.example.com/76060a80 is leaving
Jicofo 2020-05-18 07:31:23.157 WARNING: [39] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Participant not found for ROOMNAME01@conference.example.com/76060a80 terminated already or never started ?
Jicofo 2020-05-18 07:31:23.158 INFO: [39] org.jitsi.jicofo.FocusManager.log() Disposed conference for room: ROOMNAME01@conference.example.com conference count: 115

I have an error in prosody.err a bit later:

May 18 07:31:30 c2s56164f68a9e0 error Traceback[c2s]: …itsi-meet/prosody-plugins/mod_speakerstats_component.lua:53: attempt to index local ‘roomSpeakerStats’ (a nil value)

For the last one, I think I can edit the function on_message of the file /usr/share/jitsi-meet/prosody-plugins/mod_speakerstats_component.lua like you told me before https://github.com/jitsi/jitsi-meet/blob/3b4037553a941f9502075b4cb474fd706c144da5/resources/prosody-plugins/mod_speakerstats_component.lua#L46:

if roomSpeakerStats == nil then
module:log(‘warn’, ‘Speaker stats is nil for: %s’, occupant.jid)
return
end

The mod_pinger module seems to have solved the issue but I will keep trying today.

mcmohd · May 18, 2020, 7:03pm

Not sure how correct is this but I resolved this problem by changing following parameter to 10s from 1w

archive_expires_after = "10s"

in the following config file.

/etc/prosody/prosody.cfg.lua

Btw, I had read it in the forum suggested by someone for the same ghost participant issue.

mcmohd · May 18, 2020, 7:09pm

@ptualek
Can you please share the syntax ie. place where you have added this module and let me also give a try to it. Right now I’m getting rid of ghost participants using archive_expires_after = “10s” setting.

joker-x · May 18, 2020, 9:30pm

Thanks @ptualek!! Your workaround using mod_pinger is working for me. I spend several days trying to solve the ghosts users issue without any results and your post works like a charm

joker-x · May 18, 2020, 9:36pm

Only have to copy the file to /usr/lib/prosody/modules/mod_pinger.lua ; add “pinger” to modules_enabled section in /etc/prosody/prosody.cfg.lua and restart prosody.

ptualek · May 19, 2020, 4:07am

Glad to here that :). btw Thanks @zoftdev for help me figured out on this issue.

yves-d · May 21, 2020, 7:49pm

Hello, everything is OK since we made the changes. Thank you!

To sum-up:
We have added the mod_pinger to prosody main config as suggested by @ptualek & @zoftdev
To avoid the errors we had in prosody’s logs, we have edited the file /usr/share/jitsi-meet/prosody_plugins/mod_speakerstats_component.lua as suggested by @damencho
After a restart of prosody, everything is fine.

Here are the changes in mod_speakerstats_component.lua
In “occupant_leaving” function, just before the line
local speakerStatsForOccupant = room.speakerStats[occupant.jid];

We have added:

if room.speakerStats == nil then
module:log(‘warn’, ‘Speaker stats is nil for: %s’, room.jid)
return
end

In “on_message” function, just before the line
local newDominantSpeaker = roomSpeakerStats[occupant.jid];

We have added:

if roomSpeakerStats == nil then
module:log(‘warn’, ‘Speaker stats is nil for: %s’, room.jid)
return
end

hhamiri · May 30, 2020, 11:46am

Do you know the difference between mod_ping and mod_pinger?