jibri icon indicating copy to clipboard operation
jibri copied to clipboard
verified publisher icon jitsi

Jibri continuously running and ffmpeg recording proces not getting stopped

Open harishnv opened this issue 7 years ago • 9 comments

Description

Jibri continuously running and ffmpeg recording process also not getting stopped. Many times jibri status remain busy some time it has been observed that it fails to update its status on jicofo. which shows jibri is IDLE but actually it is showing same log output for the busy state. This makes jibri instace available in pool but fails to process any request.

Current behavior

jibri log is generating this repetitive log continuously.

  Build info: version: 'unknown', revision: 'unknown', time: 'unknown'
   System info: host: 'rec-20', ip: '10.0.21.14', os.name: 'Linux', os.arch: 'amd64', os.version: '4.4.0-141-generic', java.version: '1.8.0_191'
   Driver info: driver.version: RemoteWebDriver with stack: 
   org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:131)
   org.openqa.selenium.remote.service.DriverCommandExecutor.execute(DriverCommandExecutor.java:83)
   org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:601)
   org.openqa.selenium.remote.RemoteWebDriver.executeScript(RemoteWebDriver.java:537)
   org.jitsi.jibri.selenium.pageobjects.CallPage.getNumParticipants(CallPage.kt:71)
   org.jitsi.jibri.selenium.JibriSelenium$EmptyCallStatusCheck.run(JibriSelenium.kt:303)
   org.jitsi.jibri.selenium.JibriSelenium$startRecurringCallStatusChecks$1$event$1.invoke(JibriSelenium.kt:188)
   org.jitsi.jibri.selenium.JibriSelenium$startRecurringCallStatusChecks$1$event$1.invoke(JibriSelenium.kt:100)
   kotlin.sequences.TransformingSequence$iterator$1.next(Sequences.kt:149)
   org.jitsi.jibri.selenium.JibriSelenium$startRecurringCallStatusChecks$1.invoke(JibriSelenium.kt:334)
   org.jitsi.jibri.selenium.JibriSelenium$startRecurringCallStatusChecks$1.invoke(JibriSelenium.kt:100)
   org.jitsi.jibri.util.extensions.SchedulerExecutorServiceExtsKt$sam$java_lang_Runnable$0.run(SchedulerExecutorServiceExts.kt)
   java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
   java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
   java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
   java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
   java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
   java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
   java.lang.Thread.run(Thread.java:748)

   2019-02-14 06:14:15.472 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:15.472 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:15.598 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:15.598 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:16.867 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:16.867 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:17.472 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:17.472 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:17.598 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:17.599 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:18.867 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:18.867 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:19.472 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:19.473 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:19.598 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:19.599 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:20.867 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:20.868 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:21.472 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:21.472 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error
   2019-02-14 06:14:21.598 FINE: [184] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
   2019-02-14 06:14:21.598 INFO: [2571] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegProcessUpdate() Ffmpeg quit abruptly.  Last output line: hw:0,1,0: Input/output error

ps ffmpeg shows its running for 421:59

jibri 40936 40.7 5.9 1020504 237864 ? Sl Feb13 421:59 ffmpeg -y -v info -f x11grab -draw_mouse 0 -r 30 -s 1280x720 -thread_queue_size 4096 -i :0.0+0,0 -f alsa -thread_queue_size 4096 -i hw:0,1,0 -acodec aac -strict -2 -ar 44100 -c:v libx264 -preset veryfast -profile:v main -level 3.1 -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f mp4 /recordings/nngibukurbcdiptx/191563065_2019-02-13-12-58-33.mp4

ffmpeg file log only have this kind of data

