BigBlueButton 2.3 - invalid recordings

lonesomewalker commented 3 years ago

Something seems messed up in combination with BBB 2.3.

Fresh install, shows X deleted recordings. Unfortunately, for a fresh recording, there should be NO recordings? Also, the imported recordings do not count up correctly, and there is one "unprocessed"...?

greenstatic commented 3 years ago

Do you have the RECORDINGS_METRICS_READ_FROM_DISK optimization turned on or do you get recordings data from BBB's API?

lonesomewalker commented 3 years ago

Turned on. And yes, the API in general delivers the information correct :-|

greenstatic commented 3 years ago

Have you managed to figure this out?

amg-web commented 3 years ago

in my case I see published records == unprocessed records environment: RECORDINGS_METRICS_READ_FROM_DISK: "true"

# HELP bbb_meetings_participants_origin Total number of participants in all BigBlueButton meetings by origin servername
# TYPE bbb_meetings_participants_origin gauge
# HELP bbb_recordings_unpublished Total number of BigBlueButton recordings unpublished
# TYPE bbb_recordings_unpublished gauge
bbb_recordings_unpublished 0.0
# HELP bbb_recordings_processing Total number of BigBlueButton recordings processing (scraped from disk)
# TYPE bbb_recordings_processing gauge
bbb_recordings_processing 0.0
# HELP bbb_recordings_published Total number of BigBlueButton recordings published (scraped from disk)
# TYPE bbb_recordings_published gauge
bbb_recordings_published 379.0
# HELP bbb_recordings_deleted Total number of BigBlueButton recordings deleted (scraped from disk)
# TYPE bbb_recordings_deleted gauge
bbb_recordings_deleted 0.0
# HELP bbb_recordings_unprocessed Total number of BigBlueButton recordings enqueued to be processed (scraped from disk)
# TYPE bbb_recordings_unprocessed gauge
bbb_recordings_unprocessed 379.0

amg-web commented 3 years ago

one more thing: it's time to depricate flash related items bbb_meetings_participant_clients{type="flash"} 0.0

semzor commented 3 years ago

I have the same problem with @amg-web. unprocessed record number never drops even though everything is already published. I am using bbb 2.3.13 and exporter 0.6.0

greenstatic commented 3 years ago

Do you also have the RECORDINGS_METRICS_READ_FROM_DISK enabled?
How many files do you have under /var/bigbluebutton/recording/status/sanity?

semzor commented 3 years ago

Do you also have the RECORDINGS_METRICS_READ_FROM_DISK enabled?

How many files do you have under /var/bigbluebutton/recording/status/sanity?

Yes it is enabled in my config.
I have 4 files under /var/bigbluebutton/recording/status/sanity right now.

greenstatic commented 3 years ago

Does the unprocessed metric have the value 4?

On Fri, Sep 10, 2021, at 4:06 PM, semzor wrote:

Do you also have the RECORDINGS_METRICS_READ_FROM_DISK https://bigbluebutton-exporter.greenstatic.dev/exporter-user-guide/#optimizations enabled?

How many files do you have under /var/bigbluebutton/recording/status/sanity?

Yes it is enabled in my config.

I have 4 files under /var/bigbluebutton/recording/status/sanity right now.

— You are receiving this because you were assigned. Reply to this email directly, view it on GitHub https://github.com/greenstatic/bigbluebutton-exporter/issues/81#issuecomment-916931430, or unsubscribe https://github.com/notifications/unsubscribe-auth/ADPHVUUDFS4MWCCZVMRNXQ3UBIGGTANCNFSM4W37VLWQ. Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

semzor commented 3 years ago

Yes it is like this now:

amg-web commented 3 years ago

sanity files is not deleted in BBB v.2.3.x

greenstatic commented 3 years ago

I see, do you maybe know where the unprocessed files are being stored now? We need to fix this.

amg-web commented 3 years ago

sanity files was removed by /usr/local/bigbluebutton/core/scripts/rap-process-worker.rb despite the fact this script is still in a folder on developer branch actually this script is missing on production systems. https://github.com/bigbluebutton/bigbluebutton/blob/develop/record-and-playback/core/scripts/rap-process-worker.rb So I do not know if it still needed by BBB

balbertho commented 2 years ago

Are there any updates on this issue? I am currently running a production environment with bigbluebutton 2.4.7 which has been upgraded from 2.2.x, currently the dashboard shows this: The recording unprocessed count has never gone down since last year's upgrade. At this moment, the process has this status:

● bbb-rap-starter.service - BigBlueButton recording processing starter
   Loaded: loaded (/usr/lib/systemd/system/bbb-rap-starter.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2022-05-25 15:44:04 UTC; 1 day 11h ago
 Main PID: 1568 (rap-starter.rb)
    Tasks: 2 (limit: 4915)
   CGroup: /bbb_record_core.slice/bbb-rap-starter.service
           └─1568 /usr/bin/ruby /usr/local/bigbluebutton/core/scripts/rap-starter.rb

May 26 10:05:30 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"6c97dcfbf80b0377dba5087658305e87450853ad-1653554375409", :break_timestamp=>nil}
May 26 10:09:26 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"4a889165ae67f96896538d871c27e3b76a2b17cc-1653554408017", :break_timestamp=>nil}
May 26 10:20:31 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"8d069af5146eb5febcab062663f34bc73d08bafe-1653559876515", :break_timestamp=>nil}
May 26 10:24:23 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"861a66ddbf622e92667c68867606d9db8d108b4d-1653554068595", :break_timestamp=>nil}
May 26 10:30:43 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"48fb22e9392dd851e7ea968c7da189db2d8e0a81-1653555919370", :break_timestamp=>nil}
May 26 10:50:32 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"cc5d2d758dabd4f8ac00f77394a0f7fb697266bc-1653551637151", :break_timestamp=>nil}
May 26 11:16:34 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"9c6efd0f92230e6159d1def2c926f3f49a0be469-1653558364480", :break_timestamp=>nil}
May 26 11:33:42 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"5287f5a6a8bf200a8d3eef2a258327acde21d6ac-1653559447436", :break_timestamp=>nil}
May 26 11:38:31 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"a95c7f7ddb824000516ae6727117a9f5cca5f06a-1653559486513", :break_timestamp=>nil}
May 26 11:58:05 instance-1 bbb-rap[1568]: Enqueuing job to archive {:meeting_id=>"f31b65a85c9d56413be3e89a15a4916b2e6d7174-1653557440520", :break_timestamp=>nil}

