Error to start recording, but jibri goes BUSY and DOES record the room (happens only on first record attempt)

Hi all,
I’m facing some trouble with Jibri and AWS

I have my jitsi meet running in AWS EC2 instances (1 jitsi shard, 2 Jvbs and 2 Jibris), it all works just fine.
The problem is that now, due to the high demand, I need to autoscale jibris.

When jitsi tries to use a jibri from one of my autoscale-launched instances (or a manually launched instance with the same AMI), i get an error message at the conference screen, but the jibri goes BUSY and starts recording the room normally( no preparing to record and no REC icon at the browser, just the error to start recording) i can’t make the recording stop from the UI. So, after quitting the room and waiting 30s it stopped itself and the whole video was at my recording folder, it worked.

After this first attempt to record, the same jibri works just fine, it doesn’t throw any errors at jibri or jicofo log, no error at the browser, REC icon appears normally and i can stop recording from the UI.

I’ve tried a lot of things but nothing worked, so @damencho, @bbaldino, @Aaron_K_van_Meerten
do you guys hava a clue about what is causing this problem?

Usefull info:

  • EC2 instance type: t2.medium
  • No Firewall
  • I’m using java 8
  • Ubuntu 18.04
  • i have a service that runs everytime the instance starts, it runs a script that change jibri nickname to the instance current time nanoseconds value (‘date +%N’ command) and restarts the jibri service
  • all instances are in the same VPC and subnet.
  • It happens with every instance launched from my custom AMI(that only contains ubuntu, jibri default install and my service/script)
  • It only happens the first time i try recording, after rebooting the instance, leaving jibri alone for 30s, or doing anything that forces the recording to stop, when i try to record again it works. Same instance, same jibri.

Jicofo Logs:

Jicofo 2020-08-17 21:23:34.780 INFO: [28] org.jitsi.jicofo.xmpp.BaseBrewery.log() Added brewery instance: jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967
Jicofo 2020-08-17 21:23:34.780 INFO: [28] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967 status
Jicofo 2020-08-17 21:23:34.780 INFO: [28] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967 available: true
Jicofo 2020-08-17 21:23:34.992 INFO: [69] org.jitsi.jicofo.xmpp.FocusComponent.log() Focus request for room: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br
Jicofo 2020-08-17 21:23:34.992 INFO: [69] org.jitsi.jicofo.FocusManager.log() Created new focus for palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br(at)auth.xxxxxdomainxxxxx.com.br. Conference count 2,options: channelLastN=-1 enableLipSync=false openSctp=true disableRtx=false
Jicofo 2020-08-17 21:23:34.993 INFO: [69] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Joining the room: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br
Jicofo 2020-08-17 21:23:35.399 INFO: [28] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl(at)2b00df0 member=ChatMemberpalemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e, jid: null659012562]
Jicofo 2020-08-17 21:23:35.400 INFO: [28] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Granted owner to palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:23:35.400 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e joined.
Jicofo 2020-08-17 21:25:58.855 INFO: [312] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967
Jicofo 2020-08-17 21:25:58.855 INFO: [312] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967 for stream ID: null in room: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br
Jicofo 2020-08-17 21:26:13.855 SEVERE: [312] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null
Jicofo 2020-08-17 21:26:13.856 SEVERE: [312] 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:582)
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.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Jicofo 2020-08-17 21:26:13.856 INFO: [312] org.jitsi.jicofo.recording.jibri.JibriRecorder.log() Failed to start a Jibri session:Internal server error
org.jitsi.jicofo.recording.jibri.JibriSession$StartException: Internal server error
at org.jitsi.jicofo.recording.jibri.JibriSession.startInternal(JibriSession.java:376)
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.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Jicofo 2020-08-17 21:26:16.084 INFO: [28] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967 status
Jicofo 2020-08-17 21:26:16.084 INFO: [28] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/751476967 available: false
Jicofo 2020-08-17 21:26:19.721 INFO: [66] org.jitsi.jicofo.xmpp.FocusComponent.log() Focus request for room: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br
Jicofo 2020-08-17 21:26:19.832 INFO: [28] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl(at)2b00df0 member=ChatMemberpalemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b, jid: null448224761]
Jicofo 2020-08-17 21:26:19.832 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b joined.
Jicofo 2020-08-17 21:26:19.833 INFO: [28] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/a53f6a4f-161f-4616-9bd7-7b163fee9af1, relayId=null, region=null, stress=0.00] with packetRate=0 for participantRegion=null
Jicofo 2020-08-17 21:26:19.833 INFO: [28] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl(at)5137e73a
Jicofo 2020-08-17 21:26:19.834 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e, bridge=jvbbrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/a53f6a4f-161f-4616-9bd7-7b163fee9af1
Jicofo 2020-08-17 21:26:19.834 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=ffbd26 octo_enabled= false: [[null, null]]
Jicofo 2020-08-17 21:26:19.835 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Added participant jid= palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b, bridge=jvbbrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/a53f6a4f-161f-4616-9bd7-7b163fee9af1
Jicofo 2020-08-17 21:26:19.835 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=ffbd26 octo_enabled= false: [[null, null, null]]
Jicofo 2020-08-17 21:26:19.835 INFO: [317] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:26:19.836 INFO: [317] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e in 0
Jicofo 2020-08-17 21:26:19.836 INFO: [317] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/a53f6a4f-161f-4616-9bd7-7b163fee9af1 to allocate channels for: Participantpalemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e907344033
Jicofo 2020-08-17 21:26:19.839 INFO: [318] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Doing feature discovery for palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b
Jicofo 2020-08-17 21:26:19.840 INFO: [318] org.jitsi.jicofo.discovery.DiscoveryUtil.log() Successfully discovered features for palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b in 1
Jicofo 2020-08-17 21:26:19.840 INFO: [318] org.jitsi.jicofo.AbstractChannelAllocator.log() Using jvbbrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/a53f6a4f-161f-4616-9bd7-7b163fee9af1 to allocate channels for: Participantpalemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b731864802
Jicofo 2020-08-17 21:26:19.848 INFO: [317] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:26:19.857 INFO: [318] org.jitsi.jicofo.ParticipantChannelAllocator.log() Sending session-initiate to: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b
Jicofo 2020-08-17 21:26:20.257 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b
Jicofo 2020-08-17 21:26:20.258 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b with accepted sources:Sources{ }(at)1762775988
Jicofo 2020-08-17 21:26:20.258 WARNING: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() No jingle session yet for palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:26:21.249 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Got session-accept from: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:26:21.250 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Received session-accept from palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e with accepted sources:Sources{ video: [ssrc=3557234110 ssrc=3931355480 ssrc=3920854534 ssrc=1022740667 ssrc=4209720415 ssrc=1518413625 ] audio: [ssrc=4224024318 ] }(at)133293979
Jicofo 2020-08-17 21:26:21.251 INFO: [28] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Notify add SSRC palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b SID: 6dkdt51hagi0o Sources{ video: [ssrc=3557234110 ssrc=3931355480 ssrc=3920854534 ssrc=1022740667 ssrc=4209720415 ssrc=1518413625 ] audio: [ssrc=4224024318 ] }(at)31904179 source_Groups{ video:[ SourceGroup(FID)[ ssrc=3557234110 ssrc=3931355480 ]SourceGroup(FID)[ ssrc=3920854534 ssrc=4209720415 ]SourceGroup(FID)[ ssrc=1022740667 ssrc=1518413625 ]SourceGroup(SIM)[ ssrc=3557234110 ssrc=3920854534 ssrc=1022740667 ] ] }(at)3258565
Jicofo 2020-08-17 21:28:11.873 INFO: [28] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberLeft sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl(at)2b00df0 member=ChatMemberpalemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e, jid: 4d6bf63e-0dbc-4b38-b9d8-823654262139(at)xxxxxdomainxxxxx.com.br/1ca5f14d-8209-470d-9ca3-dc66078b56a1659012562]
Jicofo 2020-08-17 21:28:11.874 INFO: [28] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Owner has left the room !
Jicofo 2020-08-17 21:28:11.874 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e is leaving
Jicofo 2020-08-17 21:28:11.874 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Terminating: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:28:11.874 INFO: [28] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Terminate session: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e
Jicofo 2020-08-17 21:28:11.875 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removing palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e sources Sources{ video: [ssrc=3557234110 ssrc=3931355480 ssrc=3920854534 ssrc=1022740667 ssrc=4209720415 ssrc=1518413625 ] audio: [ssrc=4224024318 ] }(at)1733969668
Jicofo 2020-08-17 21:28:11.875 INFO: [28] org.jitsi.protocol.xmpp.AbstractOperationSetJingle.log() Notify remove SSRC palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/9ae3884b SID: 6dkdt51hagi0o Sources{ video: [ssrc=3557234110 ssrc=3931355480 ssrc=3920854534 ssrc=1022740667 ssrc=4209720415 ssrc=1518413625 ] audio: [ssrc=4224024318 ] }(at)1733969668 source_Groups{ video:[ SourceGroup(FID)[ ssrc=3557234110 ssrc=3931355480 ]SourceGroup(FID)[ ssrc=3920854534 ssrc=4209720415 ]SourceGroup(FID)[ ssrc=1022740667 ssrc=1518413625 ]SourceGroup(SIM)[ ssrc=3557234110 ssrc=3920854534 ssrc=1022740667 ] ] }(at)1872734539
Jicofo 2020-08-17 21:28:11.875 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Region info, conference=ffbd26 octo_enabled= false: [[null, null]]
Jicofo 2020-08-17 21:28:11.876 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Expiring channels for: palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e on: Bridge[jid=jvbbrewery(at)internal.auth.xxxxxdomainxxxxx.com.br/a53f6a4f-161f-4616-9bd7-7b163fee9af1, relayId=null, region=null, stress=0.01]
Jicofo 2020-08-17 21:28:11.876 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Removed participant: true, palemainstreamskickhopefully(at)conference.xxxxxdomainxxxxx.com.br/4d6bf63e

