What steps will reproduce the problem?
1. Generates a timer with delay 5s in every 1 second
What is the expected output? I expect the timer runs after 5 s.
What do you see instead? It sometimes runs in 1s
What version of the product are you using? On what operating system?
Prosody 0.11.10 -"Red Hat Enterprise Linux 8.4 (Ootpa)"
Please provide any additional information below.
This bug is reproduced in Jitsi breakout scenario. I opened a ticcket to Jitsi, and they redirect me to prosody. https://community.jitsi.org/t/breakout-rooms-timer-functionality/115239?u=esrayilmaz
When someone leaves the breakout room, it is checked whether this is last user in all breakoutrooms + main room. If so, main room is destroyed after 5 s. Code sets a timer with module:add_timer(ROOMS_TTL_IF_ALL_LEFT, function()
function on_occupant_left(event)
local room_jid = event.room.jid;
if is_healthcheck_room(room_jid) then
return;
end
local main_room = get_main_room(room_jid);
if not main_room then
return;
end
if main_room._data.breakout_rooms_active and jid_node(event.occupant.jid) ~= 'focus' then
broadcast_breakout_rooms(room_jid);
end
-- Close the conference if all left for good.
if main_room._data.breakout_rooms_active and not main_room._data.is_close_all_scheduled and not exist_occupants_in_rooms(main_room) then
main_room._data.is_close_all_scheduled = true;
main_room:save(true);
module:log('info', 'on_occupant_left-- %s', socket.gettime());
module:add_timer(ROOMS_TTL_IF_ALL_LEFT, function()
-- we need to look up again the room as till the timer is fired, the room maybe already destroyed/recreated
-- and we will have the old instance
module:log('info', 'inside timer-- %s', socket.gettime());
local main_room, main_room_jid = get_main_room(room_jid);
if main_room and main_room._data.is_close_all_scheduled and not exist_occupants_in_rooms(main_room) then
module:log('info', 'Closing conference %s as all left for good at %s ', main_room_jid, socket.gettime());
main_room:set_persistent(false);
main_room:destroy(nil, 'All occupants left.');
end
end)
end
end
However, I see behavior that this timer does not always work after 5 s. It sometimes works earlier than 1s. This creates a raise condition when someone tries to leave a breakout room and join to another room. In scenario, it sends unavailable presence for the breakout room. While unavailable presence is processing, timer sets and works in same second, and main room is destroyed. So same client sending an iq for another breakout room/main room gets “No main room” error.
How can I assure that this timer works 5 sec after set?
Jun 17 14:19:09 muc_breakout_rooms: on_occupant_left-- 1655464749.3107 -> timer set to 5s
Jun 17 14:19:09 muc_breakout_rooms: inside timer-- 1655464749.3444 -> timer runs
Jun 17 14:19:09 muc_breakout_rooms: Closing conference [prp]esrayilmaz@xx as all left for good at 1655464749.3445
Full Log:
Jun 17 14:19:09 muc_breakout_rooms: on_occupant_left-- 1655464749.3107
Jun 17 14:19:09 c2s2f44760: Received[c2s]: <presence to='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus'>
Jun 17 14:19:09 pep: get_pep_service("focus")
Jun 17 14:19:09muc: presence update for 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus from session focus@auth.xx/focus
Jun 17 14:19:09 c2s2f44760: Sending[c2s]: <presence to='focus@auth.xx/focus' from='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus'>
Jun 17 14:19:09 c2s2f44760: Received[c2s]: <presence type='unavailable' to='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus' id='9K4JY-191'>
Jun 17 14:19:09 breakout.xx:muc: session focus@auth.xx/focus is leaving occupant 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus
Jun 17 14:19:09 c2s2f44760: Sending[c2s]: <presence type='unavailable' from='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus' to='focus@auth.xx/focus' id='9K4JY-191'>
Jun 17 14:19:09 breakout.xx:muc: "351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx" empty, destroying
Jun 17 14:19:09 breakout.xx:muc: Forgetting 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx
Jun 17 14:19:09 breakout.xx:muc: Deleting 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx
Jun 17 14:19:09 mod_websocket: Websocket received frame: opcode=1, 26 bytes
Jun 17 14:19:09 c2s31a7600: Received[c2s]: <r xmlns='urn:xmpp:sm:3'>
Jun 17 14:19:09 :smacks: Received ack request, acking for 37
Jun 17 14:19:09 c2s31a7600: Sending[c2s]: <a xmlns='urn:xmpp:sm:3' h='37'>
Jun 17 14:19:09 c2s31a7600: Queuing <r> (in a moment) from piggybacked by handle_r - #queue=3
Jun 17 14:19:09 c2s31a7600: Sending <r> (inside timer, before send) from piggybacked by handle_r - #queue=3
Jun 17 14:19:09 c2s31a7600: Sending[c2s]: <r xmlns='urn:xmpp:sm:3'>
Jun 17 14:19:09 c2s31a7600: Sending <r> (inside timer, after send) from piggybacked by handle_r - #queue=3
Jun 17 14:19:09 mod_websocket: Websocket received frame: opcode=1, 33 bytes
Jun 17 14:19:09 c2s31a7600: Received[c2s]: <a h='54' xmlns='urn:xmpp:sm:3'>
Jun 17 14:19:09 c2s31a7600: #queue = 0
Jun 17 14:19:09 xx:muc_breakout_rooms: inside timer-- 1655464749.3444
Jun 17 14:19:09 xx:muc_breakout_rooms: Closing conference [prp]esrayilmaz@conference.xx as all left for good at 1655464749.3445
Jun 17 14:19:09 conference.xx:muc: Forgetting [prp]esrayilmaz@conference.xx
Jun 17 14:19:09 conference.xx:muc: Deleting [prp]esrayilmaz@conference.xx
Jun 17 14:19:09 xx:reservations: Sending DELETE /conference/1952/prp/PRIVATE_ROOM
Jun 17 14:19:09 http: Making HTTP DELETE request '2c97030' to uy:8080/conference/1952/prp/PRIVATE_ROOM
Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Starting connection process
Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Checking for targets...
Jun 17 14:19:09 adns: Records for uy not in cache, sending query (thread: 0x328bf00)...
Jun 17 14:19:09 server_epoll: Watching FD 35 (dns, 53, 0.0.0.0, 0)
Jun 17 14:19:09 adns: Sending DNS query to 10.218.128.140
Jun 17 14:19:09 adns: Records for uy in cache, sending query (thread: 0x21b6610)...
Jun 17 14:19:09 adns: Sending DNS query to 10.218.128.140
Jun 17 14:19:09 adns: Reply for uy (thread: 0x328bf00)
Jun 17 14:19:09 server_epoll: Close FD 35 (dns, 53, 0.0.0.0, 0) now
Jun 17 14:19:09 server_epoll: Unwatched FD 35 (dns, 53, 0.0.0.0, 0)
Jun 17 14:19:09 adns: Reply for uy (thread: 0x21b6610)
Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Next target to try is 172.21.193.94:8080
Jun 17 14:19:09 server_epoll: Watching FD 35 (172.21.193.121, 34524)
Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Successfully connected
Jun 17 14:19:09 mod_websocket: Websocket received frame: opcode=1, 433 bytes
Jun 17 14:19:09 c2s31a7600: Handled 38 incoming stanzas
Jun 17 14:19:09 c2s31a7600: Received[c2s]: <iq type='set' to='focus.xx' id='0b9eaed1-1966-4e9f-b6e4-95f30a387465:sendIQ'>
MattJ
on
Hi, thanks for the issue report.
Can you please try upgrading to a more recent release? Either 0.12.1 or 0.11.13.
Also, please provide the output of 'prosodyctl about' if the issue persists with the new version.
Thanks!
What steps will reproduce the problem? 1. Generates a timer with delay 5s in every 1 second What is the expected output? I expect the timer runs after 5 s. What do you see instead? It sometimes runs in 1s What version of the product are you using? On what operating system? Prosody 0.11.10 -"Red Hat Enterprise Linux 8.4 (Ootpa)" Please provide any additional information below. This bug is reproduced in Jitsi breakout scenario. I opened a ticcket to Jitsi, and they redirect me to prosody. https://community.jitsi.org/t/breakout-rooms-timer-functionality/115239?u=esrayilmaz When someone leaves the breakout room, it is checked whether this is last user in all breakoutrooms + main room. If so, main room is destroyed after 5 s. Code sets a timer with module:add_timer(ROOMS_TTL_IF_ALL_LEFT, function() function on_occupant_left(event) local room_jid = event.room.jid; if is_healthcheck_room(room_jid) then return; end local main_room = get_main_room(room_jid); if not main_room then return; end if main_room._data.breakout_rooms_active and jid_node(event.occupant.jid) ~= 'focus' then broadcast_breakout_rooms(room_jid); end -- Close the conference if all left for good. if main_room._data.breakout_rooms_active and not main_room._data.is_close_all_scheduled and not exist_occupants_in_rooms(main_room) then main_room._data.is_close_all_scheduled = true; main_room:save(true); module:log('info', 'on_occupant_left-- %s', socket.gettime()); module:add_timer(ROOMS_TTL_IF_ALL_LEFT, function() -- we need to look up again the room as till the timer is fired, the room maybe already destroyed/recreated -- and we will have the old instance module:log('info', 'inside timer-- %s', socket.gettime()); local main_room, main_room_jid = get_main_room(room_jid); if main_room and main_room._data.is_close_all_scheduled and not exist_occupants_in_rooms(main_room) then module:log('info', 'Closing conference %s as all left for good at %s ', main_room_jid, socket.gettime()); main_room:set_persistent(false); main_room:destroy(nil, 'All occupants left.'); end end) end end However, I see behavior that this timer does not always work after 5 s. It sometimes works earlier than 1s. This creates a raise condition when someone tries to leave a breakout room and join to another room. In scenario, it sends unavailable presence for the breakout room. While unavailable presence is processing, timer sets and works in same second, and main room is destroyed. So same client sending an iq for another breakout room/main room gets “No main room” error. How can I assure that this timer works 5 sec after set? Jun 17 14:19:09 muc_breakout_rooms: on_occupant_left-- 1655464749.3107 -> timer set to 5s Jun 17 14:19:09 muc_breakout_rooms: inside timer-- 1655464749.3444 -> timer runs Jun 17 14:19:09 muc_breakout_rooms: Closing conference [prp]esrayilmaz@xx as all left for good at 1655464749.3445 Full Log: Jun 17 14:19:09 muc_breakout_rooms: on_occupant_left-- 1655464749.3107 Jun 17 14:19:09 c2s2f44760: Received[c2s]: <presence to='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus'> Jun 17 14:19:09 pep: get_pep_service("focus") Jun 17 14:19:09muc: presence update for 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus from session focus@auth.xx/focus Jun 17 14:19:09 c2s2f44760: Sending[c2s]: <presence to='focus@auth.xx/focus' from='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus'> Jun 17 14:19:09 c2s2f44760: Received[c2s]: <presence type='unavailable' to='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus' id='9K4JY-191'> Jun 17 14:19:09 breakout.xx:muc: session focus@auth.xx/focus is leaving occupant 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus Jun 17 14:19:09 c2s2f44760: Sending[c2s]: <presence type='unavailable' from='351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx/focus' to='focus@auth.xx/focus' id='9K4JY-191'> Jun 17 14:19:09 breakout.xx:muc: "351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx" empty, destroying Jun 17 14:19:09 breakout.xx:muc: Forgetting 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx Jun 17 14:19:09 breakout.xx:muc: Deleting 351c1711-6460-42ba-aeb1-8611b317fbf5@breakout.xx Jun 17 14:19:09 mod_websocket: Websocket received frame: opcode=1, 26 bytes Jun 17 14:19:09 c2s31a7600: Received[c2s]: <r xmlns='urn:xmpp:sm:3'> Jun 17 14:19:09 :smacks: Received ack request, acking for 37 Jun 17 14:19:09 c2s31a7600: Sending[c2s]: <a xmlns='urn:xmpp:sm:3' h='37'> Jun 17 14:19:09 c2s31a7600: Queuing <r> (in a moment) from piggybacked by handle_r - #queue=3 Jun 17 14:19:09 c2s31a7600: Sending <r> (inside timer, before send) from piggybacked by handle_r - #queue=3 Jun 17 14:19:09 c2s31a7600: Sending[c2s]: <r xmlns='urn:xmpp:sm:3'> Jun 17 14:19:09 c2s31a7600: Sending <r> (inside timer, after send) from piggybacked by handle_r - #queue=3 Jun 17 14:19:09 mod_websocket: Websocket received frame: opcode=1, 33 bytes Jun 17 14:19:09 c2s31a7600: Received[c2s]: <a h='54' xmlns='urn:xmpp:sm:3'> Jun 17 14:19:09 c2s31a7600: #queue = 0 Jun 17 14:19:09 xx:muc_breakout_rooms: inside timer-- 1655464749.3444 Jun 17 14:19:09 xx:muc_breakout_rooms: Closing conference [prp]esrayilmaz@conference.xx as all left for good at 1655464749.3445 Jun 17 14:19:09 conference.xx:muc: Forgetting [prp]esrayilmaz@conference.xx Jun 17 14:19:09 conference.xx:muc: Deleting [prp]esrayilmaz@conference.xx Jun 17 14:19:09 xx:reservations: Sending DELETE /conference/1952/prp/PRIVATE_ROOM Jun 17 14:19:09 http: Making HTTP DELETE request '2c97030' to uy:8080/conference/1952/prp/PRIVATE_ROOM Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Starting connection process Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Checking for targets... Jun 17 14:19:09 adns: Records for uy not in cache, sending query (thread: 0x328bf00)... Jun 17 14:19:09 server_epoll: Watching FD 35 (dns, 53, 0.0.0.0, 0) Jun 17 14:19:09 adns: Sending DNS query to 10.218.128.140 Jun 17 14:19:09 adns: Records for uy in cache, sending query (thread: 0x21b6610)... Jun 17 14:19:09 adns: Sending DNS query to 10.218.128.140 Jun 17 14:19:09 adns: Reply for uy (thread: 0x328bf00) Jun 17 14:19:09 server_epoll: Close FD 35 (dns, 53, 0.0.0.0, 0) now Jun 17 14:19:09 server_epoll: Unwatched FD 35 (dns, 53, 0.0.0.0, 0) Jun 17 14:19:09 adns: Reply for uy (thread: 0x21b6610) Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Next target to try is 172.21.193.94:8080 Jun 17 14:19:09 server_epoll: Watching FD 35 (172.21.193.121, 34524) Jun 17 14:19:09 net.connect: [pending connection 4zeAtnGk] Successfully connected Jun 17 14:19:09 mod_websocket: Websocket received frame: opcode=1, 433 bytes Jun 17 14:19:09 c2s31a7600: Handled 38 incoming stanzas Jun 17 14:19:09 c2s31a7600: Received[c2s]: <iq type='set' to='focus.xx' id='0b9eaed1-1966-4e9f-b6e4-95f30a387465:sendIQ'>
Hi, thanks for the issue report. Can you please try upgrading to a more recent release? Either 0.12.1 or 0.11.13. Also, please provide the output of 'prosodyctl about' if the issue persists with the new version. Thanks!