● bbb-rap-resque-worker.service - BigBlueButton resque worker for recordings
   Loaded: loaded (/usr/lib/systemd/system/bbb-rap-resque-worker.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2022-05-25 15:44:14 UTC; 1 day 11h ago
 Main PID: 2436 (sh)
    Tasks: 7 (limit: 4915)
   CGroup: /system.slice/bbb-rap-resque-worker.service
           ├─2436 /bin/sh -c /usr/bin/rake -f ../Rakefile resque:workers >> /var/log/bigbluebutton/bbb-rap-worker.log
           ├─2441 /usr/bin/ruby /usr/bin/rake -f ../Rakefile resque:workers
           └─2513 resque-2.0.0: Waiting for rap:archive,rap:publish,rap:process,rap:sanity,rap:captions,rap:events

May 26 21:49:29 instance-1 bbb-rap[1110]: /usr/lib/ruby/vendor_ruby/rubygems/defaults/operating_system.rb:10: warning: constant Gem::ConfigMap is deprecated
May 26 21:49:29 instance-1 bbb-rap[1110]: Success?: true
May 26 21:49:29 instance-1 bbb-rap[1110]: Process exited? true
May 26 21:49:29 instance-1 bbb-rap[1110]: Exit status: 0
May 26 21:49:29 instance-1 bbb-rap[1110]: Task: Getting external meeting id
May 26 21:49:29 instance-1 bbb-rap[1110]: Task: Getting meeting metadata
May 26 21:49:29 instance-1 bbb-rap[1110]: Ended worker publish for 411621f71bb335ffd7f1bc6429bfcb6d087f7b26-1607139078630 with result true
May 26 21:49:29 instance-1 bbb-rap[1110]: Scheduling next step for publish
May 26 21:49:29 instance-1 bbb-rap[1110]: No next step for publish, will not schedule anything
May 26 21:49:29 instance-1 bbb-rap[1110]: done: (Job{rap:publish} | BigBlueButton::Resque::PublishWorker | [{"meeting_id"=>"411621f71bb335ffd7f1bc6429bfcb6d087f7b26-1607139078630", "single_step"=>false, "format_name"=>"presentation"}])

Which makes me think that all recordings should have been processed, but the processing count in dashboard is not 0. So I run the following bash script:

#!/bin/bash
ENDED_DONE=`ls /var/bigbluebutton/recording/status/ended | grep done | wc -l`
RECORDED_DONE=`ls /var/bigbluebutton/recording/status/recorded | grep done | wc -l`
ARCHIVED_DONE=`ls /var/bigbluebutton/recording/status/archived | grep done | wc -l`
ARCHIVED_NORECORD=`ls /var/bigbluebutton/recording/status/archived | grep norecord | wc -l`
RAW=`ls /var/bigbluebutton/recording/raw | wc -l`
SANITY_STATUS=`ls /var/bigbluebutton/recording/status/sanity`
SANITY_DONE=`echo "$SANITY_STATUS" | grep done | wc -l`
SANITY_FAIL_STATUS=`echo "$SANITY_STATUS" | grep fail`
SANITY_FAIL=`echo "$SANITY_FAIL_STATUS" | grep fail | wc -l`
PROCESS=`ls /var/bigbluebutton/recording/process/presentation`
PROCESS_COUNT=`ls /var/bigbluebutton/recording/process/presentation | wc -l`
PROCESSED_STATUS=`ls /var/bigbluebutton/recording/status/processed`
PROCESSED_DONE=`echo "$PROCESSED_STATUS" | grep done | wc -l`
PROCESSED_FAIL_STATUS=`echo "$PROCESSED_STATUS" | grep fail`
PROCESSED_FAIL=`echo "$PROCESSED_FAIL_STATUS" | grep fail | wc -l`
PUBLISH=`ls /var/bigbluebutton/recording/publish/presentation`
PUBLISH_COUNT=`ls /var/bigbluebutton/recording/publish/presentation | wc -l`
PUBLISHED_STATUS=`ls /var/bigbluebutton/recording/status/published`
PUBLISHED_DONE=`echo "$PUBLISHED_STATUS" | grep done | wc -l`
PUBLISHED_FAIL_STATUS=`echo "$PUBLISHED_STATUS" | grep fail`
PUBLISHED_FAIL=`echo "$PUBLISHED_FAIL_STATUS" | grep fail | wc -l`
PUBLISHED=`ls /var/bigbluebutton/published/presentation | wc -l`
UNPUBLISHED=`ls /var/bigbluebutton/unpublished/presentation | wc -l`
DELETED=`ls /var/bigbluebutton/deleted/presentation | wc -l`

echo "ended.done: $ENDED_DONE
recorded.done: $RECORDED_DONE
archived.done: $ARCHIVED_DONE
archived.norecord: $ARCHIVED_NORECORD
Archived files (raw): $RAW
---
sanity.done: $SANITY_DONE
sanity.fail: $SANITY_FAIL
$SANITY_FAIL_STATUS
Processed files (process) (processing?): $PROCESS_COUNT
$PROCESS
processed.done: $PROCESSED_DONE
processed.fail: $PROCESSED_FAIL
$PROCESSED_FAIL_STATUS
Unprocessed files (sanity.done - processed.done - processed.fail?): $(($ARCHIVED_DONE-$PROCESSED_DONE))
Published files (publish) (publishing?): $PUBLISH_COUNT
$PUBLISH
published.done: $PUBLISHED_DONE
published.fail: $PUBLISHED_FAIL
$PUBLISHED_FAIL_STATUS
Playback files (published): $PUBLISHED
---
unpublished: $UNPUBLISHED
deleted: $DELETED"

And the output is:

ended.done: 0
recorded.done: 0
archived.done: 3935
archived.norecord: 330
Archived files (raw): 556
---
sanity.done: 3937
sanity.fail: 0

Processed files (process) (processing?): 3
20de4c8b29fb145cc3f6eca7cf9ad97f68fd7af2-1607133533203
25c111e09c93a6d4c827c93b5e89ff5074c15983-1580970887876
8f3a33eb9b7802e8c9db74565d613a0966317b63-1596876176321
processed.done: 3935
processed.fail: 2
25c111e09c93a6d4c827c93b5e89ff5074c15983-1580970887876-presentation.fail
8f3a33eb9b7802e8c9db74565d613a0966317b63-1596876176321-presentation.fail
Unprocessed files (sanity.done - processed.done - processed.fail?): 0
Published files (publish) (publishing?): 1
20de4c8b29fb145cc3f6eca7cf9ad97f68fd7af2-1607133533203
published.done: 8795
published.fail: 1
20de4c8b29fb145cc3f6eca7cf9ad97f68fd7af2-1607133533203-presentation.fail
Playback files (published): 8742
---
unpublished: 22
deleted: 31

This provides me with the following thoughts:

sanity.done seems no longer clear, while ended.done and recorded.done will be cleared automatically
when the process failed or the publish failed, the entries in both process folder and published folder (depends on what state failed) will not be cleared automatically, so the processing in dashboard keep showing 3, as 2 failed to process and 1 fail to publish
sanity.done = processed.done + processed.fail
the deleted metrics in dashboard seems include both entries in unpublished and deleted
published.done = published + unpublished + deleted
rebuilding recording will delete sanity.done, processed.done and published.done and will ignore whether record has been pressed if set record=true and raw files must exist

Hope this can help debug or enhance the program.

greenstatic commented 2 years ago

Thanks for the detailed report, I'll try to look over it over the weekend.

pabloapico commented 2 years ago

Hello, Any news on this? i believe the right folder now is "recorded" instead of "sanity

Then i would guess that modifying collector.py:345 path = os.path.join(bigbluebutton_base_dir, "recording/status/sanity") to path = os.path.join(bigbluebutton_base_dir, "recording/status/recorded") would do the trick.

Current versions of BigBlueButton use this "recorded" status in order to determine that a recording is pending. Source: https://docs.bigbluebutton.org/dev/recording.html#overview

I wanted to update the code in my server but did not find how to change code inside the docker...

Saludos!

greenstatic commented 2 years ago

I wasn't able to dedicate any time over the last two weekends. :/

But the suggested fix seems trivial enough to give it a try right away. I created a preview release, docker tag v0.7.1-preview1.

Give it a try and report back :)

