Session recording not working in BBB-2.0

[mont...@gmail.com]

Hi All,
         I'm wondering if anyone could point me in the direction of where things are going wrong with session recording on my BBB-2.0 install. I've attempted this under the flash and HTML5 clients, with the same results. Basically what happens when I record a session, the recorded session goes through it's various stages listed in bbb-record --watch, but either crashes out on the publish worker, or never gets there, so the recordings are never published back to their owner.

For information, I've mounted a 2Tb iscsi share on to /var/bigbluebutton/ but I took a backup, with permissions, of the original folder before I mounted the drive to the folder, then restored the backup to the newly mounted drive.

Anyway, I've looked through the logs, but as I'm not good enough to know the internal workings of the system, I've not made much headway into this, although I do think it's at the end of the process log that's the issue where it can't find the thumbnails, but as the folder in which teh thumbnails reside is generated in relation to the internal session ID, I cna't just copy/create files to ensure that this file is present to even test getting past this bit. I've included the logs here to see if anyone can give me a nod to where I've went wrong (For clarity, no screensharing or upload of files/presentations was carried out during the test recording, but audio and webcam were on the flash, and audio only on the HTML5 client as the webcam doesn't work with that client).

Cheers,
            Mark

bbb-rap-worker.log:

I, [2018-05-02T10:04:57.484340 #17857]  INFO -- : Temporarily skipping 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867 for Red5 race workaround
I, [2018-05-02T10:05:29.121688 #18872]  INFO -- : Temporarily skipping 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867 for Red5 race workaround
I, [2018-05-02T10:06:00.794713 #19879]  INFO -- : Temporarily skipping 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867 for Red5 race workaround
I, [2018-05-02T10:06:32.442418 #20886]  INFO -- : Temporarily skipping 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867 for Red5 race workaround
I, [2018-05-02T10:07:04.140454 #21891]  INFO -- : Executing: ruby archive/archive.rb -m 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:07:04.624966 #21891]  INFO -- : Exit status: 0
I, [2018-05-02T10:07:04.625116 #21891]  INFO -- : Task: Getting external meeting id
I, [2018-05-02T10:07:04.625166 #21891]  INFO -- : Task: Getting meeting metadata
I, [2018-05-02T10:07:04.636172 #21891]  INFO -- : Successfully archived 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:07:36.186280 #23244]  INFO -- : Task: Getting external meeting id
I, [2018-05-02T10:07:36.186363 #23244]  INFO -- : Task: Getting meeting metadata
I, [2018-05-02T10:07:36.192403 #23244]  INFO -- : Executing: ruby sanity/sanity.rb -m 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:07:36.697365 #23244]  INFO -- : Exit status: 0
I, [2018-05-02T10:07:36.697557 #23244]  INFO -- : Task: Getting external meeting id
I, [2018-05-02T10:07:36.697619 #23244]  INFO -- : Task: Getting meeting metadata
I, [2018-05-02T10:07:36.708831 #23244]  INFO -- : Successfully sanity checked 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:08:08.280412 #24601]  INFO -- : Task: Getting external meeting id
I, [2018-05-02T10:08:08.280488 #24601]  INFO -- : Task: Getting meeting metadata
I, [2018-05-02T10:08:08.287953 #24601]  INFO -- : Executing: ruby process/presentation.rb -m 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:08:10.273892 #24601]  INFO -- : Exit status: 1
I, [2018-05-02T10:08:10.274217 #24601]  INFO -- : Task: Getting external meeting id
I, [2018-05-02T10:08:10.274280 #24601]  INFO -- : Task: Getting meeting metadata
I, [2018-05-02T10:08:10.282744 #24601]  INFO -- : Process format presentation failed for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:08:10.282815 #24601]  INFO -- : Process took 1987ms

archive-30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.log:

# Logfile created on 2018-05-02 10:07:04 +0100 by logger.rb/v1.2.7
I, [2018-05-02T10:07:04.430450 #21901]  INFO -- : Archiving events for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
I, [2018-05-02T10:07:04.600913 #21901]  INFO -- : Archiving audio /var/freeswitch/meetings/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867*.wav.
D, [2018-05-02T10:07:04.601205 #21901] DEBUG -- : Copying /var/freeswitch/meetings/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav to /var/bigbluebutton/recording/raw/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio
I, [2018-05-02T10:07:04.605107 #21901]  INFO -- : Archiving presentation for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
W, [2018-05-02T10:07:04.605372 #21901]  WARN -- : Failed to archive presentations for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867. Directory not found /var/bigbluebutton/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:07:04.605435 #21901]  INFO -- : Archiving deskshare for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
I, [2018-05-02T10:07:04.605625 #21901]  INFO -- : Archiving screenshare for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
W, [2018-05-02T10:07:04.605809 #21901]  WARN -- : Failed to archive screenshare for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867. Directory not found /usr/share/red5/webapps/screenshare/streams/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867
I, [2018-05-02T10:07:04.605865 #21901]  INFO -- : Archiving video for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
W, [2018-05-02T10:07:04.606012 #21901]  WARN -- : Failed to archive video for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867. Directory not found: [/usr/share/red5/webapps/video/streams/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867]
I, [2018-05-02T10:07:04.606070 #21901]  INFO -- : Fetching the recording marks for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
I, [2018-05-02T10:07:04.606121 #21901]  INFO -- : Getting record status events
I, [2018-05-02T10:07:04.616242 #21901]  INFO -- : record_events:
[{:timestamp=>61327723}, {:timestamp=>61341728}]

process-30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.log:

# Logfile created on 2018-05-02 10:08:08 +0100 by logger.rb/v1.2.7
I, [2018-05-02T10:08:08.571932 #24608]  INFO -- : Processing script presentation.rb
I, [2018-05-02T10:08:08.576371 #24608]  INFO -- : Created inital metadata.xml
I, [2018-05-02T10:08:08.576441 #24608]  INFO -- : AudioProcessor.process: Processing audio...
D, [2018-05-02T10:08:08.582856 #24608] DEBUG -- : EDL Dump:
D, [2018-05-02T10:08:08.582903 #24608] DEBUG -- : ---
D, [2018-05-02T10:08:08.582937 #24608] DEBUG -- :   Timestamp: 0
D, [2018-05-02T10:08:08.582968 #24608] DEBUG -- :   Audio:
D, [2018-05-02T10:08:08.582998 #24608] DEBUG -- :     silence
D, [2018-05-02T10:08:08.583027 #24608] DEBUG -- : ---
D, [2018-05-02T10:08:08.583056 #24608] DEBUG -- :   Timestamp: 12159
D, [2018-05-02T10:08:08.583084 #24608] DEBUG -- :   Audio:
D, [2018-05-02T10:08:08.583115 #24608] DEBUG -- :     /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav at 0
D, [2018-05-02T10:08:08.583151 #24608] DEBUG -- : ---
D, [2018-05-02T10:08:08.583182 #24608] DEBUG -- :   Timestamp: 41724
D, [2018-05-02T10:08:08.583210 #24608] DEBUG -- :   Audio:
D, [2018-05-02T10:08:08.583238 #24608] DEBUG -- :     silence
I, [2018-05-02T10:08:08.583268 #24608]  INFO -- : Applying recording start stop events:
I, [2018-05-02T10:08:08.583307 #24608]  INFO -- : Task: Getting the timestamp of the first event.
I, [2018-05-02T10:08:08.588310 #24608]  INFO -- : Getting start and stop rec button events
I, [2018-05-02T10:08:08.588356 #24608]  INFO -- : Getting record status events
I, [2018-05-02T10:08:08.594649 #24608]  INFO -- : Matching record events
D, [2018-05-02T10:08:08.594705 #24608] DEBUG -- : Recording interval: 26565 to 40570
D, [2018-05-02T10:08:08.594740 #24608] DEBUG -- : Offset is now 26565
D, [2018-05-02T10:08:08.594774 #24608] DEBUG -- : Found last event prior to recording start:
D, [2018-05-02T10:08:08.595162 #24608] DEBUG -- : {:timestamp=>12159,
 :audio=>
  {:filename=>
    "/var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav",
   :timestamp=>0}}

D, [2018-05-02T10:08:08.595205 #24608] DEBUG -- : Have to trim 14406
D, [2018-05-02T10:08:08.595240 #24608] DEBUG -- : New event at recording start:
D, [2018-05-02T10:08:08.595457 #24608] DEBUG -- : {:audio=>
  {:filename=>
    "/var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav",
   :timestamp=>14406},
 :timestamp=>0}

D, [2018-05-02T10:08:08.595502 #24608] DEBUG -- : EDL Dump:
D, [2018-05-02T10:08:08.595535 #24608] DEBUG -- : ---
D, [2018-05-02T10:08:08.595565 #24608] DEBUG -- :   Timestamp: 0
D, [2018-05-02T10:08:08.595593 #24608] DEBUG -- :   Audio:
D, [2018-05-02T10:08:08.595622 #24608] DEBUG -- :     /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav at 14406
D, [2018-05-02T10:08:08.595651 #24608] DEBUG -- : ---
D, [2018-05-02T10:08:08.595680 #24608] DEBUG -- :   Timestamp: 14005
D, [2018-05-02T10:08:08.595708 #24608] DEBUG -- :   Audio:
D, [2018-05-02T10:08:08.595736 #24608] DEBUG -- :     silence
I, [2018-05-02T10:08:08.595774 #24608]  INFO -- : Pre-processing EDL
I, [2018-05-02T10:08:08.595811 #24608]  INFO -- : Reading source audio information
D, [2018-05-02T10:08:08.595844 #24608] DEBUG -- :   /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav
D, [2018-05-02T10:08:08.672061 #24608] DEBUG -- : Recalculated duration from wav file length
D, [2018-05-02T10:08:08.672265 #24608] DEBUG -- :     sample rate: 48000, duration: 34780
I, [2018-05-02T10:08:08.672310 #24608]  INFO -- : Generating ffmpeg command
I, [2018-05-02T10:08:08.672353 #24608]  INFO -- :   Using input /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav
I, [2018-05-02T10:08:08.672418 #24608]  INFO -- : Running audio processing...
I, [2018-05-02T10:08:08.672461 #24608]  INFO -- : Executing: ffmpeg -y -v warning -nostats -max_error_rate 1.0 -ss 14.406 -ignore_length 1 -i /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867-61313292.wav -filter_complex [0] aformat=sample_fmts=s16:sample_rates=48000:channel_layouts=stereo,apad,atrim=end=14.005 [out0] ; [out0] anull -c:a flac -f flac /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/recording.flac
I, [2018-05-02T10:08:08.747092 #24608]  INFO -- : Guessed Channel Layout for  Input Stream #0.0 : mono
I, [2018-05-02T10:08:08.831710 #24608]  INFO -- : Exit status: 0
I, [2018-05-02T10:08:08.831865 #24608]  INFO -- : Performing video encode pass 0
I, [2018-05-02T10:08:08.891839 #24608]  INFO -- : Executing: ffmpeg -y -v warning -nostats -max_error_rate 1.0 -i /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/recording.flac -c:a libvorbis -q:a 2 -f ogg -passlogfile /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio.encode.ogg
I, [2018-05-02T10:08:09.505339 #24608]  INFO -- : Exit status: 0
I, [2018-05-02T10:08:09.505644 #24608]  INFO -- : Performing video encode pass 0
I, [2018-05-02T10:08:09.570892 #24608]  INFO -- : Executing: ffmpeg -y -v warning -nostats -max_error_rate 1.0 -i /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio/recording.flac -c:a libvorbis -q:a 2 -f webm -passlogfile /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio.encode.webm
I, [2018-05-02T10:08:10.190072 #24608]  INFO -- : Exit status: 0
I, [2018-05-02T10:08:10.190203 #24608]  INFO -- : Performing post-processing step 0
I, [2018-05-02T10:08:10.190295 #24608]  INFO -- : Executing: mkclean --quiet /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio.encode.webm /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/audio.pp0.webm
I, [2018-05-02T10:08:10.202106 #24608]  INFO -- : The Title element at 297 is not part of profile 'webm', skipping
I, [2018-05-02T10:08:10.202178 #24608]  INFO -- : The SegmentUID element at 348 is not part of profile 'webm', skipping
I, [2018-05-02T10:08:10.202787 #24608]  INFO -- : The MinCache element at -1 is not part of profile 'webm', skipping
I, [2018-05-02T10:08:10.202861 #24608]  INFO -- : The TrackTimecodeScale element at -1 is not part of profile 'webm', skipping
I, [2018-05-02T10:08:10.202914 #24608]  INFO -- : The MaxBlockAdditionID element at -1 is not part of profile 'webm', skipping
I, [2018-05-02T10:08:10.202960 #24608]  INFO -- : The CodecDecodeAll element at -1 is not part of profile 'webm', skipping
I, [2018-05-02T10:08:10.214167 #24608]  INFO -- : Exit status: 0
I, [2018-05-02T10:08:10.214643 #24608]  INFO -- : Task: Getting presentations from events
I, [2018-05-02T10:08:10.234767 #24608]  INFO -- : Task: Getting num participants
I, [2018-05-02T10:08:10.244708 #24608]  INFO -- : Counting id = wxtzizsmyp04a
I, [2018-05-02T10:08:10.244778 #24608]  INFO -- : get_num_participants = 1
I, [2018-05-02T10:08:10.245352 #24608]  INFO -- : Task: Getting meeting metadata
I, [2018-05-02T10:08:10.253985 #24608]  INFO -- : Created an updated metadata.xml with start_time and end_time
I, [2018-05-02T10:08:10.254056 #24608]  INFO -- : Task: Getting number of pages in presentation
W, [2018-05-02T10:08:10.254607 #24608]  WARN -- : Could not find pdf file for presentation d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1525251847911
E, [2018-05-02T10:08:10.254892 #24608] ERROR -- : unknown file type: /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/presentation/d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1525251847911/thumbnails
E, [2018-05-02T10:08:10.254990 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:1387:in `copy'
E, [2018-05-02T10:08:10.255041 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:472:in `block in copy_entry'
E, [2018-05-02T10:08:10.255086 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:1498:in `wrap_traverse'
E, [2018-05-02T10:08:10.255129 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:469:in `copy_entry'
E, [2018-05-02T10:08:10.255173 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:444:in `block in cp_r'
E, [2018-05-02T10:08:10.255216 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:1571:in `block in fu_each_src_dest'
E, [2018-05-02T10:08:10.255259 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:1587:in `fu_each_src_dest0'
E, [2018-05-02T10:08:10.255302 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:1569:in `fu_each_src_dest'
E, [2018-05-02T10:08:10.255344 #24608] ERROR -- : /usr/lib/ruby/2.3.0/fileutils.rb:443:in `cp_r'
E, [2018-05-02T10:08:10.255405 #24608] ERROR -- : process/presentation.rb:198:in `block in <main>'
E, [2018-05-02T10:08:10.255449 #24608] ERROR -- : process/presentation.rb:153:in `each'
E, [2018-05-02T10:08:10.255491 #24608] ERROR -- : process/presentation.rb:153:in `<main>'

Sanity.log:

I, [2018-05-02T10:07:36.510170 #23256]  INFO -- : Starting sanity check for recording 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.
I, [2018-05-02T10:07:36.510241 #23256]  INFO -- : Checking events.xml
I, [2018-05-02T10:07:36.515219 #23256]  INFO -- : Checking audio
D, [2018-05-02T10:07:36.598924 #23256] DEBUG -- : Recalculated duration from wav file length
I, [2018-05-02T10:07:36.599204 #23256]  INFO -- : Checking webcam videos
I, [2018-05-02T10:07:36.599284 #23256]  INFO -- : Repairing red5 serialized streams
I, [2018-05-02T10:07:36.599357 #23256]  INFO -- : Checking all webcam recorded streams from events were archived.
I, [2018-05-02T10:07:36.599411 #23256]  INFO -- : Task: Getting start video events
I, [2018-05-02T10:07:36.609146 #23256]  INFO -- : Checking the length of webcam streams is not zero.
I, [2018-05-02T10:07:36.617511 #23256]  INFO -- : Webcam streams with length zero were not found.
I, [2018-05-02T10:07:36.617574 #23256]  INFO -- : Checking deskshare videos
I, [2018-05-02T10:07:36.617642 #23256]  INFO -- : Repairing red5 serialized streams
I, [2018-05-02T10:07:36.617799 #23256]  INFO -- : Task: Getting start DESKSHARE events
I, [2018-05-02T10:07:36.627452 #23256]  INFO -- : Deleting keys
I, [2018-05-02T10:07:36.681941 #23256]  INFO -- : creating sanity done files

[Calvin Walton]

Hi,

These lines in particular are the error that's causing the scripts to
fail:

> W, [2018-05-02T10:08:10.254607 #24608] WARN -- : Could not find pdf
> file
> for presentation d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-
> 1525251847911
> E, [2018-05-02T10:08:10.254892 #24608] ERROR -- : unknown file type:
> /var/bigbluebutton/recording/process/presentation/30e1e299556a69b9a3e
> 8b789fd0f5903e24ecd9a-
> 1525251847867/temp/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-
> 1525251847867/presentation/d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-
> 1525251847911/thumbnails

Can you please share the result of this command:

ls -l /var/bigbluebutton/recording/raw/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867/presentation/d2d9a672040fbde2a47a10bf6c37b6a4b5ae187f-1525251847911

That should provide some hints on what's going wrong. It sounds like
there's either some missing/corrupt files from the backup or a
permissions issue.

Calvin.

> *bbb-rap-worker.log:*

> *archive-30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.log:*

> *process-30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1525251847867.log:*

> *Sanity.log:*

--
Calvin Walton <calvin...@kepstin.ca>

[mont...@gmail.com]

Hi Calvin,

              Unfortunately, due to me testing things out over and over for the last week or so, that exact recording is long gone. However, the results are the same from any new test recordings I've made. I just created a test recording just now, with the same error. The results of this new test show the following:

ls -l /var/bigbluebutton/recording/raw/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740/presentation/
total 0

Basically that there's nothing in there at all.

Apart from /var, which is obviously owned by root, the ownership chain all the way down the tree from /var/bigbluebutton is owned by tomcat7, with these same permissions all the way:

drwxr-xr-x  6 tomcat7 tomcat7 4096 May  8 10:25 recording

In fact there are only two directories under /var/bigbluebutton that have different permissions, screenshare and streams, and they are listed as follows:

drwxr-xr-x  2 tomcat7 tomcat7 4096 May  8 10:21 blank
drwxr-xr-x  2 tomcat7 tomcat7 4096 Feb 16 15:16 configs
drwxr-xr-x  3 tomcat7 tomcat7 4096 May  8 13:52 deleted
drwxr-xr-x  2 tomcat7 tomcat7 4096 May  1 17:25 deskshare
drwxr-xr-x  2 tomcat7 tomcat7 4096 May  8 10:25 diagnostics
drwxr-xr-x  3 tomcat7 tomcat7 4096 May  8 10:20 playback
drwxr-xr-x  3 tomcat7 tomcat7 4096 May  8 10:25 published
drwxr-xr-x  6 tomcat7 tomcat7 4096 May  8 10:25 recording
drwxr-xr-x  2 red5    red5    4096 Jan 31 21:56 screenshare
drwxr-xr-x 18 tomcat7 tomcat7 4096 May 15 13:56 slides
drwxr-xr-x  7 red5    red5    4096 May 15 13:56 streams
drwxr-xr-x  2 tomcat7 tomcat7 4096 May  8 10:25 unpublished

Screenshare is empty just now, and /var/bigbluebutton/streams/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740/ has the following, with these permissions:

-rw-r--r-- 1 red5 red5 818667 May 15 13:57 medium-w_e7lkjoymdldt-1526389006415-recorded.flv
-rw-r--r-- 1 red5 red5   7174 May 15 13:57 medium-w_e7lkjoymdldt-1526389006415-recorded.flv.meta

I had played about with the system a bit, and had renamed the check files in /var/bigbluebutton/recording/status/processed/ that the worker processes use from .fail to .done, whereupon the publish-worker process picked everything up and published it correctly. However, having never had this working properly, I've only got audio, no video, and a background with the BBB logo on it, showing the recorded scribbles I made on the screen during the recording, so I'm not 100% sure if this the intended output, or other items should be present on playback.

Cheers,

            Mark

[Calvin Walton]

Responses below.

On Tue, 2018-05-15 at 06:25 -0700, mont...@gmail.com wrote:
> Hi Calvin,
> Unfortunately, due to me testing things out over and
> over for
> the last week or so, that exact recording is long gone. However, the
> results are the same from any new test recordings I've made. I just
> created
> a test recording just now, with the same error. The results of this
> new
> test show the following:
>
> ls -l
> /var/bigbluebutton/recording/raw/30e1e299556a69b9a3e8b789fd0f5903e24e
> cd9a-1526388964740/presentation/
> total 0
>
> Basically that there's nothing in there at all.

Ah, this looks like the problem. There should be *something* in that
directory - all of the presentation files uploaded during the session
should be copied there. It sounds like something is going wrong during
the archive step, and some of the files aren't being copied from the
local bigbluebutton storage to the /var/bigbluebutton/recording/raw
directory.

Could you attach the log file:
/var/bigbluebutton/log/archive-<recordingid>.log
for one of your affected recordings? That might have some information
about why some of the files aren't being archived.

Calvin.
--
Calvin Walton <calvin...@kepstin.ca>

[mont...@gmail.com]

Hi Calvin,

              The contents of the log file is as follows:

# Logfile created on 2018-05-15 13:59:34 +0100 by logger.rb/v1.2.7
I, [2018-05-15T13:59:34.759851 #31319]  INFO -- : Archiving events for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740.
I, [2018-05-15T13:59:35.060468 #31319]  INFO -- : Archiving audio /var/freeswitch/meetings/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740*.wav.
D, [2018-05-15T13:59:35.060754 #31319] DEBUG -- : Copying /var/freeswitch/meetings/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740-1198445105.wav to /var/bigbluebutton/recording/raw/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740/audio
I, [2018-05-15T13:59:35.066071 #31319]  INFO -- : Archiving presentation for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740.
W, [2018-05-15T13:59:35.066330 #31319]  WARN -- : Failed to archive presentations for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740. Directory not found /var/bigbluebutton/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740
I, [2018-05-15T13:59:35.066392 #31319]  INFO -- : Archiving deskshare for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740.
I, [2018-05-15T13:59:35.066605 #31319]  INFO -- : Archiving screenshare for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740.
W, [2018-05-15T13:59:35.066784 #31319]  WARN -- : Failed to archive screenshare for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740. Directory not found /usr/share/red5/webapps/screenshare/streams/30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740
I, [2018-05-15T13:59:35.066843 #31319]  INFO -- : Archiving video for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740.
I, [2018-05-15T13:59:35.068472 #31319]  INFO -- : Fetching the recording marks for 30e1e299556a69b9a3e8b789fd0f5903e24ecd9a-1526388964740.
I, [2018-05-15T13:59:35.068537 #31319]  INFO -- : Getting record status events
I, [2018-05-15T13:59:35.079616 #31319]  INFO -- : record_events:
[{:timestamp=>1198462552}, {:timestamp=>1198488363}]

I had looked at these logs before, but not knowing the exact setup of the system, didn't know which process should be creating these directories that are shown to be missing in the above log. I had initially attempted to change the permissions on the folders to 777, to see if it was a process I wasn't aware of that should have been creating these directories, but that changed nothing at the subsequent recording attempts, and the archive logs of those attempts showed the exact same errors.

Looking at the error log above, I though it might have been something to do with the config files, and possibly something that I'd changed, but comparing the location files in /usr/local/bigbluebutton/core/scripts/bigbluebutton.yml, /var/lib/tomcat7/webapps/bigbluebutton/WEB-INF/classes/bigbluebutton.properties, and /var/lib/red5/webapps/bigbluebutton/WEB-INF/bigbluebutton.properties from the github master, there's no change that I can immediately see.

Once again, any help or info is much appreciated.

Cheers,

           Mark

[Calvin Walton]

Hi Monty,

The directory /var/bigbluebutton/{meetingid} should be created by
BigBlueButton (I think bbb-web specifically) automatically when the
meeting starts - that's the location where presentation files are
uploaded to. That directory is required for live meetings to operate -
if it wasn't being created correctly, then you would not see
presentations during the live meeting.

I guess to start with, could you please make sure the permissions on
the /var/bigbluebutton directory match these:

$ ls -ld /var/bigbluebutton
drwxr-xr-x 31 tomcat7 tomcat7 4096 May 20 06:25 /var/bigbluebutton

The other thing to note is that the /var/bigbluebutton/{meetingid}
directories get cleaned up (by default) 7 days after the meeting
occurred, checked against the timestamps on the directory.

Make sure that the recording processing (archiving at a minimum) is
running as soon as possible after the live session ends.

Please also try creating a live meeting, and verify that the directory
/var/bigbluebutton/{meetingid} was created, contains presentation files
(they'll be a few directories deep in the tree), and that the timestamp
on that directory is correct.

Calvin.

On Mon, 2018-05-21 at 08:23 -0700, mont...@gmail.com wrote:
> Hi Calvin,

--
Calvin Walton <calvin...@kepstin.ca>

[mont...@gmail.com]

Hi Calvin,

               I created a test meeting, and there was no directory created under /var/bigbluebutton/{meeting-id}. I took a look under /var/bigbluebutton/recording/raw, and although there was directories in there, nothing with the current time stamp. By the time I thought of searching for files with today's timestamp, I'd ended the recording, and so more files were picked up under the search, but I'll attempt this again tomorrow.

I can confirm that it is picking the recording up within a few miuntes of the recording ending. Using bbb-record --watch --withDesc, I can follow that process. I also know from following that the bbb-rap-archive-worker.service and bbb-rap-sanity-worker.service run, but obviously that's where things fail (Or fail when the bbb-rap-process-worker.service is run, but I think it's failing at the second step). As I've said before, if I go in and manually change the .failed extensions to .done, the bbb-rap-process-worker.service and bbb-rap-publish-worker.service then run and the recording is successfully published (Although what's published is a blank background with the BB logo on it, no presentation pdf, no video, but audio and the recording of my squiggles on the desktop).

In relation to your permissions query, running ls -ld /var/bigbluebutton

returns

drwxr-xr-x 14 tomcat7 tomcat7 4096 May  3 10:21 /var/bigbluebutton

Permissions of the directories under /var/bigbluebutton are:

drwxr-xr-x  2 tomcat7 tomcat7 4096 May  8 10:21 blank
drwxr-xr-x  2 tomcat7 tomcat7 4096 Feb 16 15:16 configs
drwxr-xr-x  3 tomcat7 tomcat7 4096 May  8 13:52 deleted
drwxr-xr-x  2 tomcat7 tomcat7 4096 May  1 17:25 deskshare
drwxr-xr-x  2 tomcat7 tomcat7 4096 May  8 10:25 diagnostics
drwxr-xr-x  3 tomcat7 tomcat7 4096 May  8 10:20 playback
drwxr-xr-x  3 tomcat7 tomcat7 4096 May  8 10:25 published

drwxr-xr-x  6 tomcat7 tomcat7 4096 May 23 12:15 recording

drwxr-xr-x  2 red5    red5    4096 Jan 31 21:56 screenshare

drwxr-xr-x 21 tomcat7 tomcat7 4096 May 23 12:12 slides
drwxr-xr-x  4 red5    red5    4096 May 23 12:13 streams

drwxr-xr-x  2 tomcat7 tomcat7 4096 May  8 10:25 unpublished

As far as I can tell this is exactly the same as a clean install (In fact at one point I mounted a blank drive and untarred, including permissions, the /var/bigbluebutton folder from a clean install of 2.0 on a VM, which sadly made no difference).

For note /var/bigbluebutton is a mounted disk that connects to an iSCSI LUN, but again, although I've read about networked drives being problematic with this system, it's a fast connection with good iOPS, so I don't think this is an issue in this instance.

Cheers,

           Mark