Jigasi join empty Room

Install & Config
#1

Hello all,

As we had a ride in the last weeks, we finally made it and Jitsi including Jigasi are running including an IVR with custom SIP Headers for joining Rooms via Dial-In.

But we have one Problem left:
If I try to join an empty Room, Our call server receives a SIP 180 Ringing and the connection drops immediately after this.

If there are already participants in the room we can join the same room flawlessly.

I also tried to add

net.java.sip.communicator.impl.protocol.sip.SKIP_REINVITE_ON_FOCUS_CHANGE_PROP=true
to the Jigasi config without success.

These are the Jigasi logs during the failed Dial-In

2020-05-06 14:39:57.083 INFO: [54] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=15887687970821915904002] Incoming call received…

2020-05-06 14:39:57.084 INFO: [832] org.jitsi.jigasi.SipGatewaySession.run().1490 [ctx=15887687970821915904002] Wait thread cancelled

2020-05-06 14:39:57.085 INFO: [54] org.jitsi.jigasi.JvbConference.start().430 [ctx=15887687970821915904002] Starting JVB conference room: roomName

2020-05-06 14:39:57.088 INFO: [54] org.jitsi.jigasi.JvbConference.setXmppProvider().561 [ctx=15887687970821915904002] Using ProtocolProviderServiceJabberImpl(Jabber:0452b304@jitsi-test.XXXXXXXXXX.de/0452b304)

2020-05-06 14:39:57.184 INFO: [834] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON

2020-05-06 14:39:57.185 INFO: [834] org.jitsi.jigasi.JvbConference.registrationStateChanged().612 [ctx=15887687970821915904002] Registering XMPP.

2020-05-06 14:39:57.238 INFO: [834] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false

2020-05-06 14:39:57.245 INFO: [834] org.jitsi.jigasi.JvbConference.joinConferenceRoom().700 [ctx=15887687970821915904002] Joining JVB conference room: virtuelleTeerunde

2020-05-06 14:39:57.362 INFO: [837] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 virtuelleteerunde@conference.jitsi-test.XXXXXX.de/focus has joined the virtuelleteerunde@conference.jitsi-test.XXXXXX.de chat room.

2020-05-06 14:40:02.039 INFO: [54] org.jitsi.jigasi.SipGatewaySession.handleCallState().1391 [ctx=15887687970821915904002] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Incoming Call newV=net.java.sip.communicator.service.protocol.CallPeerState:Disconnected for peer=00123456789 ~~id~media@voip.helmholtz-berlin.de;status=Disconnected

2020-05-06 14:40:02.040 INFO: [54] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=15887687970821915904002] SIP peer state: Disconnected

2020-05-06 14:40:07.041 INFO: [845] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().584 [ctx=15887687970821915904002] Sip call ended: Call: id=15887687970811313712625 peers=0

2020-05-06 14:40:07.043 INFO: [845] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15887687970821915904002] Member left : OWNER focus@auth.jitsi-test.XXXXXX.de/focus1126687319821069

2020-05-06 14:40:07.044 INFO: [845] org.jitsi.jigasi.JvbConference.memberPresenceChanged().994 [ctx=15887687970821915904002] Focus left! - stopping

2020-05-06 14:40:07.045 SEVERE: [845] org.jitsi.jigasi.JvbConference.stop().491 [ctx=15887687970821915904002] Already stopped !

2020-05-06 14:40:07.045 INFO: [845] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15887687970821915904002] Member left : GUEST 0452b304@jitsi-test.XXXXXX.de

2020-05-06 14:40:07.046 INFO: [845] org.jitsi.jigasi.JvbConference.stop().521 [ctx=15887687970821915904002] Removing account Jabber:0452b304@jitsi-test.XXXXXX.de/0452b304

2020-05-06 14:40:07.053 INFO: [845] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF

2020-05-06 14:40:07.054 INFO: [845] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=15887687970821915904002] Removed session for call. Sessions:0

#2

You can add org.jitsi.jigasi.JVB_INVITE_TIMEOUT=1800000 so jigasi will wait in the room for 30 mins for someone to join.

Jigasi - setting to change SIP invite timeout?
#3

Hello damencho,
Thanks for your response.

I tried setting

org.jitsi.jigasi.JVB_INVITE_TIMEOUT=1800000

But when I set it I still can’t join empty rooms. Further I also can’t join already existing rooms when I set this option.
Our call Server receives a SIP 486 Busy Here then, no matter if the room exists or not.

