Stability issues with Jigasi and JVB. javax.media.ClockStartedError and unable to handle format: LINEAR


#1

We are continuing to run into stability issues with our Jitsi / Jigasi cluster. Video conferences seem to be working reasonably well, but every 4-5 conference sessions, transcription in Jigasi fails. We are running in AWS and using the docker setup. We notice the following exceptions and errors in the logs reasonably consistently. If anyone has any suggestions or can offer any advice, we would even be willing to pay for consulting to help diagnose and solve this problem (as we’ve been debugging for weeks).

Based on the logs, the error seems to be related to an issue between Jigasi and JVB. The first issue we notice is:

2018-08-20 15:50:04.363 SEVERE: [1645] impl.protocol.jabber.InfoRetreiver.retrieveDetails().369 Cannot load details for contact 16558076463@meet.chatterbubble.com : XMPP error reply received from 16558076463@meet.chatterbubble.com: XMPPError: item-not-found - cancel

And then we also notice:

2018-08-20 15:50:05.221 SEVERE: [682] service.protocol.AbstractCallPeer.fireCallPeerChangeEvent().433 Error dispatching event of typeCallPeerStatusChange in Call: id=15347802044272137357133 peers=1
javax.media.ClockStartedError: deallocate cannot be used on a started controller.

and:

Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed,

I’ve copied the full log snippet below, so that you can see everything together. We’ve tried tweaking ICE settings and other configuration changes, but we can’t get things to work reliably/consistently.

I was wondering whether the first error about not being able to retrieve details from the user might be causing the other downstream problems, but it isn’t clear why retrieving user details would cause these media streaming-related problems. It’s also strange why this does work some times, but not others. We do see invalid rtt messages with large (negative) numbers being reported back for rtt, but I’m not sure whether this is relevant or not.

Thanks in advance for your help. Here are the relevant logs:

