jitsi / jitsi-meet

Jitsi Meet - Secure, Simple and Scalable Video Conferences that you use as a standalone app or embed in your web application.
https://jitsi.org/meet
Apache License 2.0
23.33k stars 6.76k forks source link

Jibri is not recording the meeting when there is no active session on jibri #15335

Closed krishnakingdom closed 5 days ago

krishnakingdom commented 5 days ago

What happened?

I have configured the Jibri in autoscaling to record multiple conferences, it was working fine. But suddenly sometimes when there is no load on Jibri still the Jibri is not recording the meeting, once we restart the Jibri service then it is start recording. My Jitsi meet setup is enabled for auto recording.

image

Platform

Browser / app / sdk version

jibri version 8.0-160-g5af7dd7-1

Relevant log output

No response

Reproducibility

More details?

No response

saghul commented 5 days ago

Can you share the Jibri logs?

krishnakingdom commented 5 days ago

Hi @saghul

sharing the jibri logs, please verify once.

Copy of browser.1.txt Copy of browser.2.txt Copy of browser.0.txt ffmpeg.2.txt Copy of ffmpeg.0.txt Copy of ffmpeg.1.txt Copy of log.2.txt Copy of log.1.txt Copy of log.0.txt Copy of xorg.log log.0.txt log.1.txt log.2.txt xorg.log ffmpeg.1.txt ffmpeg.0.txt ffmpeg.3.txt browser.3.txt browser.2.txt browser.1.txt browser.0.txt

saghul commented 5 days ago

Hum, it looks like Jibri correctly went on to the IDLE state:

2024-11-26 06:46:57.569 INFO: [205] JibriStatusManager$special$$inlined$observable$1.afterChange#75: Busy status has changed: BUSY -> IDLE
2024-11-26 06:46:57.569 FINE: [205] WebhookClient$updateStatus$1.invokeSuspend#109: Updating 0 subscribers of status
2024-11-26 06:46:57.569 INFO: [205] XmppApi.updatePresence#212: Jibri reports its status is now JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), publishing presence to connections
2024-11-26 06:47:39.092 FINE: [19] WebhookClient$updateStatus$1.invokeSuspend#109: Updating 0 subscribers of status

Do you see any errors (in prosody I guess?) when a meeting cannot be auto-recorded?

krishnakingdom commented 5 days ago

In prosody I am getting this error. Jibri is working fine all the time but sometimes it is got stuck may be some session like browser or ffmpeg or not closed correctly.