Can I provide some other logs which are helpful in this case?

#4

Yeah share your jigasi log.

#5

Thank you very much :slight_smile:

Here are the jigasi logs:

Case 1: Timeout not set, room not empty

2020-05-06 23:03:49.897 INFO: [54] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=1588799029896300843323] Incoming call received...
2020-05-06 23:03:50.899 INFO: [218] org.jitsi.jigasi.SipGatewaySession.run().1490 [ctx=1588799029896300843323] Wait thread cancelled
2020-05-06 23:03:50.900 INFO: [54] org.jitsi.jigasi.JvbConference.start().430 [ctx=1588799029896300843323] Starting JVB conference room: testRoom
2020-05-06 23:03:50.905 INFO: [54] org.jitsi.jigasi.JvbConference.setXmppProvider().561 [ctx=1588799029896300843323] Using ProtocolProviderServiceJabberImpl(Jabber:607dc2f0@jitsi-test.XXXXXXX.de/607dc2f0)
2020-05-06 23:03:51.007 INFO: [219] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON 
2020-05-06 23:03:51.009 INFO: [219] org.jitsi.jigasi.JvbConference.registrationStateChanged().612 [ctx=1588799029896300843323] Registering XMPP.
2020-05-06 23:03:51.071 INFO: [219] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-05-06 23:03:51.078 INFO: [219] org.jitsi.jigasi.JvbConference.joinConferenceRoom().700 [ctx=1588799029896300843323] Joining JVB conference room: testRoom
2020-05-06 23:03:51.129 INFO: [223] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 testroom@conference.jitsi-test.XXXXXXX.de/focus has joined the testroom@conference.jitsi-test.XXXXXXX.de chat room.
2020-05-06 23:03:51.132 INFO: [223] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 testroom@conference.jitsi-test.XXXXXXX.de/86a6d3e2 has joined the testroom@conference.jitsi-test.XXXXXXX.de chat room.
2020-05-06 23:03:51.227 INFO: [234] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 5 ms
2020-05-06 23:03:52.366 INFO: [234] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 1134 ms
2020-05-06 23:03:52.377 INFO: [234] org.jitsi.jigasi.JvbConference.incomingCallReceived().1077 [ctx=1588799029896300843323] Got invite from focus
2020-05-06 23:03:52.398 INFO: [239] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 
2020-05-06 23:03:52.398 INFO: [239] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2020-05-06 23:03:52.413 INFO: [239] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=1588799029896300843323] SIP peer state: Connecting*
2020-05-06 23:03:52.420 INFO: [54] org.jitsi.jigasi.SipGatewaySession.handleCallState().1374 [ctx=1588799029896300843323] Sip call IN_PROGRESS: Call: id=15887990298951925291424 peers=1
2020-05-06 23:03:52.421 INFO: [54] org.jitsi.jigasi.SipGatewaySession.handleCallState().1383 [ctx=1588799029896300843323] SIP call format used: rtpmap:9 G722/8000
2020-05-06 23:03:52.422 INFO: [54] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=1588799029896300843323] SIP peer state: Connected
2020-05-06 23:03:52.423 INFO: [54] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-05-06 23:03:52.451 INFO: [240] 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-05-06 23:03:52.452 INFO: [240] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2020-05-06 23:03:52.463 INFO: [240] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-05-06 23:03:52.507 INFO: [54] service.protocol.media.TransportManager.sendHolePunchPacket().552 Send NAT hole punch packets
2020-05-06 23:03:52.557 INFO: [240] org.jitsi.jigasi.JvbConference.callStateChanged().1182 [ctx=1588799029896300843323] JVB conference call IN_PROGRESS.
2020-05-06 23:03:52.608 SEVERE: [312] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2020-05-06 23:03:52.610 SEVERE: [312] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@6459a8c8
2020-05-06 23:03:52.614 SEVERE: [310] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@6459a8c8
2020-05-06 23:04:01.767 INFO: [54] org.jitsi.jigasi.SipGatewaySession.handleCallState().1391 [ctx=1588799029896300843323] 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=001234567890 <~~id~media@voip.XXXXXXX.de>;status=Disconnected
2020-05-06 23:04:01.771 INFO: [54] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=1588799029896300843323] SIP peer state: Disconnected
2020-05-06 23:04:06.771 INFO: [335] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().584 [ctx=1588799029896300843323] Sip call ended: Call: id=15887990298951925291424 peers=0
2020-05-06 23:04:06.773 INFO: [335] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=1588799029896300843323] Member left : MEMBER 607dc2f0@jitsi-test.XXXXXXX.de
2020-05-06 23:04:06.773 INFO: [335] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=1588799029896300843323] Member left : OWNER focus@auth.jitsi-test.XXXXXXX.de/focus1145014382654038
2020-05-06 23:04:06.774 INFO: [335] org.jitsi.jigasi.JvbConference.memberPresenceChanged().994 [ctx=1588799029896300843323] Focus left! - stopping
2020-05-06 23:04:06.774 SEVERE: [335] org.jitsi.jigasi.JvbConference.stop().491 [ctx=1588799029896300843323] Already stopped !
2020-05-06 23:04:06.774 INFO: [335] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=1588799029896300843323] Member left : OWNER 86a6d3e2-f183-4f15-a19c-70d6f161928a@jitsi-test.XXXXXXX.de/ca33d7d9-903f-488c-8e76-d6df0e74dc33
2020-05-06 23:04:06.775 INFO: [335] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=1588799029896300843323] Removed session for call. Sessions:0
2020-05-06 23:04:06.801 SEVERE: [252] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /134.30.108.56:10000:java.io.IOException: No active socket.
2020-05-06 23:04:06.824 SEVERE: [251] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /134.30.108.56:10000:java.io.IOException: No active socket.
2020-05-06 23:04:06.830 SEVERE: [98] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /134.30.108.56:10000:java.io.IOException: No active socket.
2020-05-06 23:04:06.852 INFO: [98] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF 
2020-05-06 23:04:06.853 INFO: [98] org.jitsi.jigasi.CallManager$HangupCallThread.run().597 [ctx=1588799029896300843323] Removing account Jabber:607dc2f0@jitsi-test.XXXXXXX.de/607dc2f0
2020-05-06 23:04:06.854 INFO: [98] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF

Case 2 : Timeout not set, room empty

2020-05-06 23:06:38.125 INFO: [54] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=15887991981241219259214] Incoming call received...
2020-05-06 23:06:39.127 INFO: [470] org.jitsi.jigasi.SipGatewaySession.run().1490 [ctx=15887991981241219259214] Wait thread cancelled
2020-05-06 23:06:39.128 INFO: [54] org.jitsi.jigasi.JvbConference.start().430 [ctx=15887991981241219259214] Starting JVB conference room: testRoom
2020-05-06 23:06:39.132 INFO: [54] org.jitsi.jigasi.JvbConference.setXmppProvider().561 [ctx=15887991981241219259214] Using ProtocolProviderServiceJabberImpl(Jabber:77e1a9cb@jitsi-test.XXXXXXX.de/77e1a9cb)
2020-05-06 23:06:39.212 INFO: [472] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON 
2020-05-06 23:06:39.213 INFO: [472] org.jitsi.jigasi.JvbConference.registrationStateChanged().612 [ctx=15887991981241219259214] Registering XMPP.
2020-05-06 23:06:39.266 INFO: [472] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-05-06 23:06:39.270 INFO: [472] org.jitsi.jigasi.JvbConference.joinConferenceRoom().700 [ctx=15887991981241219259214] Joining JVB conference room: testRoom
2020-05-06 23:06:39.363 INFO: [475] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 testroom@conference.jitsi-test.XXXXXXX.de/focus has joined the testroom@conference.jitsi-test.XXXXXXX.de chat room.
2020-05-06 23:06:39.365 INFO: [475] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 testroom@conference.jitsi-test.XXXXXXX.de/77e1a9cb has joined the testroom@conference.jitsi-test.XXXXXXX.de chat room.
2020-05-06 23:06:43.016 INFO: [54] org.jitsi.jigasi.SipGatewaySession.handleCallState().1391 [ctx=15887991981241219259214] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Incoming Call newV=net.java.sip.communicator.service.protocol.CallPeerState:Disconnected for peer=0012347123889 <~~id~media@voip.XXXXXXX.de>;status=Disconnected
2020-05-06 23:06:43.017 INFO: [54] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=15887991981241219259214] SIP peer state: Disconnected
2020-05-06 23:06:48.018 INFO: [486] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().584 [ctx=15887991981241219259214] Sip call ended: Call: id=1588799198123203703767 peers=0
2020-05-06 23:06:48.020 INFO: [486] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15887991981241219259214] Member left : OWNER focus@auth.jitsi-test.XXXXXXX.de/focus1145014382654038
2020-05-06 23:06:48.020 INFO: [486] org.jitsi.jigasi.JvbConference.memberPresenceChanged().994 [ctx=15887991981241219259214] Focus left! - stopping
2020-05-06 23:06:48.020 SEVERE: [486] org.jitsi.jigasi.JvbConference.stop().491 [ctx=15887991981241219259214] Already stopped !
2020-05-06 23:06:48.021 INFO: [486] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15887991981241219259214] Member left : MEMBER 77e1a9cb@jitsi-test.XXXXXXX.de
2020-05-06 23:06:48.021 INFO: [486] org.jitsi.jigasi.JvbConference.stop().521 [ctx=15887991981241219259214] Removing account Jabber:77e1a9cb@jitsi-test.XXXXXXX.de/77e1a9cb
2020-05-06 23:06:48.030 INFO: [486] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF 
2020-05-06 23:06:48.031 INFO: [486] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=15887991981241219259214] Removed session for call. Sessions:0