2019-02-06 12:57:38.918 INFO: [506] ffmpeg.call() frame=10364 fps= 30 q=25.0 size=   51874kB time=00:05:45.46 bitrate=1230.1kbits/s
2019-02-06 12:57:38.918 INFO: [506] ffmpeg.call() frame=10379 fps= 30 q=26.0 size=   51942kB time=00:05:45.96 bitrate=1229.9kbits/s
2019-02-06 12:57:39.918 INFO: [506] ffmpeg.call() frame=10394 fps= 30 q=24.0 size=   52010kB time=00:05:46.46 bitrate=1229.7kbits/s
2019-02-06 12:57:39.918 INFO: [506] ffmpeg.call() frame=10409 fps= 30 q=26.0 size=   52101kB time=00:05:46.96 bitrate=1230.1kbits/s
2019-02-06 12:57:40.918 INFO: [506] ffmpeg.call() frame=10425 fps= 30 q=26.0 size=   52175kB time=00:05:47.50 bitrate=1230.0kbits/s
2019-02-06 12:57:40.919 INFO: [506] ffmpeg.call() frame=10440 fps= 30 q=25.0 size=   52246kB time=00:05:48.00 bitrate=1229.9kbits/s
2019-02-06 12:57:41.919 INFO: [506] ffmpeg.call() frame=10455 fps= 30 q=26.0 size=   52314kB time=00:05:48.50 bitrate=1229.7kbits/s
2019-02-06 12:57:41.919 INFO: [506] ffmpeg.call() frame=10470 fps= 30 q=26.0 size=   52407kB time=00:05:49.00 bitrate=1230.1kbits/s
2019-02-06 12:57:42.919 INFO: [506] ffmpeg.call() frame=10485 fps= 30 q=24.0 size=   52482kB time=00:05:49.50 bitrate=1230.1kbits/s
2019-02-06 12:57:42.919 INFO: [506] ffmpeg.call() frame=10500 fps= 30 q=25.0 size=   52547kB time=00:05:50.00 bitrate=1229.9kbits/s
2019-02-06 12:57:43.919 INFO: [506] ffmpeg.call() frame=10515 fps= 30 q=25.0 size=   52618kB time=00:05:50.50 bitrate=1229.8kbits/s
2019-02-06 12:57:43.919 INFO: [506] ffmpeg.call() frame=10531 fps= 30 q=26.0 size=   52711kB time=00:05:51.03 bitrate=1230.1kbits/s
2019-02-06 12:57:44.920 INFO: [506] ffmpeg.call() frame=10546 fps= 30 q=26.0 size=   52779kB time=00:05:51.53 bitrate=1229.9kbits/s
2019-02-06 12:57:44.920 INFO: [506] ffmpeg.call() frame=10561 fps= 30 q=26.0 size=   52845kB time=00:05:52.03 bitrate=1229.7kbits/s
2019-02-06 12:57:45.920 INFO: [506] ffmpeg.call() frame=10577 fps= 30 q=25.0 size=   52914kB time=00:05:52.56 bitrate=1229.5kbits/s
2019-02-06 12:57:45.920 INFO: [506] ffmpeg.call() frame=10592 fps= 30 q=24.0 size=   52999kB time=00:05:53.06 bitrate=1229.7kbits/s
2019-02-06 12:57:46.920 INFO: [506] ffmpeg.call() frame=10607 fps= 30 q=24.0 size=   53061kB time=00:05:53.56 bitrate=1229.4kbits/s
2019-02-06 12:57:46.920 INFO: [506] ffmpeg.call() frame=10623 fps= 30 q=24.0 size=   53124kB time=00:05:54.10 bitrate=1229.0kbits/s
2019-02-06 12:57:47.920 INFO: [506] ffmpeg.call() frame=10638 fps= 30 q=26.0 size=   53194kB time=00:05:54.60 bitrate=1228.9kbits/s
2019-02-06 12:57:47.921 INFO: [506] ffmpeg.call() frame=10653 fps= 30 q=24.0 size=   53285kB time=00:05:55.10 bitrate=1229.3kbits/s
2019-02-06 12:57:48.922 INFO: [506] ffmpeg.call() frame=10669 fps= 30 q=26.0 size=   53360kB time=00:05:55.63 bitrate=1229.2kbits/s
2019-02-06 12:57:49.922 INFO: [506] ffmpeg.call() frame=10684 fps= 30 q=25.0 size=   53433kB time=00:05:56.13 bitrate=1229.1kbits/s
2019-02-06 12:57:49.922 INFO: [506] ffmpeg.call() frame=10699 fps= 30 q=25.0 size=   53501kB time=00:05:56.63 bitrate=1228.9kbits/s
2019-02-06 12:57:50.922 INFO: [506] ffmpeg.call() frame=10715 fps= 30 q=26.0 size=   53603kB time=00:05:57.16 bitrate=1229.4kbits/s
2019-02-06 12:57:50.922 INFO: [506] ffmpeg.call() frame=10730 fps= 30 q=26.0 size=   53672kB time=00:05:57.66 bitrate=1229.3kbits/s
2019-02-06 12:57:51.923 INFO: [506] ffmpeg.call() frame=10745 fps= 30 q=24.0 size=   53739kB time=00:05:58.16 bitrate=1229.1kbits/s
2019-02-06 12:57:51.923 INFO: [506] ffmpeg.call() frame=10761 fps= 30 q=25.0 size=   53807kB time=00:05:58.70 bitrate=1228.9kbits/s
2019-02-06 12:57:52.923 INFO: [506] ffmpeg.call() frame=10776 fps= 30 q=25.0 size=   53896kB time=00:05:59.20 bitrate=1229.2kbits/s
2019-02-06 12:57:52.923 INFO: [506] ffmpeg.call() frame=10791 fps= 30 q=24.0 size=   53966kB time=00:05:59.70 bitrate=1229.0kbits/

