Jibri retry fail

I build the jibri from master branch. i am using open jdk 8. also i set the https://raw.githubusercontent.com/jitsi/jibri/master/resources/debian-package/etc/jitsi/jibri/asoundrc in /home/jibri location

when first time staring stream i streaming fail
jibri.log

2020-07-11 08:20:11.724 FINE: [23] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=IDLE, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=null)

2020-07-11 08:20:13.486 INFO: [44] org.openqa.selenium.remote.ProtocolHandshake.createSession() Detected dialect: OSS

2020-07-11 08:20:13.504 INFO: [44] org.jitsi.jibri.selenium.JibriSelenium.() Starting empty call check with a timeout of PT30S

2020-07-11 08:20:13.508 FINE: [44] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: start:live_stream

2020-07-11 08:20:13.590 INFO: [44] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: IDLE -> BUSY

2020-07-11 08:20:13.590 INFO: [44] 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-07-11 08:20:13.593 INFO: [44] org.jitsi.jibri.api.xmpp.XmppApi.handleStartJibriIq() Sending ‘pending’ response to start IQ

2020-07-11 08:20:16.220 FINE: [57] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Visiting url https://ges.mykenshomedia.com.au/11112#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-07-11 08:20:16.722 FINE: [21] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:16.722 FINE: [21] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:16.793 FINE: [57] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property ‘isJoined’ of undefined

2020-07-11 08:20:17.300 FINE: [57] org.jitsi.jibri.selenium.pageobjects.CallPage.apply() Not joined yet: Cannot read property ‘isJoined’ of undefined

2020-07-11 08:20:17.911 INFO: [57] org.jitsi.jibri.selenium.pageobjects.CallPage.visit() Waited 1131 milliseconds for call page to load

2020-07-11 08:20:17.935 INFO: [57] org.jitsi.jibri.selenium.JibriSelenium.onSeleniumStateChange() Transitioning from state Starting up to Running

2020-07-11 08:20:17.936 INFO: [57] org.jitsi.jibri.service.impl.StreamingJibriService.invoke() Selenium joined the call, starting capturer

2020-07-11 08:20:17.961 INFO: [57] 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 -maxrate 2976k -bufsize 5952k -pix_fmt yuv420p -r 30 -crf 25 -g 60 -tune zerolatency -f flv rtmp://a.rtmp.youtube.com/live2/11112 ([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, -maxrate, 2976k, -bufsize, 5952k, -pix_fmt, yuv420p, -r, 30, -crf, 25, -g, 60, -tune, zerolatency, -f, flv, rtmp://a.rtmp.youtube.com/live2/11112])

2020-07-11 08:20:21.723 FINE: [26] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:21.723 FINE: [26] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:23.023 FINE: [58] org.jitsi.jibri.util.ProcessStatePublisher.ffmpeg.invoke() Process ffmpeg hasn’t written in 2 seconds, publishing periodic update

2020-07-11 08:20:26.198 INFO: [61] org.jitsi.jibri.capture.ffmpeg.FfmpegCapturer.onFfmpegStateMachineStateChange() Ffmpeg capturer transitioning from state Starting up to Running

2020-07-11 08:20:26.201 INFO: [61] org.jitsi.jibri.service.impl.StreamingJibriService.onServiceStateChange() Streaming service transitioning from state Starting up to Running

2020-07-11 08:20:26.203 INFO: [61] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service started up successfully, sending on iq

2020-07-11 08:20:26.730 FINE: [23] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:26.730 FINE: [23] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:31.728 FINE: [26] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:31.729 FINE: [26] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:32.974 INFO: [58] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, all clients muted? false

2020-07-11 08:20:36.729 FINE: [21] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:36.729 FINE: [21] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:41.729 FINE: [23] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:41.729 FINE: [23] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:46.736 FINE: [26] org.jitsi.jibri.api.http.HttpApi.health() Got health request

2020-07-11 08:20:46.736 FINE: [26] org.jitsi.jibri.api.http.HttpApi.health() Returning health JibriHealth(status=JibriStatus(busyStatus=BUSY, health=OverallHealth(healthStatus=HEALTHY, details={})), environmentContext=EnvironmentContext(name=prod environment))

2020-07-11 08:20:47.946 INFO: [58] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=31, upload=0}, download=417, upload=0, video={download=230, upload=0}}, all clients muted? false

jicofo log

Jicofo 2020-07-11 08:19:50.205 INFO: [432] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting session with Jibri jibribrewery@internal.auth.ges.mykenshomedia.com.au/jibri-nickname58661109651594455332495655533

Jicofo 2020-07-11 08:19:50.205 INFO: [432] org.jitsi.jicofo.recording.jibri.JibriSession.log() Starting Jibri jibribrewery@internal.auth.ges.mykenshomedia.com.au/jibri-nickname58661109651594455332495655533 for stream ID: 11112 in room: 11112@conference.ges.mykenshomedia.com.au

Jicofo 2020-07-11 08:20:05.205 SEVERE: [432] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null

Jicofo 2020-07-11 08:20:05.205 SEVERE: [432] 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-07-11 08:20:05.206 INFO: [432] 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-07-11 08:20:13.595 INFO: [28] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Received Jibri jibribrewery@internal.auth.ges.mykenshomedia.com.au/jibri-nickname58661109651594455332495655533 status

Jicofo 2020-07-11 08:20:13.595 INFO: [28] org.jitsi.jicofo.recording.jibri.JibriDetector.log() Jibri: jibribrewery@internal.auth.ges.mykenshomedia.com.au/jibri-nickname58661109651594455332495655533 available: false

Jicofo 2020-07-11 08:20:17.509 INFO: [85] org.jitsi.jicofo.xmpp.FocusComponent.log() Focus request for room: 11112@conference.ges.mykenshomedia.com.au

