Sip Video Gateway JIBRI No Video & Audio

Hi @damencho

I am able to stream video and able to do recording using jibri, but following error coming when trying sip video gateway. No Audio & video is coming or going to sip phone.

Following error is coming :

2020-05-23 16:58:46.568 INFO: [47] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {}, all clients muted? false
2020-05-23 16:58:46.569 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:58:48.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:58:50.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:58:52.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:58:54.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:58:56.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:58:58.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:59:00.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:59:01.530 INFO: [47] org.jitsi.jibri.selenium.JibriSelenium.run() Jibri client receive bitrates: {audio={download=33, upload=0}, download=781, upload=0, video={download=748, upload=0}}, all clients muted? false
2020-05-23 16:59:02.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:59:04.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:59:06.519 FINE: [47] org.jitsi.jibri.util.ProcessStatePublisher.pjsua.invoke() Process pjsua hasn’t written in 2 seconds, publishing periodic update
2020-05-23 16:59:06.523 INFO: [50] org.jitsi.jibri.service.impl.SipGatewayJibriService.onServiceStateChange() SIP gateway service transitioning from state Running to Error: PjsuaExitedPrematurely SESSION Pjsua exited with code 134
2020-05-23 16:59:06.524 INFO: [50] org.jitsi.jibri.api.xmpp.XmppApi.invoke() Current service had an error Error: PjsuaExitedPrematurely SESSION Pjsua exited with code 134, sending error iq
2020-05-23 16:59:06.527 FINE: [50] org.jitsi.jibri.statsd.JibriStatsDClient.incrementCounter() Incrementing statsd counter: stop:sip_gateway
2020-05-23 16:59:06.528 INFO: [50] org.jitsi.jibri.JibriManager.stopService() Stopping the current service
2020-05-23 16:59:06.528 INFO: [50] org.jitsi.jibri.util.JibriSubprocess.pjsua.stop() Stopping pjsua process
2020-05-23 16:59:06.531 INFO: [50] org.jitsi.jibri.util.JibriSubprocess.pjsua.stop() pjsua exited with value 134
2020-05-23 16:59:06.532 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Leaving call and quitting browser
2020-05-23 16:59:06.532 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Recurring call status checks cancelled
2020-05-23 16:59:06.564 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Got 24 log entries for type browser
2020-05-23 16:59:06.662 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Got 689 log entries for type driver
2020-05-23 16:59:06.856 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Got 0 log entries for type client
2020-05-23 16:59:06.856 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Leaving web call
2020-05-23 16:59:07.171 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Quitting chrome driver
2020-05-23 16:59:07.248 INFO: [50] org.jitsi.jibri.selenium.JibriSelenium.leaveCallAndQuitBrowser() Chrome driver quit
2020-05-23 16:59:07.248 INFO: [50] org.jitsi.jibri.status.JibriStatusManager.log() Busy status has changed: BUSY -> IDLE
2020-05-23 16:59:07.249 INFO: [50] 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

