search

jitsi / jibri

Jitsi BRoadcasting Infrastructure
Apache License 2.0
609 stars 313 forks source link

recording race condition #368

Open vkruoso opened 3 years ago

vkruoso commented 3 years ago

Description

I've faced a race condition when recordings start nearly at the same moment. The logs below show it happening.

The following are the steps Jibri took:

In the interface this is what happened:

Expected Behavior

I'm assuming this is a mix up on the interface considering which recording has failed to start. So the interface would indicate to the customer that the recording has failed.

Regardless of this problem being in Jibri or the interface, I'm open to get a PR done to fix this issue.

Logs

2021-01-25 18:09:31.806 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-25 18:09:41.814 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Got health request
2021-01-25 18:09:41.814 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-25 18:09:42.230 FINE: [149] org.jitsi.xmpp.mucclient.MucClient.log() Received an IQ with type set: IQ Stanza (jibri http://jitsi.org/protocol/jibri) [to=jibri@auth.meet-leads2b/FaK1AVVM,from=jibribrewery@internal-muc.meet-leads2b/focus,id=amlicmlAYXV0aC5tZWV0LWxlYWRzMmIvRmFLMUFWVk0ARTRBcG4tODI3MDAzACawjfGb8BuHQ83fI37fNDY=,type=set,]
2021-01-25 18:09:42.233 INFO: [149] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-leads2b/FaK1AVVM' from='jibribrewery@internal-muc.meet-leads2b/focus' id='amlicmlAYXV0aC5tZWV0LWxlYWRzMmIvRmFLMUFWVk0ARTRBcG4tODI3MDAzACawjfGb8BuHQ83fI37fNDY=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='1l8-kquu-yhi@muc.meet-leads2b' session_id='lkwbyxerwxqszcjc' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=prosody hostname=prosody]
2021-01-25 18:09:42.234 INFO: [149] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request
2021-01-25 18:09:42.236 INFO: [149] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending 'pending' response to start IQ
2021-01-25 18:09:42.237 INFO: [150] org.jitsi.jibri.api.xmpp.XmppApi.run() Starting service
2021-01-25 18:09:42.257 INFO: [150] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-leads2b, callName=1l8-kquu-yhi, urlParams=[])
2021-01-25 18:09:42.259 INFO: [150] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://meet-leads2b, callName=1l8-kquu-yhi, urlParams=[])), sessionId=lkwbyxerwxqszcjc, callLoginParams=XmppCredentials(domain=recorder.meet-leads2b, username=recorder, password=ace48541af732b310544661d5ede05ca)) finalize script path: /finalize.sh and recordings directory: /config/recordings
Starting ChromeDriver 78.0.3904.105 (60e2d8774a8151efa6a00b1f358371b1e0e07ee2-refs/branch-heads/3904@{#877}) on port 9929
Only local connections are allowed.
Please protect ports used by ChromeDriver and related test frameworks to prevent access by malicious code.
2021-01-25 18:09:42.606 FINE: [149] org.jitsi.xmpp.mucclient.MucClient.log() Received an IQ with type set: IQ Stanza (jibri http://jitsi.org/protocol/jibri) [to=jibri@auth.meet-leads2b/FaK1AVVM,from=jibribrewery@internal-muc.meet-leads2b/focus,id=amlicmlAYXV0aC5tZWV0LWxlYWRzMmIvRmFLMUFWVk0ARTRBcG4tODI3MDA3ACawjfGb8BuHQ83fI37fNDY=,type=set,]
2021-01-25 18:09:42.606 INFO: [149] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-leads2b/FaK1AVVM' from='jibribrewery@internal-muc.meet-leads2b/focus' id='amlicmlAYXV0aC5tZWV0LWxlYWRzMmIvRmFLMUFWVk0ARTRBcG4tODI3MDA3ACawjfGb8BuHQ83fI37fNDY=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='qnw-p30y-awd@muc.meet-leads2b' session_id='zfjxucqjsebwcimv' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=prosody hostname=prosody]
2021-01-25 18:09:42.606 INFO: [149] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request
2021-01-25 18:09:42.607 INFO: [149] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending 'pending' response to start IQ
2021-01-25 18:09:42.607 INFO: [157] org.jitsi.jibri.api.xmpp.XmppApi.run() Starting service
2021-01-25 18:09:42.629 INFO: [157] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-leads2b, callName=qnw-p30y-awd, urlParams=[])
2021-01-25 18:09:43.228 INFO: [150] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS
2021-01-25 18:09:43.246 INFO: [150] org.jitsi.jibri.selenium.JibriSelenium.<init>() Starting empty call check with a timeout of PT30S
2021-01-25 18:09:43.256 FINE: [150] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.<init>() Detected os as OS: LINUX
2021-01-25 18:09:43.262 INFO: [150] org.jitsi.jibri.service.impl.FileRecordingJibriService.<init>() Writing recording to /config/recordings/lkwbyxerwxqszcjc
2021-01-25 18:09:43.264 FINE: [150] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:recording
2021-01-25 18:09:43.264 INFO: [150] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY
2021-01-25 18:09:43.265 INFO: [150] org.jitsi.jibri.api.xmpp.XmppApi.updatePresence() Jibri reports its status is now JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), publishing presence to connections
2021-01-25 18:09:43.265 INFO: [150] org.jitsi.xmpp.mucclient.MucClientManager.log() Setting a presence extension: org.jitsi.xmpp.extensions.jibri.JibriStatusPacketExt@5b104edf
2021-01-25 18:09:43.265 FINE: [150] org.jitsi.xmpp.mucclient.MucClientManager.log() Replacing presence extension: org.jitsi.xmpp.extensions.jibri.JibriStatusPacketExt@5aa6202e
2021-01-25 18:09:43.271 FINE: [31] org.jitsi.xmpp.extensions.DefaultPacketExtensionProvider.parse() Could not add a provider for element busy-status from namespace http://jitsi.org/protocol/jibri
2021-01-25 18:09:43.271 INFO: [157] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://meet-leads2b, callName=qnw-p30y-awd, urlParams=[])), sessionId=zfjxucqjsebwcimv, callLoginParams=XmppCredentials(domain=recorder.meet-leads2b, username=recorder, password=ace48541af732b310544661d5ede05ca)) finalize script path: /finalize.sh and recordings directory: /config/recordings
2021-01-25 18:09:43.271 INFO: [157] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-25 18:09:43.271 FINE: [157] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-25 18:09:43.272 FINE: [31] org.jitsi.xmpp.extensions.DefaultPacketExtensionProvider.parse() Could not add a provider for element health-status from namespace http://jitsi.org/protocol/health
2021-01-25 18:09:43.272 SEVERE: [157] org.jitsi.jibri.api.xmpp.XmppApi.run() Jibri is currently busy, cannot service this request
2021-01-25 18:09:44.137 FINE: [161] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url https://meet-leads2b/1l8-kquu-yhi#config.iAmRecorder=true&config.externalConnectUrl=null&config.startWithAudioMuted=true&config.startWithVideoMuted=true&interfaceConfig.APP_NAME="Jibri"&config.analytics.disabled=true&config.p2p.enabled=false
2021-01-25 18:09:45.729 INFO: [161] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1130 milliseconds for call page to load
2021-01-25 18:09:45.748 INFO: [161] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running
2021-01-25 18:09:45.749 INFO: [161] org.jitsi.jibri.service.impl.FileRecordingJibriService.invoke() Selenium joined the call, starting the capturer
2021-01-25 18:09:45.982 INFO: [161] org.jitsi.jibri.util.JibriSubprocess.ffmpeg.launch() Starting ffmpeg with command 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 plug:cloop -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 /config/recordings/lkwbyxerwxqszcjc/1l8-kquu-yhi_2021-01-25-18-09-43.mp4 ([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, plug:cloop, -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, /config/recordings/lkwbyxerwxqszcjc/1l8-kquu-yhi_2021-01-25-18-09-43.mp4])
2021-01-25 18:09:47.174 INFO: [164] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running
2021-01-25 18:09:47.176 INFO: [164] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Starting up to Running
2021-01-25 18:09:47.177 INFO: [164] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq <iq to='jibribrewery@internal-muc.meet-leads2b/focus' id='6WQ9j-264' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' status='on'/></iq>
2021-01-25 18:09:51.823 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Got health request
2021-01-25 18:09:51.823 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))
2021-01-25 18:10:00.825 INFO: [162] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, all clients muted? false
2021-01-25 18:10:01.846 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Got health request
2021-01-25 18:10:01.846 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))
2021-01-25 18:10:11.834 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Got health request
2021-01-25 18:10:11.835 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))
2021-01-25 18:10:15.790 INFO: [162] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=113, upload=22}, download=1442, upload=22, video={download=1308, upload=0}}, all clients muted? false
2021-01-25 18:10:21.840 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Got health request
2021-01-25 18:10:21.841 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))
2021-01-25 18:10:22.047 FINE: [31] org.jitsi.xmpp.extensions.DefaultPacketExtensionProvider.parse() Could not add a provider for element busy-status from namespace http://jitsi.org/protocol/jibri
2021-01-25 18:10:22.048 FINE: [31] org.jitsi.xmpp.extensions.DefaultPacketExtensionProvider.parse() Could not add a provider for element health-status from namespace http://jitsi.org/protocol/health
2021-01-25 18:10:30.784 INFO: [162] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=76, upload=22}, download=1424, upload=22, video={download=1348, upload=0}}, all clients muted? false
2021-01-25 18:10:31.851 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Got health request
2021-01-25 18:10:31.851 FINE: [22] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))
2021-01-25 18:10:41.858 FINE: [28] org.jitsi.jibri.api.http.HttpApi.health() Got health request
bbaldino commented 3 years ago

Which Jicofo version did you see this with?

vkruoso commented 3 years ago

Im running with the stable-4548-1 tag on the docker images. jitsi/jicofo:stable-4548-1

bbaldino commented 3 years ago

Oh, that's very old..it's from May of last year. I ask because I fixed something in Jicofo recently that I think may fix what you're reporting here.

vkruoso commented 3 years ago

Yeah, we have not updated so often to keep stability (and determine how we handle new features like the lobby). Can you point out to the changes? Is there tests running that catch that scenario? Before going to the upgrade process, it would be great to have the security that it will solve the issue. Im also open to do work on that so we can move forward.

bbaldino commented 3 years ago

https://github.com/jitsi/jicofo/pull/659 was the one I was referring to, but there was this one related to Jibri as well: https://github.com/jitsi/jicofo/pull/603