balbertho commented 2 years ago

I have tried and it seems a fix for unpublished stat. However, the processing stat is still incorrect in my instance (now using version 2.5) because of the three failed cases I mentioned earlier, should error metrics to be added and clear the processing metrics?

pabloapico commented 2 years ago

I tried several times using v0.7.1-preview1 to see if the metrics goes above zero. But it did not. At first i thought that maybe it was because i did not have enough simultaneous recordings on the tested server. But then i gave up. It was always Zero. I could not determine if the documentation is wrong and .done files are never created in "recording/status/recorded" folder. Maybe they are created and deleted too fast. I have not had enough time test a routine for this but my best guess so far is that unprocessed recordings should be something like this:

get all files in recording/status/sanity in an array And then find the files with the same name in recording/status/processed Those files found will be removed from the array (Because it means they were processed) Then find the files with the same name in recording/status/published Those files found will be removed from the array (Because it means they were processed even if the .done file in processed does not exist) Then the remaining count of files in the array is the number of unprocessed recordings. Like i said. this is just a theory. i have not tested it Thanks in advance @greenstatic and all of you for the help.

balbertho commented 2 years ago

Oh, I haven't noticed that it has never been increased. After inspection, it seems recorded done files are removed after being watched, created relevant raw folder and enqueued for next process, that's why it seems no increase, because it is nearly processed and removed instantly.

A recap of what I found and thought before:

sanity.done seems no longer clear, while ended.done and recorded.done will be cleared automatically
when the process failed or the publish failed, the entries in both process folder and published folder (depends on what state failed) will not be cleared automatically, so the processing in dashboard keep showing 3, as 2 failed to process and 1 fail to publish
sanity.done = processed.done + processed.fail
the deleted metrics in dashboard seems include both entries in unpublished and deleted
published.done = published + unpublished + deleted
rebuilding recording will delete sanity.done, processed.done and published.done and will ignore whether record has been pressed if set record=true and raw files must exist

All the above are based on status level. However as mentioned in their docs, I only need to care about /var/bigbluebutton/published /var/bigbluebutton/unpublished /var/bigbluebutton/recording/raw when moving recordings from another server. This will however become unable to republish the recordings and can only rebuild the recordings if relevant raw files exist. And besides removing the done files mentioned above, rebuilding recording also removed relevant entries in published, unpublished and deleted folder and enqueue the meeting id directly to sanity stage and published.done = published + unpublished + deleted. So, I guess maybe monitoring the output folder instead of the status folders will be better:

PUBLISHED=ls /var/bigbluebutton/published/presentation | wc -l UNPUBLISHED=ls /var/bigbluebutton/unpublished/presentation | wc -l DELETED=ls /var/bigbluebutton/deleted/presentation | wc -l

while deleted may not be correct and/or may not exist with different definitions (e.g. soft deleted), the same also goes to unpublished case, but I guess this should be enough.

And for Processing and Unprocessed, the definitions of the default workflow stages are as follows: Recorded: ending the session, will have .done file but nearly instantly deleted and go to next stage Archived: raw files generated, will have .done file for recorded case and .norecord for no recording case Sanity: check raw recordings in raw files are complete, will have .done and .fail file Processed: presentation generated, will have .done and .fail file Published: presentation available for playback, will have .done and .fail file

