Jibri Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response

Hi Guys,

I’ve got an autoscaling Jibri setup in AWS. It uses a cronjob that will send cloudwatch metrics depending on IDLE/BUSY. I’m scaling my instances in and out depending on these metrics.

jibri has to connect to the jitsi server via internal IP (private ip). To do this, we have added etc-host entries to the jibri server on the userdata(this will also change the nickname).

I’m getting the following error on the jicofo logs and the recording is not getting started on the UI. But after some time the recording is getting started in the jibri server and its triggering the scaleup policy. But this is not reflected in the UI.

jicofo.log

Jicofo 2021-01-08 12:39:37.873 INFO: [31] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:39:37.874 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='idle'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-08 12:39:37.874 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 available: true
Jicofo 2021-01-08 12:40:37.106 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:40:37.106 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 for stream ID: null in room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:40:52.107 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2021-01-08 12:40:52.107 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:589)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:370)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:178)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:271)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-08 12:40:52.107 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 had a transient error, moving to the backof the queue
Jicofo 2021-01-08 12:40:52.107 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:40:52.108 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 went offline
Jicofo 2021-01-08 12:40:52.108 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:40:52.108 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:40:52.108 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 for stream ID: null in room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:40:52.108 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Rescheduling pending timeout task for room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:41:07.109 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2021-01-08 12:41:07.109 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:589)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:370)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:378)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:178)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:271)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-08 12:41:07.109 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 had a transient error, moving to the backof the queue
Jicofo 2021-01-08 12:41:07.109 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
  Jicofo 2021-01-08 12:41:07.109 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 went offline
Jicofo 2021-01-08 12:41:07.110 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:41:07.110 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:41:07.110 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 for stream ID: null in room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:41:07.110 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Rescheduling pending timeout task for room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:41:09.712 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='busy'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-08 12:41:09.713 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 available: false
Jicofo 2021-01-08 12:41:09.760 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected status received in response to the start IQ: <iq to='focus@auth.meet-qa.example.com/focus1392563055353438' from='jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155' id='BWDoj-474738' type='result'><jibri xmlns='http://jitsi.org/protocol/jibri' status='off' failure_reason='busy' should_retry='true'/></iq>
Jicofo 2021-01-08 12:41:09.761 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:602)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:370)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:378)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:378)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:178)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:271)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-08 12:41:09.761 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 had a transient error, moving to the backof the queue
Jicofo 2021-01-08 12:41:09.761 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:41:09.761 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 went offline
Jicofo 2021-01-08 12:41:09.762 INFO: [810] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:41:09.762 SEVERE: [810] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unable to find an available Jibri, can't start
Jicofo 2021-01-08 12:41:09.762 INFO: [810] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Failed to start a Jibri session, all Jibris were busy
Jicofo 2021-01-08 12:41:09.762 SEVERE: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri went offline: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 for room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:41:09.763 INFO: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Got Jibri status update: Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 has status off and failure reason error, current Jibri jid is jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155
Jicofo 2021-01-08 12:41:09.763 INFO: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri is no longer pending, cancelling pending timeout task
Jicofo 2021-01-08 12:41:09.763 INFO: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri failed, trying to fall back to another Jibri
Jicofo 2021-01-08 12:41:09.763 SEVERE: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unable to find an available Jibri, can't start
Jicofo 2021-01-08 12:41:09.763 INFO: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to fall back to another Jibri, this session has now failed: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: All Jibri instances are busy
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: All Jibri instances are busy
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:359)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.handleJibriStatusUpdate(JibriSession.java:719)
	at org.jitsi.jicofo.recording.jibri.JibriSession.access$600(JibriSession.java:49)
	at org.jitsi.jicofo.recording.jibri.JibriSession$JibriEventHandler.handleEvent(JibriSession.java:827)
	at org.jitsi.eventadmin.EventAdminImpl.callEventHandler(EventAdminImpl.java:209)
	at org.jitsi.eventadmin.EventAdminImpl.access$000(EventAdminImpl.java:35)
	at org.jitsi.eventadmin.EventAdminImpl$1.run(EventAdminImpl.java:189)
	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:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-08 12:41:09.764 SEVERE: [285] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() onSessionStateChanged for unknown session: org.jitsi.jicofo.recording.jibri.JibriSession@1b385933
