Jibri immediately reports offline status to Jicofo


#1

When I start Jibri, everything appears correct in the Jibri logs, however Jicofo reports an offline status for Jibri. I’m assuming this is the reason that when attempting to start a recording I end up with a no recorder available message. When I hit the api at port 2222 for Jibri to get the status, I get a response of {busy:false}

Not sure what I should be looking at next for further troubleshooting.

Jibri log:

2018-11-16 21:33:44.572 INFO: [1] org.jitsi.jibri.Main.main() Jibri run with args [--config, /etc/jitsi/jibri/config.json]
2018-11-16 21:33:44.575 INFO: [1] org.jitsi.jibri.Main.main() Using config file /etc/jitsi/jibri/config.json
2018-11-16 21:33:44.577 INFO: [1] org.jitsi.jibri.Main.main() Using port 3333 for internal HTTP API
2018-11-16 21:33:44.577 INFO: [1] org.jitsi.jibri.Main.main() Using port 2222 for the HTTP API
2018-11-16 21:33:45.124 INFO: [1] org.jitsi.jibri.Main.loadConfig() Parsed config:
JibriConfig(recordingDirectory=/recordings, enabledStatsD=true, finalizeRecordingScriptPath=/finalize_recording.sh, xmppEnvironments=[XmppEnvironmentConfig(name=dev-sip-jitsi.synzi.com, xmppServerHosts=[10.109.214.184], xmppDomain=dev-sip-jitsi.synzi.com, controlLogin=XmppCredentials(domain=auth.dev-sip-jitsi.synzi.com, username=jibri, password=jibriauthpass), controlMuc=XmppMuc(domain=internal.auth.dev-sip-jitsi.synzi.com, roomName=JibriBrewery, nickname=jibrijibri1), sipControlMuc=null, callLogin=XmppCredentials(domain=recorder.dev-sip-jitsi.synzi.com, username=recorder, password=jibrirecorderpass), stripFromRoomDomain=conference., usageTimeoutMins=0, trustAllXmppCerts=true)])
2018-11-16 21:33:45.188:INFO::main: Logging initialized @822ms
2018-11-16 21:33:45.218:WARN:oejsh.ContextHandler:main: o.e.j.s.ServletContextHandler@28194a50{/,null,null} contextPath ends with /*
2018-11-16 21:33:45.218:WARN:oejsh.ContextHandler:main: Empty contextPath
2018-11-16 21:33:45.232:INFO:oejs.Server:main: jetty-9.2.z-SNAPSHOT
2018-11-16 21:33:45.266 CONFIG: [1] org.glassfish.jersey.internal.ServiceFinder.<clinit>() Running in a non-OSGi environment
2018-11-16 21:33:45.389 FINE: [1] org.glassfish.jersey.inject.hk2.AbstractHk2InjectionManager.<init>() Clearing Jersey HK2 caches. Service cache size: 3, reflection cache size: 20.
2018-11-16 21:33:45.400 CONFIG: [1] org.glassfish.jersey.server.ApplicationHandler.initialize() Initiating Jersey application, version Jersey: 2.26 2017-09-05 11:50:34...
2018-11-16 21:33:45.486 FINE: [1] org.glassfish.jersey.internal.util.collection.DataStructures.<clinit>() USING LTQ class:{0}
2018-11-16 21:33:45.688 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. 
2018-11-16 21:33:45.741 CONFIG: [1] org.glassfish.jersey.process.internal.ExecutorProviders.config() Selected ExecutorServiceProvider implementation [org.glassfish.jersey.server.ServerExecutorProvidersConfigurator$DefaultManagedAsyncExecutorProvider] to be used for injection of executor qualified by [org.glassfish.jersey.server.ManagedAsyncExecutor] annotation.
2018-11-16 21:33:45.744 CONFIG: [1] org.glassfish.jersey.process.internal.ExecutorProviders.config() Selected ScheduledExecutorServiceProvider implementation [org.glassfish.jersey.server.ServerExecutorProvidersConfigurator$DefaultBackgroundSchedulerProvider] to be used for injection of scheduler qualified by [org.glassfish.jersey.server.BackgroundScheduler] annotation.
2018-11-16 21:33:45.838 CONFIG: [1] org.glassfish.jersey.server.ApplicationHandler.logApplicationInitConfiguration() Jersey application initialized.
2018-11-16 21:33:45.842:INFO:oejsh.ContextHandler:main: Started o.e.j.s.ServletContextHandler@28194a50{/,null,AVAILABLE}
2018-11-16 21:33:45.856:INFO:oejs.ServerConnector:main: Started ServerConnector@9be620c{HTTP/1.1}{0.0.0.0:3333}
2018-11-16 21:33:45.859:INFO:oejs.Server:main: Started @1492ms
2018-11-16 21:33:45.988 INFO: [1] org.jitsi.jibri.api.xmpp.XmppApi.start() Connecting to xmpp environment on 10.109.214.184 with config XmppEnvironmentConfig(name=dev-sip-jitsi.synzi.com, xmppServerHosts=[10.109.214.184], xmppDomain=dev-sip-jitsi.synzi.com, controlLogin=XmppCredentials(domain=auth.dev-sip-jitsi.synzi.com, username=jibri, password=jibriauthpass), controlMuc=XmppMuc(domain=internal.auth.dev-sip-jitsi.synzi.com, roomName=JibriBrewery, nickname=jibrijibri1), sipControlMuc=null, callLogin=XmppCredentials(domain=recorder.dev-sip-jitsi.synzi.com, username=recorder, password=jibrirecorderpass), stripFromRoomDomain=conference., usageTimeoutMins=0, trustAllXmppCerts=true)
2018-11-16 21:33:45.996 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
2018-11-16 21:33:46.315 INFO: [1] class org.jitsi.xmpp.mucclient.MucClient.connected() [dev-sip-jitsi.synzi.com: auth.dev-sip-jitsi.synzi.com@10.109.214.184] Xmpp connection status: connected
2018-11-16 21:33:46.371 INFO: [1] class org.jitsi.xmpp.mucclient.MucClient.authenticated() [dev-sip-jitsi.synzi.com: auth.dev-sip-jitsi.synzi.com@10.109.214.184] Xmpp connection status: authenticated (resume from previous? false)
2018-11-16 21:33:46.400:WARN:oejsh.ContextHandler:main: o.e.j.s.ServletContextHandler@1d035be3{/,null,null} contextPath ends with /*
2018-11-16 21:33:46.400:WARN:oejsh.ContextHandler:main: Empty contextPath
2018-11-16 21:33:46.410:INFO:oejs.Server:main: jetty-9.2.z-SNAPSHOT
2018-11-16 21:33:46.420 FINE: [1] org.glassfish.jersey.inject.hk2.AbstractHk2InjectionManager.<init>() Clearing Jersey HK2 caches. Service cache size: 3, reflection cache size: 20.
2018-11-16 21:33:46.423 CONFIG: [1] org.glassfish.jersey.server.ApplicationHandler.initialize() Initiating Jersey application, version Jersey: 2.26 2017-09-05 11:50:34...
2018-11-16 21:33:46.517 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. 
2018-11-16 21:33:46.537 CONFIG: [1] org.glassfish.jersey.process.internal.ExecutorProviders.config() Selected ExecutorServiceProvider implementation [org.glassfish.jersey.server.ServerExecutorProvidersConfigurator$DefaultManagedAsyncExecutorProvider] to be used for injection of executor qualified by [org.glassfish.jersey.server.ManagedAsyncExecutor] annotation.
2018-11-16 21:33:46.542 CONFIG: [1] org.glassfish.jersey.process.internal.ExecutorProviders.config() Selected ScheduledExecutorServiceProvider implementation [org.glassfish.jersey.server.ServerExecutorProvidersConfigurator$DefaultBackgroundSchedulerProvider] to be used for injection of scheduler qualified by [org.glassfish.jersey.server.BackgroundScheduler] annotation.
2018-11-16 21:33:46.579 CONFIG: [1] org.glassfish.jersey.server.ApplicationHandler.logApplicationInitConfiguration() Jersey application initialized.
2018-11-16 21:33:46.590:INFO:oejsh.ContextHandler:main: Started o.e.j.s.ServletContextHandler@1d035be3{/,null,AVAILABLE}
2018-11-16 21:33:46.591:INFO:oejs.ServerConnector:main: Started ServerConnector@69eb86b4{HTTP/1.1}{0.0.0.0:2222}
2018-11-16 21:33:46.594:INFO:oejs.Server:main: Started @2227ms

Jicofo Log:

Jicofo 2018-11-16 21:33:28.801 FINER: [97] org.jitsi.impl.protocol.xmpp.XmppProtocolProvider.processStanza().832 <-- <iq to='focus@auth.dev-sip-jitsi.synzi.com/focus2008304477682091' from='focus.dev-sip-jitsi.synzi.com' id='0FLG2-1071' type='result'><query xmlns='http://jabber.org/protocol/disco#info'><identity category='component' name='Jitsi Meet Focus' type='generic'/><feature var='http://jabber.org/protocol/disco#info'/><feature var='urn:xmpp:ping'/><feature var='jabber:iq:last'/><feature var='urn:xmpp:time'/><feature var='http://jitsi.org/protocol/focus'/></query></iq>
Jicofo 2018-11-16 21:33:28.802 FINER: [97] org.jitsi.impl.protocol.xmpp.XmppProtocolProvider.processStanza().832 --> <iq to='jitsi-videobridge.dev-sip-jitsi.synzi.com' id='0FLG2-1073' type='get'><query xmlns='http://jabber.org/protocol/disco#info'></query></iq>
Jicofo 2018-11-16 21:33:28.803 FINER: [97] org.jitsi.impl.protocol.xmpp.XmppProtocolProvider.processStanza().832 <-- <iq to='focus@auth.dev-sip-jitsi.synzi.com/focus2008304477682091' from='jitsi-videobridge.dev-sip-jitsi.synzi.com' id='0FLG2-1073' type='result'><query xmlns='http://jabber.org/protocol/disco#info'><identity category='component' name='JitsiVideobridge' type='conference'/><feature var='http://jabber.org/protocol/disco#info'/><feature var='urn:xmpp:ping'/><feature var='jabber:iq:last'/><feature var='urn:xmpp:time'/><feature var='http://jitsi.org/protocol/colibri'/><feature var='http://jitsi.org/protocol/healthcheck'/><feature var='urn:xmpp:jingle:apps:dtls:0'/><feature var='urn:xmpp:jingle:transports:ice-udp:1'/><feature var='urn:xmpp:jingle:transports:raw-udp:1'/><feature var='jabber:iq:version'/></query></iq>
Jicofo 2018-11-16 21:33:37.096 FINER: [97] org.jitsi.impl.protocol.xmpp.XmppProtocolProvider.processStanza().832 <-- <presence to='focus@auth.dev-sip-jitsi.synzi.com/focus2008304477682091' from='jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1' type='unavailable'><status>Disconnected: closed</status><x xmlns='http://jabber.org/protocol/muc#user'><item affiliation='owner' jid='jibri@auth.dev-sip-jitsi.synzi.com/5dcf6b62-9370-4b74-9d0c-8cd503569a79' role='none'></item></x></presence>
Jicofo 2018-11-16 21:33:37.096 FINE: [39] org.jitsi.impl.protocol.xmpp.ChatRoomImpl.left().1290 Left jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1 room: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com
Jicofo 2018-11-16 21:33:37.096 INFO: [39] org.jitsi.jicofo.xmpp.BaseBrewery.removeInstance().368 Removed brewery instance: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1
Jicofo 2018-11-16 21:33:37.096 INFO: [39] org.jitsi.jicofo.recording.jibri.JibriDetector.notifyInstanceOffline().163 Jibri: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1 went offline
Jicofo 2018-11-16 21:33:37.096 FINER: [39] org.jitsi.impl.protocol.xmpp.ChatRoomImpl.processPresence().1223 Presence received <presence to='focus@auth.dev-sip-jitsi.synzi.com/focus2008304477682091' from='jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1' type='unavailable'><status>Disconnected: closed</status><x xmlns='http://jabber.org/protocol/muc#user'><item affiliation='owner' jid='jibri@auth.dev-sip-jitsi.synzi.com/5dcf6b62-9370-4b74-9d0c-8cd503569a79' role='none'></item></x></presence>
Jicofo 2018-11-16 21:33:46.383 FINER: [97] org.jitsi.impl.protocol.xmpp.XmppProtocolProvider.processStanza().832 <-- <presence to='focus@auth.dev-sip-jitsi.synzi.com/focus2008304477682091' from='jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1' id='au7tr-21'><jibri-status xmlns='http://jitsi.org/protocol/jibri'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.igniterealtime.org/projects/smack' ver='lWpWNgqtfynY+MxupmhOr2LZqOg='/><x xmlns='http://jabber.org/protocol/muc#user'><item affiliation='owner' jid='jibri@auth.dev-sip-jitsi.synzi.com/e101c15b-fadf-44ab-aeef-501ec871b819' role='moderator'></item></x></presence>
Jicofo 2018-11-16 21:33:46.383 FINE: [39] org.jitsi.impl.protocol.xmpp.ChatRoomImpl.joined().1262 Ignore a member joined event for jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1
Jicofo 2018-11-16 21:33:46.384 FINER: [39] org.jitsi.impl.protocol.xmpp.ChatRoomImpl.processPresence().1223 Presence received <presence to='focus@auth.dev-sip-jitsi.synzi.com/focus2008304477682091' from='jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1' id='au7tr-21'><jibri-status xmlns='http://jitsi.org/protocol/jibri'/><c xmlns='http://jabber.org/protocol/caps' hash='sha-1' node='http://www.igniterealtime.org/projects/smack' ver='lWpWNgqtfynY+MxupmhOr2LZqOg='/><x xmlns='http://jabber.org/protocol/muc#user'><item affiliation='owner' jid='jibri@auth.dev-sip-jitsi.synzi.com/e101c15b-fadf-44ab-aeef-501ec871b819' role='moderator'></item></x></presence>
Jicofo 2018-11-16 21:33:46.384 FINE: [39] org.jitsi.impl.protocol.xmpp.ChatRoomImpl.processOtherPresence().1174 Joined jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1 room: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com
Jicofo 2018-11-16 21:33:46.384 INFO: [39] org.jitsi.jicofo.xmpp.BaseBrewery.processInstanceStatusChanged().324 Added brewery instance: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1
Jicofo 2018-11-16 21:33:46.384 INFO: [39] org.jitsi.jicofo.recording.jibri.JibriDetector.onInstanceStatusChanged().138 Received Jibri status <jibri-status xmlns='http://jitsi.org/protocol/jibri'/>
Jicofo 2018-11-16 21:33:46.384 INFO: [39] org.jitsi.jicofo.recording.jibri.JibriDetector.notifyInstanceOffline().163 Jibri: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1 went offline
Jicofo 2018-11-16 21:33:46.384 INFO: [39] org.jitsi.jicofo.recording.jibri.JibriDetector.onInstanceStatusChanged().138 Received Jibri status <jibri-status xmlns='http://jitsi.org/protocol/jibri'/>
Jicofo 2018-11-16 21:33:46.384 INFO: [39] org.jitsi.jicofo.recording.jibri.JibriDetector.notifyInstanceOffline().163 Jibri: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1 went offline

Prosody Log

|Nov 16 21:33:42 jcpfe6ac0|debug|Received[component]: <iq id='kO2Jm-264444' type='get' to='dev-sip-jitsi.synzi.com' from='jitsi-videobridge.dev-sip-jitsi.synzi.com'>|
|---|---|---|
|Nov 16 21:33:46 socket|debug|server.lua: accepted new client connection from 10.109.213.250:57261 to 5222|
|Nov 16 21:33:46 c2sf28850|info|Client connected|
|Nov 16 21:33:46 c2sf28850|debug|Client sent opening <stream:stream> to auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 c2sf28850|debug|Sent reply <stream:stream> to client|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s_unauthed]: <starttls xmlns='urn:ietf:params:xml:ns:xmpp-tls'>|
|Nov 16 21:33:46 socket|debug|server.lua: we need to do tls, but delaying until send buffer empty|
|Nov 16 21:33:46 c2sf28850|debug|TLS negotiation started for c2s_unauthed...|
|Nov 16 21:33:46 socket|debug|server.lua: attempting to start tls on tcp{client}: 0x146c048|
|Nov 16 21:33:46 socket|debug|server.lua: ssl handshake done|
|Nov 16 21:33:46 c2sf28850|debug|Client sent opening <stream:stream> to auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 c2sf28850|debug|Sent reply <stream:stream> to client|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s_unauthed]: <auth mechanism='SCRAM-SHA-1' xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>|
|Nov 16 21:33:46 auth.dev-sip-jitsi.synzi.com:auth_internal_plain|debug|get_password for username 'jibri' at host 'auth.dev-sip-jitsi.synzi.com'|
|Nov 16 21:33:46 auth.dev-sip-jitsi.synzi.com:saslauth|debug|sasl reply: <challenge xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>cj0vdWN3M2MvJFQubzREY2ohOXw3MVBzJUd4I1YpQ1dmKDA2YTdhMzk2LTQ5OTItNGYzMy04NDAxLTBkODI2ZDQ0YWY0ZixzPVkyRXpORGxoTVRZdFpEQTRNaTAwTVRJd0xUbGlZV0l0TnpNMVlqTTFNelUxWVRreSxpPTQwOTY=</challenge>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s_unauthed]: <response xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>|
|Nov 16 21:33:46 c2sf28850|info|Authenticated as jibri@auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 auth.dev-sip-jitsi.synzi.com:saslauth|debug|sasl reply: <success xmlns='urn:ietf:params:xml:ns:xmpp-sasl'>dj1VRlJXOFMyTmQvR0FWektJSnpRakpmZjlpcjg9</success>|
|Nov 16 21:33:46 c2sf28850|debug|Client sent opening <stream:stream> to auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 c2sf28850|debug|Sent reply <stream:stream> to client|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-5' type='set'>|
|Nov 16 21:33:46 rostermanager|debug|load_roster: asked for: jibri@auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 rostermanager|debug|load_roster: loading for new user: jibri@auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 datamanager|debug|Assuming empty roster storage ('cannot open /var/lib/prosody/auth%2edev%2dsip%2djitsi%2esynzi%2ecom/roster/jibri.dat: No such file or directory') for user: jibri@auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 c2sf28850|debug|Resource bound: jibri@auth.dev-sip-jitsi.synzi.com/e101c15b-fadf-44ab-aeef-501ec871b819|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-7' type='get'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-8' type='get' to='auth.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-11' type='get' to='auth.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-13' type='get' to='internal.auth.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-15' type='get' to='auth.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-17' type='get' to='internal.auth.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <presence id='au7tr-19'>|
|Nov 16 21:33:46 datamanager|debug|Assuming empty offline storage ('cannot open /var/lib/prosody/auth%2edev%2dsip%2djitsi%2esynzi%2ecom/offline/jibri.list: No such file or directory') for user: jibri@auth.dev-sip-jitsi.synzi.com|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <iq id='au7tr-22' type='get' to='internal.auth.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:46 c2sf28850|debug|Received[c2s]: <presence to='jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1' id='au7tr-21'>|
|Nov 16 21:33:46 mod_muc|debug|room: jibribrewery@internal.auth.dev-sip-jitsi.synzi.com, current_nick: nil, stanza: <presence id='au7tr-21' to='jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1' from='jibri@auth.dev-sip-jitsi.synzi.com/e101c15b-fadf-44ab-aeef-501ec871b819'>|
|Nov 16 21:33:46 mod_muc|debug|jibri@auth.dev-sip-jitsi.synzi.com/e101c15b-fadf-44ab-aeef-501ec871b819 joining as jibribrewery@internal.auth.dev-sip-jitsi.synzi.com/jibrijibri1|
|Nov 16 21:33:48 jcp1086270|debug|Received[component]: <iq id='0FLG2-1079' type='get' to='dev-sip-jitsi.synzi.com' from='focus.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:48 jcp1086270|debug|Received[component]: <iq id='0FLG2-1080' type='get' to='dev-sip-jitsi.synzi.com' from='focus.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:52 jcpfe6ac0|debug|Received[component]: <iq id='kO2Jm-264446' type='get' to='dev-sip-jitsi.synzi.com' from='jitsi-videobridge.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:58 jcp1086270|debug|Received[component]: <iq id='0FLG2-1081' type='get' to='dev-sip-jitsi.synzi.com' from='focus.dev-sip-jitsi.synzi.com'>|
|Nov 16 21:33:58 jcp1086270|debug|Received[component]: <iq id='0FLG2-1082' type='get' to='dev-sip-jitsi.synzi.com' from='focus.dev-sip-jitsi.synzi.com'>|


#2

I was able to get Jicofo to detect Jibri as connected. Looks like this was caused due to a version incompatibility. By running apt-get install jicofo the latest version was installed. (Thanks to some info found in this thread: All recorders are currently busy issue faced when we click start recording)

Now the recording at least attempts to start, however it fails. This is what I’m seeing in the Jibri logs:

2018-11-19 17:10:00.078 INFO: [38] org.jitsi.jibri.JibriManager.startFileRecording() Starting a file recording with params: FileRecordingRequestParams(callParams=CallParams(callUrlInfo=CallUrlInfo(baseUrl=https://dev-sip-jitsi.synzi.com, callName=testmeeting, urlParams=[])), sessionId=zrrckohupbijgwgj, callLoginParams=XmppCredentials(domain=recorder.dev-sip-jitsi.synzi.com, username=recorder, password=jibrirecorderpass)) finalize script path: /finalize_recording.sh and recordings directory: /recordings
Starting ChromeDriver 2.28.455506 (18f6627e265f442aeec9b6661a49fe819aeeea1f) on port 24159
Only local connections are allowed.
2018-11-19 17:11:00.731 SEVERE: [38] org.jitsi.jibri.api.xmpp.XmppApi.handleStartService() Error starting service: org.openqa.selenium.WebDriverException: unknown error: Chrome failed to start: exited abnormally
  (Driver info: chromedriver=2.28.455506 (18f6627e265f442aeec9b6661a49fe819aeeea1f),platform=Linux 3.16.0-5-amd64 x86_64) (WARNING: The server did not provide any stacktrace information)
Command duration or timeout: 60.06 seconds
Build info: version: 'unknown', revision: 'unknown', time: 'unknown'
System info: host: '2f6cf8a3dbbb', ip: '172.17.0.2', os.name: 'Linux', os.arch: 'amd64', os.version: '3.16.0-5-amd64', java.version: '1.8.0_191'
Driver info: driver.version: ChromeDriver with stack: 
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
java.lang.reflect.Constructor.newInstance(Constructor.java:423)
org.openqa.selenium.remote.ErrorHandler.createThrowable(ErrorHandler.java:214)
org.openqa.selenium.remote.ErrorHandler.throwIfResponseFailed(ErrorHandler.java:166)
org.openqa.selenium.remote.JsonWireProtocolResponse.lambda$new$0(JsonWireProtocolResponse.java:53)
org.openqa.selenium.remote.JsonWireProtocolResponse.lambda$getResponseFunction$2(JsonWireProtocolResponse.java:91)
org.openqa.selenium.remote.ProtocolHandshake.lambda$createSession$0(ProtocolHandshake.java:123)
java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
java.util.Spliterators$ArraySpliterator.tryAdvance(Spliterators.java:958)
java.util.stream.ReferencePipeline.forEachWithCancel(ReferencePipeline.java:126)
java.util.stream.AbstractPipeline.copyIntoWithCancel(AbstractPipeline.java:498)
java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:485)
java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
java.util.stream.FindOps$FindOp.evaluateSequential(FindOps.java:152)
java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
java.util.stream.ReferencePipeline.findFirst(ReferencePipeline.java:464)
org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:126)
org.openqa.selenium.remote.ProtocolHandshake.createSession(ProtocolHandshake.java:73)
org.openqa.selenium.remote.HttpCommandExecutor.execute(HttpCommandExecutor.java:142)
org.openqa.selenium.remote.service.DriverCommandExecutor.execute(DriverCommandExecutor.java:83)
org.openqa.selenium.remote.RemoteWebDriver.execute(RemoteWebDriver.java:601)
org.openqa.selenium.remote.RemoteWebDriver.startSession(RemoteWebDriver.java:219)
org.openqa.selenium.remote.RemoteWebDriver.<init>(RemoteWebDriver.java:142)
org.openqa.selenium.chrome.ChromeDriver.<init>(ChromeDriver.java:181)
org.openqa.selenium.chrome.ChromeDriver.<init>(ChromeDriver.java:168)
org.jitsi.jibri.selenium.JibriSelenium.<init>(JibriSelenium.kt:142)
org.jitsi.jibri.selenium.JibriSelenium.<init>(JibriSelenium.kt:102)
org.jitsi.jibri.service.impl.FileRecordingJibriService.<init>(FileRecordingJibriService.kt:109)
org.jitsi.jibri.JibriManager.startFileRecording(JibriManager.kt:124)
org.jitsi.jibri.api.xmpp.XmppApi.handleStartService(XmppApi.kt:293)
org.jitsi.jibri.api.xmpp.XmppApi.access$handleStartService(XmppApi.kt:72)
org.jitsi.jibri.api.xmpp.XmppApi$handleStartJibriIq$1.run(XmppApi.kt:206)
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
java.util.concurrent.FutureTask.run(FutureTask.java:266)
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
java.lang.Thread.run(Thread.java:748)

2018-11-19 17:11:00.738 FINE: [38] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: stop:
2018-11-19 17:11:00.739 INFO: [38] org.jitsi.jibri.JibriManager.stopService() Stopping the current service
2018-11-19 17:11:00.740 INFO: [38] org.jitsi.jibri.status.JibriStatusManager.log() Received component health update: XMPPAPI has status UNHEALTHY (detail: org.openqa.selenium.WebDriverException: unknown error: Chrome failed to start: exited abnormally
  (Driver info: chromedriver=2.28.455506 (18f6627e265f442aeec9b6661a49fe819aeeea1f),platform=Linux 3.16.0-5-amd64 x86_64) (WARNING: The server did not provide any stacktrace information)
Command duration or timeout: 60.06 seconds

Seems like Chrome cannot start.


#3

Was able to resolve the chrome issue by installing Xvfb and manually starting up an xwindow instance on display :0 (Display :0 is hardcoded in JibriSelenium.kt.

Also had to add additional flags when starting chrome. More details here if it helps anyone: Jibri - Chrome fails to start / PJSUA issues