SIP call in (Jigasi) not working if local Videobridge gets disabled

Alex80 · April 13, 2022, 7:04am

I have the following set up:
JMS (Jitsi, Videobridge, Jicofo, Jigasi, …) on one server and running at another server with way more performance and bandwidth a second videobridge (connected via muc).
I would like to disable the local running videobridge on the JMS.
Everything looks fine so far but than I discovered that external persons cannot call in anymore via SIP.
In the logs I get the message that jigasi cannot connect to the JVB.
But I could not find out what I have to change to make this work.
Does anybody have any idea?

I found two other entries in this forum, already with the same problem.
One solution was to open firewall for port 10000/udp.
But this wasn’t my problem. Between these two server IPs there is no port being blocked.

The other person with this problem is in this thread:

But there is also no solution so far

Freddie · April 13, 2022, 8:51am

Are you saying everything works when both videobridges are active, but when you disable the local videobridge, then Jigasi stops working?

If so, do you see any errors in your browser’s js console when Jigasi is not working?

Alex80 · April 13, 2022, 9:42am

Thanks for the fast reply!
I also have to note that it is necessary to stop the external jvb sometimes too.
For me it looks like jigasi only works with local one running and if Jitsi uses the local JVB and not the external one.

Yes exactly.

Logs working case:
jigasi.log (JMS):

dSessionAccept>:  JingleSessionPC[session=JVB,initiator=false,sid=5uih5udjhmv5a] Sending session-accept
Logger.js:154 2022-04-13T09:32:33.341Z [modules/xmpp/JingleSessionPC.js] <ha.peerconnection.oniceconnectionstatechange>:  (TIME) ICE checking JVB:	 34670.39999997616
Logger.js:154 2022-04-13T09:32:33.390Z [modules/RTC/BridgeChannel.js] <WebSocket.e.onopen>:  websocket channel opened
Logger.js:154 2022-04-13T09:32:33.390Z [JitsiConferenceEventManager.js] <r.<anonymous>>:  (TIME) data.channel.opened:	 34720.19999998808
Logger.js:154 2022-04-13T09:32:33.391Z [modules/RTC/BridgeChannel.js] <Kr.sendNewReceiverVideoConstraintsMessage>:  Sending ReceiverVideoConstraints with {"constraints":{"2197223b":{"maxHeight":2160}},"defaultConstraints":{"maxHeight":0},"lastN":-1,"onStageEndpoints":["2197223b"],"selectedEndpoints":[]}
Logger.js:154 2022-04-13T09:32:33.392Z [modules/RTC/BridgeChannel.js] <WebSocket.e.onmessage>:  Received ServerHello, version=undefined.
app.bundle.min.js?v=5675:207 2022-04-13T09:32:33.426Z [modules/UI/videolayout/LargeVideoManager.js] hover in 2197223b
Logger.js:154 2022-04-13T09:32:33.451Z [modules/xmpp/JingleSessionPC.js] <ha.peerconnection.oniceconnectionstatechange>:  (TIME) ICE connected JVB:	 34781.30000001192
Logger.js:154 2022-04-13T09:32:33.476Z [modules/xmpp/JingleSessionPC.js] <br.sendIceCandidate>:  JingleSessionPC[session=JVB,initiator=false,sid=5uih5udjhmv5a] sendIceCandidate: last candidate
Logger.js:154 2022-04-13T09:32:33.501Z [modules/xmpp/JingleSessionPC.js] <br.sendIceCandidates>:  JingleSessionPC[session=JVB,initiator=false,sid=5uih5udjhmv5a] sendIceCandidates [{"candidate":"candidate:4267274805 1 udp 2122262783 2003:c0:7f17:6c00:d0ab:9e2:45ff:aaba 47950 typ host generation 0 ufrag 0m/Z network-id 2","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:1273009030 1 udp 2122194687 192.168.177.71 37553 typ host generation 0 ufrag 0m/Z network-id 1","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:3867149351 1 udp 2122129151 192.168.15.21 55042 typ host generation 0 ufrag 0m/Z network-id 3","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:2967113413 1 tcp 1518283007 2003:c0:7f17:6c00:d0ab:9e2:45ff:aaba 9 typ host tcptype active generation 0 ufrag 0m/Z network-id 2","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:90402678 1 tcp 1518214911 192.168.177.71 9 typ host tcptype active generation 0 ufrag 0m/Z network-id 1","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:2818832599 1 tcp 1518149375 192.168.15.21 9 typ host tcptype active generation 0 ufrag 0m/Z network-id 3","sdpMid":"0","sdpMLineIndex":0}]
Logger.js:154 2022-04-13T09:32:33.579Z [modules/RTC/BridgeChannel.js] <Kr.sendNewReceiverVideoConstraintsMessage>:  Sending ReceiverVideoConstraints with {"constraints":{"2197223b":{"maxHeight":2160}},"defaultConstraints":{"maxHeight":0},"lastN":-1,"onStageEndpoints":["2197223b"],"selectedEndpoints":[]}
Logger.js:154 2022-04-13T09:32:48.589Z [modules/RTC/BridgeChannel.js] <WebSocket.e.onmessage>:  Endpoint connection status changed: 2197223b active=false
app.bundle.min.js?v=5675:207

