stefanor commented 3 years ago

Description

No audio is carried when Jigasi runs under OpenJDK 17 on Debian bullseye.

We have an Asterisk in front of a jitsi+jigasi. When deployed on Debian 11 bullseye, with the default OpenJDK 17, no audio is carried after the conference room selection in Asterisk. Asterisk is configured to only use opus with jigasi.

Relevant issue seems to be:

SEVERE net.sf.fmj.media.Log.error():
Failed to build a graph for the given custom options.
Failed to realize: net.sf.fmj.media.ProcessEngine@52a5a34b
  Cannot build a flow graph with the customized options: 
    Unable to transcode format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
      to: opus/rtp, 48000.0 Hz, Stereo
      outputting to: raw.rtp
    Unable to add customed codecs:·
      org.jitsi.impl.neomedia.audiolevel.AudioLevelEffect2@2e8816de
Error: Unable to realize net.sf.fmj.media.ProcessEngine@52a5a34b

Downgrading to OpenJDK 11 makes it work again.

Current behaviour

Here are the relevant log lines from jigasi:

2021-08-21 23:16:20.807 INFO: [67] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=1629587780806902500081] Incoming call received...
2021-08-21 23:16:20.811 INFO: [69] org.jitsi.jigasi.SipGatewaySession.run().1721 [ctx=1629587780806902500081] Wait thread cancelled
2021-08-21 23:16:20.815 INFO: [67] org.jitsi.jigasi.JvbConference.start().493 [ctx=1629587780806902500081] Starting JVB conference room: TestCall
2021-08-21 23:16:20.821 INFO: [67] org.jitsi.jigasi.JvbConference.setXmppProvider().636 [ctx=1629587780806902500081] Using ProtocolProviderServiceJabberImpl(Jabber:5b60cdb4@jitsi.dc21.debconf.org/5b60cdb4)
2021-08-21 23:16:20.848 INFO: [72] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON 
2021-08-21 23:16:20.849 INFO: [72] org.jitsi.jigasi.JvbConference.registrationStateChanged().687 [ctx=1629587780806902500081] Registering XMPP.
2021-08-21 23:16:20.853 INFO: [72] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2423 Authenticated: false
2021-08-21 23:16:20.855 INFO: [72] org.jitsi.jigasi.JvbConference.joinConferenceRoom().778 [ctx=1629587780806902500081] Joining JVB conference room: TestCall@conference.jitsi.dc21.debconf.org
2021-08-21 23:16:20.871 INFO: [76] impl.protocol.jabber.ChatRoomJabberImpl.joined().1361 testcall@conference.jitsi.dc21.debconf.org/29167fe9 has joined the testcall@conference.jitsi.dc21.debconf.org chat room.
2021-08-21 23:16:20.872 INFO: [76] impl.protocol.jabber.ChatRoomJabberImpl.joined().1361 testcall@conference.jitsi.dc21.debconf.org/focus has joined the testcall@conference.jitsi.dc21.debconf.org chat room.
2021-08-21 23:16:22.212 INFO: [82] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().347 End gathering harvester within 1302 ms
2021-08-21 23:16:22.445 INFO: [82] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 20 ms
2021-08-21 23:16:22.449 INFO: [82] org.jitsi.jigasi.JvbConference.incomingCallReceived().1419 [ctx=1629587780806902500081] Got invite from focus
2021-08-21 23:16:22.557 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 107=rtpmap:-1 opus/48000/2; 
2021-08-21 23:16:22.557 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2021-08-21 23:16:22.563 INFO: [91] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1683 [ctx=1629587780806902500081] SIP peer state: Connecting*
2021-08-21 23:16:22.564 INFO: [100] org.jitsi.jigasi.SipGatewaySession.handleCallState().1600 [ctx=1629587780806902500081] Sip call IN_PROGRESS: Call: id=16295877807811387049923 peers=1
2021-08-21 23:16:22.564 INFO: [100] org.jitsi.jigasi.SipGatewaySession.handleCallState().1609 [ctx=1629587780806902500081] SIP call format used: rtpmap:-1 opus/48000/2
2021-08-21 23:16:22.565 INFO: [100] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1683 [ctx=1629587780806902500081] SIP peer state: Connected
2021-08-21 23:16:22.565 INFO: [100] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2021-08-21 23:16:22.567 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 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; 
2021-08-21 23:16:22.567 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2021-08-21 23:16:22.579 INFO: [91] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2021-08-21 23:16:22.664 SEVERE: [148] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2021-08-21 23:16:22.664 SEVERE: [148] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@5f1b678
2021-08-21 23:16:22.666 SEVERE: [147] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@5f1b678