Case 3: Timeout set to 180000, room not empty

2020-05-06 23:08:16.953 INFO: [54] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=1588799296929999749916] Incoming call received...
2020-05-06 23:08:16.972 INFO: [60] org.jitsi.jigasi.SipGatewaySession.run().1490 [ctx=1588799296929999749916] Wait thread cancelled
2020-05-06 23:08:16.986 INFO: [54] org.jitsi.jigasi.JvbConference.start().430 [ctx=1588799296929999749916] Starting JVB conference room: testRoom
2020-05-06 23:08:17.194 INFO: [54] org.jitsi.jigasi.JvbConference.setXmppProvider().561 [ctx=1588799296929999749916] Using ProtocolProviderServiceJabberImpl(Jabber:710392fc@jitsi-test.XXXXXXX.de/710392fc)
2020-05-06 23:08:17.537 INFO: [62] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON 
2020-05-06 23:08:17.539 INFO: [62] org.jitsi.jigasi.JvbConference.registrationStateChanged().612 [ctx=1588799296929999749916] Registering XMPP.
2020-05-06 23:08:17.730 INFO: [62] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-05-06 23:08:17.760 INFO: [62] org.jitsi.jigasi.JvbConference.joinConferenceRoom().700 [ctx=1588799296929999749916] Joining JVB conference room: testRoom
2020-05-06 23:08:17.972 INFO: [67] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 testroom@conference.jitsi-test.XXXXXXX.de/focus has joined the testroom@conference.jitsi-test.XXXXXXX.de chat room.
2020-05-06 23:08:17.985 INFO: [67] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 testroom@conference.jitsi-test.XXXXXXX.de/f9a86ec8 has joined the testroom@conference.jitsi-test.XXXXXXX.de chat room.
2020-05-06 23:08:18.779 INFO: [83] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 580 ms
2020-05-06 23:08:20.595 INFO: [83] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 1191 ms
2020-05-06 23:08:20.656 INFO: [83] org.jitsi.jigasi.JvbConference.incomingCallReceived().1077 [ctx=1588799296929999749916] Got invite from focus
2020-05-06 23:08:20.807 INFO: [54] org.jitsi.jigasi.SipGatewaySession.handleCallState().1391 [ctx=1588799296929999749916] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Incoming Call newV=net.java.sip.communicator.service.protocol.CallPeerState:Disconnected for peer=0012347123889 <~~id~media@voip.XXXXXXX.de>;status=Disconnected
2020-05-06 23:08:20.815 INFO: [54] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=1588799296929999749916] SIP peer state: Disconnected
2020-05-06 23:08:20.958 INFO: [97] 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-05-06 23:08:20.959 INFO: [97] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2020-05-06 23:08:20.979 INFO: [96] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1003 Dynamic PT map: 101=rtpmap:-1 telephone-event/8000; 
2020-05-06 23:08:20.980 INFO: [96] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2020-05-06 23:08:20.983 SEVERE: [96] 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.processFirstOffer(CallPeerMediaHandlerSipImpl.java:483)
	at net.java.sip.communicator.impl.protocol.sip.CallPeerMediaHandlerSipImpl.processOffer(CallPeerMediaHandlerSipImpl.java:446)
	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.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	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)