Expected Behavior

  1. On this failure jibri should update Health status to UNHEALTHY
  2. if possible reinitate jibri service

Possible Solution

Steps to reproduce

not able to reporduce but happens frequenlty.

Environment details

Jibri version:7.2.71-1 os : 16.04 ubuntu VM

Jicofo version: 455 os : 16.04 ubuntu VM

harishnv avatar Feb 25 '19 06:02 harishnv

Thanks, can you attach an entire Jibri log from when it happens?

bbaldino avatar Feb 26 '19 22:02 bbaldino

Hi @bbaldino, Please check this google drive link for the log file. Mentioned problematic log starts after line no 2103.

harishnv avatar Feb 27 '19 13:02 harishnv

Well it looks like your audio device isn't set up correctly (causing the input/output error in ffmpeg)--If it's not happening every time though then maybe it's some kind of race? Not sure. @aaronkvanmeerten , did you see anything like that?

On top of that, it looks like selenium is crashing at the same time. Not sure if there's any relation there.

bbaldino avatar Feb 28 '19 06:02 bbaldino

@bbaldino as you have mentioned race. I have observed the following scenario where this behavior is happening.

  1. Jibri get the event to start recording. jibri initiate process along with FFmpeg.
  2. meanwhile, if stop recording event received then jibri proceed with stop and update its event to idle.
  3. The FFmpeg process then starts and try to do recording in the conference which already closed.
  4. This FFmpeg Process doesn't stop. This jibri status is idle so it will receive the start event again but FFmpeg process is already running so this will give hardware busy.
  5. Jibri fails to update its health status to unhealthy which makes it vulnerable.

Will it be possible to have a jibri status object so that if this kind of event happens ffmpeg recording process will check for status and work according to it?.

harishnv avatar Mar 14 '19 11:03 harishnv

Cool, thanks for that, sounds like a legit bug but don't think I'll have time to look into it anytime soon...hopefully that should be rare (I don't think we've been encountering it in any of our Jibris).

bbaldino avatar Mar 14 '19 16:03 bbaldino

Not really rare issue. Identical problem here.

urbanovits avatar Apr 28 '19 10:04 urbanovits

Facing the same problem Any update on this issue ?

Harishkrishna17 avatar Mar 15 '21 08:03 Harishkrishna17

Any update on this ?, I am also facing similar issue.

Tinkesh-Kumar avatar Nov 19 '21 13:11 Tinkesh-Kumar

We had never seen this issue in production or in our development systems, so we have no good way to reproduce it. I agree there is value in having jibri never lose track of a process, and we'd welcome pull requests attempting to implement said behavior, but as we've been unable to reproduce it and isn't affecting our deployments it's not been on our radar to work on.

aaronkvanmeerten avatar Nov 19 '21 13:11 aaronkvanmeerten