Nov 25 12:42:24 endconference.video.aauti.com:end_conference info Room comprehensivepaintingcourseforallskilllevelsfrombeginnertoex-673f08e8567a49041dcb3d71@conference.video.aauti.com destroyed by occupant 621fa695-aee7-4166-92c7-877d27b02d0c@video.aauti.com/Qi5FHdgN Nov 25 12:42:30 bosh5db7215b-579e-48f7-879e-10ce40c010d8 info BOSH client disconnected: session close Nov 25 12:42:39 mod_bosh info New BOSH session, assigned it sid '01e67d13-c01c-4bff-bc64-733987d717de' Nov 25 12:42:40 bosh01e67d13-c01c-4bff-bc64-733987d717de info Authenticated as 4cd75556-30e9-44c5-94a4-8650a282eba3@video.aauti.com Nov 25 12:42:41 conference.video.aauti.com:token_moderation info room created, adding token moderation code Nov 25 12:42:55 mod_bosh info New BOSH session, assigned it sid 'b3815455-9a7e-4168-8696-c69e6df2ae0a' Nov 25 12:42:55 boshb3815455-9a7e-4168-8696-c69e6df2ae0a info Authenticated as 08ca54a7-94d0-4581-9ab5-ea9cd532b07e@video.aauti.com Nov 25 12:44:19 endconference.video.aauti.com:end_conference info Room comprehensivepaintingcourseforallskilllevelsfrombeginnertoex-673f08e8567a49041dcb3d71@conference.video.aauti.com destroyed by occupant 08ca54a7-94d0-4581-9ab5-ea9cd532b07e@video.aauti.com/rHELFHtw Nov 25 12:44:24 boshb3815455-9a7e-4168-8696-c69e6df2ae0a info BOSH client disconnected: session close Nov 25 12:44:24 bosh01e67d13-c01c-4bff-bc64-733987d717de info BOSH client disconnected: session close Nov 25 12:45:52 mod_bosh info New BOSH session, assigned it sid '4a7ff66f-1c8f-4977-9484-4b7149fad6c0' Nov 25 12:45:53 bosh4a7ff66f-1c8f-4977-9484-4b7149fad6c0 info Authenticated as 73516e12-abeb-4e52-be0f-1d18226e50d5@video.aauti.com Nov 25 12:45:55 conference.video.aauti.com:token_moderation info room created, adding token moderation code Nov 25 12:45:56 bosh4a7ff66f-1c8f-4977-9484-4b7149fad6c0 info BOSH client disconnected: session close Nov 25 12:45:57 mod_bosh info New BOSH session, assigned it sid 'a52fd872-3712-40c8-a9f8-a64b8718d68c' Nov 25 12:45:57 bosha52fd872-3712-40c8-a9f8-a64b8718d68c info Authenticated as 7708ced1-396c-4b8f-b881-b73d559c0f4e@video.aauti.com Nov 25 12:45:59 timer error Traceback[timer]: ...share/jitsi-meet/prosody-plugins/mod_jibri_autostart.lua:26: attempt to index local 'occupant' (a nil value) stack traceback: ...share/jitsi-meet/prosody-plugins/mod_jibri_autostart.lua:26: in function '_start_recording' ...share/jitsi-meet/prosody-plugins/mod_jibri_autostart.lua:64: in function <...share/jitsi-meet/prosody-plugins/mod_jibri_autostart.lua:63> [C]: in function 'xpcall' /usr/lib/prosody/util/timer.lua:41: in function 'callback' /usr/lib/prosody/net/server_select.lua:885: in function '?' /usr/lib/prosody/net/server_select.lua:916: in function </usr/lib/prosody/net/server_select.lua:908> [C]: in function 'xpcall' /usr/bin/prosody:76: in function 'loop' /usr/bin/prosody:86: in main chunk [C]: in ? Nov 25 12:45:59 conference.video.aauti.com:token_moderation info room created, adding token moderation code Nov 25 12:46:18 bosha52fd872-3712-40c8-a9f8-a64b8718d68c info BOSH client disconnected: session close Nov 25 12:47:35 mod_bosh info New BOSH session, assigned it sid '42973b19-fa0a-4180-891c-cef8077981f6' Nov 25 12:47:35 bosh42973b19-fa0a-4180-891c-cef8077981f6 info Authenticated as 90f13966-d1c4-4d62-8da4-092e9a062cfd@video.aauti.com Nov 25 12:47:37 conference.video.aauti.com:token_moderation info room created, adding token moderation code Nov 25 12:47:42 endconference.video.aauti.com:end_conference info Room explorepaintingtechniquesandstylesforallskilllevels-67345a09dd08eb77bdded6a8@conference.video.aauti.com destroyed by occupant 90f13966-d1c4-4d62-8da4-092e9a062cfd@video.aauti.com/nBT63I6i Nov 25 12:47:46 bosh42973b19-fa0a-4180-891c-cef8077981f6 info BOSH client disconnected: session close Nov 25 12:48:06 mod_bosh info New BOSH session, assigned it sid 'c100ec0a-aa8e-4cf6-af00-94a7b6219bdf' Nov 25 12:48:06 boshc100ec0a-aa8e-4cf6-af00-94a7b6219bdf info Authenticated as 3e391133-5d68-40e8-9813-a6a5fb22dead@video.aauti.com Nov 25 12:48:08 conference.video.aauti.com:token_moderation info room created, adding token moderation code

shawnchin commented 5 days ago
.../mod_jibri_autostart.lua:26: attempt to index local 'occupant' (a nil value)

That would imply that the jibri_autostart could not find the room occupant given the jid, which, looking at the code could happen when someone joins the room then leaves within 3 seconds of joining.

I'm not sure this is the cause of your problems, since I'm assuming that event handler would kick in again when the next person joins and it should work then. But you could try to fix that to rule out the issue and have cleaner logs.

Try changing https://github.com/jitsi-contrib/prosody-plugins/blob/ecfdcdc52992ff064e5844440be16e8b47f7db85/jibri_autostart/mod_jibri_autostart.lua#L25-L26 to something like:

    -- check recording permission
    if occupant == nil or occupant.role ~= "moderator" then
krishnakingdom commented 5 days ago

@shawnchin

I changed the jibri AutoStart plugin accordingly as you suggested. But i think this might not causing the issue. could you please verify the below error and error log once. log.6.txt

Verify the below log file from line number 432