2020-05-06 23:08:21.043 INFO: [97] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-05-06 23:08:21.637 INFO: [97] org.jitsi.jigasi.JvbConference.callStateChanged().1182 [ctx=1588799296929999749916] JVB conference call IN_PROGRESS.
2020-05-06 23:08:21.664 SEVERE: [139] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2020-05-06 23:08:21.667 SEVERE: [139] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@66eae896
2020-05-06 23:08:21.673 SEVERE: [138] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@66eae896
2020-05-06 23:08:25.815 INFO: [98] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().584 [ctx=1588799296929999749916] Sip call ended: Call: id=158879929677622546602 peers=0
2020-05-06 23:08:25.823 INFO: [98] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=1588799296929999749916] Member left : OWNER focus@auth.jitsi-test.XXXXXXX.de/focus1145014382654038
2020-05-06 23:08:25.824 INFO: [98] org.jitsi.jigasi.JvbConference.memberPresenceChanged().994 [ctx=1588799296929999749916] Focus left! - stopping
2020-05-06 23:08:25.824 SEVERE: [98] org.jitsi.jigasi.JvbConference.stop().491 [ctx=1588799296929999749916] Already stopped !
2020-05-06 23:08:25.824 INFO: [98] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=1588799296929999749916] Member left : OWNER f9a86ec8-12d3-407e-8e4a-6a8d4b57d6ee@jitsi-test.XXXXXXX.de/abf959b3-f491-47cd-98a9-578967162aab
2020-05-06 23:08:25.825 INFO: [98] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=1588799296929999749916] Member left : GUEST 710392fc@jitsi-test.XXXXXXX.de
2020-05-06 23:08:25.836 INFO: [98] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=1588799296929999749916] Removed session for call. Sessions:0
2020-05-06 23:08:25.860 SEVERE: [100] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /134.30.108.56:10000:java.io.IOException: No active socket.
2020-05-06 23:08:25.863 SEVERE: [157] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /134.30.108.56:10000:java.io.IOException: No active socket.
2020-05-06 23:08:25.893 INFO: [157] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF 
2020-05-06 23:08:25.895 INFO: [157] org.jitsi.jigasi.CallManager$HangupCallThread.run().597 [ctx=1588799296929999749916] Removing account Jabber:710392fc@jitsi-test.XXXXXXX.de/710392fc
2020-05-06 23:08:25.896 INFO: [157] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF
#6

Case 2 is normal. Case 1, need the pcap file from /var/log/jitsi/jigasi … to be able to tell something … The NPE from case 3 … not sure what is wrong …

#7

Case 1 is the only case here where it is working as intended.
In case 2 I can’t join the room via SIP.
The callserver receives the SIP 180 Ringing and nothing happens afterwards, it just hangs up.

And in Case 3 (as soon as I set the timeout) our callserver receives a SIP 486 Busy Here, no matter if the room is already existing or not

#8

Case 3 is the NPE I’m not sure what is this … cannot create SDP … did you change anything else other than the timer? Hum … can you send the pcap file for that one, it seems like the call was disconnected even before the exception, like 70 ms before that there is SIP call ended … Disconnected

#9

Of Course :slight_smile:

Here is the packet capture from case 3.
I didn´t modify anything beside the timer.

Thank you very much again!

jitsi-Timeout180000.pcap (63.7 KB)

#10

image
image856×324 45.2 KB

#11

I manage to read it as text file.
So m=audio 50480 RTP/SAVP 9 8 101 13 your server offers only secured media. Search the forum how to enable that through the accounts properties.
This is why it is failing, as sip account does not have this option turned on.

#12

Sorry, I uploaded the pcap file Jigasi created.

I thought encryption is enabled as our callserver only allows encrypted connections or did I miss a setting?
Our VoIP Admin and me had a rough time configuring this.
Can this still be the issue even when the calls to non-empty rooms are working with the same settings?

Settings in sip-communicator.properties are:

org.jitsi.jigasi.DEFAULT_JVB_ROOM_NAME=siptest
#org.jitsi.jigasi.JVB_INVITE_TIMEOUT=1800000
net.java.sip.communicator.impl.protocol.SingleCallInProgressPolicy.enabled=false
net.java.sip.communicator.impl.protocol.sip.SKIP_REINVITE_ON_FOCUS_CHANGE_PROP=true
net.java.sip.communicator.impl.neomedia.codec.audio.opus.encoder.COMPLEXITY=10

net.java.sip.communicator.packetlogging.PACKET_LOGGING_ENABLED=true