Jibri Logs:

2020-08-17 21:23:30.861 INFO: [1] org.jitsi.jibri.Main.main() Jibri run with args [–config, /etc/jitsi/jibri/config.json]
2020-08-17 21:23:30.868 INFO: [1] org.jitsi.jibri.Main.main() Using config file /etc/jitsi/jibri/config.json
2020-08-17 21:23:30.868 INFO: [1] org.jitsi.jibri.Main.main() Using port 3333 for internal HTTP API
2020-08-17 21:23:30.868 INFO: [1] org.jitsi.jibri.Main.main() Using port 2222 for the HTTP API
2020-08-17 21:23:32.393 INFO: [1] org.jitsi.jibri.Main.loadConfig() Parsed config:
JibriConfig(recordingDirectory=/home/jibri/recordings/, singleUseMode=false, enabledStatsD=true, finalizeRecordingScriptPath=/path/to/finalize_recording.sh, xmppEnvironments=[XmppEnvironmentConfig(name=prod environment, xmppServerHosts=[xxxxxdomainxxxxx.com.br], xmppDomain=xxxxxdomainxxxxx.com.br, controlLogin=XmppCredentials(domain=auth.xxxxxdomainxxxxx.com.br, username=jibri, password=***********), controlMuc=XmppMuc(domain=internal.auth.xxxxxdomainxxxxx.com.br, roomName=JibriBrewery, nickname=751476967), sipControlMuc=null, callLogin=XmppCredentials(domain=recorder.xxxxxdomainxxxxx.com.br, username=recorder, password=**********), stripFromRoomDomain=conference., usageTimeoutMins=0, trustAllXmppCerts=true)])
2020-08-17 21:23:33.400 WARNING: [1] org.glassfish.jersey.internal.inject.Providers.checkProviderRuntime() A provider org.jitsi.jibri.api.http.internal.InternalHttpApi registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.jitsi.jibri.api.http.internal.InternalHttpApi will be ignored.
2020-08-17 21:23:33.995 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
2020-08-17 21:23:34.034 INFO: [1] org.jitsi.jibri.api.xmpp.XmppApi.start() Connecting to xmpp environment on xxxxxdomainxxxxx.com.br with config XmppEnvironmentConfig(name=prod environment, xmppServerHosts=[xxxxxdomainxxxxx.com.br], xmppDomain=xxxxxdomainxxxxx.com.br, controlLogin=XmppCredentials(domain=auth.xxxxxdomainxxxxx.com.br, username=jibri, password=(at)), controlMuc=XmppMuc(domain=internal.auth.xxxxxdomainxxxxx.com.br, roomName=JibriBrewery, nickname=751476967), sipControlMuc=null, callLogin=XmppCredentials(domain=recorder.xxxxxdomainxxxxx.com.br, username=recorder, password=(at)), stripFromRoomDomain=conference., usageTimeoutMins=0, trustAllXmppCerts=true)
2020-08-17 21:23:34.035 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
2020-08-17 21:23:34.079 WARNING: [19] org.jitsi.xmpp.mucclient.MucClient.log() Disabling certificate verification!
2020-08-17 21:23:34.160 WARNING: [1] org.glassfish.jersey.internal.inject.Providers.checkProviderRuntime() A provider org.jitsi.jibri.api.http.HttpApi registered in SERVER runtime does not implement any provider interfaces applicable in the SERVER runtime. Due to constraint configuration problems the provider org.jitsi.jibri.api.http.HttpApi will be ignored.
2020-08-17 21:23:34.587 INFO: [19] org.jitsi.xmpp.mucclient.MucClient.log() Connected.
2020-08-17 21:23:34.587 INFO: [19] org.jitsi.xmpp.mucclient.MucClient.log() Logging in.
2020-08-17 21:23:34.691 INFO: [19] org.jitsi.xmpp.mucclient.MucClient.log() Joined MUC: jibribrewery(at)internal.auth.xxxxxdomainxxxxx.com.br
2020-08-17 21:25:58.857 INFO: [38] org.jitsi.jibri.api.xmpp.XmppApi.handleJibriIq() Received JibriIq from environment [MucClient id=xxxxxdomainxxxxx.com.br hostname=xxxxxdomainxxxxx.com.br]
2020-08-17 21:25:58.858 INFO: [38] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Received start request, starting service
2020-08-17 21:25:58.906 INFO: [38] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Parsed call url info: CallUrlInfo(baseUrl=https://xxxxxdomainxxxxx.com.br, callName=palemainstreamskickhopefully, urlParams=)
2020-08-17 21:25:58.907 INFO: [38] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://xxxxxdomainxxxxx.com.br, callName=palemainstreamskickhopefully, urlParams=)), sessionId=ukhkrxobkhcxfvje, callLoginParams=XmppCredentials(domain=recorder.xxxxxdomainxxxxx.com.br, username=recorder, password=(at))) finalize script path: /path/to/finalize_recording.sh and recordings directory: /home/jibri/recordings/
2020-08-17 21:26:16.037 INFO: [38] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS
2020-08-17 21:26:16.057 INFO: [38] org.jitsi.jibri.selenium.JibriSelenium.() Starting empty call check with a timeout of PT30S
2020-08-17 21:26:16.069 FINE: [38] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.() Detected os as OS: LINUX
2020-08-17 21:26:16.075 INFO: [38] org.jitsi.jibri.service.impl.FileRecordingJibriService.() Writing recording to /home/jibri/recordings/ukhkrxobkhcxfvje
2020-08-17 21:26:16.078 FINE: [38] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:recording
2020-08-17 21:26:16.078 INFO: [38] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY
2020-08-17 21:26:16.079 INFO: [38] 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
2020-08-17 21:26:16.086 INFO: [38] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending ‘pending’ response to start IQ
2020-08-17 21:26:18.299 FINE: [52] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url https://xxxxxdomainxxxxx.com.br/palemainstreamskickhopefully#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
2020-08-17 21:26:18.963 FINE: [52] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property ‘isJoined’ of undefined
2020-08-17 21:26:19.471 FINE: [52] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property ‘isJoined’ of undefined
2020-08-17 21:26:19.986 INFO: [52] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1050 milliseconds for call page to load
2020-08-17 21:26:20.002 INFO: [52] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running
2020-08-17 21:26:20.003 INFO: [52] org.jitsi.jibri.service.impl.FileRecordingJibriService.invoke() Selenium joined the call, starting the capturer
2020-08-17 21:26:20.111 INFO: [52] 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 /home/jibri/recordings/ukhkrxobkhcxfvje/palemainstreamskickhopefully_2020-08-17-21-26-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, /home/jibri/recordings/ukhkrxobkhcxfvje/palemainstreamskickhopefully_2020-08-17-21-26-16.mp4])
2020-08-17 21:26:25.127 FINE: [53] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn’t written in 2 seconds, publishing periodic update
2020-08-17 21:26:27.138 INFO: [56] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running
2020-08-17 21:26:27.141 INFO: [56] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Starting up to Running
2020-08-17 21:26:27.142 INFO: [56] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq
2020-08-17 21:26:35.087 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, all clients muted? false
2020-08-17 21:26:50.045 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=42, upload=0}, download=1848, upload=0, video={download=1806, upload=0}}, all clients muted? false
2020-08-17 21:27:05.036 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=41, upload=0}, download=1845, upload=0, video={download=1804, upload=0}}, all clients muted? false
2020-08-17 21:27:20.027 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=41, upload=0}, download=1846, upload=0, video={download=1805, upload=0}}, all clients muted? false
2020-08-17 21:27:35.030 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=40, upload=0}, download=1842, upload=0, video={download=1802, upload=0}}, all clients muted? false
2020-08-17 21:27:50.042 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=41, upload=0}, download=1844, upload=0, video={download=1803, upload=0}}, all clients muted? false
2020-08-17 21:28:05.034 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=39, upload=0}, download=1844, upload=0, video={download=1805, upload=0}}, all clients muted? false
2020-08-17 21:28:20.020 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=41, upload=0}, download=1843, upload=0, video={download=1802, upload=0}}, all clients muted? true
2020-08-17 21:28:35.014 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=0, upload=0}, download=0, upload=0, video={download=0, upload=0}}, all clients muted? true
2020-08-17 21:28:50.013 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=0, upload=0}, download=0, upload=0, video={download=0, upload=0}}, all clients muted? true
2020-08-17 21:29:04.994 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.run() Call has been empty since 2020-08-17T21:28:19.999Z (PT44.988S ago). Returning CallEmpty event
2020-08-17 21:29:04.994 INFO: [53] org.jitsi.jibri.selenium.JibriSelenium.invoke() Recurring call status checks generated event org.jitsi.jibri.selenium.SeleniumEvent$CallEmpty(at)345a8f70
2020-08-17 21:29:04.996 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Running to Finished
2020-08-17 21:29:04.996 INFO: [63] org.jitsi.jibri.service.impl.FileRecordingJibriService.onServiceStateChange() File recording service transitioning from state Running to Finished
2020-08-17 21:29:04.996 INFO: [63] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service finished, sending off iq
2020-08-17 21:29:04.997 FINE: [63] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: stop:recording
2020-08-17 21:29:04.997 INFO: [63] org.jitsi.jibri.JibriManager.stopService() Stopping the current service
2020-08-17 21:29:04.998 INFO: [63] org.jitsi.jibri.service.impl.FileRecordingJibriService.stop() Stopping capturer
2020-08-17 21:29:04.998 INFO: [63] org.jitsi.jibri.util.JibriSubprocess.ffmpeg.stop() Stopping ffmpeg process
2020-08-17 21:29:05.693 INFO: [63] org.jitsi.jibri.util.JibriSubprocess.ffmpeg.stop() ffmpeg exited with value 255
2020-08-17 21:29:05.693 INFO: [63] org.jitsi.jibri.service.impl.FileRecordingJibriService.stop() Quitting selenium
2020-08-17 21:29:05.693 INFO: [56] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Running to Finished
2020-08-17 21:29:05.706 INFO: [63] org.jitsi.jibri.service.impl.FileRecordingJibriService.stop() Participants in this recording:
2020-08-17 21:29:05.749 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Leaving call and quitting browser
2020-08-17 21:29:05.750 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Recurring call status checks cancelled
2020-08-17 21:29:05.761 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Got 24 log entries for type browser
2020-08-17 21:29:05.831 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Got 1170 log entries for type driver
2020-08-17 21:29:06.008 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Got 0 log entries for type client
2020-08-17 21:29:06.008 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Leaving web call
2020-08-17 21:29:06.080 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Quitting chrome driver
2020-08-17 21:29:06.211 INFO: [63] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Chrome driver quit
2020-08-17 21:29:06.211 INFO: [63] org.jitsi.jibri.service.impl.FileRecordingJibriService.stop() Finalizing the recording