2018-08-20 15:50:04.131 WARNING: [73] org.jitsi.jigasi.xmpp.CallControl.checkAuthorized().262 Requests are not secured by JID filter!
2018-08-20 15:50:04.131 INFO: [73] org.jitsi.jigasi.xmpp.CallControl.handleDialIq().188 Got dial request fromnumber -> jitsi_meet_transcribe room: test201149@conference.meet.chatterbubble.com
2018-08-20 15:50:04.132 INFO: [73] org.jitsi.jigasi.JvbConference.setXmppProvider().532 16558076463@callcontrol.meet.chatterbubble.com will use ProtocolProviderServiceJabberImpl(16558076463@meet.chatterbubble.com (Jabber))
2018-08-20 15:50:04.147 WARNING: [73] org.jitsi.xmpp.component.ComponentBase.verifyProcessingTime().540 PROCESSING TIME LIMIT EXCEEDED - it took 16ms to process:
2018-08-20 15:50:04.247 INFO: [1620] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().125 Jingle : ON
2018-08-20 15:50:04.247 INFO: [1620] org.jitsi.jigasi.JvbConference.registrationStateChanged().571 XMPP (16558076463@callcontrol.meet.chatterbubble.com): RegistrationStateChangeEvent[ oldState=Registering; newState=RegistrationState=Registering; reasonCode=-1; reason=null]
2018-08-20 15:50:04.259 INFO: [1620] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2457 Authenticated: false
2018-08-20 15:50:04.260 INFO: [1620] org.jitsi.jigasi.JvbConference.joinConferenceRoom().612 Joining JVB conference room: test201149@conference.meet.chatterbubble.com
2018-08-20 15:50:04.260 INFO: [1620] org.jitsi.jigasi.JvbConference.joinConferenceRoom().618 No focus in the room, let’s invite it!
2018-08-20 15:50:04.301 WARNING: [1620] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.302 INFO: [1630] impl.protocol.jabber.ChatRoomJabberImpl.joined().1236 test201149@conference.meet.chatterbubble.com/focus has joined the test201149@conference.meet.chatterbubble.com chat room.
2018-08-20 15:50:04.304 WARNING: [1633] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.305 WARNING: [1632] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.306 WARNING: [1630] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.306 WARNING: [1635] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.307 WARNING: [1640] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.309 WARNING: [1636] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.316 WARNING: [1633] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.316 WARNING: [1632] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.316 INFO: [1630] org.jitsi.jigasi.JvbConference.memberPresenceChanged().780 Member presence change: ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl@66958078 member=net.java.sip.communicator.impl.protocol.jabber.ChatRoomMemberJabberImpl@685262da]
2018-08-20 15:50:04.317 WARNING: [1635] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.322 WARNING: [1640] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.322 WARNING: [1636] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.337 INFO: [1630] impl.protocol.jabber.ChatRoomJabberImpl.joined().1236 test201149@conference.meet.chatterbubble.com/993a7e15 has joined the test201149@conference.meet.chatterbubble.com chat room.
2018-08-20 15:50:04.337 WARNING: [1630] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.337 INFO: [1630] org.jitsi.jigasi.JvbConference.memberPresenceChanged().780 Member presence change: ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl@66958078 member=net.java.sip.communicator.impl.protocol.jabber.ChatRoomMemberJabberImpl@63b3bbf4]
2018-08-20 15:50:04.349 WARNING: [1631] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.349 WARNING: [1631] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.352 INFO: [1630] impl.protocol.jabber.ChatRoomJabberImpl.joined().1236 test201149@conference.meet.chatterbubble.com/958f1f4d has joined the test201149@conference.meet.chatterbubble.com chat room.
2018-08-20 15:50:04.352 WARNING: [1630] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.352 INFO: [1630] org.jitsi.jigasi.JvbConference.memberPresenceChanged().780 Member presence change: ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl@66958078 member=net.java.sip.communicator.impl.protocol.jabber.ChatRoomMemberJabberImpl@494097ae]
2018-08-20 15:50:04.362 WARNING: [1633] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.362 WARNING: [1633] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.363 WARNING: [1640] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.363 WARNING: [1640] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.363 SEVERE: [1645] impl.protocol.jabber.InfoRetreiver.retrieveDetails().369 Cannot load details for contact 16558076463@meet.chatterbubble.com : XMPP error reply received from 16558076463@meet.chatterbubble.com: XMPPError: item-not-found - cancel
2018-08-20 15:50:04.366 INFO: [1630] impl.protocol.jabber.ChatRoomJabberImpl.joined().1236 test201149@conference.meet.chatterbubble.com/0e64b7ec has joined the test201149@conference.meet.chatterbubble.com chat room.
2018-08-20 15:50:04.366 WARNING: [1630] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:04.366 INFO: [1630] org.jitsi.jigasi.JvbConference.memberPresenceChanged().780 Member presence change: ChatRoomMemberPresenceChangeEvent[type=MemberJoined sourceRoom=net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl@66958078 member=net.java.sip.communicator.impl.protocol.jabber.ChatRoomMemberJabberImpl@3e2009]
2018-08-20 15:50:04.420 INFO: [1630] impl.protocol.jabber.ChatRoomJabberImpl.subjectUpdated().2386 Subject updated to
2018-08-20 15:50:04.426 INFO: [1651] impl.protocol.jabber.JingleNodesServiceDiscovery.run().110 Start Jingle Nodes discovery!
2018-08-20 15:50:04.427 INFO: [1651] impl.protocol.jabber.JingleNodesServiceDiscovery.run().150 Jingle Nodes discovery terminated!
2018-08-20 15:50:04.427 INFO: [1651] impl.protocol.jabber.JingleNodesServiceDiscovery.run().151 Found 0 Jingle Nodes relay for account: 16558076463@meet.chatterbubble.com in 1 ms.
2018-08-20 15:50:04.533 INFO: [1653] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().190 Auto discovered harvester is null
2018-08-20 15:50:04.541 INFO: [1653] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().282 End gathering harvester within 62 ms
2018-08-20 15:50:04.541 INFO: [1653] org.ice4j.ice.Agent.log() Gathering candidates for component audio.RTP. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.574 INFO: [1661] impl.protocol.jabber.JingleNodesHarvester.harvest().92 harvest Jingle Nodes
2018-08-20 15:50:04.652 INFO: [1653] org.ice4j.ice.Agent.log() Gathering candidates for component audio.RTCP. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.754 INFO: [1653] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 213 ms
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Component.log() Add remote candidate for audio.RTP: 192.168.164.4:10000/udp/host
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Component.log() Add remote candidate for audio.RTCP: 192.168.164.4:10001/udp/host
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Component.log() Add remote candidate for audio.RTP: 18.204.213.252:10000/udp/srflx
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Component.log() Add remote candidate for audio.RTCP: 18.204.213.252:10001/udp/srflx
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Agent.log() Start ICE connectivity establishment. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Agent.log() Init checklist for stream audio
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.Agent.log() ICE state changed from Waiting to Running. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.754 INFO: [1653] org.ice4j.ice.ConnectivityCheckClient.log() Start connectivity checks. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.758 INFO: [1653] org.jitsi.jigasi.JvbConference.incomingCallReceived().932 Got invite from focus
2018-08-20 15:50:04.791 INFO: [1654] org.ice4j.ice.ConnectivityCheckClient.log() Pair succeeded: 192.168.77.97:10019/udp/host -> 192.168.164.4:10000/udp/host (audio.RTP). Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.791 INFO: [1654] org.ice4j.socket.MergingDatagramSocket.log() Adding allowed address: 192.168.164.4:10000/udp
2018-08-20 15:50:04.791 INFO: [1654] org.ice4j.ice.ConnectivityCheckClient.log() Pair validated: 192.168.77.97:10019/udp/host -> 192.168.164.4:10000/udp/host (audio.RTP). Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.791 INFO: [1654] org.ice4j.ice.ConnectivityCheckClient.log() IsControlling: false USE-CANDIDATE:false. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.795 INFO: [1655] org.ice4j.ice.CheckList.log() Selected pair for stream audio.RTP: 192.168.77.97:10019/udp/host -> 192.168.164.4:10000/udp/host (audio.RTP)
2018-08-20 15:50:04.813 INFO: [1656] org.ice4j.ice.ConnectivityCheckClient.log() Pair succeeded: 192.168.77.97:10020/udp/host -> 192.168.164.4:10001/udp/host (audio.RTCP). Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.814 INFO: [1656] org.ice4j.socket.MergingDatagramSocket.log() Adding allowed address: 192.168.164.4:10001/udp
2018-08-20 15:50:04.814 INFO: [1656] org.ice4j.ice.ConnectivityCheckClient.log() Pair validated: 192.168.77.97:10020/udp/host -> 192.168.164.4:10001/udp/host (audio.RTCP). Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.814 INFO: [1656] org.ice4j.ice.ConnectivityCheckClient.log() IsControlling: false USE-CANDIDATE:false. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.835 INFO: [1656] org.ice4j.ice.CheckList.log() Selected pair for stream audio.RTCP: 192.168.77.97:10020/udp/host -> 192.168.164.4:10001/udp/host (audio.RTCP)
2018-08-20 15:50:04.837 INFO: [1655] org.ice4j.socket.MergingDatagramSocket.log() Adding allowed address: 18.204.213.252:10001/udp
2018-08-20 15:50:04.837 INFO: [1655] org.ice4j.ice.Agent.log() CheckList of stream audio is COMPLETED
2018-08-20 15:50:04.837 INFO: [1655] org.ice4j.ice.Agent.log() ICE state changed from Running to Completed. Local ufrag fvta91clc0epe3
2018-08-20 15:50:04.838 INFO: [1655] org.ice4j.ice.Agent.log() Harvester used for selected pair for audio.RTP (local ufrag fvta91clc0epe3): host
2018-08-20 15:50:04.838 INFO: [1655] org.ice4j.ice.Agent.log() Harvester used for selected pair for audio.RTCP (local ufrag fvta91clc0epe3): host
2018-08-20 15:50:04.891 INFO: [682] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1001 Dynamic PT map: 126=rtpmap:-1 telephone-event/8000; 111=rtpmap:-1 opus/48000/2 fmtp:useinbandfec=1;minptime=10; 103=rtpmap:-1 unknown/90000;
2018-08-20 15:50:04.891 INFO: [682] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1018 PT overrides [103->104 ]
2018-08-20 15:50:04.898 INFO: [682] service.protocol.media.CallPeerMediaHandler.start().1963 Starting
2018-08-20 15:50:04.952 WARNING: [1672] org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.log() Unknown DTLS handshake message type: 48
2018-08-20 15:50:04.961 INFO: [1672] org.jitsi.impl.neomedia.transform.srtp.AES.log() AES benchmark (of execution times expressed in nanoseconds): BouncyCastle 206750, SunJCE 85318, SunPKCS11 442709
2018-08-20 15:50:05.007 WARNING: [1671] org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.log() Unknown DTLS handshake message type: 68
2018-08-20 15:50:05.019 INFO: [1676] net.sf.fmj.media.Log.info() Resetting queue, last seq added: 9223372036854775806, current seq: 13874
2018-08-20 15:50:05.026 INFO: [1676] net.sf.fmj.media.Log.info() Resetting queue, last seq added: 9223372036854775806, current seq: 27199
2018-08-20 15:50:05.026 INFO: [1676] net.sf.fmj.media.Log.info() Resetting queue, last seq added: 9223372036854775806, current seq: 14691
2018-08-20 15:50:05.094 INFO: [1700] net.sf.fmj.media.Log.info() Starting RTPSourceStream.
2018-08-20 15:50:05.114 INFO: [1709] net.sf.fmj.media.Log.info() Starting RTPSourceStream.
2018-08-20 15:50:05.117 INFO: [1711] net.sf.fmj.media.Log.info() Starting RTPSourceStream.
2018-08-20 15:50:05.122 INFO: [682] org.jitsi.impl.neomedia.MediaStreamImpl.log() audio codec/freq: opus/48000 Hz
2018-08-20 15:50:05.122 INFO: [682] org.jitsi.impl.neomedia.MediaStreamImpl.log() audio remote IP/port: 192.168.164.4/10000
2018-08-20 15:50:05.142 INFO: [682] net.sf.fmj.media.Log.info() Starting RTPSourceStream.
2018-08-20 15:50:05.143 INFO: [682] net.sf.fmj.media.Log.info() Starting RTPSourceStream.
2018-08-20 15:50:05.143 INFO: [682] net.sf.fmj.media.Log.info() Starting RTPSourceStream.
2018-08-20 15:50:05.143 INFO: [682] org.jitsi.jigasi.JvbConference.onJvbCallStarted().715 JVB conference call IN_PROGRESS test201149@conference.meet.chatterbubble.com
2018-08-20 15:50:05.143 INFO: [682] org.jitsi.jigasi.transcription.GoogleCloudTranscriptionService.log() googleCredentials: ServiceAccountCredentials{clientId=101290649615321651988, clientEmail=transcription-service@chatterbubble-stag.iam.gserviceaccount.com, privateKeyId=a0bf883a44b9d2cbe7b1f536f72b44e7f5c16ac6, transportFactoryClassName=com.google.auth.oauth2.OAuth2Utils$DefaultHttpTransportFactory, tokenServerUri=https://accounts.google.com/o/oauth2/token, scopes=[], serviceAccountUser=null}
2018-08-20 15:50:05.220 INFO: [682] net.sf.fmj.media.Log.info() Stopping RTPSourceStream.
2018-08-20 15:50:05.220 INFO: [682] net.sf.fmj.media.Log.info() Stopping RTPSourceStream.
2018-08-20 15:50:05.221 SEVERE: [682] service.protocol.AbstractCallPeer.fireCallPeerChangeEvent().433 Error dispatching event of typeCallPeerStatusChange in Call: id=15347802044272137357133 peers=1
javax.media.ClockStartedError: deallocate cannot be used on a started controller.
at net.sf.fmj.media.BasicController.deallocate(BasicController.java:334)
at net.sf.fmj.media.BasicPlayer.abortPrefetch(BasicPlayer.java:100)
at net.sf.fmj.media.BasicController.deallocate(BasicController.java:353)
at org.jitsi.impl.neomedia.protocol.TranscodingDataSource.disconnect(TranscodingDataSource.java:196)
at org.jitsi.impl.neomedia.conference.InDataSourceDesc.disconnect(InDataSourceDesc.java:210)
at org.jitsi.impl.neomedia.conference.AudioMixer.disconnect(AudioMixer.java:502)
at org.jitsi.impl.neomedia.conference.AudioMixingPushBufferDataSource.disconnect(AudioMixingPushBufferDataSource.java:171)
at org.jitsi.impl.neomedia.device.MediaDeviceSession.disconnectCaptureDevice(MediaDeviceSession.java:674)
at org.jitsi.impl.neomedia.device.MediaDeviceSession.close(MediaDeviceSession.java:366)
at org.jitsi.impl.neomedia.device.AudioMixerMediaDevice$AudioMixerMediaDeviceSession.removeMediaStreamMediaDeviceSession(AudioMixerMediaDevice.java:908)
at org.jitsi.impl.neomedia.device.AudioMixerMediaDevice$MediaStreamMediaDeviceSession.close(AudioMixerMediaDevice.java:1041)
at org.jitsi.impl.neomedia.MediaStreamImpl.setDevice(MediaStreamImpl.java:2740)
at net.java.sip.communicator.service.protocol.media.CallPeerMediaHandler.callPropertyChange(CallPeerMediaHandler.java:427)
at net.java.sip.communicator.service.protocol.media.CallPeerMediaHandler.access$000(CallPeerMediaHandler.java:50)
at net.java.sip.communicator.service.protocol.media.CallPeerMediaHandler$CallPropertyChangeListener.propertyChange(CallPeerMediaHandler.java:2141)
at java.beans.PropertyChangeSupport.fire(PropertyChangeSupport.java:335)
at java.beans.PropertyChangeSupport.firePropertyChange(PropertyChangeSupport.java:327)
at java.beans.PropertyChangeSupport.firePropertyChange(PropertyChangeSupport.java:263)
at net.java.sip.communicator.service.protocol.AbstractCall.firePropertyChange(AbstractCall.java:198)
at net.java.sip.communicator.service.protocol.media.MediaAwareCall.firePropertyChange(MediaAwareCall.java:961)
at net.java.sip.communicator.service.protocol.Call.setConference(Call.java:559)
at net.java.sip.communicator.service.protocol.media.MediaAwareCall.setConference(MediaAwareCall.java:974)
at org.jitsi.jigasi.TranscriptionGatewaySession.onConferenceCallStarted(TranscriptionGatewaySession.java:155)
at org.jitsi.jigasi.JvbConference.onJvbCallStarted(JvbConference.java:723)
at org.jitsi.jigasi.JvbConference.access$1300(JvbConference.java:55)
at org.jitsi.jigasi.JvbConference$JvbCallChangeListener.callStateChanged(JvbConference.java:1047)
at net.java.sip.communicator.service.protocol.Call.fireCallChangeEvent(Call.java:362)
at net.java.sip.communicator.service.protocol.Call.setCallState(Call.java:408)
at net.java.sip.communicator.service.protocol.media.MediaAwareCall.setCallState(MediaAwareCall.java:833)
at net.java.sip.communicator.service.protocol.Call.setCallState(Call.java:385)
at net.java.sip.communicator.service.protocol.media.MediaAwareCall.peerStateChanged(MediaAwareCall.java:287)
at net.java.sip.communicator.service.protocol.AbstractCallPeer.fireCallPeerChangeEvent(AbstractCallPeer.java:428)
at net.java.sip.communicator.service.protocol.AbstractCallPeer.setState(AbstractCallPeer.java:959)
at net.java.sip.communicator.service.protocol.media.MediaAwareCallPeer.setState(MediaAwareCallPeer.java:1061)
at net.java.sip.communicator.impl.protocol.jabber.CallPeerJabberImpl.setState(CallPeerJabberImpl.java:1495)
at net.java.sip.communicator.service.protocol.AbstractCallPeer.setState(AbstractCallPeer.java:931)
at net.java.sip.communicator.service.protocol.AbstractCallPeer.setState(AbstractCallPeer.java:917)
at net.java.sip.communicator.impl.protocol.jabber.CallPeerJabberImpl.answer(CallPeerJabberImpl.java:259)
at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.answerCallPeer(OperationSetBasicTelephonyJabberImpl.java:805)
at org.jitsi.jigasi.CallManager$AnswerCallThread.run(CallManager.java:309)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
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)
2018-08-20 15:50:05.225 INFO: [682] org.jitsi.jigasi.JvbConference.peerStateChanged().998 16558076463@callcontrol.meet.chatterbubble.com JVB peer state: net.java.sip.communicator.service.protocol.CallPeerState:Connected
2018-08-20 15:50:05.225 INFO: [682] org.jitsi.jigasi.JvbConference.advertisePeerSSRCs().263 Peer net.java.sip.communicator.service.protocol.CallPeerState:Connected SSRCs audio: 3978463206 video: null
2018-08-20 15:50:05.225 SEVERE: [1755] net.sf.fmj.media.Log.error() Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2018-08-20 15:50:05.225 SEVERE: [1755] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@1154b530
2018-08-20 15:50:05.226 SEVERE: [1752] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@1154b530