2021-08-21 23:16:22.683 SEVERE: [150] net.sf.fmj.media.Log.error() Failed to build a graph for the given custom options.
2021-08-21 23:16:22.683 SEVERE: [150] net.sf.fmj.media.Log.error() Failed to realize: net.sf.fmj.media.ProcessEngine@5fc8fbc7
2021-08-21 23:16:22.684 SEVERE: [150] net.sf.fmj.media.Log.error()   Cannot build a flow graph with the customized options:
2021-08-21 23:16:22.684 SEVERE: [150] net.sf.fmj.media.Log.error()     Unable to transcode format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2021-08-21 23:16:22.684 SEVERE: [150] net.sf.fmj.media.Log.error()       to: opus/rtp, 48000.0 Hz, Stereo
2021-08-21 23:16:22.684 SEVERE: [150] net.sf.fmj.media.Log.error()       outputting to: raw.rtp
2021-08-21 23:16:22.684 SEVERE: [149] net.sf.fmj.media.Log.error() Error: Unable to realize net.sf.fmj.media.ProcessEngine@5fc8fbc7
2021-08-21 23:16:22.687 INFO: [100] service.protocol.media.TransportManager.sendHolePunchPacket().552 Send NAT hole punch packets
2021-08-21 23:16:22.697 SEVERE: [153] net.sf.fmj.media.Log.error() Failed to build a graph for the given custom options.
2021-08-21 23:16:22.698 SEVERE: [153] net.sf.fmj.media.Log.error() Failed to realize: net.sf.fmj.media.ProcessEngine@52a5a34b
2021-08-21 23:16:22.698 SEVERE: [153] net.sf.fmj.media.Log.error()   Cannot build a flow graph with the customized options:
2021-08-21 23:16:22.698 SEVERE: [153] net.sf.fmj.media.Log.error()     Unable to transcode format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2021-08-21 23:16:22.700 SEVERE: [153] net.sf.fmj.media.Log.error()       to: opus/rtp, 48000.0 Hz, Stereo
2021-08-21 23:16:22.700 SEVERE: [153] net.sf.fmj.media.Log.error()       outputting to: raw.rtp
2021-08-21 23:16:22.700 SEVERE: [153] net.sf.fmj.media.Log.error()     Unable to add customed codecs: 
2021-08-21 23:16:22.700 SEVERE: [153] net.sf.fmj.media.Log.error()       org.jitsi.impl.neomedia.audiolevel.AudioLevelEffect2@2e8816de
2021-08-21 23:16:22.700 SEVERE: [151] net.sf.fmj.media.Log.error() Error: Unable to realize net.sf.fmj.media.ProcessEngine@52a5a34b
2021-08-21 23:16:22.701 INFO: [91] org.jitsi.jigasi.JvbConference.callStateChanged().1530 [ctx=1629587780806902500081] JVB conference call IN_PROGRESS.
2021-08-21 23:16:22.732 INFO: [109] org.jitsi.srtp.crypto.OpenSslWrapperLoader.log() jitsisrtp successfully loaded
2021-08-21 23:16:27.566 SEVERE: [105] util.UtilActivator.uncaughtException().122 An uncaught exception occurred in thread=Thread[RTPEventHandler,9,system] and message was: getTrackControls cannot be called before configured
javax.media.NotConfiguredError: getTrackControls cannot be called before configured
        at net.sf.fmj.media.ProcessEngine.getTrackControls(ProcessEngine.java:1385)
        at net.sf.fmj.media.MediaProcessor.getTrackControls(MediaProcessor.java:113)
        at org.jitsi.impl.neomedia.device.MediaDeviceSession.getAllTrackControls(MediaDeviceSession.java:2521)
        at org.jitsi.impl.neomedia.device.MediaDeviceSession.getEncoderControls(MediaDeviceSession.java:2472)
        at org.jitsi.impl.neomedia.MediaStreamImpl.update(MediaStreamImpl.java:3599)
        at net.sf.fmj.media.rtp.RTPEventHandler.processEvent(RTPEventHandler.java:80)
        at net.sf.fmj.media.rtp.RTPEventHandler.dispatchEvents(RTPEventHandler.java:50)
        at net.sf.fmj.media.rtp.RTPEventHandler.run(RTPEventHandler.java:114)

Expected Behaviour

