search

littleredbutton / cloud_bbb

@bigbluebutton integration for @nextcloud
GNU Affero General Public License v3.0
103 stars 42 forks source link

Cannot delete recordings on load-balanced bbb setup #76

Closed sushifrick closed 4 years ago

sushifrick commented 4 years ago

Describe the bug When using a loadbalanced BBB setup with the scalelite balancer, recordings cannot be deleted. I testet the setup using the Api backend of a single server and it works well, when using the scaler, I get the error message "Server error. Could not delete record". The scaler acts as a BBB Server as a "normal" Api end point and underneath delegated to different BBB servers itself. The default frontend Greenlight works with the scaler, including deleting recordings. I am not sure if this is a scalelite, or a cloud_bbb bug. I am happy to provide additional logs if needed.

To Reproduce Steps to reproduce the behavior:

  1. Start a meeting via cloud_bbb
  2. Start a recording, stop it, end meeting
  3. After the processing is finished, the recording is shown with a collapsible menu.
  4. Trying to delete the recording throws an error: Could not delete record

Expected behavior The recording is deleted

System (please complete the following information):

Nextcloud log:

No errors regarding this problem

Javascript log:

Failed to load resource: the server responded with a status of 500 (Internal Server Error)
RoomRow.tsx:144 Could not delete recording Error: Request failed with status code 500
    at e.exports (createError.js:16)
    at e.exports (settle.js:17)
    at XMLHttpRequest.p.onreadystatechange (xhr.js:69)
(anonymous) @ RoomRow.tsx:144

Scalelite logs: When trying to delete a recording, the Logs on the scaler show a list request, but no delete request.