Jicofo 2021-01-08 12:41:09.764 INFO: [285] org.jitsi.jicofo.recording.jibri.JibriSession.log() Cleaning up current JibriSession
Jicofo 2021-01-08 12:41:15.077 INFO: [81] org.jitsi.jicofo.xmpp.FocusComponent.log() Focus request for room: testurl@conference.meet-qa.example.com
Jicofo 2021-01-08 12:41:15.199 INFO: [31] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@27f857be member=ChatMember[testurl@conference.meet-qa.example.com/7baf6a12, jid: null]@887126350]
Jicofo 2021-01-08 12:41:15.199 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member testurl@conference.meet-qa.example.com/7baf6a12 joined.
Jicofo 2021-01-08 12:41:15.200 INFO: [31] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370, relayId=null, region=null, stress=0.00] with stress=0.0 for participantRegion=null
Jicofo 2021-01-08 12:41:15.200 INFO: [31] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl@7a95d50d
Jicofo 2021-01-08 12:41:15.200 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= testurl@conference.meet-qa.example.com/7baf6a12, bridge=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370
Jicofo 2021-01-08 12:41:15.200 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=39533 octo_enabled= false: [[null, null]]
Jicofo 2021-01-08 12:41:15.201 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= testurl@conference.meet-qa.example.com/8d0cd5e4, bridge=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370
Jicofo 2021-01-08 12:41:15.201 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=39533 octo_enabled= false: [[null, null, null]]
Jicofo 2021-01-08 12:41:15.201 INFO: [813] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for testurl@conference.meet-qa.example.com/8d0cd5e4
Jicofo 2021-01-08 12:41:15.201 INFO: [812] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for testurl@conference.meet-qa.example.com/7baf6a12
Jicofo 2021-01-08 12:41:15.202 INFO: [813] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for testurl@conference.meet-qa.example.com/8d0cd5e4 in 0
Jicofo 2021-01-08 12:41:15.202 INFO: [813] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370 to allocate channels for: Participant[testurl@conference.meet-qa.example.com/8d0cd5e4]@2091603736
Jicofo 2021-01-08 12:41:15.206 INFO: [812] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for testurl@conference.meet-qa.example.com/7baf6a12 in 1
Jicofo 2021-01-08 12:41:15.208 INFO: [812] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370 to allocate channels for: Participant[testurl@conference.meet-qa.example.com/7baf6a12]@179945830
Jicofo 2021-01-08 12:41:15.220 INFO: [813] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: testurl@conference.meet-qa.example.com/8d0cd5e4
Jicofo 2021-01-08 12:41:15.236 INFO: [812] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: testurl@conference.meet-qa.example.com/7baf6a12
Jicofo 2021-01-08 12:41:15.915 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: testurl@conference.meet-qa.example.com/7baf6a12
Jicofo 2021-01-08 12:41:15.915 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from testurl@conference.meet-qa.example.com/7baf6a12 with accepted sources:Sources{ }@1985305488
Jicofo 2021-01-08 12:41:15.916 WARNING: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No jingle session yet for testurl@conference.meet-qa.example.com/8d0cd5e4
Jicofo 2021-01-08 12:41:17.554 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: testurl@conference.meet-qa.example.com/8d0cd5e4
Jicofo 2021-01-08 12:41:17.555 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from testurl@conference.meet-qa.example.com/8d0cd5e4 with accepted sources:Sources{ }@582800874
Jicofo 2021-01-08 12:41:17.555 INFO: [31] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Notify add SSRC testurl@conference.meet-qa.example.com/7baf6a12 SID: d92psn3mh8orf Sources{ }@901194965 source_Groups{ }@939191709
Jicofo 2021-01-08 12:45:49.763 INFO: [31] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-183
Jicofo 2021-01-08 12:45:49.764 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-183 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='idle'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-08 12:45:49.764 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-183 available: true
Jicofo 2021-01-08 12:51:46.339 INFO: [31] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberLeft sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@27f857be member=ChatMember[testurl@conference.meet-qa.example.com/7baf6a12, jid: null]@887126350]
Jicofo 2021-01-08 12:51:46.339 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member testurl@conference.meet-qa.example.com/7baf6a12 is leaving
Jicofo 2021-01-08 12:51:46.339 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Terminating Participant[testurl@conference.meet-qa.example.com/7baf6a12]@179945830, reason: gone, send st: false
Jicofo 2021-01-08 12:51:46.339 INFO: [31] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Terminate session: testurl@conference.meet-qa.example.com/7baf6a12, reason: gone, send terminate: false
Jicofo 2021-01-08 12:51:46.340 WARNING: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No sources or groups to be removed from: testurl@conference.meet-qa.example.com/7baf6a12
Jicofo 2021-01-08 12:51:46.340 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=39533 octo_enabled= false: [[null, null]]
Jicofo 2021-01-08 12:51:46.340 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Expiring channels for: testurl@conference.meet-qa.example.com/7baf6a12 on: Bridge[jid=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370, relayId=null, region=null, stress=0.00]
Jicofo 2021-01-08 12:51:46.340 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removed participant: true, testurl@conference.meet-qa.example.com/7baf6a12
Jicofo 2021-01-08 12:51:47.593 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='idle'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-08 12:51:47.594 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-155 available: true
Jicofo 2021-01-08 12:52:06.341 INFO: [123] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Timing out single participant: testurl@conference.meet-qa.example.com/8d0cd5e4
Jicofo 2021-01-08 12:52:06.341 INFO: [123] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Terminating Participant[testurl@conference.meet-qa.example.com/8d0cd5e4]@2091603736, reason: expired, send st: true
Jicofo 2021-01-08 12:52:06.341 INFO: [123] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Terminate session: testurl@conference.meet-qa.example.com/8d0cd5e4, reason: expired, send terminate: true
Jicofo 2021-01-08 12:52:06.341 WARNING: [123] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No sources or groups to be removed from: testurl@conference.meet-qa.example.com/8d0cd5e4
Jicofo 2021-01-08 12:52:06.342 INFO: [123] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=39533 octo_enabled= false: [[null]]
Jicofo 2021-01-08 12:52:06.342 INFO: [123] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Expiring channels for: testurl@conference.meet-qa.example.com/8d0cd5e4 on: Bridge[jid=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370, relayId=null, region=null, stress=0.00]

jibri.log