We expect sound to be carried. After downgrading to OpenJDK 11, the log entries are:

2021-08-21 23:21:46.124 INFO: [68] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=16295881061241058989745] Incoming call received...
2021-08-21 23:21:46.129 INFO: [70] org.jitsi.jigasi.SipGatewaySession.run().1721 [ctx=16295881061241058989745] Wait thread cancelled
2021-08-21 23:21:46.132 INFO: [68] org.jitsi.jigasi.JvbConference.start().493 [ctx=16295881061241058989745] Starting JVB conference room: TestCall
2021-08-21 23:21:46.141 INFO: [68] org.jitsi.jigasi.JvbConference.setXmppProvider().636 [ctx=16295881061241058989745] Using ProtocolProviderServiceJabberImpl(Jabber:431c1417@jitsi.dc21.debco
nf.org/431c1417)
2021-08-21 23:21:46.171 INFO: [73] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON 
2021-08-21 23:21:46.171 INFO: [73] org.jitsi.jigasi.JvbConference.registrationStateChanged().687 [ctx=16295881061241058989745] Registering XMPP.
2021-08-21 23:21:46.176 INFO: [73] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2423 Authenticated: false
2021-08-21 23:21:46.183 INFO: [73] org.jitsi.jigasi.JvbConference.joinConferenceRoom().778 [ctx=16295881061241058989745] Joining JVB conference room: TestCall@conference.jitsi.dc21.debconf.o
rg
2021-08-21 23:21:46.208 INFO: [77] impl.protocol.jabber.ChatRoomJabberImpl.joined().1361 testcall@conference.jitsi.dc21.debconf.org/29167fe9 has joined the testcall@conference.jitsi.dc21.deb
conf.org chat room.
2021-08-21 23:21:46.211 INFO: [77] impl.protocol.jabber.ChatRoomJabberImpl.joined().1361 testcall@conference.jitsi.dc21.debconf.org/focus has joined the testcall@conference.jitsi.dc21.debcon
f.org chat room.
2021-08-21 23:21:47.595 INFO: [82] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().347 End gathering harvester within 1306 ms
2021-08-21 23:21:47.803 INFO: [82] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 17 ms
2021-08-21 23:21:47.807 INFO: [82] org.jitsi.jigasi.JvbConference.incomingCallReceived().1419 [ctx=16295881061241058989745] Got invite from focus
2021-08-21 23:21:47.920 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 107=rtpmap:-1 opus/48000/2; 
2021-08-21 23:21:47.920 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2021-08-21 23:21:47.926 INFO: [91] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1683 [ctx=16295881061241058989745] SIP peer state: Connecting*
2021-08-21 23:21:47.934 INFO: [100] org.jitsi.jigasi.SipGatewaySession.handleCallState().1600 [ctx=16295881061241058989745] Sip call IN_PROGRESS: Call: id=16295881060981347438778 peers=1
2021-08-21 23:21:47.934 INFO: [100] org.jitsi.jigasi.SipGatewaySession.handleCallState().1609 [ctx=16295881061241058989745] SIP call format used: rtpmap:-1 opus/48000/2
2021-08-21 23:21:47.935 INFO: [100] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1683 [ctx=16295881061241058989745] SIP peer state: Connected
2021-08-21 23:21:47.935 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 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; 
2021-08-21 23:21:47.936 INFO: [91] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2021-08-21 23:21:47.939 INFO: [100] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2021-08-21 23:21:47.973 INFO: [91] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2021-08-21 23:21:48.148 INFO: [108] org.jitsi.srtp.crypto.OpenSslWrapperLoader.log() jitsisrtp successfully loaded
2021-08-21 23:21:48.178 SEVERE: [154] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2021-08-21 23:21:48.178 SEVERE: [154] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@1e5e4212
2021-08-21 23:21:48.179 SEVERE: [148] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@1e5e4212

2021-08-21 23:21:48.206 INFO: [100] service.protocol.media.TransportManager.sendHolePunchPacket().552 Send NAT hole punch packets
2021-08-21 23:21:48.224 INFO: [91] org.jitsi.jigasi.JvbConference.callStateChanged().1530 [ctx=16295881061241058989745] JVB conference call IN_PROGRESS.
2021-08-21 23:21:53.000 INFO: [195] org.jitsi.jigasi.SipGatewaySession.handleCallState().1617 [ctx=16295881061241058989745] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Connected newV=net.java.sip.communicator.service.protocol.CallPeerState:Disconnected for peer=Test Caller...1234 <415[REDACTED]@127.0.0.1>;status=Disconnected

