blindsidenetworks / scalelite

Scalable load balancer for BigBlueButton.
GNU Affero General Public License v3.0
472 stars 248 forks source link

Race condition with meeting creation and poller can cause meeting to end immediately #320

Open mabeyj opened 4 years ago

mabeyj commented 4 years ago

A user reported that they created a meeting and then immediately got an error when joining the meeting. From the logs, it looks like there is a race condition between meeting creation and the poller that could cause a meeting to immediately end. In this case, the poller ran in the middle of meeting creation:

Relevant logs:

// scalelite-api
[2020-09-08T19:03:46.377908 #6]  INFO -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Started GET "/bigbluebutton/api/create?name=Test+123&meetingID=OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg&..." for ... at 2020-09-08 19:03:46 +0000
[2020-09-08T19:03:46.379320 #6]  INFO -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Processing by BigBlueButtonApiController#create as XML
[2020-09-08T19:03:46.379440 #6]  INFO -- : [e8134140-9a35-498a-85ff-a9e24cf33506]   Parameters: {"name"=>"Test 123", "meetingID"=>"OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg", ...}
[2020-09-08T19:03:46.380605 #6] DEBUG -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Creating meeting OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg in database.
[2020-09-08T19:03:46.381189 #6] DEBUG -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Meeting find_or_create: created=true on server_id=26126ec3-25df-44b5-972a-2d5b41f1e3ce (wanted 26126ec3-25df-44b5-972a-2d5b41f1e3ce)
[2020-09-08T19:03:46.381320 #6] DEBUG -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Incrementing server 26126ec3-25df-44b5-972a-2d5b41f1e3ce load by 1
[2020-09-08T19:03:46.381686 #6] DEBUG -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Creating meeting OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg on BigBlueButton server 26126ec3-25df-44b5-972a-2d5b41f1e3ce
// poller ran here
[2020-09-08T19:03:46.481595 #6]  INFO -- : [e8134140-9a35-498a-85ff-a9e24cf33506] Completed 200 OK in 102ms (Views: 0.2ms | ActiveRecord: 0.0ms | Allocations: 1301)
[2020-09-08T19:03:46.792546 #6]  INFO -- : [0f8fa145-8737-4349-a312-030d741ed5e6] Started GET "/bigbluebutton/api/join?fullName=...&meetingID=OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg&..." for ... at 2020-09-08 19:03:46 +0000
[2020-09-08T19:03:46.794082 #6]  INFO -- : [0f8fa145-8737-4349-a312-030d741ed5e6] Processing by BigBlueButtonApiController#join as XML
[2020-09-08T19:03:46.794333 #6]  INFO -- : [0f8fa145-8737-4349-a312-030d741ed5e6]   Parameters: {"fullName"=>"...", "meetingID"=>"OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg", ...}
[2020-09-08T19:03:46.796014 #6]  INFO -- : [0f8fa145-8737-4349-a312-030d741ed5e6] The requested meeting OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg does not exist

// scalelite-poller
[2020-09-08T19:03:46.407294 #6] DEBUG -- : Polling Meeting id=OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg on Server id=26126ec3-25df-44b5-972a-2d5b41f1e3ce
[2020-09-08T19:03:46.422979 #6]  INFO -- : Meeting id=OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg on Server id=26126ec3-25df-44b5-972a-2d5b41f1e3ce has ended
[2020-09-08T19:03:46.441980 #6] DEBUG -- : Polling Server id=26126ec3-25df-44b5-972a-2d5b41f1e3ce
[2020-09-08T19:03:46.460165 #6]  INFO -- : Server id=26126ec3-25df-44b5-972a-2d5b41f1e3ce online load: 1.0

// bbb
2020-09-08T19:03:46.398Z DEBUG o.b.web.controllers. - ApiController#create
2020-09-08T19:03:46.398Z DEBUG o.b.web.controllers. - [name:[Test 123], meetingID:[OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg], ...]
2020-09-08T19:03:46.424Z DEBUG o.b.web.controllers. - ApiController#getMeetingInfo
2020-09-08T19:03:46.424Z INFO  o.b.web.controllers. - Retrieving meeting e0c21292e8ec170dce2c00f0d9658a7f4e1c1750
2020-09-08T19:03:46.424Z DEBUG o.b.web.controllers. - ApiController#invalid We could not find a meeting with that meeting ID
2020-09-08T19:03:46.440Z DEBUG o.b.web.controllers. - ApiController#uploadDocuments(e0c21292e8ec170dce2c00f0d9658a7f4e1c1750-1599591826399)
2020-09-08T19:03:46.441Z DEBUG o.b.web.controllers. - ApiController#downloadAndProcessDocument(https://.../default.pdf, e0c21292e8ec170dce2c00f0d9658a7f4e1c1750-1599591826399, )
2020-09-08T19:03:46.441Z DEBUG o.b.p.PresentationUrlDownloadService - Creating dir [/var/bigbluebutton/e0c21292e8ec170dce2c00f0d9658a7f4e1c1750-1599591826399/e0c21292e8ec170dce2c00f0d9658a7f4e1c1750-1599591826399/d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1599591826441]
2020-09-08T19:03:46.441Z INFO  o.bigbluebutton.api.MeetingService -  --analytics-- data={"duration":0,"record":true,"logCode":"create_meeting","name":"Test 123","description":"Create meeting.","meetingId":"e0c21292e8ec170dce2c00f0d9658a7f4e1c1750-1599591826399","externalMeetingId":"OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg","isBreakout":false,"webcamsOnlyForModerator":false}
2020-09-08T19:03:46.447Z INFO  o.bigbluebutton.api.MeetingService -  --analytics-- data={"duration":0,"record":true,"logCode":"meeting_started","name":"Test 123","description":"Meeting has started.","meetingId":"e0c21292e8ec170dce2c00f0d9658a7f4e1c1750-1599591826399","externalMeetingId":"OjRGyT7u-6BQFGsqOFCVEYQv1ZUnCJPvbr1Se-zmcrg","isBreakout":false}
2020-09-08T19:03:46.460Z DEBUG o.b.web.controllers. - ApiController#getMeetings
2020-09-08T19:03:46.482Z DEBUG o.b.web.controllers. - Rendering as xml
farhatahmad commented 3 years ago

Hmm - I'm not quite sure there is anything that can be done here on Scalelite's end. The issue here is that the BigBlueButton API replies with notFound if it receives a getMeetingInfo request for a meeting currently being created. Without significant architecture changes, I'm not quite sure how this could be resolved on Scalelite's side.

Maybe add in some sort of delay to the poller so that it doesn't delete meetings that are less than > 1 min old?