24-11-20-11-25-08.mp4 ([ffmpeg, -y, -v, info, -f, x11grab, -draw_mouse, 0, -r, 30, -s, 1920x1080, -thread_queue_size, 4096, -i, :0.0+0,0, -f, alsa, -thread_queue_size, 4096, -i, plug:bsnoop, -acodec, aac, -strict, -2, -ar, 44100, -b:a, 128k, -af, aresample=async=1, -c:v, libx264, -preset, veryfast, -profile:v, main, -level, 3.1, -pix_fmt, yuv420p, -r, 30, -crf, 25, -g, 60, -tune, zerolatency, -timestamp, now, -f, mp4, /s3/aauti-recordings/bacf3d60-6cd8-40e2-82be-9670d5733660/mastertheartofpaintingwithexpertguidanceforeveryskilllevel-673343efdd08eb77bdd3d0ec_2024-11-20-11-25-08.mp4]) 2024-11-20 11:25:19.467 INFO: [144] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] FfmpegCapturer.onFfmpegStateMachineStateChange#134: Ffmpeg capturer transitioning from state Starting up to Running 2024-11-20 11:25:19.468 INFO: [144] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] StatefulJibriService.onServiceStateChange#39: File recording service transitioning from state Starting up to Running 2024-11-20 11:25:19.468 INFO: [144] XmppApi$createServiceStatusHandler$1.invoke#337: Current service started up successfully, sending on iq 2024-11-20 11:25:27.377 INFO: [135] XmppApi.handleJibriIq#239: Received JibriIq from environment [MucClient id=video.aauti.com hostname=video.aauti.com] 2024-11-20 11:25:27.377 FINE: [135] JibriStatsDClient.incrementCounter#38: Incrementing statsd counter: stop:recording 2024-11-20 11:25:27.377 INFO: [135] JibriManager.stopService#274: Stopping the current service 2024-11-20 11:25:27.377 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] FileRecordingJibriService.stop#182: Stopping capturer 2024-11-20 11:25:27.377 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSubprocess.stop#75: Stopping ffmpeg process 2024-11-20 11:25:29.173 INFO: [144] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] FfmpegCapturer.onFfmpegStateMachineStateChange#134: Ffmpeg capturer transitioning from state Running to Finished 2024-11-20 11:25:29.173 INFO: [144] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] StatefulJibriService.onServiceStateChange#39: File recording service transitioning from state Running to Finished 2024-11-20 11:25:29.173 INFO: [144] XmppApi$createServiceStatusHandler$1.invoke#330: Current service finished, sending off iq 2024-11-20 11:25:29.174 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSubprocess.stop#89: ffmpeg exited with value 255 2024-11-20 11:25:29.174 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] FileRecordingJibriService.stop#184: Quitting selenium 2024-11-20 11:25:29.436 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] FileRecordingJibriService.stop#211: Participants in this recording: [] 2024-11-20 11:25:30.941 INFO: [19] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] MediaReceivedStatusCheck.run#45: Jibri client receive bitrates: {audio={download=0, upload=0}, download=0, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 1, numJigasis: 0, all clients muted? true 2024-11-20 11:25:30.951 WARNING: [19] CallPage.isIceConnected#244: ICE not connected: null 2024-11-20 11:25:32.425 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#338: Leaving call and quitting browser 2024-11-20 11:25:32.425 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#341: Recurring call status checks cancelled 2024-11-20 11:25:32.429 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#347: Got 13 log entries for type browser 2024-11-20 11:25:32.446 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#347: Got 595 log entries for type driver 2024-11-20 11:25:32.465 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#347: Got 0 log entries for type client 2024-11-20 11:25:32.465 INFO: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#356: Leaving web call 2024-11-20 11:25:32.476 SEVERE: [135] [session_id=bacf3d60-6cd8-40e2-82be-9670d5733660] JibriSelenium.leaveCallAndQuitBrowser#360: Error trying to leave the call org.openqa.selenium.JavascriptException: javascript error: You have already left the conference (Session info: chrome=114.0.5735.198)

