search

bigbluebutton / greenlight

A really simple end-user interface for your BigBlueButton server.
GNU Lesser General Public License v3.0
794 stars 3.8k forks source link

invalid The createTime parameter submitted mismatches with the current meeting. #2541

Closed christmart closed 1 year ago

christmart commented 3 years ago

Since updating to greenlight version 2.7.19 which introduced the usage of the createTime parameter in the join-call we see in some cases the error:

invalid The createTime parameter submitted mismatches with the current meeting.

After searching through the logs, we found about 2700 cases of the error from about 368000 joins in the last day.

If the error happens, all the users trying to join the conference get the error.

christmart commented 3 years ago

The oldest timestamp I found from todays join calls is 1605795322860 . This is Thu 19 Nov 2020 03:15:22 PM CET we definitely have no meetings which live so long. The whole infrastructure was down since then several times. Also redis on scalelite was cleared since then. Is greenlight somehow caching these values?

farhatahmad commented 3 years ago

So Greenlight uses the rooms last_session value as the createTime. The last_session should be set everytime a room is started. I have a potential idea of a case where it might not happen so I'll take a look

christmart commented 3 years ago

A possible cause could be if the bbb_server.create_meeting returns with an error like:

BigBlueButton failed on create: : Timeout error. Your server is probably down: "https://scalelite/bigbluebutton/api". Error: Net::ReadTimeout

Then the timestamp is not updated and the wrong value is stored in last_session.

christmart commented 3 years ago

Scalelite nginx logs the error code HTTP/1.1" 499 0 "-" "Ruby" "-" which meens that the client (greenlight) closes the connection before scalelite is ready to return the result.

christmart commented 3 years ago

Is there a way to increase the timeout for API-calls? At which location in the code is the timeout defined? I have the impression, that the timeout is about 10 seconds, right?

farhatahmad commented 3 years ago

I believe the timeout is hardcoded in the BigBlueButton ruby gem here: https://github.com/mconf/bigbluebutton-api-ruby/blob/91dc495324a6b7e162773227ec3650f8a5b39c50/lib/bigbluebutton_api.rb#L75

christmart commented 3 years ago

Thanks for the pointer. I would be nice, if this value could be configurable.

farhatahmad commented 3 years ago

I must be missing something. If the create call times out or fails, isn't it correct for us not to update the create Time?

farhatahmad commented 3 years ago

The only situation I can think of that would cause this would be a potential race condition. If the users are waiting for a room to start, there might be a tiny chance that the create call succeeds but the update in the database isn't complete before the join call from the users waiting comes in, which would result in the old last_session value being used

andrekutianski commented 3 years ago

I have the same issue with BigBlueButton Server 2.2.36 (2416) and Greenlight 2.8.3

strangely the error does not occur if I use another BBB instance that runs BigBlueButton Server 2.2.30 (2283)

andrekutianski commented 3 years ago

I have the same issue with BigBlueButton Server 2.2.36 (2416) and Greenlight 2.8.3

strangely the error does not occur if I use another BBB instance that runs BigBlueButton Server 2.2.30 (2283)

After create a new room, the problem no ocour again =/

Tecumtha commented 3 years ago

I have the same Problem:

First start of the Room with a Presentation:

2021-04-19 13:21:30 +0000 - INFO: [9ab26dfabf02d696e614a0ced861d4e7] Support: bbbadmin@krzn.de is starting room krz-mc8-5mb-ioc 
2021-04-19 13:21:30 +0000 - DEBUG: [9ab26dfabf02d696e614a0ced861d4e7]   ActiveStorage::Attachment Load (0.7ms)  SELECT  "active_storage_attachments".* FROM "active_storage_attachments" WHERE "active_storage_attachments"."record_id" = $1 AND "active_storage_attachments"."record_type" = $2 AND "active_storage_attachments"."name" = $3 LIMIT $4  [["record_id", 1], ["record_type", "Room"], ["name", "presentation"], ["LIMIT", 1]] 
2021-04-19 13:21:30 +0000 - DEBUG: [9ab26dfabf02d696e614a0ced861d4e7]   ActiveStorage::Blob Load (0.7ms)  SELECT  "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2  [["id", 9], ["LIMIT", 1]] 
2021-04-19 13:21:30 +0000 - INFO: [9ab26dfabf02d696e614a0ced861d4e7] Support: Room krz-mc8-5mb-ioc starting using presentation: https://<hiddenurl>/rails/active_storage/blobs/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBEZz09IiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--cadf4c26cbaacf549c5a66d9f27f0c8f6e28737f/default%20(1).pdf 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   Setting Load (0.9ms)  SELECT  "settings".* FROM "settings" WHERE "settings"."provider" = $1 LIMIT $2  [["provider", "greenlight"], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   Feature Load (0.9ms)  SELECT "features".* FROM "features" WHERE "features"."setting_id" = $1  [["setting_id", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   User Load (1.0ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   CACHE User Load (0.1ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   CACHE User Load (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   CACHE User Load (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   CACHE User Load (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   CACHE User Load (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - DEBUG: [cf53bc3fec0a42727474485b08f8dc48]   CACHE User Load (0.0ms)  SELECT  "users".* FROM "users" WHERE "users"."deleted" = $1 AND "users"."id" IS NULL LIMIT $2  [["deleted", false], ["LIMIT", 1]] 
2021-04-19 13:21:36 +0000 - INFO: [cf53bc3fec0a42727474485b08f8dc48] method=GET path=/ format=html controller=MainController action=index status=200 duration=37.15 view=21.06 db=2.93 host=greenlight 
2021-04-19 13:21:40 +0000 - ERROR: [9ab26dfabf02d696e614a0ced861d4e7] Support: krz-mc8-5mb-ioc start failed: Timeout error. Your server is probably down: "https://<hiddenurl>/bigbluebutton/api". Error: Net::ReadTimeout 
2021-04-19 13:21:40 +0000 - ERROR: [9ab26dfabf02d696e614a0ced861d4e7] BigBlueButtonException: Timeout error. Your server is probably down: "https://<hiddenurl>/bigbluebutton/api". Error: Net::ReadTimeout

The path in "starting using presentation: https:///rail...." works fine and i can open the Presentation with a Browser.

Second Start with Errormessage:

https:///?errors=[%7B%22message%22:%22The%20createTime%20parameter%20submitted%20mismatches%20with%20the%20current%20meeting.%22,%22key%22:%22mismatchCreateTimeParam%22%7D]