Since "Recorded" state changed too fast, cannot use recorded status as unprocessed base, sanity.done = processed.done + processed.fail, so maybe unprocessed should be :

ls /var/bigbluebutton/recording/status/sanity | wc -l MINUS ls /var/bigbluebutton/recording/status/processed | wc -l

may also minus published status count but that is skipping flow, we may also skip handling that.

And may add one or more error metrics, since sanity, process and publish phrase may have fail results. And of course, all paths in discussion do not handle custom paths cases, just the default paths and workflow.

pabloapico commented 2 years ago

@balbertho Hi. The solution you propose for "unprocessed recordings":

ls /var/bigbluebutton/recording/status/sanity | wc -l MINUS ls /var/bigbluebutton/recording/status/processed | wc -l

This solution is light and will work on new servers. However i think it is not accurate to assume that processed.done file has to exist for a recording to be pending (unprocessed) because the bbb-record logic does not. For instance, as far as i understand, if there is a sanity.done file and the recording is published it will not be processed again even if the processed.done file is there. In fact, some people do clean that folder on purpose.

On the other hand the approach i propose, i believe is exact in all scenarios. The only disadvantage i see is that if there are too many files, it will be slower.

A possible solution would be to implement both methods and allow to switch them via configuration since (i think) most cases will be covered by @balbertho 's method?

@greenstatic any thoughts?

pabloapico commented 2 years ago

Hello again. @balbertho after running some tests i concluded your method:

ls /var/bigbluebutton/recording/status/sanity | wc -l MINUS ls /var/bigbluebutton/recording/status/processed | wc -l

is the best solution. i have changed my mind because after my tests i concluded that no one should erase the processed.done file without also erasing the sanity.done file. I checked and deleting both files is safe. Then the count in both directories will allways tend to be the same.

@greenstatic Could you please include this in the next version / preview? :)

greenstatic commented 2 years ago

Thanks @balbertho and @pabloapico for your investigation. I've created a build v0.7.1-preview2 with the unprocessed count

ls /var/bigbluebutton/recording/status/sanity | wc -l MINUS ls /var/bigbluebutton/recording/status/processed | wc -l

recommended fix.

Please report back with your findings.

balbertho commented 2 years ago

Thanks @greenstatic for changing the code and @pabloapico for supporting me.

However, I think I have made misleading statements before. Since now it seems that "unprocessed" metric now is equal to "processing" count without all fail status at least for time I am monitoring, and it sounds a little bit weird.

Not only processed.done and sanity.done files, in fact all status files can be deleted safely except recorded.done files which are monitored and deleted by bbb-rap-starter.service. And then what it does is to create a raw folder for that recording and enqueue the archive task to Redis database, then delete the recorded.done file, which is usually less than 1 second work. And for other latter sanity, process, publish etc. are done by bbb-rap-resque-worker.service, which enqueue for next task flow to Redis database after previous task flow script completed. That's why the main folders are only /var/bigbluebutton/published /var/bigbluebutton/unpublished /var/bigbluebutton/recording/raw as mentioned before. By default, /var/bigbluebutton/recording/raw will be cleaned up also but once cleaned up, the corresponding recording can never be rebuilt again. /var/bigbluebutton/unpublished is not cleaned up automatically and can be used as the base for republish.

So, the real "unprocessed" metrics seems to be that the recordings raw folder exist but no corresponding (archived.done files or archived.norecord files) and sanity.done files and not in process status folder (which are the one processing or failed). But this will need to keep track of a list of recordings not yet processed.

Here is a log for inspection to 2 critical bbb-record services discussed above with more than 1 meeting ending at nearly the same time:

● bbb-rap-starter.service - BigBlueButton recording processing starter
     Loaded: loaded (/lib/systemd/system/bbb-rap-starter.service; enabled; vendor preset: enabled)
     CGroup: /bbb_record_core.slice/bbb-rap-starter.service