2024-11-20 11:30:51.264 INFO: [135] XmppApi.updatePresence#212: Jibri reports its status is now JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), publishing presence to connections 2024-11-20 11:30:51.617 SEVERE: [160] [session_id=70c1fbdf-cd36-437c-8972-7d6a05efdcd7] JibriSelenium.joinCall$lambda$3#327: An error occurred while joining the call org.openqa.selenium.NoSuchSessionException: Session ID is null. Using WebDriver after calling quit()? Build info: version: 'unknown', revision: 'unknown', time: 'unknown' System info: host: 'jibri-vms0JLJED', ip: '10.3.0.5', os.name: 'Linux', os.arch: 'amd64', os.version: '4.15.0-221-generic', java.version: '11.0.25' Driver info: driver.version: RemoteWebDriver at org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:125) at org.openqa.selenium.remote.service.DriverCommandExecutor.execute(DriverCommandExecutor.java:83) at org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:543) at org.openqa.selenium.remote.RemoteWebDriver.executeScript(RemoteWebDriver.java:480) at org.jitsi.jibri.selenium.pageobjects.CallPage$visit$1$1.invoke(CallPage.kt:46) at org.jitsi.jibri.selenium.pageobjects.CallPage$visit$1$1.invoke(CallPage.kt:45) at org.jitsi.jibri.selenium.pageobjects.CallPage.visit$lambda$1$lambda$0(CallPage.kt:45) at org.openqa.selenium.support.ui.FluentWait.until(FluentWait.java:248) at org.jitsi.jibri.selenium.pageobjects.CallPage.visit(CallPage.kt:45) at org.jitsi.jibri.selenium.JibriSelenium.joinCall$lambda$3(JibriSelenium.kt:318) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) at java.base/java.lang.Thread.run(Thread.java:829) 2024-11-20 11:30:51.617 INFO: [160] [session_id=70c1fbdf-cd36-437c-8972-7d6a05efdcd7] JibriSelenium.onSeleniumStateChange#216: Transitioning from state Starting up to Error: FailedToJoinCall SESSION Failed to join the call 2024-11-20 11:30:51.617 INFO: [160] [session_id=70c1fbdf-cd36-437c-8972-7d6a05efdcd7] StatefulJibriService.onServiceStateChange#39: File recording service transitioning from state Starting up to Error: FailedToJoinCall SESSION Failed to join the call 2024-11-20 11:30:51.617 INFO: [160] XmppApi$createServiceStatusHandler$1.invoke#320: Current service had an error Error: FailedToJoinCall SESSION Failed to join the call, sending error iq 2024-11-20 11:30:51.617 INFO: [160] JibriManager.stopService#270: No service active, ignoring stop 2024-11-20 11:31:21.213 INFO: [135] XmppApi.handleJibriIq#239: Received JibriIq from environment [MucClient id=video.aauti.com hostname=video.aauti.com] 2024-11-20 11:31:21.213 INFO: [135] XmppApi.handleStartJibriIq#271: Received start request, starting service 2024-11-20 11:31:21.215 INFO: [135] XmppApi.handleStartService#382: Parsed call url info: CallUrlInfo(baseUrl=https://video.aauti.com, callName=explorepaintingtechniquesandstylesforallskilllevels-67345a09dd08eb77bdded6a3, urlParams=[]) 2024-11-20 11:31:21.215 INFO: [135] JibriManager.startFileRecording#152: Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://video.aauti.com, callName=explorepaintingtechniquesandstylesforallskilllevels-67345a09dd08eb77bdded6a3, urlParams=[]), email='', passcode=null, callStatsUsernameOverride=, displayName=), sessionId=393c5e1b-951e-4e0f-9597-3f66005663f6, callLoginParams=XmppCredentials(domain=recorder.video.aauti.com, port=null, username=recorder, password=*****)) 2024-11-20 11:31:21.216 FINE: [135] [session_id=393c5e1b-951e-4e0f-9597-3f66005663f6] FfmpegCapturer.#92: Detected os as OS: LINUX 2024-11-20 11:31:21.465 INFO: [135] org.openqa.selenium.remote.ProtocolHandshake.createSession: Detected dialect: OSS

shawnchin commented 5 days ago

Yup, I guessed as much that the error was a red herring, but I didn't want you to be hung up on that error hence my comments above.

From the error logs, it looks like Jibri is unable to join the call. I'm afraid I don't work with Jibri much so I can't be of much use here. Sorry.

p.s. you should really have posted this on the Community Forum before opening a Github issue. You'll get a wider audience of folks there than can assist you with debugging your deployment.

krishnakingdom commented 5 days ago

ok sure @shawnchin , thank you for the help.

@saghul could you please verify the issue once and suggest me the solution

saghul commented 5 days ago

@krishnakingdom See https://github.com/jitsi-contrib/prosody-plugins/pull/36