2018-08-20 15:50:05.230 WARNING: [1639] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:05.230 WARNING: [1639] service.resources.AbstractResourcesService.getI18NString().530 Missing resource for key: service.gui.NOT_IN_CONTACT_LIST_GROUP_NAME
2018-08-20 15:50:07.870 INFO: [1668] org.ice4j.ice.Agent.log() ICE state changed from Completed to Terminated. Local ufrag fvta91clc0epe3
2018-08-20 15:50:10.885 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 8
2018-08-20 15:50:10.885 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 8
2018-08-20 15:50:10.970 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:10.980 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:11.556 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 8
2018-08-20 15:50:11.985 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:13.385 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:13.386 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:13.504 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:13.504 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:15.915 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:15.915 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:16.007 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:16.007 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:18.405 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:18.406 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:18.561 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:18.562 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:20.960 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:20.960 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:21.089 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:21.090 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:23.654 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:23.655 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:23.656 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:23.656 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:26.025 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:26.026 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:26.169 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:26.169 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:28.565 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:28.566 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:28.713 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:28.714 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:31.096 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:31.096 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:31.248 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:31.249 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:33.869 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:33.869 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:33.926 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:33.926 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:36.181 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:36.181 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:36.334 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:36.334 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:38.718 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:38.776 INFO: [1636] org.jitsi.jigasi.JvbConference.memberPresenceChanged().780 Member presence change: ChatRoomMemberPresenceChangeEvent[type=MemberUpdated sourceRoom=net.java.sip.communicator.impl.protocol.jabber.ChatRoomJabberImpl@66958078 member=net.java.sip.communicator.impl.protocol.jabber.ChatRoomMemberJabberImpl@494097ae]
2018-08-20 15:50:38.835 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:38.942 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:38.942 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:41.265 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:41.331 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:41.402 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:41.510 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:43.798 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:43.865 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:43.945 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:43.998 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:47.088 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:47.108 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:47.376 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:47.421 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:50.677 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:51.013 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:51.033 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:51.059 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:53.845 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:54.022 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:54.023 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:54.142 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:56.707 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:56.836 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:56.849 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:57.031 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:59.527 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:59.676 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:50:59.770 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:50:59.870 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:02.068 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:02.200 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:02.261 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:02.398 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:04.603 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:04.738 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:04.800 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:04.949 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:07.150 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:07.279 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:07.343 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:07.488 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:09.676 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:09.824 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:09.878 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:10.022 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:12.221 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:12.426 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:12.426 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:12.561 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:14.761 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:14.896 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16
2018-08-20 15:51:14.964 INFO: [1676] net.sf.fmj.media.Log.info() Shrinking packet queue to 15
2018-08-20 15:51:15.098 INFO: [1676] net.sf.fmj.media.Log.info() Growing packet queue to 16