Jul 07 08:46:19 instance-1 bbb-rap[46423]: Enqueuing job to archive {:meeting_id=>"254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431", :break_timestamp=>nil}
Jul 07 08:46:28 instance-1 bbb-rap[46423]: Enqueuing job to archive {:meeting_id=>"8b5ec999047e79e39f4ea7fae8a6b988d2f8e194-1657178673826", :break_timestamp=>nil}
Jul 07 08:46:46 instance-1 bbb-rap[46423]: Enqueuing job to archive {:meeting_id=>"08b3e124f953af41ac13be3c5ab955299fd45ecd-1657179111873", :break_timestamp=>nil}
Jul 07 08:48:58 instance-1 bbb-rap[46423]: Enqueuing job to archive {:meeting_id=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", :break_timestamp=>nil}
Jul 07 08:49:57 instance-1 bbb-rap[46423]: Enqueuing job to archive {:meeting_id=>"ba0339f18930bfe6f78d00523966a5014af97624-1657178509717", :break_timestamp=>nil}
Jul 07 08:50:11 instance-1 bbb-rap[46423]: Enqueuing job to archive {:meeting_id=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", :break_timestamp=>nil}
● bbb-rap-resque-worker.service - BigBlueButton resque worker for recordings
     Loaded: loaded (/lib/systemd/system/bbb-rap-resque-worker.service; enabled; vendor preset: enabled)
     CGroup: /system.slice/bbb-rap-resque-worker.service
Jul 07 08:51:46 instance-1 bbb-rap[995016]: Started worker publish for 254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431
Jul 07 08:51:46 instance-1 bbb-rap[995016]: Running publish worker for 254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431:presentation
Jul 07 08:51:46 instance-1 bbb-rap[995016]: Task: Getting external meeting id
Jul 07 08:51:46 instance-1 bbb-rap[995016]: Task: Getting meeting metadata
Jul 07 08:51:46 instance-1 bbb-rap[995016]: Executing: ruby /usr/local/bigbluebutton/core/scripts/publish/presentation.rb -m 254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431-presentation
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Success?: true
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Process exited? true
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Exit status: 0
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Task: Getting external meeting id
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Task: Getting meeting metadata
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Publish format succeeded for 254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431:presentation
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Running post publish script post_publish_recording_ready_callback
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Task: Getting external meeting id
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Task: Getting meeting metadata
Jul 07 08:51:49 instance-1 bbb-rap[995016]: Executing: ruby /usr/local/bigbluebutton/core/scripts/post_publish/post_publish_recording_ready_callback.rb -m 254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431 -f presentation
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Success?: true
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Process exited? true
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Exit status: 0
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Task: Getting external meeting id
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Task: Getting meeting metadata
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Ended worker publish for 254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431 with result true
Jul 07 08:51:50 instance-1 bbb-rap[995016]: Scheduling next step for publish
Jul 07 08:51:50 instance-1 bbb-rap[995016]: No next step for publish, will not schedule anything
Jul 07 08:51:50 instance-1 bbb-rap[995016]: done: (Job{rap:publish} | BigBlueButton::Resque::PublishWorker | [{"meeting_id"=>"254afabc052e88a74cf9f100c4986e0ea340d0ca-1657178964431", "single_step"=>false, "format_name"=>"presentation"}])
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Started worker sanity for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Running sanity worker for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Task: Getting external meeting id
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Task: Getting meeting metadata
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Executing: ruby /usr/local/bigbluebutton/core/scripts/sanity/sanity.rb -m 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:50 instance-1 bbb-rap[995033]: ruby: warning: shebang line ending with \r may cause problems
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Success?: true
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Process exited? true
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Exit status: 0
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Task: Getting external meeting id
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Task: Getting meeting metadata
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Successfully sanity checked 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Ended worker sanity for 301476b025f8b7c33088ad890d0231b542833719-1657177813365 with result true
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Scheduling next step for sanity
Jul 07 08:51:50 instance-1 bbb-rap[995033]: Enqueueing captions worker with {:meeting_id=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", :single_step=>false}
Jul 07 08:51:50 instance-1 bbb-rap[995033]: done: (Job{rap:sanity} | BigBlueButton::Resque::SanityWorker | [{"meeting_id"=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", "single_step"=>false}])
Jul 07 08:51:50 instance-1 bbb-rap[995035]: Started worker sanity for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:51:50 instance-1 bbb-rap[995035]: Running sanity worker for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:51:50 instance-1 bbb-rap[995035]: Task: Getting external meeting id
Jul 07 08:51:50 instance-1 bbb-rap[995035]: Task: Getting meeting metadata
Jul 07 08:51:50 instance-1 bbb-rap[995035]: Executing: ruby /usr/local/bigbluebutton/core/scripts/sanity/sanity.rb -m 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:51:50 instance-1 bbb-rap[995035]: ruby: warning: shebang line ending with \r may cause problems
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Success?: true
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Process exited? true
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Exit status: 0
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Task: Getting external meeting id
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Task: Getting meeting metadata
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Successfully sanity checked 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Ended worker sanity for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914 with result true
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Scheduling next step for sanity
Jul 07 08:51:51 instance-1 bbb-rap[995035]: Enqueueing captions worker with {:meeting_id=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", :single_step=>false}
Jul 07 08:51:51 instance-1 bbb-rap[995035]: done: (Job{rap:sanity} | BigBlueButton::Resque::SanityWorker | [{"meeting_id"=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", "single_step"=>false}])
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Started worker captions for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Running captions worker for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Executing: ruby /usr/local/bigbluebutton/core/scripts/utils/captions.rb -m 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:51 instance-1 bbb-rap[995038]: Setting process dir
Jul 07 08:51:51 instance-1 bbb-rap[995038]: setting captions dir
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Success?: true
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Process exited? true
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Exit status: 0
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Succeeded generating captions for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Finished format succeeded for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Ended worker captions for 301476b025f8b7c33088ad890d0231b542833719-1657177813365 with result 0
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Scheduling next step for captions
Jul 07 08:51:51 instance-1 bbb-rap[995037]: Enqueueing process worker with {:meeting_id=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", :single_step=>false, "format_name"=>"presentation"}
Jul 07 08:51:51 instance-1 bbb-rap[995037]: done: (Job{rap:captions} | BigBlueButton::Resque::CaptionsWorker | [{"meeting_id"=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", "single_step"=>false}])
Jul 07 08:51:51 instance-1 bbb-rap[995040]: Started worker process for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:51:51 instance-1 bbb-rap[995040]: Running process worker for 301476b025f8b7c33088ad890d0231b542833719-1657177813365:presentation
Jul 07 08:51:51 instance-1 bbb-rap[995040]: Task: Getting external meeting id
Jul 07 08:51:51 instance-1 bbb-rap[995040]: Task: Getting meeting metadata
Jul 07 08:51:51 instance-1 bbb-rap[995040]: Executing: ruby /usr/local/bigbluebutton/core/scripts/process/presentation.rb -m 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Success?: true
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Process exited? true
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Exit status: 0
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Task: Getting external meeting id
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Task: Getting meeting metadata
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Process format succeeded for 301476b025f8b7c33088ad890d0231b542833719-1657177813365:presentation
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Process took 213624ms
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Ended worker process for 301476b025f8b7c33088ad890d0231b542833719-1657177813365 with result true
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Scheduling next step for process
Jul 07 08:55:25 instance-1 bbb-rap[995040]: Enqueueing publish worker with {:meeting_id=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", :single_step=>false, "format_name"=>"presentation"}
Jul 07 08:55:25 instance-1 bbb-rap[995040]: done: (Job{rap:process} | BigBlueButton::Resque::ProcessWorker | [{"meeting_id"=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", "single_step"=>false, "format_name"=>"presentation"}])
Jul 07 08:55:25 instance-1 bbb-rap[1020440]: Started worker publish for 301476b025f8b7c33088ad890d0231b542833719-1657177813365
Jul 07 08:55:25 instance-1 bbb-rap[1020440]: Running publish worker for 301476b025f8b7c33088ad890d0231b542833719-1657177813365:presentation
Jul 07 08:55:25 instance-1 bbb-rap[1020440]: Task: Getting external meeting id
Jul 07 08:55:25 instance-1 bbb-rap[1020440]: Task: Getting meeting metadata
Jul 07 08:55:25 instance-1 bbb-rap[1020440]: Executing: ruby /usr/local/bigbluebutton/core/scripts/publish/presentation.rb -m 301476b025f8b7c33088ad890d0231b542833719-1657177813365-presentation
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Success?: true
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Process exited? true
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Exit status: 0
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Task: Getting external meeting id
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Task: Getting meeting metadata
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Publish format succeeded for 301476b025f8b7c33088ad890d0231b542833719-1657177813365:presentation
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Running post publish script post_publish_recording_ready_callback
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Task: Getting external meeting id
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Task: Getting meeting metadata
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Executing: ruby /usr/local/bigbluebutton/core/scripts/post_publish/post_publish_recording_ready_callback.rb -m 301476b025f8b7c33088ad890d0231b542833719-1657177813365 -f presentation
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Success?: true
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Process exited? true
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Exit status: 0
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Task: Getting external meeting id
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Task: Getting meeting metadata
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Ended worker publish for 301476b025f8b7c33088ad890d0231b542833719-1657177813365 with result true
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: Scheduling next step for publish
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: No next step for publish, will not schedule anything
Jul 07 08:55:27 instance-1 bbb-rap[1020440]: done: (Job{rap:publish} | BigBlueButton::Resque::PublishWorker | [{"meeting_id"=>"301476b025f8b7c33088ad890d0231b542833719-1657177813365", "single_step"=>false, "format_name"=>"presentation"}])
Jul 07 08:55:27 instance-1 bbb-rap[1020458]: Started worker captions for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:55:27 instance-1 bbb-rap[1020458]: Running captions worker for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:55:27 instance-1 bbb-rap[1020458]: Executing: ruby /usr/local/bigbluebutton/core/scripts/utils/captions.rb -m 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:55:28 instance-1 bbb-rap[1020459]: Setting process dir
Jul 07 08:55:28 instance-1 bbb-rap[1020459]: setting captions dir
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Success?: true
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Process exited? true
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Exit status: 0
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Succeeded generating captions for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Finished format succeeded for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Ended worker captions for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914 with result 0
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Scheduling next step for captions
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: Enqueueing process worker with {:meeting_id=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", :single_step=>false, "format_name"=>"presentation"}
Jul 07 08:55:28 instance-1 bbb-rap[1020458]: done: (Job{rap:captions} | BigBlueButton::Resque::CaptionsWorker | [{"meeting_id"=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", "single_step"=>false}])
Jul 07 08:55:28 instance-1 bbb-rap[1020461]: Started worker process for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:55:28 instance-1 bbb-rap[1020461]: Running process worker for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914:presentation
Jul 07 08:55:28 instance-1 bbb-rap[1020461]: Task: Getting external meeting id
Jul 07 08:55:28 instance-1 bbb-rap[1020461]: Task: Getting meeting metadata
Jul 07 08:55:28 instance-1 bbb-rap[1020461]: Executing: ruby /usr/local/bigbluebutton/core/scripts/process/presentation.rb -m 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Success?: true
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Process exited? true
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Exit status: 0
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Task: Getting external meeting id
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Task: Getting meeting metadata
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Process format succeeded for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914:presentation
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Process took 270375ms
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Ended worker process for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914 with result true
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Scheduling next step for process
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: Enqueueing publish worker with {:meeting_id=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", :single_step=>false, "format_name"=>"presentation"}
Jul 07 08:59:58 instance-1 bbb-rap[1020461]: done: (Job{rap:process} | BigBlueButton::Resque::ProcessWorker | [{"meeting_id"=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", "single_step"=>false, "format_name"=>"presentation"}])
Jul 07 08:59:58 instance-1 bbb-rap[1021112]: Started worker publish for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914
Jul 07 08:59:58 instance-1 bbb-rap[1021112]: Running publish worker for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914:presentation
Jul 07 08:59:58 instance-1 bbb-rap[1021112]: Task: Getting external meeting id
Jul 07 08:59:58 instance-1 bbb-rap[1021112]: Task: Getting meeting metadata
Jul 07 08:59:59 instance-1 bbb-rap[1021112]: Executing: ruby /usr/local/bigbluebutton/core/scripts/publish/presentation.rb -m 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914-presentation
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Success?: true
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Process exited? true
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Exit status: 0
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Task: Getting external meeting id
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Task: Getting meeting metadata
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Publish format succeeded for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914:presentation
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Running post publish script post_publish_recording_ready_callback
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Task: Getting external meeting id
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Task: Getting meeting metadata
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Executing: ruby /usr/local/bigbluebutton/core/scripts/post_publish/post_publish_recording_ready_callback.rb -m 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914 -f presentation
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Success?: true
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Process exited? true
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Exit status: 0
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Task: Getting external meeting id
Jul 07 09:00:02 instance-1 bbb-rap[1021112]: Task: Getting meeting metadata
Jul 07 09:00:03 instance-1 bbb-rap[1021112]: Ended worker publish for 397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914 with result true
Jul 07 09:00:03 instance-1 bbb-rap[1021112]: Scheduling next step for publish
Jul 07 09:00:03 instance-1 bbb-rap[1021112]: No next step for publish, will not schedule anything
Jul 07 09:00:03 instance-1 bbb-rap[1021112]: done: (Job{rap:publish} | BigBlueButton::Resque::PublishWorker | [{"meeting_id"=>"397ca2f6e74acb33cdf18fb37bca8ea7bec5fdc6-1657178786914", "single_step"=>false, "format_name"=>"presentation"}])

greenstatic commented 6 months ago

Could you try the latest release v0.7.0 (just released now) and see if the metric is correct? Please also mention which version of BBB you are running.

greenstatic / bigbluebutton-exporter

BigBlueButton 2.3 - invalid recordings #81