Inconsistent behavior/failures with Jigasi/Transcription

[pfisher]

Description

We are running into instability issues with Jigasi (and potentially JVB). Everything works OK for a little while, and then (when starting a new conference), we will suddenly see errors in the logs, and notice that transcription fails.

Current behavior

We have spent a while trying to diagnose and debug this issue, but since there are a number of warning and error messages in the logs, it is difficult to pinpoint the cause of the problem. We have noticed a few abnormalities in the logs, such as the following:

We will suddenly get a ton of the following error. This appears in the JVB logs rather frequently, and usually includes a large block of the same type of error:

EndpointMessageTransport: No available transport channel

JVB 2018-08-07 22:34:20.701 FINE: [139] org.jitsi.videobridge.xmpp.ComponentImpl.log() RECV:
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632bf8f not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632bfc1 not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632c2cb not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632c2fd not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632c5ba not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632c654 not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632c8dc not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632c978 not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632cc37 not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632ccd3 not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632cd86 not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632cfcd not ready yet.
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() No available transport channel, can't send a message
JVB 2018-08-07 22:34:21.647 WARNING: [24] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with 1651632d01d not ready yet.

DatagramTransportImpl is closed

We have also seen the following error in the Jigasi logs:

java.lang.IllegalStateException: java.io.IOException: org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl is closed!
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.queueReceive(DatagramTransportImpl.java:299)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.reverseTransformDtls(DtlsPacketTransformer.java:893)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.transformDtls(DtlsPacketTransformer.java:1427)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.transform(DtlsPacketTransformer.java:1373)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.reverseTransform(DtlsPacketTransformer.java:857)
at org.jitsi.impl.neomedia.transform.TransformEngineChain$PacketTransformerChain.reverseTransform(TransformEngineChain.java:381)
at org.jitsi.impl.neomedia.transform.TransformInputStream.createRawPacket(TransformInputStream.java:85)
at org.jitsi.impl.neomedia.RTPConnectorInputStream.runInReceiveThread(RTPConnectorInputStream.java:768)
at org.jitsi.impl.neomedia.RTPConnectorInputStream.access$000(RTPConnectorInputStream.java:42)
at org.jitsi.impl.neomedia.RTPConnectorInputStream$3.run(RTPConnectorInputStream.java:565)
Caused by: java.io.IOException: org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl is closed!
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.assertNotClosed(DatagramTransportImpl.java:125)
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.queueReceive(DatagramTransportImpl.java:295)
... 9 more
JVB 2018-08-07 21:03:37.435 SEVERE: [6603] org.jitsi.impl.neomedia.RTPConnectorInputStream.log() Failed to receive a packet:
java.lang.IllegalStateException: java.io.IOException: org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl is closed!
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.queueReceive(DatagramTransportImpl.java:299)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.reverseTransformDtls(DtlsPacketTransformer.java:893)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.transformDtls(DtlsPacketTransformer.java:1427)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.transform(DtlsPacketTransformer.java:1373)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.reverseTransform(DtlsPacketTransformer.java:857)
at org.jitsi.impl.neomedia.transform.TransformEngineChain$PacketTransformerChain.reverseTransform(TransformEngineChain.java:381)
at org.jitsi.impl.neomedia.transform.TransformInputStream.createRawPacket(TransformInputStream.java:85)
at org.jitsi.impl.neomedia.RTPConnectorInputStream.runInReceiveThread(RTPConnectorInputStream.java:768)
at org.jitsi.impl.neomedia.RTPConnectorInputStream.access$000(RTPConnectorInputStream.java:42)
at org.jitsi.impl.neomedia.RTPConnectorInputStream$3.run(RTPConnectorInputStream.java:565)
Caused by: java.io.IOException: org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl is closed!
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.assertNotClosed(DatagramTransportImpl.java:125)
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.queueReceive(DatagramTransportImpl.java:295)
... 9 more

javax.media.ClockStartedError: deallocate cannot be used on a started controller.

We've also seen the following error in the JVB logs:

2018-08-13 23:54:38.116 SEVERE: [1365] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /172.17.0.1:15544:java.io.IOException: No active socket.
2018-08-13 23:54:38.123 SEVERE: [1320] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /172.17.0.1:15543:java.io.IOException: No active socket.
2018-08-13 23:54:38.127 SEVERE: [1320] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /172.17.0.1:15544:java.io.IOException: No active socket.
2018-08-13 23:54:38.137 SEVERE: [1320] util.UtilActivator.uncaughtException().122 An uncaught exception occurred in thread=Thread[Smack-Single Threaded Executor 0 (2),5,main] and message was: deallocate cannot be used on a started controller.
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.device.MediaDeviceSession.closeProcessor(MediaDeviceSession.java:411)
at org.jitsi.impl.neomedia.device.MediaDeviceSession.close(MediaDeviceSession.java:367)
at org.jitsi.impl.neomedia.device.AudioMixerMediaDevice$MediaStreamMediaDeviceSession.close(AudioMixerMediaDevice.java:1036)
at org.jitsi.impl.neomedia.MediaStreamImpl.close(MediaStreamImpl.java:849)
at org.jitsi.impl.neomedia.AudioMediaStreamImpl.close(AudioMediaStreamImpl.java:298)
at net.java.sip.communicator.service.protocol.media.MediaHandler.setAudioStream(MediaHandler.java:1252)
at net.java.sip.communicator.service.protocol.media.MediaHandler.closeStream(MediaHandler.java:638)
at net.java.sip.communicator.service.protocol.media.CallPeerMediaHandler.closeStream(CallPeerMediaHandler.java:488)
at net.java.sip.communicator.service.protocol.media.CallPeerMediaHandler.close(CallPeerMediaHandler.java:442)
at net.java.sip.communicator.impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.close(CallPeerMediaHandlerJabberImpl.java:223)
at net.java.sip.communicator.service.protocol.media.MediaAwareCallPeer.setState(MediaAwareCallPeer.java:1068)
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.impl.protocol.jabber.CallPeerJabberImpl.processSessionTerminate(CallPeerJabberImpl.java:966)
at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.processJingleIQ(OperationSetBasicTelephonyJabberImpl.java:1115)
at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.access$100(OperationSetBasicTelephonyJabberImpl.java:53)
at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl$JingleIqSetRequestHandler.handleIQRequest(OperationSetBasicTelephonyJabberImpl.java:1010)
at org.jivesoftware.smack.AbstractXMPPConnection$3.run(AbstractXMPPConnection.java:1153)
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)