cat /var/log/jitsi/jibri/log.0.txt
2021-01-08 12:39:30.439 INFO: [1] org.jitsi.jibri.Main.handleCommandLineArgs() Jibri run with args [--config, /etc/jitsi/jibri/config.json]
2021-01-08 12:39:31.023 INFO: [1] org.jitsi.jibri.Main.setupLegacyConfig() Checking legacy config file /etc/jitsi/jibri/config.json
2021-01-08 12:39:31.023 INFO: [1] org.jitsi.jibri.Main.setupLegacyConfig() Legacy config file /etc/jitsi/jibri/config.json doesn't exist
2021-01-08 12:39:34.445 INFO: [1] org.jitsi.jibri.webhooks.v1.JwtInfo.Companion.fromConfig() got jwtConfig: {}
2021-01-08 12:39:34.446 INFO: [1] org.jitsi.jibri.webhooks.v1.JwtInfo.Companion.fromConfig() Unable to create JwtInfo: com.typesafe.config.ConfigException$Missing: reference.conf @ jar:file:/opt/jitsi/jibri/jibri.jar!/reference.conf: 52: No configuration setting found for key 'signing-key-path'
2021-01-08 12:39:35.017 INFO: [1] org.jitsi.jibri.Main.main() Using port 3333 for internal HTTP API
2021-01-08 12:39:35.175 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:39:37.141 INFO: [1] org.jitsi.jibri.api.xmpp.XmppApi.updatePresence() Jibri reports its status is now JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), publishing presence to connections
2021-01-08 12:39:37.154 INFO: [1] org.jitsi.jibri.api.xmpp.XmppApi.start() Connecting to xmpp environment on meet-qa.example.com with config XmppEnvironmentConfig(name=Jitsi, xmppServerHosts=[meet-qa.example.com], xmppDomain=meet-qa.example.com, controlLogin=XmppCredentials(domain=auth.meet-qa.example.com, username=jibri, password=f5xPcxjY2YFGuy5rPKFsKUS), controlMuc=XmppMuc(domain=internal.auth.meet-qa.example.com, roomName=JibriBrewery, nickname=jibri-ip-10-11-1-155), sipControlMuc=null, callLogin=XmppCredentials(domain=recorder.meet-qa.example.com, username=recorder, password=PAfj5v7XmbMYUjtm858fmRvY), stripFromRoomDomain=conference., usageTimeoutMins=60, trustAllXmppCerts=true)
2021-01-08 12:39:37.155 INFO: [1] org.jitsi.jibri.api.xmpp.XmppApi.start() The trustAllXmppCerts config is enabled for this domain, all XMPP server provided certificates will be accepted
2021-01-08 12:39:37.201 INFO: [1] org.jitsi.jibri.Main.main() Using port 2222 for HTTP API
2021-01-08 12:39:37.203 WARNING: [25] org.jitsi.xmpp.mucclient.MucClient.log() Disabling certificate verification!
2021-01-08 12:39:37.733 INFO: [25] org.jitsi.xmpp.mucclient.MucClient.log() Connected.
2021-01-08 12:39:37.733 INFO: [25] org.jitsi.xmpp.mucclient.MucClient.log() Logging in.
2021-01-08 12:39:37.865 INFO: [25] org.jitsi.xmpp.mucclient.MucClient.log() Joined MUC: jibribrewery@internal.auth.meet-qa.example.com
2021-01-08 12:40:01.266 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:40:01.267 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-08 12:40:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:40:37.118 INFO: [39] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/qTKPxvpd' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vcVRLUHh2cGQAQldEb2otNDc0NzE4AJz5+iJgn/5LcFurzsB6WcY=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='testurl@conference.meet-qa.example.com' session_id='dmtbpethfiealhik' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meet-qa.example.com hostname=meet-qa.example.com]
2021-01-08 12:40:37.119 INFO: [39] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-08 12:40:37.190 INFO: [39] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=testurl, urlParams=[])
2021-01-08 12:40:37.191 INFO: [39] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=testurl, urlParams=[])), sessionId=dmtbpethfiealhik, callLoginParams=XmppCredentials(domain=recorder.meet-qa.example.com, username=recorder, password=PAfj5v7XmbMYUjtm858fmRvY))
2021-01-08 12:40:52.111 INFO: [52] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/qTKPxvpd' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vcVRLUHh2cGQAQldEb2otNDc0NzMwAJz5+iJgn/5LcFurzsB6WcY=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='testurl@conference.meet-qa.example.com' session_id='dmtbpethfiealhik' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meet-qa.example.com hostname=meet-qa.example.com]
2021-01-08 12:40:52.111 INFO: [52] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-08 12:40:52.117 INFO: [52] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=testurl, urlParams=[])
2021-01-08 12:41:01.430 FINE: [53] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:41:01.433 FINE: [53] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-08 12:41:07.113 INFO: [54] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/qTKPxvpd' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vcVRLUHh2cGQAQldEb2otNDc0NzM4AJz5+iJgn/5LcFurzsB6WcY=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='testurl@conference.meet-qa.example.com' session_id='dmtbpethfiealhik' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meet-qa.example.com hostname=meet-qa.example.com]
2021-01-08 12:41:07.114 INFO: [54] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-08 12:41:07.124 INFO: [54] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=testurl, urlParams=[])
2021-01-08 12:41:09.657 INFO: [39] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS
2021-01-08 12:41:09.688 FINE: [39] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.<init>() Detected os as OS: LINUX
2021-01-08 12:41:09.698 INFO: [39] org.jitsi.jibri.service.impl.FileRecordingJibriService.<init>() Writing recording to /recordings/dmtbpethfiealhik, finalize script path /etc/jitsi/jibri/final.sh
2021-01-08 12:41:09.708 FINE: [39] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:recording
2021-01-08 12:41:09.709 INFO: [39] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY
2021-01-08 12:41:09.710 FINE: [39] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:41:09.710 INFO: [39] 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-08 12:41:09.712 INFO: [39] org.jitsi.jibri.JibriManager.startService() This service will have a usage timeout of 60 minute(s)
2021-01-08 12:41:09.716 INFO: [39] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending 'pending' response to start IQ
2021-01-08 12:41:09.717 INFO: [54] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-08 12:41:09.717 FINE: [54] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-08 12:41:09.718 SEVERE: [54] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Jibri is currently busy, cannot service this request
2021-01-08 12:41:09.719 INFO: [52] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-08 12:41:09.719 FINE: [52] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-08 12:41:09.719 SEVERE: [52] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Jibri is currently busy, cannot service this request
2021-01-08 12:41:13.523 FINE: [59] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url https://meet-qa.example.com/testurl#config.iAmRecorder=true&config.externalConnectUrl=null&config.startWithAudioMuted=true&config.startWithVideoMuted=true&interfaceConfig.APP_NAME="Jibri"&config.analytics.disabled=true&config.p2p.enabled=false&config.prejoinPageEnabled=false&config.requireDisplayName=false
2021-01-08 12:41:14.240 FINE: [59] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-01-08 12:41:14.749 FINE: [59] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-01-08 12:41:15.373 INFO: [59] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1191 milliseconds for call page to load
2021-01-08 12:41:15.374 INFO: [59] org.jitsi.jibri.selenium.JibriSelenium.<init>() Starting empty call check with a timeout of PT30S
2021-01-08 12:41:15.415 INFO: [59] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running
2021-01-08 12:41:15.416 INFO: [59] org.jitsi.jibri.service.impl.FileRecordingJibriService.invoke() Selenium joined the call, starting the capturer
2021-01-08 12:41:15.758 INFO: [59] 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: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 -f mp4 /recordings/dmtbpethfiealhik/testurl_2021-01-08-12-41-09.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: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, -f, mp4, /recordings/dmtbpethfiealhik/testurl_2021-01-08-12-41-09.mp4])
2021-01-08 12:41:20.838 FINE: [16] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
2021-01-08 12:41:22.838 FINE: [16] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
2021-01-08 12:41:24.589 INFO: [62] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running
2021-01-08 12:41:24.590 INFO: [62] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Starting up to Running
2021-01-08 12:41:24.591 INFO: [62] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq <iq to='jibribrewery@internal.auth.meet-qa.example.com/focus' id='zyNQP-28' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' status='on'/></iq>
2021-01-08 12:41:30.454 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, num participants: 1, numMutedParticipants: 1, numJigasis: 0, all clients muted? true
2021-01-08 12:41:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:41:45.417 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:42:00.421 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:42:01.812 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:42:01.812 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-08 12:42:15.422 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:42:30.417 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:42:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:42:45.417 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:43:00.421 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:43:01.400 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:43:01.401 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-08 12:43:15.427 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:43:30.418 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:43:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:43:45.422 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:44:00.419 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:44:02.009 FINE: [53] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:44:02.010 FINE: [53] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-08 12:44:15.419 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:44:30.419 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:44:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:44:45.415 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:45:00.417 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:45:01.575 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:45:01.575 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-08 12:45:15.414 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:45:30.417 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:45:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:45:45.415 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:46:00.411 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:46:01.161 FINE: [53] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:46:01.161 FINE: [53] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-08 12:46:15.412 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:46:30.417 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:46:35.001 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-08 12:46:45.420 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:47:00.428 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-08 12:47:01.711 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-08 12:47:01.711 FINE: [41] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))

I have gone through related issues on the community posts:

I have tested with correcting permissions, but no luck on that one too.
Please help.

What Jibri version are you using?

jibri: 8.0-61-g99288dc-1
jicofo: 1.0-644-1

@damencho Can you please help with this?

The error you’re seeing happens when Jicofo times out waiting for a response from Jibri. There was a bug where we were taking longer than we needed that would cause this problem, but the Jibri version you’re using already has that fix. Are you seeing the issue consistently?

I do see you are also hitting this situation where a request comes in right after and Jibri returns a busy as well…I just fixed a bug in Jicofo around that, but it looked slightly different than what your logs show here I think.

Yeah. I still have this issue.

I have 2 normal servers (not autoscaled) which are working fine. I use the AMI from one of those servers for autoscaling.

On booting up, I have a user data scripts which will replace the nickname on the conf file and restart jibri-xorg, jibri-icewm and jibri services.

#!/bin/bash -xe
CONF_FILE="/etc/jitsi/jibri/jibri.conf"
HOSTNAME=`hostname`
sed -i  "s/nickname.*/nickname \= \"jibri-$HOSTNAME\"/g" $CONF_FILE
systemctl restart jibri-xorg.service
systemctl restart jibri-icewm.service
systemctl restart jibri

Do I have to update the jicofo version for the bug fix?
If yes, please let me know a safe way to do that.

Thanks in advance @bbaldino

Can you attach another set of Jicofo/Jibri logs from when it happens? I want to see if that busy case is happening every time. And using latest stable of both, if you’re not, would be good.

Jicofo log for autoscaled jibri instance connecting to jicofo:

Jicofo 2021-01-15 05:44:44.784 INFO: [31] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:44:44.785 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='idle'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-15 05:44:44.785 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 available: true

Jicofo log when Starting recording:

Jicofo 2021-01-15 05:49:59.685 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:49:59.685 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 for stream ID: null in room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:14.685 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2021-01-15 05:50:14.686 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:589)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:370)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:178)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:271)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-15 05:50:14.686 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 had a transient error, moving to the backof the queue
Jicofo 2021-01-15 05:50:14.686 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:14.686 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 went offline
Jicofo 2021-01-15 05:50:14.695 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:14.696 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:14.696 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 for stream ID: null in room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:14.696 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Rescheduling pending timeout task for room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:29.697 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2021-01-15 05:50:29.697 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:589)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:370)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:378)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:178)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:271)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-15 05:50:29.697 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 had a transient error, moving to the backof the queue
Jicofo 2021-01-15 05:50:29.697 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:29.698 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 went offline
Jicofo 2021-01-15 05:50:29.698 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:29.698 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:29.699 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 for stream ID: null in room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:29.699 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Rescheduling pending timeout task for room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:33.043 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='busy'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-15 05:50:33.043 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 available: false
Jicofo 2021-01-15 05:50:33.105 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected status received in response to the start IQ: <iq to='focus@auth.meet-qa.example.com/focus2447728657146761' from='jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13' id='2hn7p-191944' type='result'><jibri xmlns='http://jitsi.org/protocol/jibri' status='off' failure_reason='busy' should_retry='true'/></iq>
Jicofo 2021-01-15 05:50:33.105 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:602)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:370)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:378)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:378)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:178)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:271)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-15 05:50:33.105 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 had a transient error, moving to the backof the queue
Jicofo 2021-01-15 05:50:33.105 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:33.105 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 went offline
Jicofo 2021-01-15 05:50:33.105 INFO: [756] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:33.105 SEVERE: [756] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unable to find an available Jibri, can't start
Jicofo 2021-01-15 05:50:33.106 SEVERE: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri went offline: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 for room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Got Jibri status update: Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13 has status off and failure reason error, current Jibri jid is jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-13
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri is no longer pending, cancelling pending timeout task
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri failed, trying to fall back to another Jibri
Jicofo 2021-01-15 05:50:33.106 SEVERE: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unable to find an available Jibri, can't start
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to fall back to another Jibri, this session has now failed: org.jitsi.jicofo.recording.jibri.JibriSession$StartException: All Jibri instances are busy
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: All Jibri instances are busy
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:359)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:335)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:649)
	at org.jitsi.jicofo.recording.jibri.JibriSession.handleJibriStatusUpdate(JibriSession.java:719)
	at org.jitsi.jicofo.recording.jibri.JibriSession.access$600(JibriSession.java:49)
	at org.jitsi.jicofo.recording.jibri.JibriSession$JibriEventHandler.handleEvent(JibriSession.java:827)
	at org.jitsi.eventadmin.EventAdminImpl.callEventHandler(EventAdminImpl.java:209)
	at org.jitsi.eventadmin.EventAdminImpl.access$000(EventAdminImpl.java:35)
	at org.jitsi.eventadmin.EventAdminImpl$1.run(EventAdminImpl.java:189)
	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:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Got jibri status off and failure error
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Publishing new jibri-recording-status: <jibri-recording-status xmlns='http://jitsi.org/protocol/jibri' status='off' failure_reason='error' session_id='sazrtmtaxfiwokbb' recording_mode='file'/> in: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:33.106 INFO: [51] org.jitsi.jicofo.recording.jibri.JibriSession.log() Cleaning up current JibriSession
Jicofo 2021-01-15 05:50:33.112 INFO: [756] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Failed to start a Jibri session, all Jibris were busy
Jicofo 2021-01-15 05:50:38.303 INFO: [76] org.jitsi.jicofo.xmpp.FocusComponent.log() Focus request for room: test@conference.meet-qa.example.com
Jicofo 2021-01-15 05:50:38.428 INFO: [31] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@5628c9ec member=ChatMember[test@conference.meet-qa.example.com/e73d7089, jid: null]@125314849]
Jicofo 2021-01-15 05:50:38.428 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member test@conference.meet-qa.example.com/e73d7089 joined.
Jicofo 2021-01-15 05:50:38.429 INFO: [31] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370, relayId=null, region=null, stress=0.00] with stress=0.0 for participantRegion=null
Jicofo 2021-01-15 05:50:38.429 INFO: [31] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl@500cf4c
Jicofo 2021-01-15 05:50:38.429 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= test@conference.meet-qa.example.com/e73d7089, bridge=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370
Jicofo 2021-01-15 05:50:38.429 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=3165 octo_enabled= false: [[null, null]]
Jicofo 2021-01-15 05:50:38.429 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= test@conference.meet-qa.example.com/78b23440, bridge=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370
Jicofo 2021-01-15 05:50:38.429 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=3165 octo_enabled= false: [[null, null, null]]
Jicofo 2021-01-15 05:50:38.430 INFO: [761] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for test@conference.meet-qa.example.com/e73d7089
Jicofo 2021-01-15 05:50:38.430 INFO: [761] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for test@conference.meet-qa.example.com/e73d7089 in 0
Jicofo 2021-01-15 05:50:38.431 INFO: [761] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370 to allocate channels for: Participant[test@conference.meet-qa.example.com/e73d7089]@674080409
Jicofo 2021-01-15 05:50:38.431 INFO: [762] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for test@conference.meet-qa.example.com/78b23440
Jicofo 2021-01-15 05:50:38.432 INFO: [762] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for test@conference.meet-qa.example.com/78b23440 in 0
Jicofo 2021-01-15 05:50:38.432 INFO: [762] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370 to allocate channels for: Participant[test@conference.meet-qa.example.com/78b23440]@1733684231
Jicofo 2021-01-15 05:50:38.444 INFO: [761] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: test@conference.meet-qa.example.com/e73d7089
Jicofo 2021-01-15 05:50:38.489 INFO: [762] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: test@conference.meet-qa.example.com/78b23440
Jicofo 2021-01-15 05:50:39.273 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: test@conference.meet-qa.example.com/e73d7089
Jicofo 2021-01-15 05:50:39.273 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from test@conference.meet-qa.example.com/e73d7089 with accepted sources:Sources{ }@1756997547
Jicofo 2021-01-15 05:50:39.274 WARNING: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No jingle session yet for test@conference.meet-qa.example.com/78b23440
Jicofo 2021-01-15 05:50:42.663 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: test@conference.meet-qa.example.com/78b23440
Jicofo 2021-01-15 05:50:42.664 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from test@conference.meet-qa.example.com/78b23440 with accepted sources:Sources{ }@1807777631
Jicofo 2021-01-15 05:50:42.664 INFO: [31] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Notify add SSRC test@conference.meet-qa.example.com/e73d7089 SID: 9n7qf57qs1c2p Sources{ }@186041348 source_Groups{ }@1402193096

Jibri log when Starting recording:

root@ip-10-11-1-13:/home/ubuntu# tail -f /var/log/jitsi/jibri/log.0.txt
2021-01-15 05:46:41.681 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-15 05:47:01.672 FINE: [42] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-15 05:47:01.672 FINE: [42] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-15 05:47:41.681 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-15 05:48:01.173 FINE: [44] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-15 05:48:01.174 FINE: [44] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-15 05:48:41.681 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-15 05:49:01.760 FINE: [44] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-15 05:49:01.761 FINE: [44] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-15 05:49:41.681 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-15 05:49:59.687 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/ZEwZK_kl' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vWkV3Wktfa2wAMmhuN3AtMTkxOTI0AEX3moJKBhdpIxNbLFHflrw=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='sazrtmtaxfiwokbb' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-15 05:49:59.688 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-15 05:49:59.761 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-15 05:49:59.762 INFO: [53] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])), sessionId=sazrtmtaxfiwokbb, callLoginParams=XmppCredentials(domain=recorder.meet-qa.example.com, username=recorder, password=password))
2021-01-15 05:50:01.332 FINE: [42] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-15 05:50:01.332 FINE: [42] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-15 05:50:14.695 INFO: [63] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/ZEwZK_kl' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vWkV3Wktfa2wAMmhuN3AtMTkxOTMyAEX3moJKBhdpIxNbLFHflrw=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='sazrtmtaxfiwokbb' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-15 05:50:14.695 INFO: [63] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-15 05:50:14.701 INFO: [63] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-15 05:50:29.698 INFO: [64] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/ZEwZK_kl' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vWkV3Wktfa2wAMmhuN3AtMTkxOTQ0AEX3moJKBhdpIxNbLFHflrw=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='sazrtmtaxfiwokbb' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-15 05:50:29.698 INFO: [64] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-15 05:50:29.703 INFO: [64] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-15 05:50:32.947 INFO: [53] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS
2021-01-15 05:50:33.008 FINE: [53] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.<init>() Detected os as OS: LINUX
2021-01-15 05:50:33.021 INFO: [53] org.jitsi.jibri.service.impl.FileRecordingJibriService.<init>() Writing recording to /recordings/sazrtmtaxfiwokbb, finalize script path /etc/jitsi/jibri/final.sh
2021-01-15 05:50:33.033 FINE: [53] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:recording
2021-01-15 05:50:33.035 INFO: [53] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY
2021-01-15 05:50:33.035 FINE: [53] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-15 05:50:33.036 INFO: [53] 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-15 05:50:33.044 INFO: [53] org.jitsi.jibri.JibriManager.startService() This service will have a usage timeout of 60 minute(s)
2021-01-15 05:50:33.050 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending 'pending' response to start IQ
2021-01-15 05:50:33.056 INFO: [64] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-15 05:50:33.057 FINE: [64] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-15 05:50:33.057 INFO: [63] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-15 05:50:33.058 FINE: [63] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-15 05:50:33.059 SEVERE: [64] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Jibri is currently busy, cannot service this request
2021-01-15 05:50:33.060 SEVERE: [63] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Jibri is currently busy, cannot service this request
2021-01-15 05:50:36.525 FINE: [69] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url https://meet-qa.example.com/test#config.iAmRecorder=true&config.externalConnectUrl=null&config.startWithAudioMuted=true&config.startWithVideoMuted=true&interfaceConfig.APP_NAME="Jibri"&config.analytics.disabled=true&config.p2p.enabled=false&config.prejoinPageEnabled=false&config.requireDisplayName=false
2021-01-15 05:50:37.422 FINE: [69] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-01-15 05:50:37.932 FINE: [69] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-01-15 05:50:38.546 INFO: [69] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1238 milliseconds for call page to load
2021-01-15 05:50:38.550 INFO: [69] org.jitsi.jibri.selenium.JibriSelenium.<init>() Starting empty call check with a timeout of PT30S
2021-01-15 05:50:38.584 INFO: [69] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running
2021-01-15 05:50:38.586 INFO: [69] org.jitsi.jibri.service.impl.FileRecordingJibriService.invoke() Selenium joined the call, starting the capturer
2021-01-15 05:50:38.635 INFO: [69] 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: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 -f mp4 /recordings/sazrtmtaxfiwokbb/test_2021-01-15-05-50-33.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: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, -f, mp4, /recordings/sazrtmtaxfiwokbb/test_2021-01-15-05-50-33.mp4])
2021-01-15 05:50:41.681 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-15 05:50:43.743 FINE: [16] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
2021-01-15 05:50:47.090 INFO: [72] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running
2021-01-15 05:50:47.091 INFO: [72] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Starting up to Running
2021-01-15 05:50:47.092 INFO: [72] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq <iq to='jibribrewery@internal.auth.meet-qa.example.com/focus' id='IHOTz-46' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' status='on'/></iq>
2021-01-15 05:50:53.650 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, num participants: 1, numMutedParticipants: 1, numJigasis: 0, all clients muted? true
2021-01-15 05:51:01.868 FINE: [42] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-15 05:51:01.869 FINE: [42] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-15 05:51:08.603 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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
2021-01-15 05:51:23.600 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() 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

A strange thing is that after some time the recording is actually started in jibri, but this is not getting shown in the call UI. Instead, it is showing “All recorders are currently busy”.

That is the Jicofo bug that is fixed. You need to update Jicofo (yours is very old)

Can you share how to do that safely ?

Hi @bbaldino ,

As you said I have upgraded the packages I’m still getting the same error.

Jicofo:

Jicofo 2021-01-20 07:11:41.592 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:11:41.592 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 for stream ID: null in room: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:11:56.594 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2021-01-20 07:11:56.595 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException$UnexpectedResponse: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException$UnexpectedResponse: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:564)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:349)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:173)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:249)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-20 07:11:56.596 INFO: [32] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 had a transient error, moving to the backof the queue
Jicofo 2021-01-20 07:11:56.596 INFO: [32] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:11:56.596 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 went offline
Jicofo 2021-01-20 07:11:56.597 WARNING: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri went offline: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 for room: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:11:56.597 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Got Jibri status update: Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 has status off and failure reason error, current Jibri jid is jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:11:56.598 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri is no longer pending, cancelling pending timeout task
Jicofo 2021-01-20 07:11:56.598 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri failed, trying to fall back to another Jibri
Jicofo 2021-01-20 07:11:56.598 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unable to find an available Jibri, can't start
Jicofo 2021-01-20 07:11:56.599 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to fall back to another Jibri, this session has now failed: org.jitsi.jicofo.recording.jibri.JibriSession$StartException$NotAvailable: No Jibris available
org.jitsi.jicofo.recording.jibri.JibriSession$StartException$NotAvailable: No Jibris available
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:342)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:625)
	at org.jitsi.jicofo.recording.jibri.JibriSession.handleJibriStatusUpdate(JibriSession.java:695)
	at org.jitsi.jicofo.recording.jibri.JibriSession.access$900(JibriSession.java:47)
	at org.jitsi.jicofo.recording.jibri.JibriSession$JibriDetectorEventHandler.instanceOffline(JibriSession.java:910)
	at org.jitsi.jicofo.recording.jibri.JibriDetector.lambda$notifyInstanceOffline$2(JibriDetector.java:126)
	at org.jitsi.utils.event.EventEmitter.fireEvent(EventEmitter.kt:25)
	at org.jitsi.jicofo.recording.jibri.JibriDetector.notifyInstanceOffline(JibriDetector.java:124)
	at org.jitsi.jicofo.xmpp.BaseBrewery.removeInstance(BaseBrewery.java:409)
	at org.jitsi.jicofo.xmpp.BaseBrewery.memberHadTransientError(BaseBrewery.java:280)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:356)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:173)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:249)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-20 07:11:56.600 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Got jibri status off and failure error