================ JVB LOGS ===================================
2020-05-24 15:07:34.609 INFO: [173] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri conf_name=amit ufrag=ft3mr1e930mria epId=ddefbd4d local_ufrag=ft3mr1e930mria] ConnectivityCheckClient.processSuccessResponse#720: Nomination confirmed for pair: 122.160.221.52:10000/udp/srflx -> 172.105.47.145:42033/udp/prflx (stream-ddefbd4d.RTP).
2020-05-24 15:07:34.609 INFO: [173] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri conf_name=amit ufrag=ft3mr1e930mria name=stream-ddefbd4d epId=ddefbd4d local_ufrag=ft3mr1e930mria] CheckList.handleNominationConfirmed#406: Selected pair for stream stream-ddefbd4d.RTP: 122.160.221.52:10000/udp/srflx -> 172.105.47.145:42033/udp/prflx (stream-ddefbd4d.RTP)
2020-05-24 15:07:34.610 INFO: [53] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] TlsClientImpl.notifyServerVersion#165: Negotiated DTLS version DTLS 1.2
2020-05-24 15:07:34.614 INFO: [173] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri conf_name=amit ufrag=ft3mr1e930mria epId=ddefbd4d local_ufrag=ft3mr1e930mria] Agent.checkListStatesUpdated#1937: CheckList of stream stream-ddefbd4d is COMPLETED
2020-05-24 15:07:34.615 INFO: [173] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri conf_name=amit ufrag=ft3mr1e930mria epId=ddefbd4d local_ufrag=ft3mr1e930mria] Agent.setState#963: ICE state changed from Running to Completed.
2020-05-24 15:07:34.619 INFO: [173] [confId=1d47a6e8523161c0 epId=ddefbd4d local_ufrag=ft3mr1e930mria gid=ff41f0 stats_id=jibri conf_name=amit] IceTransport.iceStateChanged#321: ICE state changed old=Running new=Completed
2020-05-24 15:07:34.619 INFO: [173] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint$3.connected#401: ICE connected
2020-05-24 15:07:34.620 INFO: [173] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri conf_name=amit ufrag=ft3mr1e930mria epId=ddefbd4d local_ufrag=ft3mr1e930mria] Agent.logCandTypes#2045: Harvester used for selected pair for stream-ddefbd4d.RTP: srflx
2020-05-24 15:07:34.621 INFO: [186] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] DtlsTransport.startDtlsHandshake#98: Starting DTLS handshake
2020-05-24 15:07:34.638 INFO: [53] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] Endpoint$6.handshakeComplete#445: DTLS handshake complete
2020-05-24 15:07:34.640 INFO: [187] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] Endpoint.lambda$acceptSctpConnection$6#944: Attempting to establish SCTP socket connection
2020-05-24 15:07:34.665 INFO: [53] [confId=1d47a6e8523161c0 gid=ff41f0 conf_name=amit] Conference.dominantSpeakerChanged#446: ds_change ds_id=b2682546
2020-05-24 15:07:34.682 INFO: [186] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] TlsClientImpl.notifyServerVersion#165: Negotiated DTLS version DTLS 1.2
2020-05-24 15:07:34.762 INFO: [186] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint$6.handshakeComplete#445: DTLS handshake complete
2020-05-24 15:07:34.763 INFO: [53] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint.lambda$acceptSctpConnection$6#944: Attempting to establish SCTP socket connection
Got sctp association state update: 1
sctp is now up. was ready? false
2020-05-24 15:07:34.864 INFO: [53] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint$7.onReady#884: SCTP connection is ready, creating the Data channel stack
2020-05-24 15:07:34.865 INFO: [53] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint$7.onReady#911: Will wait for the remote side to open the data channel.
2020-05-24 15:07:34.866 INFO: [190] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] DataChannelStack.onIncomingDataChannelPacket#62: Received data channel open message
2020-05-24 15:07:34.867 INFO: [190] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint$7.lambda$onReady$1#892: Remote side opened a data channel.
2020-05-24 15:07:37.595 INFO: [177] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit ufrag=bc6go1e930mrhh epId=b2682546 local_ufrag=bc6go1e930mrhh] Agent.setState#963: ICE state changed from Completed to Terminated.
2020-05-24 15:07:37.596 INFO: [177] [confId=1d47a6e8523161c0 epId=b2682546 local_ufrag=bc6go1e930mrhh gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] IceTransport.iceStateChanged#321: ICE state changed old=Completed new=Terminated
2020-05-24 15:07:37.620 INFO: [177] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri conf_name=amit ufrag=ft3mr1e930mria epId=ddefbd4d local_ufrag=ft3mr1e930mria] Agent.setState#963: ICE state changed from Completed to Terminated.
2020-05-24 15:07:37.621 INFO: [177] [confId=1d47a6e8523161c0 epId=ddefbd4d local_ufrag=ft3mr1e930mria gid=ff41f0 stats_id=jibri conf_name=amit] IceTransport.iceStateChanged#321: ICE state changed old=Completed new=Terminated
2020-05-24 15:07:37.898 INFO: [19] Videobridge.createConference#320: create_conf, id=78e75d631c38753 gid=null logging=false
2020-05-24 15:07:37.917 INFO: [19] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.019S. Sticky failure: false
Got sctp association state update: 1
sctp is now up. was ready? false
2020-05-24 15:07:38.150 INFO: [187] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] Endpoint$7.onReady#884: SCTP connection is ready, creating the Data channel stack
2020-05-24 15:07:38.150 INFO: [187] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] Endpoint$7.onReady#911: Will wait for the remote side to open the data channel.
2020-05-24 15:07:38.151 INFO: [186] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] DataChannelStack.onIncomingDataChannelPacket#62: Received data channel open message
2020-05-24 15:07:38.195 INFO: [186] [confId=1d47a6e8523161c0 epId=b2682546 gid=ff41f0 stats_id=Kaycee-RbW conf_name=amit] Endpoint$7.lambda$onReady$1#892: Remote side opened a data channel.
2020-05-24 15:07:47.899 INFO: [19] Videobridge.createConference#320: create_conf, id=2dcc3f419e852ca6 gid=null logging=false
2020-05-24 15:07:47.959 INFO: [19] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.061S. Sticky failure: false
=======================================================================================2020-05-24 15:07:57.899 INFO: [19] Videobridge.createConference#320: create_conf, id=1c6c988d4cfc2c36 gid=null logging=false
2020-05-24 15:07:57.948 INFO: [19] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.05S. Sticky failure: false
2020-05-24 15:08:07.899 INFO: [19] Videobridge.createConference#320: create_conf, id=4d142c8f3112977a gid=null logging=false
2020-05-24 15:08:07.979 INFO: [19] AbstractHealthCheckService.run#171: Performed a successful health check in PT0.08S. Sticky failure: false
2020-05-24 15:08:11.356 INFO: [185] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] TlsClientImpl.notifyAlertReceived#211: close_notify received, connection closing
2020-05-24 15:08:11.414 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] AbstractEndpoint.expire#303: Expiring.
2020-05-24 15:08:11.415 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Transceiver.teardown#315: Tearing down
2020-05-24 15:08:11.415 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] RtpReceiverImpl.tearDown#287: Tearing down
2020-05-24 15:08:11.416 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] RtpSenderImpl.tearDown#263: Tearing down
2020-05-24 15:08:11.418 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] DtlsTransport.stop#180: Stopping
2020-05-24 15:08:11.419 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d local_ufrag=ft3mr1e930mria gid=ff41f0 stats_id=jibri conf_name=amit] IceTransport.stop#235: Stopping
2020-05-24 15:08:11.420 INFO: [172] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri componentId=1 conf_name=amit ufrag=ft3mr1e930mria name=stream-ddefbd4d epId=ddefbd4d local_ufrag=ft3mr1e930mria] MergingDatagramSocket$SocketContainer.runInReaderThread#770: Failed to receive: java.net.SocketException: Socket closed
2020-05-24 15:08:11.420 WARNING: [172] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri componentId=1 conf_name=amit ufrag=ft3mr1e930mria name=stream-ddefbd4d epId=ddefbd4d local_ufrag=ft3mr1e930mria] MergingDatagramSocket.doRemove#349: Removing the active socket. Won’t be able to send until a new one is elected.
2020-05-24 15:08:11.422 INFO: [181] [confId=1d47a6e8523161c0 gid=ff41f0 stats_id=jibri componentId=1 conf_name=amit ufrag=ft3mr1e930mria name=stream-ddefbd4d epId=ddefbd4d local_ufrag=ft3mr1e930mria] MergingDatagramSocket.close#142: Closing.
2020-05-24 15:08:11.422 INFO: [185] [confId=1d47a6e8523161c0 epId=ddefbd4d local_ufrag=ft3mr1e930mria gid=ff41f0 stats_id=jibri conf_name=amit] IceTransport.startReadingData#201: Socket closed, stopping reader
2020-05-24 15:08:11.423 INFO: [181] [confId=1d47a6e8523161c0 epId=ddefbd4d gid=ff41f0 stats_id=jibri conf_name=amit] Endpoint.expire#811: Expired.
2020-05-24 15:08:11.423 INFO: [185] [confId=1d47a6e8523161c0 epId=ddefbd4d local_ufrag=ft3mr1e930mria gid=ff41f0 stats_id=jibri conf_name=amit] IceTransport.startReadingData#213: No longer running, stopped reading packets

Hi,

Any suggestion.

Thanks.