Possible Workaround

Downgrade to OpenJDK 11.

Steps to reproduce

Provision jitsi+jigasi+asterisk on Debian 11.
Dial into jigasi.

Environment details

Debian 11 bullseye, amd64, OpenJDK 17

ii  jicofo                1.0-756-1           all          JItsi Meet COnference FOcus
ii  jigasi                1.1-195-g65ef768-1  amd64        Jitsi Gateway for SIP
ii  jitsi-meet            2.0.5963-1          all          WebRTC JavaScript video conferences
ii  jitsi-meet-prosody    1.0.5056-1          all          Prosody configuration for Jitsi Meet
ii  jitsi-meet-web        1.0.5056-1          all          WebRTC JavaScript video conferences
ii  jitsi-meet-web-config 1.0.5056-1          all          Configuration for web serving of Jitsi Meet
ii  jitsi-videobridge2    2.1-508-gb24f756c-1 all          WebRTC compatible Selective Forwarding Unit (SFU)
ii  openjdk-11-jre-headless:amd64 11.0.12+7-2  amd64        OpenJDK Java runtime, using Hotspot JIT (headless)
ii  openjdk-17-jre-headless:amd64 17~19-1      amd64        OpenJDK Java runtime, using Hotspot JIT (headless)

Ansible Config: https://salsa.debian.org/debconf-video-team/ansible/-/tree/master/roles/jitsi

damencho commented 3 years ago

Use java8 for the time beeing. We will work at some point to make sure it works with java11, but we are still not there.

damencho commented 3 years ago

Any help is welcome, we are happy to review any PRs. Thank you.

rasos commented 2 years ago

We have sound only in one direction (phone mic to Jitsi) but we do not hear anything on the phone speaker.

2022-01-23 09:38:30.995 SEVERE: [10] org.jitsi.impl.neomedia.device.DeviceConfiguration.log() Failed to register custom Renderer org.jitsi.impl.neomedia.jmfext.media.renderer.audio.PulseAudioRenderer with JMF.
...
2022-01-23 09:31:51.427 SEVERE: [187] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2022-01-23 09:31:51.432 SEVERE: [187] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@25a88eb3
2022-01-23 09:31:51.433 SEVERE: [186] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@25a88eb3
...
2022-01-23 09:32:59.626 SEVERE: [141] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /2a41:4f4:201:6241:0:0:0:2:10000:java.io.IOException: No active socket.

So it seems we have not an issue with the Java version, but probably that IPv6 may not supported by the active video bridge. However, firewall udp port 10000 is open for both IPv4 and IPv6 on this jvb server. Can we force Jigasi to talk with a jvb on IPv4?

For jicofo and jigasi we are still on openjdk version "1.8.0_312" (= Java 8), which is recommended here.

damencho commented 2 years ago

Don't hijack threads/issues reporting other problems.

Please, when you have questions or problems use the community forum before opening new issues, thank you.

-Djava.net.preferIPv4Stack=true

rasos commented 2 years ago

Ok, sorry, I thought it was related as I had some of the same SEVERE log entries and partially the same effect. Thanks for the hint with the IPv4 option, will give a try.

DouDOU-start commented 1 year ago

在arm架构操作系统上跑jigasi的时候也遇到了这个问题

Failed to build a graph for the given custom options. Failed to realize: net.sf.fmj.media.ProcessEngine@48c22159 Cannot build a flow graph with the customized options: Unable to transcode format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed to: opus/rtp, 48000.0 Hz, Stereo outputting to: raw.rtp Unable to add customed codecs: org.jitsi.impl.neomedia.audiolevel.AudioLevelEffect2@59562a94 Error: Unable to realize net.sf.fmj.media.ProcessEngine@48c22159

请问我应该怎样去解决这个问题呢

tgrymatt commented 1 year ago

Any news on this?

saghul commented 1 year ago

We deploy Jigasi with Java 11 so no news from our end.

TBG-FR commented 1 year ago

Debian 12 now uses Java 17 by default, so Jigasi won't work until you downgrade (not always possible or easy), and it could potentially come back with updates, breaking the calls :/

jbg commented 1 year ago

It works fine here on Java 17, built from source, along with libjnopus from libjitsi, libfvad, and jitsi-webrtc-vad-wrapper also built from source, so I suspect it might be to do with the native libraries being built against Java 11 and then being run against Java 17?