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”.
