Jigasi SIP Call-In disconnected immediatly

Hello,

I just installed jigasi and linked it to my asterisk sip server. The User trying to dial in is 100, jigasi is 101.
When inviting 100 to the call the phone of 100 rings and he can join to the conference.
When 100 is trying to call 101 to dial in to the siptest room the call ends and he gets a call back from 101.
In the webinterface you see the message that he joined and left immediatly.

This is the log when this happens:

2020-03-18 21:46:15.156 INFO: [302] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2020-03-18 21:46:15.162 INFO: [303] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-03-18 21:46:15.180 INFO: [304] org.jitsi.jigasi.SipGatewaySession.handleCallState().1138 [ctx=15845643332541537311723] 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=100 <100@192.168.200.96>;status=Disconnected
2020-03-18 21:46:15.184 INFO: [304] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15845643332541537311723] SIP peer state: Disconnected
2020-03-18 21:46:20.201 INFO: [306] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().629 [ctx=15845643332541537311723] Sip call ended: Call: id=1584564334791452721010 peers=0
2020-03-18 21:46:20.220 INFO: [306] org.jitsi.jigasi.JvbConference.stop().500 [ctx=15845643332541537311723] Removing account Jabber:10ae8e91@192.168.200.95/10ae8e91
2020-03-18 21:46:20.228 INFO: [306] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().132 Jingle : OFF
2020-03-18 21:46:20.230 INFO: [306] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=15845643332541537311723] Removed session for call. Sessions:0
2020-03-18 21:46:20.236 SEVERE: [308] org.jitsi.jigasi.JvbConference.callStateChanged().1114 [ctx=15845643332541537311723] Call change event for different call ? Call: id=1584564333601645460520 peers=0 : null
2020-03-18 21:46:20.242 SEVERE: [200] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /censoredipv6:java.io.IOException: No active socket.
2020-03-18 21:46:30.545 INFO: [313] org.jitsi.jigasi.SipGateway.incomingCallReceived().188 Incoming call received...
2020-03-18 21:46:31.549 INFO: [314] org.jitsi.jigasi.SipGatewaySession.run().1295 [ctx=15845643905461974660561]Using default JVB room name property siptest
2020-03-18 21:46:31.555 INFO: [314] org.jitsi.jigasi.JvbConference.setXmppProvider().539 [ctx=15845643905461974660561] Using ProtocolProviderServiceJabberImpl(Jabber:081159bf@192.168.200.95/081159bf)
2020-03-18 21:46:31.640 INFO: [316] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().125 Jingle : ON
2020-03-18 21:46:31.642 INFO: [316] org.jitsi.jigasi.JvbConference.registrationStateChanged().577 [ctx=15845643905461974660561] Registering XMPP.
2020-03-18 21:46:31.651 INFO: [316] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-03-18 21:46:31.660 INFO: [316] org.jitsi.jigasi.JvbConference.joinConferenceRoom().648 [ctx=15845643905461974660561] Joining JVB conference room: siptest
2020-03-18 21:46:31.712 INFO: [319] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 siptest@conference.192.168.200.95/ca1e4f21 has joined the siptest@conference.192.168.200.95 chat room.
2020-03-18 21:46:31.713 INFO: [319] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 siptest@conference.192.168.200.95/focus has joined the siptest@conference.192.168.200.95 chat room.
2020-03-18 21:46:31.799 INFO: [325] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().254 Auto discovered harvester is null
2020-03-18 21:46:31.822 INFO: [325] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 19 ms
2020-03-18 21:46:32.959 INFO: [325] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 1126 ms
2020-03-18 21:46:32.997 INFO: [325] org.jitsi.jigasi.JvbConference.incomingCallReceived().1024 [ctx=15845643905461974660561] Got invite from focus
2020-03-18 21:46:33.042 WARNING: [113] service.protocol.media.DynamicPayloadTypeRegistry.addMapping().270 Remote party is trying to remap payload type 97 and reassign it from rtpmap:-1 AMR-WB/16000 to rtpmap:-1 iLBC/8000 fmtp:mode=20. We'll go along but there might be issues because of this. We'll also expect to receive rtpmap:-1 iLBC/8000 fmtp:mode=20 with PT=98
2020-03-18 21:46:33.050 INFO: [332] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15845643905461974660561] SIP peer state: Connecting
2020-03-18 21:46:33.075 INFO: [114] 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;
2020-03-18 21:46:33.075 INFO: [114] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2020-03-18 21:46:33.086 INFO: [114] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-03-18 21:46:33.093 INFO: [333] org.jitsi.jigasi.SipGatewaySession.handleCallState().1138 [ctx=15845643905461974660561] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Connecting newV=net.java.sip.communicator.service.protocol.CallPeerState:Disconnected for peer=100 <100@192.168.200.96>;status=Disconnected
2020-03-18 21:46:33.105 INFO: [333] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15845643905461974660561] SIP peer state: Disconnected
2020-03-18 21:46:33.146 INFO: [113] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 96=rtpmap:-1 opus/48000/2 fmtp:usedtx=1; 98=rtpmap:-1 iLBC/8000; 97=rtpmap:-1 AMR-WB/16000; 110=rtpmap:-1 speex/8000; 117=rtpmap:-1 speex/16000; 119=rtpmap:-1 speex/32000;
2020-03-18 21:46:33.175 INFO: [113] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [96->107 97->109 98->97 ]
2020-03-18 21:46:33.200 SEVERE: [113] impl.protocol.sip.CallPeerSipImpl.answer().1334 Failed to create an SDP description for an OK response to an INVITE request!
java.lang.NullPointerException
        at net.java.sip.communicator.service.protocol.media.MediaHandler.configureStream(MediaHandler.java:703)
        at net.java.sip.communicator.service.protocol.media.MediaHandler.initStream(MediaHandler.java:953)
        at net.java.sip.communicator.service.protocol.media.CallPeerMediaHandler.initStream(CallPeerMediaHandler.java:1189)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerMediaHandlerSipImpl.createMediaDescriptionsForAnswer(CallPeerMediaHandlerSipImpl.java:832)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerMediaHandlerSipImpl.processUpdateOffer(CallPeerMediaHandlerSipImpl.java:519)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerMediaHandlerSipImpl.processOffer(CallPeerMediaHandlerSipImpl.java:447)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerSipImpl.answer(CallPeerSipImpl.java:1320)
        at net.java.sip.communicator.impl.protocol.sip.OperationSetBasicTelephonySipImpl.answerCallPeer(OperationSetBasicTelephonySipImpl.java:1955)
        at org.jitsi.jigasi.CallManager$AnswerCallThread.run(CallManager.java:298)
        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:834)