#2

The item-not-found error is nothing to worry about, the same goes for “Unable to handle format” I think you can also see that in a working scenario.

The real problem is " deallocate cannot be used on a started controller", I have currently no idea about that, but I will try debugging it these days.
I know that @Nik_V, who is working on the transcriptions reported this to me, and that it happens only on the first call when you start jigasi and then it is working fine. I will try to repro it, cause the previous time I tried I couldn’t reproduce it.


#3

Thanks for getting back to me. I really appreciate the feedback — it’s helpful to know that the main issue is likely due to “deallocate cannot be used on a started controller.” This is a difficult issue to reproduce, as it only happens every few conferences.

I tried stepping through the exception call hierarchy and it seems like this happens when a peer gets removed from the AudioMixer. AudioMixingPushBufferDataSource.disconnect gets called, which in turn calls disconnect on the AudioMixer. After decrementing the number of connected output AudioMixingPushBufferDataSources reading from the AudioMixer, the number of connected reaches 0, which triggers calling disconnect on all of the AudioMixer’s inDataSources.

These inDataSources appear to be an instance of TranscodingDataSource. In the TranscodingDataSource disconnect method, deallocate is called on the transcodingProcessor field. What seems to be the root of the problem is that the TranscodingProcessor is in a Prefetched state. This causes the abortPrefetch method to be called, which in turn calls deallocate on all the elements in the controllerList vector. One of these nested controllers appears to be in a started state, which triggers the exception:

I am still continuing to investigate, but if you have any other feedback or suggestions, please let me know. Finding a solution is a really big priority for us, so I really appreciate all of your help. As I mentioned before, we would be happy to pay someone a consulting fee to help us debug this for a few hours.

Thanks again,

Paul


#4

I was trying to reproduce it today on my dev instance and wasn’t able to see it even once :frowning:
You can notice few things, does it stop working when you are starting it, basically never works or in the middle of transcription session when it stops and you see the exception.
Also when it stops, is it when someone is muting/unmuting audio or video or someone is leaving/joining? What are the browsers in the conference chrome/firefox? Do you have p2p enabled?
I’m just shooting in the dark, trying to find any pattern that matches and will lead us to easily reproducing the issue.


#5

Hey @pfisher do you think there are occasions where it doesn’t work and you don’t see the exception?


#6

Hey @damencho — thank you so much for all your help investigating this!

Part of what makes this a bit tricky to debug is that it does work most of the time. But it seems it fails around 10-20% of the time, which is obviously a big factor affecting stability and usability.

From our tests so far, the issue always seem to happen when starting transcription, at the beginning of a conference. It does seem strange that the exception seems to relate to removing/deallocating/stopping a stream within the audioMixer, given that the error appears to happen when kicking off a transcription session.