Jicofo 2021-01-20 07:11:56.601 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Publishing new jibri-recording-status: <jibri-recording-status xmlns='http://jitsi.org/protocol/jibri' status='off' failure_reason='error' session_id='xbprwmftlziyvujl' recording_mode='file'/> in: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:11:56.602 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Cleaning up current JibriSession
Jicofo 2021-01-20 07:11:56.602 INFO: [32] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:11:56.602 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:11:56.604 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 for stream ID: null in room: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:12:11.607 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2021-01-20 07:12:11.608 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException$UnexpectedResponse: Unexpected response
org.jitsi.jicofo.recording.jibri.JibriSession$StartException$UnexpectedResponse: Unexpected response
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:564)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:349)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:625)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:360)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:173)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:249)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-20 07:12:11.608 INFO: [32] org.jitsi.jicofo.xmpp.BaseBrewery.log() Jid member jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 had a transient error, moving to the backof the queue
Jicofo 2021-01-20 07:12:11.609 INFO: [32] org.jitsi.jicofo.xmpp.BaseBrewery.log() Removed brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:12:11.609 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 went offline
Jicofo 2021-01-20 07:12:11.609 INFO: [32] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:12:11.609 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76
Jicofo 2021-01-20 07:12:11.610 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 for stream ID: null in room: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:12:11.610 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Rescheduling pending timeout task for room: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:12:16.062 INFO: [31] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 status <jibri-status xmlns='http://jitsi.org/protocol/jibri'><busy-status xmlns='http://jitsi.org/protocol/jibri' status='busy'/><health-status xmlns='http://jitsi.org/protocol/health' status='healthy'/></jibri-status>
Jicofo 2021-01-20 07:12:16.125 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Jibri jibribrewery@internal.auth.meet-qa.example.com/jibri-ip-10-11-1-76 was busy
Jicofo 2021-01-20 07:12:16.126 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Failed to send start Jibri IQ: org.jitsi.jicofo.recording.jibri.JibriSession$StartException$OneBusy: This Jibri instance was busy
org.jitsi.jicofo.recording.jibri.JibriSession$StartException$OneBusy: This Jibri instance was busy
	at org.jitsi.jicofo.recording.jibri.JibriSession.sendJibriStartIq(JibriSession.java:571)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:349)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:625)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:360)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriSession.retryRequestWithAnotherJibri(JibriSession.java:625)
	at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:360)
	at org.jitsi.jicofo.recording.jibri.JibriSession.start(JibriSession.java:315)
	at org.jitsi.jicofo.recording.jibri.JibriRecorder.handleStartRequest(JibriRecorder.java:173)
	at org.jitsi.jicofo.recording.jibri.CommonJibriStuff.handleIQRequest(CommonJibriStuff.java:249)
	at org.jitsi.jicofo.recording.jibri.OperationSetJibri.handleIQRequest(OperationSetJibri.java:98)
	at org.jivesoftware.smack.AbstractXMPPConnection$4.run(AbstractXMPPConnection.java:1188)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	at java.base/java.lang.Thread.run(Thread.java:832)
Jicofo 2021-01-20 07:12:16.126 SEVERE: [32] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unable to find an available Jibri, can't start
Jicofo 2021-01-20 07:12:16.127 INFO: [32] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Failed to start a Jibri session, all Jibris were busy
Jicofo 2021-01-20 07:12:22.401 INFO: [66] org.jitsi.jicofo.xmpp.IqHandler.log() Logout IQ received: <iq to='focus.meet-qa.example.com' from='recorder@recorder.meet-qa.example.com/OpihWzj-' id='ba521358-5c5c-41c2-87e2-088780a913eb:sendIQ' type='set'><conference xmlns='http://jitsi.org/protocol/focus' room='test@conference.meet-qa.example.com' machine-uid='230b2214264bf0137eedbaf7edce016a'><property xmlns='http://jitsi.org/protocol/focus' name='disableRtx' value='false'/></conference></iq>
Jicofo 2021-01-20 07:12:22.402 INFO: [66] org.jitsi.jicofo.xmpp.ConferenceIqHandler.log() Focus request for room: test@conference.meet-qa.example.com
Jicofo 2021-01-20 07:12:22.543 INFO: [31] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@5599e4b6 member=ChatMember[test@conference.meet-qa.example.com/8378ca20, jid: null]@480028993]
Jicofo 2021-01-20 07:12:22.544 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member test@conference.meet-qa.example.com/8378ca20 joined.
Jicofo 2021-01-20 07:12:22.554 INFO: [31] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370, relayId=null, region=null, stress=0.00] with reported stress=0.0 for participantRegion=null using strategy SingleBridgeSelectionStrategy
Jicofo 2021-01-20 07:12:22.562 INFO: [31] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl@372611c3
Jicofo 2021-01-20 07:12:22.564 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= test@conference.meet-qa.example.com/8378ca20, bridge=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370
Jicofo 2021-01-20 07:12:22.564 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=39100: [[null, null]]
Jicofo 2021-01-20 07:12:22.567 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= test@conference.meet-qa.example.com/d88ed807, bridge=jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370
Jicofo 2021-01-20 07:12:22.568 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=39100: [[null, null, null]]
Jicofo 2021-01-20 07:12:22.570 INFO: [120] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for test@conference.meet-qa.example.com/8378ca20
Jicofo 2021-01-20 07:12:22.578 INFO: [121] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for test@conference.meet-qa.example.com/d88ed807
Jicofo 2021-01-20 07:12:22.933 INFO: [120] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for test@conference.meet-qa.example.com/8378ca20 in 363
Jicofo 2021-01-20 07:12:22.954 INFO: [120] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370 to allocate channels for: Participant[test@conference.meet-qa.example.com/8378ca20]@1395320706
Jicofo 2021-01-20 07:12:23.953 INFO: [121] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for test@conference.meet-qa.example.com/d88ed807 in 1375
Jicofo 2021-01-20 07:12:23.953 INFO: [121] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery@internal.auth.meet-qa.example.com/fcb81373-9815-4e43-b8cb-911e740fd370 to allocate channels for: Participant[test@conference.meet-qa.example.com/d88ed807]@516223297
Jicofo 2021-01-20 07:12:24.485 INFO: [120] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: test@conference.meet-qa.example.com/8378ca20
Jicofo 2021-01-20 07:12:24.519 INFO: [121] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: test@conference.meet-qa.example.com/d88ed807
Jicofo 2021-01-20 07:12:25.115 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: test@conference.meet-qa.example.com/8378ca20
Jicofo 2021-01-20 07:12:25.125 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from test@conference.meet-qa.example.com/8378ca20 with accepted sources:Sources{ }@383904496
Jicofo 2021-01-20 07:12:25.134 WARNING: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No jingle session yet for test@conference.meet-qa.example.com/d88ed807
Jicofo 2021-01-20 07:12:27.018 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: test@conference.meet-qa.example.com/d88ed807
Jicofo 2021-01-20 07:12:27.021 INFO: [31] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from test@conference.meet-qa.example.com/d88ed807 with accepted sources:Sources{ audio: [ssrc=3372232330 ] }@1542886505