2021-04-19 13:11:19 +0000 - INFO: [7e3cf78a14caf8d5337a4f09108081e4] Support: bbbadmin@krzn.de is starting room krz-mc8-5mb-ioc 
2021-04-19 13:11:19 +0000 - DEBUG: [7e3cf78a14caf8d5337a4f09108081e4]   ActiveStorage::Attachment Load (0.5ms)  SELECT  "active_storage_attachments".* FROM "active_storage_attachments" WHERE "active_storage_attachments"."record_id" = $1 AND "active_storage_attachments"."record_type" = $2 AND "active_storage_attachments"."name" = $3 LIMIT $4  [["record_id", 1], ["record_type", "Room"], ["name", "presentation"], ["LIMIT", 1]] 
2021-04-19 13:11:19 +0000 - DEBUG: [7e3cf78a14caf8d5337a4f09108081e4]   ActiveStorage::Blob Load (0.6ms)  SELECT  "active_storage_blobs".* FROM "active_storage_blobs" WHERE "active_storage_blobs"."id" = $1 LIMIT $2  [["id", 6], ["LIMIT", 1]] 
2021-04-19 13:11:19 +0000 - INFO: [7e3cf78a14caf8d5337a4f09108081e4] Support: Room krz-mc8-5mb-ioc starting using presentation: https://<hiddenurl>/rails/active_storage/blobs/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBDdz09IiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--241905411ec29c7f8102af0272761871cafc5249/default%20(1).pdf 
2021-04-19 13:11:19 +0000 - INFO: [7e3cf78a14caf8d5337a4f09108081e4] [ActiveJob] Enqueued NotifyUserWaitingJob (Job ID: 62cd8ef1-d1a6-4b19-9563-d9327b5ee4da) to Async(default) at 2021-04-19 13:11:24 UTC with arguments: #<GlobalID:0x00007f7ee54973a0 @uri=#<URI::GID gid://greenlight/Room/1>> 
2021-04-19 13:11:19 +0000 - INFO: [7e3cf78a14caf8d5337a4f09108081e4] method=POST path=/krz-mc8-5mb-ioc/start format=html controller=RoomsController action=start status=302 duration=97.57 view=0.00 db=5.88 location=https://<hiddenurl>/bigbluebutton/api/join host=greenlight 
2021-04-19 13:11:24 +0000 - DEBUG:   Room Load (0.8ms)  SELECT  "rooms".* FROM "rooms" WHERE "rooms"."id" = $1 LIMIT $2  [["id", 1], ["LIMIT", 1]] 
2021-04-19 13:11:24 +0000 - INFO: [ActiveJob] [NotifyUserWaitingJob] [62cd8ef1-d1a6-4b19-9563-d9327b5ee4da] Performing NotifyUserWaitingJob (Job ID: 62cd8ef1-d1a6-4b19-9563-d9327b5ee4da) from Async(default) with arguments: #<GlobalID:0x00007f7ee5405d10 @uri=#<URI::GID gid://greenlight/Room/1>> 
2021-04-19 13:11:24 +0000 - INFO: [ActiveJob] [NotifyUserWaitingJob] [62cd8ef1-d1a6-4b19-9563-d9327b5ee4da] Performed NotifyUserWaitingJob (Job ID: 62cd8ef1-d1a6-4b19-9563-d9327b5ee4da) from Async(default) in 0.92ms

Later i see in the logfiles:

Disk Storage (1.2ms) Generated URL for file at key: LnGNjURyvAQpAFD9E8FuT4y9 (https://<hiddenurl>/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSWRURzVIVG1wVlVubDJRVkZ3UVVaRU9VVTRSblZVTkhrNUJqb0dSVlE2RUdScGMzQnZjMmwwYVc5dVNTSlRhVzVzYVc1bE95Qm1hV3hsYm1GdFpUMGlaR1ZtWVhWc2RDQWxNamd4SlRJNUxuQmtaaUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuWkdWbVlYVnNkQ1V5TUNVeU9ERWxNamt1Y0dSbUJqc0dWRG9SWTI5dWRHVnVkRjkwZVhCbFNTSVVZWEJ3YkdsallYUnBiMjR2Y0dSbUJqc0dWQT09IiwiZXhwIjoiMjAyMS0wNC0xOVQxMzoxNzo0NC4zMjdaIiwicHVyIjoiYmxvYl9rZXkifX0=--6cef6c47ac3a5b4236be8593f4d6dfc0d3bce599/default%20(1).pdf?content_type=application%2Fpdf&disposition=inline%3B+filename%3D%22default+%25281%2529.pdf%22%3B+filename%2A%3DUTF-8%27%27default%2520%25281%2529.pdf) 
2021-04-19 13:12:44 +0000 - INFO: [4467ba59e52787a78958be2e48d0ae6c] method=GET path=/rails/active_storage/blobs/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaHBDdz09IiwiZXhwIjpudWxsLCJwdXIiOiJibG9iX2lkIn19--241905411ec29c7f8102af0272761871cafc5249/default%20(1).pdf format=pdf controller=ActiveStorage::BlobsController action=show status=302 duration=6.12 view=0.00 db=0.74 location=https://<hiddenurl>/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSWRURzVIVG1wVlVubDJRVkZ3UVVaRU9VVTRSblZVTkhrNUJqb0dSVlE2RUdScGMzQnZjMmwwYVc5dVNTSlRhVzVzYVc1bE95Qm1hV3hsYm1GdFpUMGlaR1ZtWVhWc2RDQWxNamd4SlRJNUxuQmtaaUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuWkdWbVlYVnNkQ1V5TUNVeU9ERWxNamt1Y0dSbUJqc0dWRG9SWTI5dWRHVnVkRjkwZVhCbFNTSVVZWEJ3YkdsallYUnBiMjR2Y0dSbUJqc0dWQT09IiwiZXhwIjoiMjAyMS0wNC0xOVQxMzoxNzo0NC4zMjdaIiwicHVyIjoiYmxvYl9rZXkifX0=--6cef6c47ac3a5b4236be8593f4d6dfc0d3bce599/default%20(1).pdf host= 
2021-04-19 13:12:44 +0000 - INFO: [3f66699e77067e03702e2b63f2438c3a] method=GET path=/rails/active_storage/disk/eyJfcmFpbHMiOnsibWVzc2FnZSI6IkJBaDdDRG9JYTJWNVNTSWRURzVIVG1wVlVubDJRVkZ3UVVaRU9VVTRSblZVTkhrNUJqb0dSVlE2RUdScGMzQnZjMmwwYVc5dVNTSlRhVzVzYVc1bE95Qm1hV3hsYm1GdFpUMGlaR1ZtWVhWc2RDQWxNamd4SlRJNUxuQmtaaUk3SUdacGJHVnVZVzFsS2oxVlZFWXRPQ2NuWkdWbVlYVnNkQ1V5TUNVeU9ERWxNamt1Y0dSbUJqc0dWRG9SWTI5dWRHVnVkRjkwZVhCbFNTSVVZWEJ3YkdsallYUnBiMjR2Y0dSbUJqc0dWQT09IiwiZXhwIjoiMjAyMS0wNC0xOVQxMzoxNzo0NC4zMjdaIiwicHVyIjoiYmxvYl9rZXkifX0=--6cef6c47ac3a5b4236be8593f4d6dfc0d3bce599/default%20(1).pdf format=pdf controller=ActiveStorage::DiskController action=show status=200 duration=1.46 view=0.00 db=0.00 host=

in the second Line after "view=0.00 db=0.74 location=https://<hidden" and in the third Line, i dont understand the new Path and it doesn't work.

christmart commented 3 years ago

We can also correlate this problem with big preuploaded presentations. After changing the timeout to 20s in bigbluebutton-api-ruby it works in most cases but persist with big presentations.

farhatahmad commented 3 years ago

@christmart Can you point me to the file where you made the change?

christmart commented 3 years ago 
+++ b/lib/bigbluebutton_api.rb
@@ -72,7 +72,7 @@ module BigBlueButton
       @url = url
       @secret = secret
       @debug = debug
 -      @timeout = 10         # default timeout for api requests
 +      @timeout = 20         # default timeout for api requests
       @request_headers = {} # http headers sent in all requests

       version = nil if version && version.strip.empty?
farhatahmad commented 1 year ago

Please note: Greenlight v3 has been released. With this new version, many of the issues and bugs that were present in v2 have been resolved.

As a result, we will no longer be providing updates or support for v2 (except for major security issues), and we will be closing any outstanding bug reports / feature requests related to v2. While we understand that some of you may still be using v2, we highly encourage you to upgrade to v3 to take advantage of the improved features and stability. If your request/bug still applies to v3, please open a new issue for it

Ithanil commented 10 months ago

@farhatahmad The problem can still appear in GL3, when not using an increased timeout as in https://github.com/bigbluebutton/greenlight/issues/2541#issuecomment-831370708 We settled at 60s, actually.