jvb.log (JMS):

dp/host -> 192.168.15.21:53268/udp/prflx (stream-fa11b788.RTP).
JVB 2022-04-13 11:28:13.711 INFO: [77] [confId=a7f9cc0dc24413bc gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=cm5lj1g0h40v80 name=stream-fa11b788 epId=fa11b788 local_ufrag=cm5lj1g0h40v80] CheckList.handleNominationConfirmed#406: Selected pair for stream stream-fa11b788.RTP: 212.185.198.148:10000/udp/host -> 192.168.15.21:53268/udp/prflx (stream-fa11b788.RTP)
JVB 2022-04-13 11:28:13.711 INFO: [74] [confId=a7f9cc0dc24413bc gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=cm5lj1g0h40v80 epId=fa11b788 local_ufrag=cm5lj1g0h40v80] Agent.checkListStatesUpdated#1863: CheckList of stream stream-fa11b788 is COMPLETED
JVB 2022-04-13 11:28:13.712 INFO: [77] [confId=a7f9cc0dc24413bc gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=cm5lj1g0h40v80 epId=fa11b788 local_ufrag=cm5lj1g0h40v80] Agent.checkListStatesUpdated#1863: CheckList of stream stream-fa11b788 is COMPLETED
JVB 2022-04-13 11:28:13.712 INFO: [74] [confId=a7f9cc0dc24413bc gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=cm5lj1g0h40v80 epId=fa11b788 local_ufrag=cm5lj1g0h40v80] Agent.setState#908: ICE state changed from Running to Completed.
JVB 2022-04-13 11:28:13.712 INFO: [74] [confId=a7f9cc0dc24413bc epId=fa11b788 local_ufrag=cm5lj1g0h40v80 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] IceTransport.iceStateChanged#334: ICE state changed old=Running new=Completed
JVB 2022-04-13 11:28:13.713 INFO: [74] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Endpoint$setupIceTransport$2.connected#336: ICE connected
JVB 2022-04-13 11:28:13.714 INFO: [74] [confId=a7f9cc0dc24413bc gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=cm5lj1g0h40v80 epId=fa11b788 local_ufrag=cm5lj1g0h40v80] Agent.logCandTypes#1971: Harvester used for selected pair for stream-fa11b788.RTP: host
JVB 2022-04-13 11:28:13.714 INFO: [82] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] DtlsTransport.startDtlsHandshake#102: Starting DTLS handshake
JVB 2022-04-13 11:28:13.716 INFO: [82] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] TlsServerImpl.notifyClientVersion#196: Negotiated DTLS version DTLS 1.2
JVB 2022-04-13 11:28:13.767 INFO: [82] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Endpoint$setupDtlsTransport$3.handshakeComplete#379: DTLS handshake complete
JVB 2022-04-13 11:28:13.768 INFO: [83] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Endpoint.acceptSctpConnection$lambda-20#616: Attempting to establish SCTP socket connection
Got sctp association state update: 1
sctp is now up.  was ready? false
JVB 2022-04-13 11:28:13.869 INFO: [83] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Endpoint$createSctpConnection$3.onReady#564: SCTP connection is ready, creating the Data channel stack
JVB 2022-04-13 11:28:13.873 INFO: [83] [confId=a7f9cc0dc24413bc epId=fa11b788 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Endpoint$createSctpConnection$3.onReady#588: Will wait for the remote side to open the data channel.
JVB 2022-04-13 11:28:14.290 INFO: [84] Aes.createCipher#433: Will employ AES implemented by OpenSSL for AES/GCM/NoPadding.
JVB 2022-04-13 11:28:14.452 INFO: [69] [confId=a7f9cc0dc24413bc epId=288dbcdb gid=48101 conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Endpoint$setupDtlsTransport$3.handshakeComplete#379: DTLS handshake complete
JVB 2022-04-13 11:28:14.765 INFO: [69] [confId=a7f9cc0dc24413bc gid=48101 conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] Conference.recentSpeakersChanged#439: Recent speakers changed: [288dbcdb]
JVB 2022-04-13 11:28:16.426 INFO: [70] [confId=a7f9cc0dc24413bc epId=288dbcdb local_ufrag=196qh1g0h40v6j gid=48101 conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=196qh1g0h40v6j] Agent.setState#908: ICE state changed from Completed to Terminated.
JVB 2022-04-13 11:28:16.427 INFO: [70] [confId=a7f9cc0dc24413bc epId=288dbcdb local_ufrag=196qh1g0h40v6j gid=48101 conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] IceTransport.iceStateChanged#334: ICE state changed old=Completed new=Terminated
JVB 2022-04-13 11:28:16.714 INFO: [70] [confId=a7f9cc0dc24413bc gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN> ufrag=cm5lj1g0h40v80 epId=fa11b788 local_ufrag=cm5lj1g0h40v80] Agent.setState#908: ICE state changed from Completed to Terminated.
JVB 2022-04-13 11:28:16.714 INFO: [70] [confId=a7f9cc0dc24413bc epId=fa11b788 local_ufrag=cm5lj1g0h40v80 gid=48101 stats_id=Arne-A7x conf_name=aestheticlordscomputemagnificently@conference.<DOMAIN>] IceTransport.iceStateChanged#334: ICE state changed old=Completed new=Terminated
JVB 2022-04-13 11:28:22.428 INFO: [19] VideobridgeExpireThread.expire#140: Running expire()
JVB 2022-04-13 11:28:22.442 INFO: [20] HealthChecker.run#171: Performed a successful health check in PT0.00001S. Sticky failure: false
JVB 2022-04-13 11:28:32.442 INFO: [20] HealthChecker.run#171: Performed a successful health check in PT0.000009S. Sticky failure: false

Not working:
jigasi.log (JMS):

022-04-13 11:18:18.760 INFO: [264] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 
2022-04-13 11:18:18.761 INFO: [264] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2022-04-13 11:18:18.762 INFO: [264] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1416 [ctx=1649841498497157230153] SIP peer state: Connecting*
2022-04-13 11:18:18.764 INFO: [39382] org.jitsi.jigasi.SipGatewaySession.handleCallState().1343 [ctx=1649841498497157230153] Sip call IN_PROGRESS: Call: id=164984149849561296441 peers=1
2022-04-13 11:18:18.764 INFO: [39382] org.jitsi.jigasi.SipGatewaySession.handleCallState().1345 [ctx=1649841498497157230153] SIP call format used: rtpmap:9 G722/8000
2022-04-13 11:18:18.764 INFO: [39382] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1416 [ctx=1649841498497157230153] SIP peer state: Connected
2022-04-13 11:18:18.765 INFO: [39382] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2022-04-13 11:18:18.775 INFO: [39382] service.protocol.media.TransportManager.sendHolePunchPacket().552 Send NAT hole punch packets
2022-04-13 11:18:18.807 SEVERE: [39428] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2022-04-13 11:18:18.807 SEVERE: [39428] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@469cc445
2022-04-13 11:18:18.808 SEVERE: [39426] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@469cc445

2022-04-13 11:18:30.084 INFO: [264] impl.protocol.jabber.CallPeerJabberImpl.answer().201 Failed to answer an incoming call
net.java.sip.communicator.service.protocol.OperationFailedException: !service.protocol.ICE_FAILED!
        at net.java.sip.communicator.impl.protocol.jabber.IceUdpTransportManager.wrapupConnectivityEstablishment(IceUdpTransportManager.java:1277)
        at net.java.sip.communicator.impl.protocol.jabber.CallPeerJabberImpl.answer(CallPeerJabberImpl.java:194)
        at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.answerCallPeer(OperationSetBasicTelephonyJabberImpl.java:807)
        at org.jitsi.jigasi.CallManager$AnswerCallThread.run(CallManager.java:359)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
2022-04-13 11:18:30.088 INFO: [264] org.jitsi.jigasi.JvbConference.onJvbCallEnded().1030 [ctx=1649841498497157230153] Proceed with gwSession call on xmpp call hangup.

JS-Console:

dSessionAccept>:  JingleSessionPC[session=JVB,initiator=false,sid=5uih5udjhmv5a] Sending session-accept
Logger.js:154 2022-04-13T09:32:33.341Z [modules/xmpp/JingleSessionPC.js] <ha.peerconnection.oniceconnectionstatechange>:  (TIME) ICE checking JVB:	 34670.39999997616
Logger.js:154 2022-04-13T09:32:33.390Z [modules/RTC/BridgeChannel.js] <WebSocket.e.onopen>:  websocket channel opened
Logger.js:154 2022-04-13T09:32:33.390Z [JitsiConferenceEventManager.js] <r.<anonymous>>:  (TIME) data.channel.opened:	 34720.19999998808
Logger.js:154 2022-04-13T09:32:33.391Z [modules/RTC/BridgeChannel.js] <Kr.sendNewReceiverVideoConstraintsMessage>:  Sending ReceiverVideoConstraints with {"constraints":{"2197223b":{"maxHeight":2160}},"defaultConstraints":{"maxHeight":0},"lastN":-1,"onStageEndpoints":["2197223b"],"selectedEndpoints":[]}
Logger.js:154 2022-04-13T09:32:33.392Z [modules/RTC/BridgeChannel.js] <WebSocket.e.onmessage>:  Received ServerHello, version=undefined.
app.bundle.min.js?v=5675:207 2022-04-13T09:32:33.426Z [modules/UI/videolayout/LargeVideoManager.js] hover in 2197223b
Logger.js:154 2022-04-13T09:32:33.451Z [modules/xmpp/JingleSessionPC.js] <ha.peerconnection.oniceconnectionstatechange>:  (TIME) ICE connected JVB:	 34781.30000001192
Logger.js:154 2022-04-13T09:32:33.476Z [modules/xmpp/JingleSessionPC.js] <br.sendIceCandidate>:  JingleSessionPC[session=JVB,initiator=false,sid=5uih5udjhmv5a] sendIceCandidate: last candidate
Logger.js:154 2022-04-13T09:32:33.501Z [modules/xmpp/JingleSessionPC.js] <br.sendIceCandidates>:  JingleSessionPC[session=JVB,initiator=false,sid=5uih5udjhmv5a] sendIceCandidates [{"candidate":"candidate:4267274805 1 udp 2122262783 2003:c0:7f17:6c00:d0ab:9e2:45ff:aaba 47950 typ host generation 0 ufrag 0m/Z network-id 2","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:1273009030 1 udp 2122194687 192.168.177.71 37553 typ host generation 0 ufrag 0m/Z network-id 1","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:3867149351 1 udp 2122129151 192.168.15.21 55042 typ host generation 0 ufrag 0m/Z network-id 3","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:2967113413 1 tcp 1518283007 2003:c0:7f17:6c00:d0ab:9e2:45ff:aaba 9 typ host tcptype active generation 0 ufrag 0m/Z network-id 2","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:90402678 1 tcp 1518214911 192.168.177.71 9 typ host tcptype active generation 0 ufrag 0m/Z network-id 1","sdpMid":"0","sdpMLineIndex":0},{"candidate":"candidate:2818832599 1 tcp 1518149375 192.168.15.21 9 typ host tcptype active generation 0 ufrag 0m/Z network-id 3","sdpMid":"0","sdpMLineIndex":0}]
Logger.js:154 2022-04-13T09:32:33.579Z [modules/RTC/BridgeChannel.js] <Kr.sendNewReceiverVideoConstraintsMessage>:  Sending ReceiverVideoConstraints with {"constraints":{"2197223b":{"maxHeight":2160}},"defaultConstraints":{"maxHeight":0},"lastN":-1,"onStageEndpoints":["2197223b"],"selectedEndpoints":[]}
Logger.js:154 2022-04-13T09:32:48.589Z [modules/RTC/BridgeChannel.js] <WebSocket.e.onmessage>:  Endpoint connection status changed: 2197223b active=false
app.bundle.min.js?v=5675:207

damencho · April 13, 2022, 11:45am

In the case when jigasi fails, is a 3 way call working from an outside network?

Alex80 · April 13, 2022, 12:25pm

I am not sure if I understood you right, but yes, a conference with three ore more persons and enabled video is possible. Only thing not working is call in.
Jigasi receives the call (it is possible to entere the PIN) and the conference screen is also showing the number that calls in.
But the call does not get connected finally, the person who is calling hears nothing and the conference screen shows the message that is number is being connected forever.

damencho · April 13, 2022, 12:27pm

Ice failed is exactly problem in the network communication between jigasi and the bridge.
Jigasi will try connecting to the internal and external ip address of the bridge on port udp 10000.

Alex80 · April 27, 2022, 8:07am

Sorry for the late reply, but corona got me finally…

Thanks for your help. It was port 10000/udp. Did check connection just in one direction but the other way around it was not working.