Jigasi Incoming Call Suck in Connecting State

Hi All,

I have setup jigasi with a jitsi installation (using anonymous auth). Jigasi get authenticated properly to the XMPP server and I can add sip participants from web interface. But when dial in using a SIP phone to the meeting, the caller get stuck in connecting state in web interface. Here is the jigasi log.


2019-09-14 16:59:22.650 INFO: [48] impl.dns.ParallelResolverImpl.run().573 Sending query for _turn._udp.siptest.meetrix.io.us-west-2.compute.internal./SRV to backup resolvers
2019-09-14 16:59:22.667 INFO: [77] impl.dns.ParallelResolverImpl.run().573 Sending query for _stun._udp.siptest.meetrix.io./SRV to backup resolvers
2019-09-14 16:59:22.678 INFO: [50] impl.dns.ParallelResolverImpl.run().573 Sending query for _stun._udp.siptest.meetrix.io.us-west-2.compute.internal./SRV to backup resolvers
2019-09-14 16:59:22.696 INFO: [75] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().254 Auto discovered harvester is null
2019-09-14 16:59:22.708 INFO: [75] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 130 ms
2019-09-14 16:59:23.541 INFO: [75] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 389 ms
2019-09-14 16:59:23.593 INFO: [75] org.jitsi.jigasi.JvbConference.incomingCallReceived().990 Got invite from focus
2019-09-14 16:59:23.692 INFO: [92] 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; 
2019-09-14 16:59:23.692 INFO: [92] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2019-09-14 16:59:23.755 INFO: [92] service.protocol.media.CallPeerMediaHandler.start().1960 Starting
2019-09-14 16:59:24.269 INFO: [92] org.jitsi.jigasi.JvbConference.onJvbCallStarted().771 JVB conference call IN_PROGRESS siptest
2019-09-14 16:59:24.270 INFO: [92] org.jitsi.jigasi.JvbConference.peerStateChanged().1056 42900be4@siptest.meetrix.io JVB peer state: net.java.sip.communicator.service.protocol.CallPeerState:Connected
2019-09-14 16:59:24.271 INFO: [92] org.jitsi.jigasi.JvbConference.advertisePeerSSRCs().298 Peer net.java.sip.communicator.service.protocol.CallPeerState:Connected SSRCs audio: 1829025454 video: null
2019-09-14 16:59:24.424 INFO: [113] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 100=rtpmap:-1 telephone-event/8000; 97=rtpmap:-1 speex/16000 fmtp:vbr=on; 98=rtpmap:-1 speex/8000 fmtp:vbr=on; 96=rtpmap:-1 opus/48000/2 fmtp:useinbandfec=1; 
2019-09-14 16:59:24.424 INFO: [113] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2019-09-14 16:59:24.431 INFO: [113] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1007 42900be4@siptest.meetrix.io SIP peer state: Connecting*
2019-09-14 16:59:24.933 SEVERE: [35] impl.protocol.sip.SipLogger.logPacket().413 Cannot obtain message body
java.lang.NullPointerException
	at gov.nist.javax.sip.stack.MessageChannel.getKey(MessageChannel.java:314)
	at gov.nist.javax.sip.stack.TLSMessageProcessor.createMessageChannel(TLSMessageProcessor.java:257)
	at gov.nist.javax.sip.stack.SIPTransactionStack.getLocalAddressForTlsDst(SIPTransactionStack.java:666)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.getLocalAddressForDestination(SipLogger.java:516)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logPacket(SipLogger.java:307)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:264)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:246)
	at gov.nist.javax.sip.stack.MessageChannel.logMessage(MessageChannel.java:396)
	at gov.nist.javax.sip.stack.SIPServerTransactionImpl.resendLastResponseAsBytes(SIPServerTransactionImpl.java:1182)
	at gov.nist.javax.sip.stack.SIPDialog$DialogTimerTask.runTask(SIPDialog.java:591)
	at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
2019-09-14 16:59:25.813 SEVERE: [144] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2019-09-14 16:59:25.813 SEVERE: [144] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@7ec8ed53
2019-09-14 16:59:25.814 SEVERE: [142] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@7ec8ed53