2020-03-18 21:46:33.314 INFO: [114] org.jitsi.jigasi.JvbConference.callStateChanged().1122 [ctx=15845643905461974660561] JVB conference call IN_PROGRESS.
2020-03-18 21:46:33.365 SEVERE: [385] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2020-03-18 21:46:33.370 SEVERE: [385] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@4e564b32
2020-03-18 21:46:33.370 SEVERE: [384] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@4e564b32

2020-03-18 21:46:38.115 INFO: [341] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().629 [ctx=15845643905461974660561] Sip call ended: Call: id=1584564390542219961408 peers=0
2020-03-18 21:46:38.116 INFO: [341] org.jitsi.jigasi.JvbConference.stop().500 [ctx=15845643905461974660561] Removing account Jabber:081159bf@192.168.200.95/081159bf
2020-03-18 21:46:38.145 INFO: [341] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().132 Jingle : OFF
2020-03-18 21:46:38.146 INFO: [341] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=15845643905461974660561] Removed session for call. Sessions:0

I’m not quite sure if that is an issue with my asterisk setup or jigasi, maybe someone could give me a guiding hand :slight_smile:

Thank you in advance!

The log when calling via jitsi (which works):

2020-03-18 21:59:33.669 WARNING: [426] org.jitsi.jigasi.xmpp.CallControl.checkAuthorized().287 Requests are not secured by JID filter!
2020-03-18 21:59:33.669 INFO: [426] org.jitsi.jigasi.xmpp.CallControl.handleDialIq().211 [ctx=15845651736682145050261] Got dial request fromnumber -> 100 room: siptest@conference.192.168.200.95
2020-03-18 21:59:33.676 INFO: [426] org.jitsi.jigasi.JvbConference.setXmppProvider().539 [ctx=15845651736682145050261] Using ProtocolProviderServiceJabberImpl(Jabber:51cd9920@192.168.200.95/51cd9920)
2020-03-18 21:59:33.685 WARNING: [426] org.jitsi.xmpp.component.ComponentBase.log() PROCESSING TIME LIMIT EXCEEDED - it took 10ms to process: <iq to="callcontrol.192.168.200.95" from="focus@auth.192.168.200.95/focus665549474472" id="EmtEr-3900" type="set"><dial xmlns="urn:xmpp:rayo:1" from="fromnumber" to="100"><header value="siptest@conference.192.168.200.95" name="JvbRoomName"/></dial></iq>
2020-03-18 21:59:33.799 INFO: [457] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().125 Jingle : ON
2020-03-18 21:59:33.800 INFO: [457] org.jitsi.jigasi.JvbConference.registrationStateChanged().577 [ctx=15845651736682145050261] Registering XMPP.
2020-03-18 21:59:33.804 INFO: [457] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-03-18 21:59:33.806 INFO: [457] org.jitsi.jigasi.JvbConference.joinConferenceRoom().648 [ctx=15845651736682145050261] Joining JVB conference room: siptest@conference.192.168.200.95
2020-03-18 21:59:33.835 INFO: [462] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 siptest@conference.192.168.200.95/ca1e4f21 has joined the siptest@conference.192.168.200.95 chat room.
2020-03-18 21:59:33.844 INFO: [462] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 siptest@conference.192.168.200.95/focus has joined the siptest@conference.192.168.200.95 chat room.
2020-03-18 21:59:33.878 WARNING: [465] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.firePresenceStatusChanged().1675 No source contact found for id=siptest@conference.192.168.200.95/ca1e4f21
2020-03-18 21:59:33.879 WARNING: [465] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.firePresenceStatusChanged().1675 No source contact found for id=siptest@conference.192.168.200.95/focus
2020-03-18 21:59:33.879 WARNING: [465] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.firePresenceStatusChanged().1675 No source contact found for id=siptest@conference.192.168.200.95/51cd9920
2020-03-18 21:59:33.879 WARNING: [465] impl.protocol.jabber.OperationSetPersistentPresenceJabberImpl.firePresenceStatusChanged().1675 No source contact found for id=ri2d_-w7zo3xiwxd@192.168.200.95
2020-03-18 21:59:33.958 INFO: [474] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().254 Auto discovered harvester is null
2020-03-18 21:59:33.960 INFO: [474] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 17 ms
2020-03-18 21:59:35.100 INFO: [474] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 1139 ms
2020-03-18 21:59:35.150 INFO: [474] org.jitsi.jigasi.JvbConference.incomingCallReceived().1024 [ctx=15845651736682145050261] Got invite from focus
2020-03-18 21:59:35.182 SEVERE: [474] impl.protocol.sip.SipMessageFactory.throwOperationFailedException().2652 Failed to create INVITE request.
javax.sip.SipException: Dialog not yet established -- no response!
        at gov.nist.javax.sip.stack.SIPDialog.createRequest(SIPDialog.java:2328)
        at net.java.sip.communicator.impl.protocol.sip.SipMessageFactory.createRequest(SipMessageFactory.java:696)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerSipImpl.sendReInvite(CallPeerSipImpl.java:1429)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerSipImpl.sendReInvite(CallPeerSipImpl.java:1411)
        at net.java.sip.communicator.impl.protocol.sip.CallSipImpl.reInvite(CallSipImpl.java:694)
        at net.java.sip.communicator.impl.protocol.sip.CallSipImpl.conferenceFocusChanged(CallSipImpl.java:183)
        at net.java.sip.communicator.service.protocol.media.MediaAwareCall.propertyChange(MediaAwareCall.java:865)
        at org.jitsi.utils.event.PropertyChangeNotifier.firePropertyChange(PropertyChangeNotifier.java:126)
        at net.java.sip.communicator.service.protocol.CallConference.conferenceFocusChanged(CallConference.java:509)
        at net.java.sip.communicator.service.protocol.media.MediaAwareCallConference.conferenceFocusChanged(MediaAwareCallConference.java:243)
        at net.java.sip.communicator.service.protocol.CallConference.setConferenceFocus(CallConference.java:941)
        at net.java.sip.communicator.service.protocol.CallConference.callAdded(CallConference.java:430)
        at net.java.sip.communicator.service.protocol.CallConference.addCall(CallConference.java:333)
        at net.java.sip.communicator.service.protocol.Call.setConference(Call.java:557)
        at net.java.sip.communicator.service.protocol.media.MediaAwareCall.setConference(MediaAwareCall.java:975)
        at org.jitsi.jigasi.SipGatewaySession.onConferenceCallStarted(SipGatewaySession.java:579)
        at org.jitsi.jigasi.SipGatewaySession.onConferenceCallInvited(SipGatewaySession.java:467)
        at org.jitsi.jigasi.JvbConference$JvbCallListener.incomingCallReceived(JvbConference.java:1096)
        at net.java.sip.communicator.service.protocol.media.AbstractOperationSetBasicTelephony.fireCallEvent(AbstractOperationSetBasicTelephony.java:208)
        at net.java.sip.communicator.service.protocol.media.AbstractOperationSetBasicTelephony.fireCallEvent(AbstractOperationSetBasicTelephony.java:167)
        at net.java.sip.communicator.impl.protocol.jabber.CallJabberImpl.processSessionInitiate(CallJabberImpl.java:1135)
        at net.java.sip.communicator.impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl$2.run(OperationSetBasicTelephonyJabberImpl.java:1099)