Sep 04 11:59:32 mediascale01 docker[9969]: I, [2020-09-04T09:59:32.250900 #6]  INFO -- : [90a78e0d-aa43-4947-a13b-f8a5ba83f5d0] Started GET "/bigbluebutton/api/getRecordings?recordID=4e010c045b31f678a7f40bdd460984c5fb9d0696-1599212188644&state=any&checksum=944f56adfe7e07c2a5cdb5df0a72d47450fb16ab" for 172.18.0.4 at 2020-09-04 09:59:32 +0000
Sep 04 11:59:32 mediascale01 docker[9969]: I, [2020-09-04T09:59:32.251862 #6]  INFO -- : [90a78e0d-aa43-4947-a13b-f8a5ba83f5d0]   Parameters: {"recordID"=>"4e010c045b31f678a7f40bdd460984c5fb9d0696-1599212188644", "state"=>"any", "checksum"=>"944f56adfe7e07c2a5cdb5df0a72d47450fb16ab"}
Sep 04 11:59:32 mediascale01 docker[9969]: D, [2020-09-04T09:59:32.255641 #6] DEBUG -- : [90a78e0d-aa43-4947-a13b-f8a5ba83f5d0]   Recording Load (1.3ms)  SELECT "recordings".* FROM "recordings" WHERE (record_id LIKE '4e010c045b31f678a7f40bdd460984c5fb9d0696-1599212188644%' ESCAPE '|') ORDER BY "recordings"."starttime" DESC
Sep 04 11:59:32 mediascale01 docker[10147]: 172.22.15.131 - - [04/Sep/2020:09:59:32 +0000] "GET /bigbluebutton/api/getRecordings?recordID=4e010c045b31f678a7f40bdd460984c5fb9d0696-1599212188644&state=any&checksum=944f56adfe7e07c2a5cdb5df0a72d47450fb16ab HTTP/1.1" 200 1897 "-" "-" "-"

Scalelite logs using greenlight: When using the greenlight frontend /bigbluebutton/api/deleteRecordings is called, but not using cloud_bbb due to the prior server error?

Sep  3 09:52:03 mediascale01 docker: D, [2020-09-03T07:52:03.380560 #6] DEBUG -- : [1bfa7df9-8e6a-4867-ac55-c578b22d87ea]   #033[1m#033[36mRecording Load (0.2ms)#033[0m  #033[1m#033[34mSELECT "recordings".* FROM "recordings" WHERE "recordings"."meeting_id" = $1 ORDER BY "recordings"."starttime" DESC#033[0m  [["meeting_id", "6e326afeec130bdff5e76dfbe3e03b0e94815123"]]
Sep  3 09:52:03 mediascale01 docker: I, [2020-09-03T07:52:03.380895 #6]  INFO -- : [1bfa7df9-8e6a-4867-ac55-c578b22d87ea]   Rendered bigbluebutton_api/get_recordings.xml.builder (Duration: 1.1ms | Allocations: 363)
Sep  3 09:52:03 mediascale01 docker: I, [2020-09-03T07:52:03.381041 #6]  INFO -- : [1bfa7df9-8e6a-4867-ac55-c578b22d87ea] Completed 200 OK in 2ms (Views: 1.3ms | ActiveRecord: 0.2ms | Allocations: 788)
Sep  3 09:52:03 mediascale01 docker: 123.123.2.106 - - [03/Sep/2020:07:52:03 +0000] "GET /bigbluebutton/api/getRecordings?meetingID=6e326afeec130bdff5e76dfbe3e03b0e94815123&checksum=3af1f840a46648ef61202215c7e112a34ff1b0d0 HTTP/1.1" 200 203 "-" "Ruby" "-"
Sep  3 09:52:05 mediascale01 kernel: STATE_INVALID_DROP: IN=ens224 OUT= MAC=00:50:56:9b:81:8e:22:b3:99:57:95:e6:08:00 SRC=23.236.62.147 DST=123.123.2.107 LEN=60 TOS=0x00 PREC=0x00 TTL=53 ID=0 DF PROTO=TCP SPT=80 DPT=50571 WINDOW=0 RES=0x00 ACK SYN URGP=0 
Sep  3 09:52:06 mediascale01 docker: I, [2020-09-03T07:52:06.198090 #6]  INFO -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd] Started GET "/bigbluebutton/api/deleteRecordings?recordID=cd8e251ee82a3b73b7cb2e8814439e0761c76b33-1598186412696&checksum=912e38c700948886765c17c451ea2ebd599a5cdc" for 123.123.2.106 at 2020-09-03 07:52:06 +0000
Sep  3 09:52:06 mediascale01 docker: I, [2020-09-03T07:52:06.199309 #6]  INFO -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd] Processing by BigBlueButtonApiController#delete_recordings as XML
Sep  3 09:52:06 mediascale01 docker: I, [2020-09-03T07:52:06.199414 #6]  INFO -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   Parameters: {"recordID"=>"cd8e251ee82a3b73b7cb2e8814439e0761c76b33-1598186412696", "checksum"=>"912e38c700948886765c17c451ea2ebd599a5cdc"}
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.201650 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mRecording Load (0.4ms)#033[0m  #033[1m#033[34mSELECT "recordings".* FROM "recordings" WHERE "recordings"."record_id" = $1#033[0m  [["record_id", "cd8e251ee82a3b73b7cb2e8814439e0761c76b33-1598186412696"]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.202766 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[35m (0.2ms)#033[0m  #033[1m#033[35mBEGIN#033[0m
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.203309 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mRecording Load (0.4ms)#033[0m  #033[1m#033[37mSELECT "recordings".* FROM "recordings" WHERE "recordings"."id" = $1 LIMIT $2 FOR UPDATE#033[0m  [["id", 2103], ["LIMIT", 1]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.203541 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd] Deleting recording: cd8e251ee82a3b73b7cb2e8814439e0761c76b33-1598186412696
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.252335 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mMetadatum Load (0.6ms)#033[0m  #033[1m#033[34mSELECT "metadata".* FROM "metadata" WHERE "metadata"."recording_id" = $1#033[0m  [["recording_id", 2103]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.254465 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mMetadatum Destroy (0.7ms)#033[0m  #033[1m#033[31mDELETE FROM "metadata" WHERE "metadata"."id" = $1#033[0m  [["id", 9375]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.255915 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mMetadatum Destroy (0.7ms)#033[0m  #033[1m#033[31mDELETE FROM "metadata" WHERE "metadata"."id" = $1#033[0m  [["id", 9376]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.257127 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mMetadatum Destroy (0.6ms)#033[0m  #033[1m#033[31mDELETE FROM "metadata" WHERE "metadata"."id" = $1#033[0m  [["id", 9377]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.258278 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mMetadatum Destroy (0.6ms)#033[0m  #033[1m#033[31mDELETE FROM "metadata" WHERE "metadata"."id" = $1#033[0m  [["id", 9378]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.260120 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mPlaybackFormat Load (0.4ms)#033[0m  #033[1m#033[34mSELECT "playback_formats".* FROM "playback_formats" WHERE "playback_formats"."recording_id" = $1 ORDER BY "playback_formats"."format" ASC#033[0m  [["recording_id", 2103]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.262227 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mThumbnail Load (0.4ms)#033[0m  #033[1m#033[34mSELECT "thumbnails".* FROM "thumbnails" WHERE "thumbnails"."playback_format_id" = $1 ORDER BY "thumbnails"."sequence" ASC#033[0m  [["playback_format_id", 2103]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.263138 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mThumbnail Destroy (0.3ms)#033[0m  #033[1m#033[31mDELETE FROM "thumbnails" WHERE "thumbnails"."id" = $1#033[0m  [["id", 6304]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.263708 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mThumbnail Destroy (0.3ms)#033[0m  #033[1m#033[31mDELETE FROM "thumbnails" WHERE "thumbnails"."id" = $1#033[0m  [["id", 6305]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.264286 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mThumbnail Destroy (0.3ms)#033[0m  #033[1m#033[31mDELETE FROM "thumbnails" WHERE "thumbnails"."id" = $1#033[0m  [["id", 6306]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.264891 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mPlaybackFormat Destroy (0.3ms)#033[0m  #033[1m#033[31mDELETE FROM "playback_formats" WHERE "playback_formats"."id" = $1#033[0m  [["id", 2103]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.265468 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[36mRecording Destroy (0.3ms)#033[0m  #033[1m#033[31mDELETE FROM "recordings" WHERE "recordings"."id" = $1#033[0m  [["id", 2103]]
Sep  3 09:52:06 mediascale01 docker: D, [2020-09-03T07:52:06.266357 #6] DEBUG -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   #033[1m#033[35m (0.7ms)#033[0m  #033[1m#033[35mCOMMIT#033[0m
Sep  3 09:52:06 mediascale01 docker: I, [2020-09-03T07:52:06.266787 #6]  INFO -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   Rendering bigbluebutton_api/delete_recordings.xml.builder
Sep  3 09:52:06 mediascale01 docker: I, [2020-09-03T07:52:06.267035 #6]  INFO -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd]   Rendered bigbluebutton_api/delete_recordings.xml.builder (Duration: 0.2ms | Allocations: 111)
Sep  3 09:52:06 mediascale01 docker: I, [2020-09-03T07:52:06.267230 #6]  INFO -- : [fdbb270a-bb4d-41a1-9cb8-7184053e66bd] Completed 200 OK in 68ms (Views: 0.7ms | ActiveRecord: 7.1ms | Allocations: 3281)
Sep  3 09:52:06 mediascale01 docker: 123.123.2.106 - - [03/Sep/2020:07:52:06 +0000] "GET /bigbluebutton/api/deleteRecordings?recordID=cd8e251ee82a3b73b7cb2e8814439e0761c76b33-1598186412696&checksum=912e38c700948886765c17c451ea2ebd599a5cdc HTTP/1.1" 200 95 "-" "Ruby" "-"
sualko commented 4 years ago

Since I don't operate a scalelite server, I'm depending on you for debugging this issue :wink:

"the server responded with a status of 500" indicates that Nextcloud is throwing an error, so I'm wondering why you see no related error message in your logs. If you enable debug mode and look at your network tab in your chrome dev console, you should see the error message in the xhr response.

sushifrick commented 4 years ago

Hi @sualko, thank you for the quick response. I only looked at the console output, not the network tab before. Now I did find a request id fot the error with an entry in the nextcloud log. Also I increased the log level to debug. I piped the output through jq to make it more readable, although it is quite long now.

Log output

```{ "reqId": "X1X5ZBAHpj92bMvlRQ6k7wAAAIo", "level": 3, "time": "2020-09-07T09:12:05+00:00", "remoteAddr": "123.123.7.6", "user": "abc123", "app": "PHP", "method": "DELETE", "url": "/index.php/apps/bbb/server/record/a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "message": "Trying to access array offset on value of type null at /var/www/html/nextcloud-19.0.2/nextcloud/apps/bbb/lib/Controller/ServerController.php#68", "userAgent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36", "version": "19.0.2.2" } { "reqId": "X1X5ZBAHpj92bMvlRQ6k7wAAAIo", "level": 3, "time": "2020-09-07T09:12:05+00:00", "remoteAddr": "123.123.7.6", "user": "abc123", "app": "index", "method": "DELETE", "url": "/index.php/apps/bbb/server/record/a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "message": { "Exception": "Exception", "Message": "Argument 1 passed to OCA\\BigBlueButton\\Db\\RoomMapper::findByUid() must be of the type string, null given, called in /var/www/html/nextcloud-19.0.2/nextcloud/apps/bbb/lib/Service/RoomService.php on line 53", "Code": 0, "Trace": [ { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/App.php", "line": 137, "function": "dispatch", "class": "OC\\AppFramework\\Http\\Dispatcher", "type": "->", "args": [ { "__class__": "OCA\\BigBlueButton\\Controller\\ServerController" }, "deleteRecord" ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/Routing/RouteActionHandler.php", "line": 47, "function": "main", "class": "OC\\AppFramework\\App", "type": "::", "args": [ "OCA\\BigBlueButton\\Controller\\ServerController", "deleteRecord", { "__class__": "OC\\AppFramework\\DependencyInjection\\DIContainer" }, { "recordId": "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "_route": "bbb.server.delete_record" } ] }, { "function": "__invoke", "class": "OC\\AppFramework\\Routing\\RouteActionHandler", "type": "->", "args": [ { "recordId": "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "_route": "bbb.server.delete_record" } ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/Route/Router.php", "line": 297, "function": "call_user_func", "args": [ { "__class__": "OC\\AppFramework\\Routing\\RouteActionHandler" }, { "recordId": "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "_route": "bbb.server.delete_record" } ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/base.php", "line": 1012, "function": "match", "class": "OC\\Route\\Router", "type": "->", "args": [ "/apps/bbb/server/record/a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014" ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/index.php", "line": 37, "function": "handleRequest", "class": "OC", "type": "::", "args": [] } ], "File": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/Http/Dispatcher.php", "Line": 110, "Previous": { "Exception": "TypeError", "Message": "Argument 1 passed to OCA\\BigBlueButton\\Db\\RoomMapper::findByUid() must be of the type string, null given, called in /var/www/html/nextcloud-19.0.2/nextcloud/apps/bbb/lib/Service/RoomService.php on line 53", "Code": 0, "Trace": [ { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/apps/bbb/lib/Service/RoomService.php", "line": 53, "function": "findByUid", "class": "OCA\\BigBlueButton\\Db\\RoomMapper", "type": "->", "args": [ null ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/apps/bbb/lib/Controller/ServerController.php", "line": 68, "function": "findByUid", "class": "OCA\\BigBlueButton\\Service\\RoomService", "type": "->", "args": [ null ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/Http/Dispatcher.php", "line": 170, "function": "deleteRecord", "class": "OCA\\BigBlueButton\\Controller\\ServerController", "type": "->", "args": [ "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014" ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/Http/Dispatcher.php", "line": 100, "function": "executeController", "class": "OC\\AppFramework\\Http\\Dispatcher", "type": "->", "args": [ { "__class__": "OCA\\BigBlueButton\\Controller\\ServerController" }, "deleteRecord" ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/App.php", "line": 137, "function": "dispatch", "class": "OC\\AppFramework\\Http\\Dispatcher", "type": "->", "args": [ { "__class__": "OCA\\BigBlueButton\\Controller\\ServerController" }, "deleteRecord" ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/AppFramework/Routing/RouteActionHandler.php", "line": 47, "function": "main", "class": "OC\\AppFramework\\App", "type": "::", "args": [ "OCA\\BigBlueButton\\Controller\\ServerController", "deleteRecord", { "__class__": "OC\\AppFramework\\DependencyInjection\\DIContainer" }, { "recordId": "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "_route": "bbb.server.delete_record" } ] }, { "function": "__invoke", "class": "OC\\AppFramework\\Routing\\RouteActionHandler", "type": "->", "args": [ { "recordId": "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "_route": "bbb.server.delete_record" } ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/private/Route/Router.php", "line": 297, "function": "call_user_func", "args": [ { "__class__": "OC\\AppFramework\\Routing\\RouteActionHandler" }, { "recordId": "a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014", "_route": "bbb.server.delete_record" } ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/lib/base.php", "line": 1012, "function": "match", "class": "OC\\Route\\Router", "type": "->", "args": [ "/apps/bbb/server/record/a0aef0848fb387b45d52c3d576a532088aa07394-1598959374014" ] }, { "file": "/var/www/html/nextcloud-19.0.2/nextcloud/index.php", "line": 37, "function": "handleRequest", "class": "OC", "type": "::", "args": [] } ], "File": "/var/www/html/nextcloud-19.0.2/nextcloud/apps/bbb/lib/Db/RoomMapper.php", "Line": 34 }, "CustomMessage": "--" }, "userAgent": "Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/85.0.4183.83 Safari/537.36", "version": "19.0.2.2" } ```

sualko commented 4 years ago

Thanks for the nice log entry. Can you try to apply 4d9a7b8a793b776122bdf051b2ef2ac7c8a7ef36 by hand and report if it is working?

sushifrick commented 4 years ago

Hi @sualko,

i patched the two files by hand and it works without a problem now, thank you very much!

sualko commented 4 years ago

it works without a problem now

Glad to hear. Thanks for testing.