Jitsi-Videobridge seems to be working pretty reliably, however, and we’ve tested this with 4+ participants and p2p disabled. I also used wireshark on the jitsi-videobridge server, and I don’t see anything that looks suspicious.

During our tests, the transcription fails almost immediately. From an application standpoint, transcription just doesn’t start (due to the errors mentioned previously). Restarting the conference sometimes fixes this (but not always).

We had originally setup JVB to run on port 100/udp and TCP/443. However, when we read that jigasi doesn’t yet support rtcp-mux/bundle, we switched to running JVB on ports 10000-11000/udp and TCP/443. Is this correct? Can we assume that jigasi still doesn’t support rtcp-mux?

Some things that we have noticed, specifically with Jigasi, is that we see warnings related to (sometimes a lot in a row):

JVB 2018-08-13 23:55:15.459 WARNING: [19208] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 16535b66460 not ready yet.

We’ve also seen a bunch of these messages:

2018-08-13 23:45:53.747 INFO: [1372] net.sf.fmj.media.Log.info() Shrinking packet queue to 15

We have also seen sporadic warnings related to DTLS, such as:

org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl is closed!

as well as:

2018-08-13 14:53:08.661 WARNING: [110] org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.log() Unknown DTLS handshake message type: -21

In the latter DTLS warning, we have seen the message type with a range of seemingly random numbers.