2020-03-18 21:59:35.187 INFO: [474] org.jitsi.jigasi.SipGatewaySession.onConferenceCallStarted().581 [ctx=15845651736682145050261] Created outgoing call to SipGatewaySession{sipCall=Call: id=15845651751541893895919 peers=1, destination='100'}
2020-03-18 21:59:35.195 INFO: [198] 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;
2020-03-18 21:59:35.195 INFO: [198] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2020-03-18 21:59:35.203 INFO: [198] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-03-18 21:59:35.252 INFO: [504] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15845651736682145050261] SIP peer state: Connecting
2020-03-18 21:59:35.272 INFO: [505] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15845651736682145050261] SIP peer state: Alerting Remote User (Ringing)
2020-03-18 21:59:35.346 INFO: [198] org.jitsi.jigasi.JvbConference.callStateChanged().1122 [ctx=15845651736682145050261] JVB conference call IN_PROGRESS.
2020-03-18 21:59:35.435 SEVERE: [551] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2020-03-18 21:59:35.437 SEVERE: [551] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@4e1803e8
2020-03-18 21:59:35.444 SEVERE: [547] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@4e1803e8

2020-03-18 21:59:42.292 INFO: [552] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 96=rtpmap:-1 opus/48000/2 fmtp:usedtx=1; 98=rtpmap:-1 iLBC/8000; 97=rtpmap:-1 AMR-WB/16000;
2020-03-18 21:59:42.292 INFO: [552] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2020-03-18 21:59:42.298 INFO: [552] org.jitsi.jigasi.SipGatewaySession.handleCallState().1123 [ctx=15845651736682145050261] Sip call IN_PROGRESS: Call: id=15845651751541893895919 peers=1
2020-03-18 21:59:42.298 INFO: [552] org.jitsi.jigasi.SipGatewaySession.handleCallState().1132 [ctx=15845651736682145050261] SIP call format used: rtpmap:0 PCMU/8000
2020-03-18 21:59:42.299 INFO: [553] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 96=rtpmap:-1 opus/48000/2 fmtp:usedtx=1; 98=rtpmap:-1 iLBC/8000; 97=rtpmap:-1 AMR-WB/16000;
2020-03-18 21:59:42.299 INFO: [553] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2020-03-18 21:59:42.300 INFO: [552] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15845651736682145050261] SIP peer state: Connected
2020-03-18 21:59:42.307 INFO: [552] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-03-18 21:59:42.398 INFO: [552] service.protocol.media.TransportManager.sendHolePunchPacket().552 Send NAT hole punch packets
2020-03-18 21:59:42.399 INFO: [559] service.protocol.media.CallPeerMediaHandler.start().1961 Starting

I had the exact same issue under the same circumstances (Asterisk) these past couple of days while I was setting up my Jitsi Meet instance. Outbound calls worked fine, but inbound calls would terminate immediately after joining the conference room. I even noticed that the calling party is called back by Jigasi for a split second which I couldn’t wrap my head around.

Using Wireshark I discovered a weird Re-INVITE that Jigasi sends before it even ACKs the initial INVITE sent by Asterisk. A Re-INVITE shouldn’t be sent prior to session establishment so I think this is a bug in Jigasi, but maybe I’m wrong here.

Anyway, moments ago I found this thread which suggests to set net.java.sip.communicator.impl.protocol.sip .SKIP_REINVITE_ON_FOCUS_CHANGE_PROP=true. And this fixed it for me. So maybe it will help in your situation as well.

EDIT: I just found another thread where people basically made the same observation.

3 Likes

Here is also an explanation from Damian: https://github.com/jitsi/jigasi/issues/243#issuecomment-602057087