Expected Behavior

These sporadic but consistent failures are preventing transcription in Jigasi from working reliably.

Possible Solution

---

We are wondering whether these issues might be related to a misconfiguration with ice4j or perhaps a discrepancy with native library versions.

Steps to reproduce

We can reliably reproduce these issues by testing a number of conferences and triggering transcription via Dial.

Environment details

---

Thanks in advance for all your help and any feedback or suggestions you might have.

[pfisher]

Just following up on this issue. One additional question that may be relevant: I noticed in the JVB docs that Jigasi doesn't support multiplexing multiple media streams on a single UDP port, due to the fact that it doesn't support channel-bundle and rtcp-mux. Is this limitation still the case, or has Jigasi since been upgraded to support these features?

I am wondering as perhaps it might explain some of these sporadic error messages we are seeing in the logs, such as occasional errors about a media format not being supported (when it should) or
javax.media.ClockStartedError: deallocate cannot be used on a started controller

Please let me know what you think!

[arts111188]

Hi,

Dear Jitsi Team,

Do you plan to fix this issue concerning rtcp-mux as @pfisher mentioned in the comment above.

Thanks in advance,

[damencho]

This is not on our roadmap, sorry. We would love to review PRs.

[ghost]

Hi @pfisher @arts111188 @damencho - just a heads-up that I think this may be closely related to what I'm seeing in jitsi/jitsi-meet#3738 ; in that case I'm using a chromium-webrtc based client to attempt to stream via jitsi-videobridge, but am seeing the same 'SCTP connection with ... not ready yet'

I do see that a connection is accepted by the videobridge:

/var/log/jitsi/jvb.log:JVB 2018-12-29 15:16:36.070 INFO: [235] org.jitsi.videobridge.SctpConnection.log() SCTP socket accepted for endpoint 8ec768f2

... but that connection doesn't become ready:

JVB 2018-12-29 15:16:36.097 WARNING: [234] org.jitsi.videobridge.EndpointMessageTransport.log() SCTP connection with Bunny not ready yet.
# repeated continuously, as per example in this issue

It looks like the section of code that's meant to bring the server socket into a ready state (at least for the version of jitsi-videobridge I'm running) is here:

https://github.com/jitsi/jitsi-videobridge/blob/4b3fd77cac7cc3d45b9bd8ce4217f531092bb5e7/src/main/java/org/jitsi/videobridge/SctpConnection.java#L747-L756

The question is why that isn't being reached, I suppose. Doing a bit more investigation currently.

[fuqiangleon]

@damencho
Hi ,brother, I have faced the same errors in jigasi logs ,what can i do to fix it ?

###jigasi###
2019-04-26 02:36:29.963 INFO: [89] org.jitsi.jigasi.TranscriptionGatewaySession.log() Transcriber: Media Device Audio
2019-04-26 02:36:29.976 SEVERE: [1319] org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.log() Failed to connect this DTLS client to a DTLS server!
java.io.IOException: org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl is closed!
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.assertNotClosed(DatagramTransportImpl.java:124)
at org.jitsi.impl.neomedia.transform.dtls.DatagramTransportImpl.send(DatagramTransportImpl.java:477)
at org.bouncycastle.crypto.tls.DTLSRecordLayer.sendRecord(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSRecordLayer.send(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSReliableHandshake$RecordLayerBuffer.sendToRecordLayer(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSReliableHandshake.writeHandshakeFragment(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSReliableHandshake.writeMessage(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSReliableHandshake.resendOutboundFlight(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSReliableHandshake.receiveMessage(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSReliableHandshake.receiveMessageBody(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSClientProtocol.clientHandshake(Unknown Source)
at org.bouncycastle.crypto.tls.DTLSClientProtocol.connect(Unknown Source)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.runInConnectThread(DtlsPacketTransformer.java:1017)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer.access$100(DtlsPacketTransformer.java:41)
at org.jitsi.impl.neomedia.transform.dtls.DtlsPacketTransformer$2.run(DtlsPacketTransformer.java:1283)
2019-04-26 02:36:29.978 INFO: [89] org.jitsi.jigasi.JvbConference.callStateChanged().1130 callStateChanged

[damencho]

Which jigasi version are you using? The latest in unstable has even rtcp-mux.

[fuqiangleon]

version 233 from jigasi repo @damencho

[damencho]

Can you try 234, it had a small change in DtlsPacketTransformer? Do you repro on every run or this is occasionally?

[fuqiangleon]

There are 3/6 times in testing .