net.java.sip.communicator.impl.protocol.sip.acc1403273890647=XXXXXXXXXx
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ACCOUNT_UID=SIP:XXXXXXXXXX
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.PASSWORD=XXXXXXXX
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.PROTOCOL_NAME=SIP
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.SERVER_ADDRESS=XXXXXXX

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.SERVER_PORT=5061

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.USER_ID=XXXXXXXXXX

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.SAVP_OPTION=1
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.PROXY_AUTO_CONFIG=true
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DISPLAY_NAME=Jitsi Konferenz
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DTMF_METHOD=RTP_DTMF
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DTMF_MINIMAL_TONE_DURATION=70

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.KEEP_ALIVE_INTERVAL=25
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.KEEP_ALIVE_METHOD=OPTIONS
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.VOICEMAIL_ENABLED=false
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.AMR-WB/16000=750
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.G722/8000=700
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.GSM/8000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.H263-1998/90000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.H264/90000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.PCMA/8000=600
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.PCMU/8000=650
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.SILK/12000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.SILK/16000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.SILK/24000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.SILK/8000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.VP8/90000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.iLBC/8000=10
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.opus/48000=1000
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.red/90000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.speex/16000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.speex/32000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.speex/8000=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.telephone-event/8000=1
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.Encodings.ulpfec/90000=0

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.OVERRIDE_ENCODINGS=false
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DEFAULT_ENCRYPTION=true

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DEFAULT_SIPZRTP_ATTRIBUTE=true
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ENCRYPTION_PROTOCOL.ZRTP=0
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ENCRYPTION_PROTOCOL.SDES=1
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ENCRYPTION_PROTOCOL.DTLS-SRTP=2
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ENCRYPTION_PROTOCOL_STATUS.ZRTP=false
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ENCRYPTION_PROTOCOL_STATUS.SDES=true
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ENCRYPTION_PROTOCOL_STATUS.DTLS-SRTP=false
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.SDES_CIPHER_SUITES=AES_CM_128_HMAC_SHA1_80,AES_CM_128_HMAC_SHA1_32

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DOMAIN_BASE=XXXXXXXXXX

org.jitsi.jigasi.xmpp.acc.IS_SERVER_OVERRIDDEN=true
org.jitsi.jigasi.xmpp.acc.SERVER_ADDRESS=127.0.0.1
org.jitsi.jigasi.xmpp.acc.VIDEO_CALLING_DISABLED=true
org.jitsi.jigasi.xmpp.acc.JINGLE_NODES_ENABLED=false
org.jitsi.jigasi.xmpp.acc.AUTO_DISCOVER_STUN=false
org.jitsi.jigasi.xmpp.acc.IM_DISABLED=true
org.jitsi.jigasi.xmpp.acc.SERVER_STORED_INFO_DISABLED=true
org.jitsi.jigasi.xmpp.acc.IS_FILE_TRANSFER_DISABLED=true

net.java.sip.communicator.service.gui.ALWAYS_TRUST_MODE_ENABLED=true

#13

I see in the logs that cancel is coming from the server. How long does your PBX wait for the call to be answered? You should also configure it to ring for 30 minutes.

#14

Thank you once again :slight_smile:
I will talk to our VoIP Admin later and give feedback here :slight_smile:

#15

Sorry for the delay, our VoIP Admin and me were quite busy in the last time.
So far, we implemented a workaround, our IVR tells the user to try again later if the room is not open and we don’t receive a 200 OK.

After forwarding your message trying to increase the timeout on both sides and he sent me this:
“I sent the CANCEL standard conform after the timeout as I didn’t receive any Answer from Jigasi”
And I got this from him when we increased the timeout to 120 seconds (Putting our users on hold for 30 Minutes is no option):

Zeit PBX Richtung Jigasi
2020-05-19 13:22:23.856 INVITE ->
2020-05-19 13:22:24.064 <- 100 Trying
2020-05-19 13:22:24.878 <- 180 Ringing
(30 Sekunden)
2020-05-19 13:24:23.025 CANCEL ->

From his perspective it looks like Jigasi is just never answering with 200 OK in case the room is empty.

But currently there is no pressure on our side as we found a workaround.

But maybe this helps in case there is an actual issue or someone else has the same problem.

Here the same flow when the room is already open:

Zeit PBX Richtung Jigasi
2020-05-19 13:00:59.123 INVITE ->
2020-05-19 13:00:59.333 <- 100 Trying
2020-05-19 13:01:00.149 <- 180 Ringing
2020-05-19 13:01:01.885 <- 200 OK
2020-05-19 13:01:01.891 ACK ->