2019-09-14 16:59:25.932 SEVERE: [35] impl.protocol.sip.SipLogger.logPacket().413 Cannot obtain message body
java.lang.NullPointerException
	at gov.nist.javax.sip.stack.MessageChannel.getKey(MessageChannel.java:314)
	at gov.nist.javax.sip.stack.TLSMessageProcessor.createMessageChannel(TLSMessageProcessor.java:257)
	at gov.nist.javax.sip.stack.SIPTransactionStack.getLocalAddressForTlsDst(SIPTransactionStack.java:666)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.getLocalAddressForDestination(SipLogger.java:516)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logPacket(SipLogger.java:307)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:264)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:246)
	at gov.nist.javax.sip.stack.MessageChannel.logMessage(MessageChannel.java:396)
	at gov.nist.javax.sip.stack.SIPServerTransactionImpl.resendLastResponseAsBytes(SIPServerTransactionImpl.java:1182)
	at gov.nist.javax.sip.stack.SIPDialog$DialogTimerTask.runTask(SIPDialog.java:591)
	at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
2019-09-14 16:59:27.932 SEVERE: [35] impl.protocol.sip.SipLogger.logPacket().413 Cannot obtain message body
java.lang.NullPointerException
	at gov.nist.javax.sip.stack.MessageChannel.getKey(MessageChannel.java:314)
	at gov.nist.javax.sip.stack.TLSMessageProcessor.createMessageChannel(TLSMessageProcessor.java:257)
	at gov.nist.javax.sip.stack.SIPTransactionStack.getLocalAddressForTlsDst(SIPTransactionStack.java:666)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.getLocalAddressForDestination(SipLogger.java:516)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logPacket(SipLogger.java:307)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:264)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:246)
	at gov.nist.javax.sip.stack.MessageChannel.logMessage(MessageChannel.java:396)
	at gov.nist.javax.sip.stack.SIPServerTransactionImpl.resendLastResponseAsBytes(SIPServerTransactionImpl.java:1182)
	at gov.nist.javax.sip.stack.SIPDialog$DialogTimerTask.runTask(SIPDialog.java:591)
	at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)
2019-09-14 16:59:31.933 SEVERE: [35] impl.protocol.sip.SipLogger.logPacket().413 Cannot obtain message body
java.lang.NullPointerException
	at gov.nist.javax.sip.stack.MessageChannel.getKey(MessageChannel.java:314)
	at gov.nist.javax.sip.stack.TLSMessageProcessor.createMessageChannel(TLSMessageProcessor.java:257)
	at gov.nist.javax.sip.stack.SIPTransactionStack.getLocalAddressForTlsDst(SIPTransactionStack.java:666)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.getLocalAddressForDestination(SipLogger.java:516)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logPacket(SipLogger.java:307)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:264)
	at net.java.sip.communicator.impl.protocol.sip.SipLogger.logMessage(SipLogger.java:246)
	at gov.nist.javax.sip.stack.MessageChannel.logMessage(MessageChannel.java:396)
	at gov.nist.javax.sip.stack.SIPServerTransactionImpl.resendLastResponseAsBytes(SIPServerTransactionImpl.java:1182)
	at gov.nist.javax.sip.stack.SIPDialog$DialogTimerTask.runTask(SIPDialog.java:591)
	at gov.nist.javax.sip.stack.timers.DefaultSipTimer$DefaultTimerTask.run(DefaultSipTimer.java:67)
	at java.util.TimerThread.mainLoop(Timer.java:555)
	at java.util.TimerThread.run(Timer.java:505)

Any clue on this ?

I finally managed to test this. I was testing outgoing call and everything seems to work. I see the following exception:

2019-09-26 11:39:54.428 SEVERE: [354] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2019-09-26 11:39:54.429 SEVERE: [354] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@73e6555f
2019-09-26 11:39:54.429 SEVERE: [352] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@73e6555f

As seen in your logs … not sure why, but audio works both ways.

Hi @damencho
Thanks for taking a look. Above errors came when I used OnSIP. When I tried with Freeswitch, it works fine.

Probably you are talking about the signalling errors … no idea, something to do with TLS and sip.

Thanks @damencho. Yes most probably with SIP.