Jibri:

2021-01-20 07:11:41.627 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/Nm3hCSV7' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vTm0zaENTVjcAUVViVWMtMjExAMZhyYvuVXgsvZ3ypYAK2U0=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='xbprwmftlziyvujl' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-20 07:11:41.628 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-20 07:11:41.718 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-20 07:11:41.720 INFO: [40] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])), sessionId=xbprwmftlziyvujl, callLoginParams=XmppCredentials(domain=recorder.meet-qa.example.com, username=recorder, password=PAfj5v7XmbMYUjtm858fmRvY))
2021-01-20 07:11:41.734 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.call-status-checks.default-call-empty-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:11:41.741 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.call-status-checks.default-call-empty-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:11:41.763 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.chrome.flags' from source 'config' as type kotlin.collections.List<kotlin.String>
2021-01-20 07:11:41.765 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.chrome.flags' from source 'config' as type kotlin.collections.List<kotlin.String>
2021-01-20 07:11:48.742 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-20 07:11:56.638 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/Nm3hCSV7' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vTm0zaENTVjcAUVViVWMtMjI1AMZhyYvuVXgsvZ3ypYAK2U0=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='xbprwmftlziyvujl' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-20 07:11:56.646 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-20 07:11:56.657 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-20 07:12:01.075 FINE: [54] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-20 07:12:01.076 FINE: [54] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)
2021-01-20 07:12:11.643 INFO: [55] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/Nm3hCSV7' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vTm0zaENTVjcAUVViVWMtMjMzAMZhyYvuVXgsvZ3ypYAK2U0=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='xbprwmftlziyvujl' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-20 07:12:11.643 INFO: [55] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-20 07:12:11.648 INFO: [55] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-20 07:12:15.975 INFO: [40] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS
2021-01-20 07:12:16.061 FINE: [40] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.<init>() Detected os as OS: LINUX
2021-01-20 07:12:16.069 FINE: [40] org.jitsi.jibri.config.debug() FallbackSupplier: checking for value via suppliers:
  LambdaSupplier: 'JibriConfig::recordingDirectory'
  ConfigSourceSupplier: key: 'jibri.recording.recordings-directory', type: 'kotlin.String', source: 'config'
2021-01-20 07:12:16.071 FINE: [40] org.jitsi.jibri.config.debug() LambdaSupplier: Trying to retrieve value via JibriConfig::recordingDirectory
2021-01-20 07:12:16.072 FINE: [40] org.jitsi.jibri.config.debug() FallbackSupplier: failed to find value via LambdaSupplier: 'JibriConfig::recordingDirectory': org.jitsi.metaconfig.ConfigException$UnableToRetrieve$Error: class kotlin.KotlinNullPointerException
2021-01-20 07:12:16.072 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.recording.recordings-directory' from source 'config' as type kotlin.String
2021-01-20 07:12:16.073 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.recording.recordings-directory' from source 'config' as type kotlin.String
2021-01-20 07:12:16.073 FINE: [40] org.jitsi.jibri.config.debug() FallbackSupplier: value found via ConfigSourceSupplier: key: 'jibri.recording.recordings-directory', type: 'kotlin.String', source: 'config'
2021-01-20 07:12:16.074 FINE: [40] org.jitsi.jibri.config.debug() FallbackSupplier: checking for value via suppliers:
  LambdaSupplier: 'JibriConfig::finalizeRecordingScriptPath'
  ConfigSourceSupplier: key: 'jibri.recording.finalize-script', type: 'kotlin.String', source: 'config'
2021-01-20 07:12:16.074 FINE: [40] org.jitsi.jibri.config.debug() LambdaSupplier: Trying to retrieve value via JibriConfig::finalizeRecordingScriptPath
2021-01-20 07:12:16.075 FINE: [40] org.jitsi.jibri.config.debug() FallbackSupplier: failed to find value via LambdaSupplier: 'JibriConfig::finalizeRecordingScriptPath': org.jitsi.metaconfig.ConfigException$UnableToRetrieve$Error: class kotlin.KotlinNullPointerException
2021-01-20 07:12:16.075 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.recording.finalize-script' from source 'config' as type kotlin.String
2021-01-20 07:12:16.076 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.recording.finalize-script' from source 'config' as type kotlin.String
2021-01-20 07:12:16.076 FINE: [40] org.jitsi.jibri.config.debug() FallbackSupplier: value found via ConfigSourceSupplier: key: 'jibri.recording.finalize-script', type: 'kotlin.String', source: 'config'
2021-01-20 07:12:16.076 INFO: [40] org.jitsi.jibri.service.impl.FileRecordingJibriService.<init>() Writing recording to /recordings/xbprwmftlziyvujl, finalize script path /etc/jitsi/jibri/final.sh
2021-01-20 07:12:16.086 FINE: [40] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:recording
2021-01-20 07:12:16.087 INFO: [40] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY
2021-01-20 07:12:16.088 FINE: [40] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-20 07:12:16.088 INFO: [40] 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-20 07:12:16.090 INFO: [40] org.jitsi.jibri.JibriManager.startService() This service will have a usage timeout of 60 minute(s)
2021-01-20 07:12:16.093 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending 'pending' response to start IQ
2021-01-20 07:12:16.111 INFO: [55] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-20 07:12:16.112 FINE: [55] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-20 07:12:16.113 SEVERE: [55] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Jibri is currently busy, cannot service this request
2021-01-20 07:12:16.113 INFO: [53] org.jitsi.jibri.JibriManager.throwIfBusy() Jibri is busy, can't start service
2021-01-20 07:12:16.114 FINE: [53] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: busy:recording
2021-01-20 07:12:16.114 SEVERE: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Jibri is currently busy, cannot service this request
2021-01-20 07:12:20.491 FINE: [60] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url https://meet-qa.example.com/test#config.iAmRecorder=true&config.externalConnectUrl=null&config.startWithAudioMuted=true&config.startWithVideoMuted=true&interfaceConfig.APP_NAME="Jibri"&config.analytics.disabled=true&config.p2p.enabled=false&config.prejoinPageEnabled=false&config.requireDisplayName=false
2021-01-20 07:12:21.479 FINE: [60] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-01-20 07:12:21.989 FINE: [60] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property 'isJoined' of undefined
2021-01-20 07:12:23.020 INFO: [60] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1605 milliseconds for call page to load
2021-01-20 07:12:23.021 INFO: [60] org.jitsi.jibri.selenium.JibriSelenium.<init>() Starting empty call check with a timeout of PT30S
2021-01-20 07:12:23.037 INFO: [60] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running
2021-01-20 07:12:23.039 INFO: [60] org.jitsi.jibri.service.impl.FileRecordingJibriService.invoke() Selenium joined the call, starting the capturer
2021-01-20 07:12:23.079 INFO: [60] 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: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 -f mp4 /recordings/xbprwmftlziyvujl/test_2021-01-20-07-12-16.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: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, -f, mp4, /recordings/xbprwmftlziyvujl/test_2021-01-20-07-12-16.mp4])
2021-01-20 07:12:28.166 FINE: [16] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
2021-01-20 07:12:30.166 FINE: [16] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn't written in 2 seconds, publishing periodic update
2021-01-20 07:12:33.036 INFO: [63] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running
2021-01-20 07:12:33.039 INFO: [63] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Starting up to Running
2021-01-20 07:12:33.045 INFO: [63] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq <iq to='jibribrewery@internal.auth.meet-qa.example.com/focus' id='4pAaz-28' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' status='on'/></iq>
2021-01-20 07:12:38.228 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:12:38.232 FINE: [16] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.call-status-checks.all-muted-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:12:38.244 FINE: [16] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.call-status-checks.all-muted-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:12:38.246 FINE: [16] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.call-status-checks.no-media-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:12:38.250 FINE: [16] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.call-status-checks.no-media-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:12:48.742 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-20 07:12:53.083 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=34, upload=0}, download=34, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:13:01.211 FINE: [43] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-20 07:13:01.211 FINE: [43] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-20 07:13:08.092 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=34, upload=0}, download=34, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:13:23.072 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=34, upload=0}, download=34, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:13:38.075 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=33, upload=0}, download=33, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:13:48.742 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-20 07:13:53.073 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=40, upload=0}, download=40, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:14:01.935 FINE: [54] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-20 07:14:01.935 FINE: [54] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-20 07:14:08.086 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=34, upload=0}, download=34, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:14:23.075 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=32, upload=0}, download=32, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:14:38.097 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=33, upload=0}, download=33, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:14:48.742 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-20 07:14:53.080 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=35, upload=0}, download=35, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false
2021-01-20 07:15:01.724 FINE: [43] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Got health request
2021-01-20 07:15:01.724 FINE: [43] org.jitsi.jibri.api.http.HttpApi.invokeSuspend() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=Jitsi))
2021-01-20 07:15:08.072 INFO: [16] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=33, upload=0}, download=33, upload=0, video={download=0, upload=0}}, num participants: 1, numMutedParticipants: 0, numJigasis: 0, all clients muted? false

