Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

recording race condition #368

Open
vkruoso opened this issue Jan 25, 2021 · 5 comments
Open

recording race condition #368

vkruoso opened this issue Jan 25, 2021 · 5 comments

Comments

@vkruoso
Copy link

vkruoso commented Jan 25, 2021

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:

  • Jibri receives new recording request and accepts it (with Starting a file recording with params)
  • Will call this Conf 1
  • Changes its status to "Busy status has changed: IDLE -> BUSY"
  • Jibri receives new recording request and accepts it (with Starting a file recording with params)
  • Will call this Conf 2
  • Jibri says Jibri is busy, can't start service
  • Jibri starts the ffmpeg process based on the first request

In the interface this is what happened:

  • The users in the Conf 1 received the error starting the recording and initiated a new one
  • The users in the Conf 2 never received the error, the interface showed the recording was active, but it was not
  • In the end, Conf 1 got 2 recordings, and Conf 2 got none

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
Copy link
Member

Which Jicofo version did you see this with?

@vkruoso
Copy link
Author

vkruoso commented Jan 25, 2021

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

@bbaldino
Copy link
Member

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
Copy link
Author

vkruoso commented Jan 26, 2021

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
Copy link
Member

jitsi/jicofo#659 was the one I was referring to, but there was this one related to Jibri as well: jitsi/jicofo#603

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@vkruoso @bbaldino