Jicofo 2020-07-11 08:20:17.619 INFO: [28] org.jitsi.jicofo.ChatRoomRoleAndPresence.log() Chat room event ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=org.jitsi.impl.protocol.xmpp.ChatRoomImpl@3336051b member=ChatMember[11112@conference.ges.mykenshomedia.com.au/d2e9d310, jid: null]@1446796537]

Jicofo 2020-07-11 08:20:17.619 INFO: [28] org.jitsi.jicofo.JitsiMeetConferenceImpl.log() Member 11112@conference.ges.mykenshomedia.com.au/d2e9d310 joined.

Jicofo 2020-07-11 08:20:17.619 INFO: [28] org.jitsi.jicofo.bridge.BridgeSelectionStrategy.log() Selected initial bridge Bridge[jid=jvbbrewery@internal.auth.ges.mykenshomedia.com.au/703895ae-663d-4dfa-a16b-1a189189801e, relayId=null, region=null, stress=0.00] with packetRate=0 for participantRegion=null

Jicofo 2020-07-11 08:20:17.619 INFO: [28] org.jitsi.impl.protocol.xmpp.colibri.OperationSetColibriConferenceImpl.log() Conference created: org.jitsi.impl.protocol.xmpp.colibri.ColibriConferenceImpl@7c0e427e

but after error i restart the jibri then working fine

Why do the loopback device names differ?
Some are Loopback and some are Loopback_1
AFAIK they should be all the same

@bbaldino

can you tell why there are two loopback Loopback, Loopback_1

The unexpected response in Jicofo is weird…can you try running it with smack debug on? I think it should just be passing:

-Dsmack.debuggerClass=org.jivesoftware.smack.debugger.ConsoleDebugger
-Dsmack.debugEnabled=true

as jvm args when starting Jicofo

@bbaldino
same error

jicofo.log

Jicofo 2020-07-15 18:41:15.323 SEVERE: [149] org.jitsi.jicofo.recording.jibri.JibriSession.log() Unexpected response to start request: null

Jicofo 2020-07-15 18:41:15.323 SEVERE: [149] 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-07-15 18:41:15.323 INFO: [149] 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)

Yes that wouldn’t have fixed the error, just added some logging to show the XMPP messages going in and out of Jicofo, but I don’t see them there. Can you attach a clean Jicofo log (the whole thing) from when this happens?

@bbaldino,

here is logs
ffmpeg.0.txt (41.0 KB) jicofo.log (36.8 KB) log.0.txt (8.5 KB)

Those don’t appear to be the right Jibri logs, as they start at 2020-07-16 03:00:45.116 and Jicofo reports getting a status update of busy from that Jibri at 2020-07-16 02:57:46.033. Can you attach the Jibri log for that time?

Sure @bbaldino here are the correct logs. Apologies for the inconvenience. Thank you for the support. Any help would be really appreciated.

jicofo.log (46.4 KB) log.2.txt (56.7 KB)

Thanks. Jibri seems happy from its side…what versions of Jicofo and Jibri are you using?

I think we’ll need to enable smack debug logs on both Jibri and Jicofo to figure out what’s going on.

Can you try and pass:

-Dsmack.debuggerClass=org.jivesoftware.smack.debugger.ConsoleDebugger
-Dsmack.debugEnabled=true

as VM arguments when starting both Jicofo and Jibri so we can get some info there?

@bbaldino

i passed: -Dsmack.debuggerClass=org.jivesoftware.smack.debugger.ConsoleDebugger
-Dsmack.debugEnabled=true both jicofo and jibri.
jicofo.log (18.7 KB) log.2.txt (42.7 KB)

jicofo build from : jitsi-meet_4627(5382160e3a26ea7983c96707940e0c969a6dcbb2)
jibri build from:(d13317531b0554276157ebadf2c3d54849d33efb)

They’re still not enabled. Can you paste the command you’re using to start Jicofo and Jibri?

@bbaldino
here is the jicofo config.

JAVA_SYS_PROPS="-Dnet.java.sip.communicator.SC_HOME_DIR_LOCATION=/etc/jitsi -Dnet.java.sip.communicator.SC_HOME_DIR_NAME=jicofo -Dnet.java.sip.communicator.SC_LOG_DIR_LOCATION=/var/log/jitsi -Djava.util.logging.config.file=/etc/jitsi/jicofo/logging.properties -Dsmack.debuggerClass=org.jivesoftware.smack.debugger.ConsoleDebugger -Dsmack.debugEnabled=true

and i change jibri launch.sh

exec java -Dsmack.debuggerClass=org.jivesoftware.smack.debugger.ConsoleDebugger -Dsmack.debugEnabled=true  -Djava.util.logging.config.file=/etc/jitsi/jibri/logging.properties -jar /opt/jitsi/jibri/jibri.jar --config "/etc/jitsi/jibri/config.json"

It looks like the request from Jicofo -> Jibri is timing out. Jibri receives the request, but for some reason takes a long time to respond to it. Are you building this from source, or able to build Jibri from source? I think we’ll need to add some extra logging to determine where it’s getting hung up. This is happening consistently, right?

Thank you for your response! What we are doing is we are scaling the servers using aws autoscaling groups. When the server spin up, this error comes on the first request. When we restart jibri service, it works all right. The request is being sent to jibri from jicofo and the response from jibri cannot be handled by jicofo. But the jibri starts and will be busy for future requests from jicofo.

If we are using the latest commit from jibri, what should be the version which we should be using in jitsi?

Thank you for your support @bbaldino

Regards,
Supun

Hello @Supun_Madushanka,

Did you test it with the new stable Jitsi/Jicofo/Jibri which were released yesterday

Thank you @emrah i will check