The last type of log message we have noticed is a warning related to invalid_rtt. In these log messages, we see invalid_rtt values that seem way off (often negative, but corresponding to 9 hours offset, based on our calculation — which might be wrong).

Anyway, please let me know what you think, or if you have any questions. Sorry for the long response — I just wanted to give you as much context as possible. Please let me know if there’s anything else we can do to help, or if you have any more questions. We will also continue to debug on this end and will let you know if we find anything else.

Thanks again,

Paul


#7

Can you test with build 206 of jigasi and see do you still reproduce this?


#8

Thanks for the update on build 206! These recent changes seem to fix the exception mentioned earlier, and overall Jigasi seems a lot more stable for transcription!

However, we now have a new issue in which the transcription doesn’t stop — even after all the participants have left a conference room. We also have noticed that there are often two transcribers in the meeting (and two wav files getting written, etc.). I’m not sure if these two issues are related, however.

Please let me know what you think. I am guessing that the “un-ending transcription” might be related to the new delay/thread before stopping a JVBConference after there are no remaining participants requesting transcription:

if(transcriber.isTranscribing() &&
!transcriber.isAnyParticipantRequestingTranscription())
{
new Thread(() ->
{
try
{
Thread.sleep(PRESENCE_UPDATE_WAIT_UNTIL_LEAVE_DURATION);
}
catch (InterruptedException e)
{
logger.error(“interruptedException while waiting PRESENCE_UPDATE_WAIT_UNTIL_LEAVE_DURATION to check whether there are still remaining participants requesting transcription”);
}

if(!transcriber.isAnyParticipantRequestingTranscription())
{
jvbConference.stop();
}
}).start();
}
}

Thanks again for all of your help — I really appreciate it! Please let me know if you have any suggestions, or if there’s anything else I can do to help.

Best,

Paul