I’m having a similar problem and also using EC2 instances. Still couldn’t find the cause, trying to solve this for days and still got nothing.

The issue is:

Jicofo 2020-08-17 21:26:13.855 SEVERE: [312] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null

And it looks like this is because there’s a timeout waiting for the Jibri response, but I don’t know what might cause that.

Hi @bbaldino, thanks for your response!
This issue happens only in new launched ec2 instances, at the first recording.

I’ve found out that: if i wait for the aws instance to pass the health check and then wait like 30 seconds to start recording, jibri works fine. I believe something required from the instance(like all network services running fine) takes too much time to be available.

The only thing i didn’t understand yet is why jicofo/UI throws an error if the jibri actually works and record the room… Jibri need to send a response after joining the room and start recording to jicofo? i thought jicofo would see the jibri in the room and get its status to confirm it is working.

I think I know what this is, as we saw an instance of it recently. On first start, chrome can take a long time to start up on the Jibri side and a change was made a little while back where Jibri waits longer before sending the initial PENDING response, so it causes this timeout (Jicofo assumes the Jibri hung or something and moves on, that’s why the error is shown). We’re discussing some possible changes to address this.

2 Likes

Sent you a private message. Please review

1 Like

Hey, speaking of these updates… Is jibri under update right now? i’ve made a fresh install and noticed that the config file is not a json anymore, and it have some different fields… is there a way to download older versions?

Jibri now uses a new config. The old config file is still currently supported, but should be considered deprecated. You can read some more about it here and here.

1 Like