Package versions:

jibri                          8.0-61-g99288dc-1 
jicofo                         1.0-691-hf-1
jitsi-meet                     2.0.5390-2
jitsi-meet-prosody             1.0.4628-1
jitsi-meet-tokens              1.0.4628-1
jitsi-meet-turnserver          1.0.4628-1
jitsi-meet-web                 1.0.4628-1
jitsi-meet-web-config          1.0.4628-1
jitsi-videobridge2             2.1-416-g2f43d1b4-1

So this looks like something is up with your Jibri. It receives a start request, and starts a recording, but then things just stop:

2021-01-20 07:11:41.627 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/Nm3hCSV7' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vTm0zaENTVjcAUVViVWMtMjExAMZhyYvuVXgsvZ3ypYAK2U0=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='xbprwmftlziyvujl' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]
2021-01-20 07:11:41.628 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2021-01-20 07:11:41.718 INFO: [40] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])
2021-01-20 07:11:41.720 INFO: [40] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://meet-qa.example.com, callName=test, urlParams=[])), sessionId=xbprwmftlziyvujl, callLoginParams=XmppCredentials(domain=recorder.meet-qa.example.com, username=recorder, password=PAfj5v7XmbMYUjtm858fmRvY))
2021-01-20 07:11:41.734 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.call-status-checks.default-call-empty-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:11:41.741 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.call-status-checks.default-call-empty-timeout' from source 'config' as type java.time.Duration
2021-01-20 07:11:41.763 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Trying to retrieve key 'jibri.chrome.flags' from source 'config' as type kotlin.collections.List<kotlin.String>
2021-01-20 07:11:41.765 FINE: [40] org.jitsi.jibri.config.debug() ConfigSourceSupplier: Successfully retrieved key 'jibri.chrome.flags' from source 'config' as type kotlin.collections.List<kotlin.String>
2021-01-20 07:11:48.742 FINE: [16] org.jitsi.jibri.webhooks.v1.WebhookClient.invokeSuspend() Updating 0 subscribers of status
2021-01-20 07:11:56.638 INFO: [53] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq <iq to='jibri@auth.meet-qa.example.com/Nm3hCSV7' from='jibribrewery@internal.auth.meet-qa.example.com/focus' id='amlicmlAYXV0aC5tZWV0LXFhLmVuZ2F0aS5jb20vTm0zaENTVjcAUVViVWMtMjI1AMZhyYvuVXgsvZ3ypYAK2U0=' type='set'><jibri xmlns='http://jitsi.org/protocol/jibri' action='start' recording_mode='file' room='test@conference.meet-qa.example.com' session_id='xbprwmftlziyvujl' app_data='{"file_recording_metadata":{"share":true}}'/></iq> from environment [MucClient id=meetserver11.qa.example.local hostname=meetserver11.qa.example.local]

Notice how there is a big jump in time after 07:11:41: it goes to 07:11:48 with a periodic webhook client update and then to 07:11:56 with another request.

Jicofo is complaining because it doesn’t receive any response from Jibri for its request, so the request times out and gives that null result. So Jibri is getting hung up on something, but it’s hard to tell where: it could be something with chromedriver or chrome, I’d make sure those are up-to-date and are compatible versions.

I’m using the following chrome and chrome driver versions:

ChromeDriver 87.0.4280.88
Google Chrome 87.0.4280.88

Do you have any way of ‘watching’ the Jibri machine to see what happens? I’d also try Jibri with those versions on another machine–ideally one you can ‘watch’ to see if that gives you any clues.

I have setup vncserver on the autoscaled jibri instances and connect to them before starting the recording.

On the first attempt, google chrome is taking some time to startup, other than that everything looks good.

I think this is the issue. Is this fixed ?

If this is the issue, some minor hack can help. Autostart chromium or chrome when icewm starts and kill it after some seconds

/home/jibri/.icewm/startup

#!/bin/bash

chromium https://your.jitsi.host &
(sleep 20 && pkill --oldest --signal TERM '(chromium|chrome|google-chrome)' &

set the execute permission

chmod 755 /home/jibri/.icewm/startup
2 Likes

Wow. This worked. You are a lifesaver.
Thanks a lot, @emrah @bbaldino

1 Like

Hm, this is not the failure mode I remembered for a slow chrome start-up though–that’s pretty lousy. I also don’t ever remember chrome taking this long…this was like over 15 seconds? Maybe we’ll need a timeout there.

Yeah. I think icewm on the first startup takes some time to bring up chrome. I think this can be fixed from the code itself by adding a timeout.

or adding an option to bring up a chrome window to do a test-run to make sure jibri is actually healthy.

Sharing the script I’m using on my setup.

#!/bin/bash
/usr/bin/google-chrome https://{{ jitsi_hostname }} &
PID=$!
sleep 10
kill $PID
1 Like