Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Incoming Calls sometimes work and sometimes don't #243

Closed
MiningPickaxe opened this issue Mar 19, 2020 · 6 comments
Closed

Incoming Calls sometimes work and sometimes don't #243

MiningPickaxe opened this issue Mar 19, 2020 · 6 comments

Comments

@MiningPickaxe
Copy link

Hello,

I have the issue that sometimes incoming calls will either always fail, work after a few tries or always work. I havent found a pattern in this yet. During a failed call (It is someone calling from his mobile phone) I extracted this from the log:

2020-03-19 15:48:45.873 INFO: [1791] org.jitsi.jigasi.SipGateway.incomingCallReceived().188 Incoming call received...
2020-03-19 15:48:46.883 INFO: [1792] org.jitsi.jigasi.SipGatewaySession.run().1295 [ctx=15846293258742061342292]Using default JVB room name property BUS
2020-03-19 15:48:46.884 INFO: [1792] org.jitsi.jigasi.JvbConference.setXmppProvider().539 [ctx=15846293258742061342292] Using ProtocolProviderServiceJabberImpl(Jabber:21dc895b@jitsi.domain.tld/21dc895b)
2020-03-19 15:48:46.974 INFO: [1794] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().125 Jingle : ON 
2020-03-19 15:48:46.976 INFO: [1794] org.jitsi.jigasi.JvbConference.registrationStateChanged().577 [ctx=15846293258742061342292] Registering XMPP.
2020-03-19 15:48:46.985 INFO: [1794] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-03-19 15:48:46.986 INFO: [1794] org.jitsi.jigasi.JvbConference.joinConferenceRoom().648 [ctx=15846293258742061342292] Joining JVB conference room: BUS
2020-03-19 15:48:47.031 INFO: [1797] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/focus has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.043 INFO: [1797] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/3c8a40e7 has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.044 INFO: [1797] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/361a23c7 has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.044 INFO: [1797] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/1535b380 has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.047 INFO: [1797] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/69d4ef75 has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.060 INFO: [1799] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/21dc895b has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.071 INFO: [1801] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/21dc895b has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.072 INFO: [1800] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 bus@conference.jitsi.domain.tld/21dc895b has joined the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:47.136 INFO: [1807] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().254 Auto discovered harvester is null
2020-03-19 15:48:47.138 INFO: [1807] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 3 ms
2020-03-19 15:48:48.261 INFO: [1807] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 1122 ms
2020-03-19 15:48:48.267 INFO: [1807] org.jitsi.jigasi.JvbConference.incomingCallReceived().1024 [ctx=15846293258742061342292] Got invite from focus
2020-03-19 15:48:48.284 INFO: [167] 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-19 15:48:48.285 INFO: [167] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides []
2020-03-19 15:48:48.310 INFO: [167] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15846293258742061342292] SIP peer state: Connecting*
2020-03-19 15:48:48.313 SEVERE: [1816] impl.protocol.sip.OperationSetBasicTelephonySipImpl.processResponse().634 Received error: 491 Request Pending
2020-03-19 15:48:48.335 INFO: [1816] org.jitsi.jigasi.SipGatewaySession.handleCallState().1138 [ctx=15846293258742061342292] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Connecting* newV=net.java.sip.communicator.service.protocol.CallPeerState:Failed for peer=CENSOREDNUMBER <CENSOREDNUMBER@172.16.2.10>;status=Failed
2020-03-19 15:48:48.336 INFO: [1816] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1204 [ctx=15846293258742061342292] SIP peer state: Failed
2020-03-19 15:48:48.347 SEVERE: [1817] impl.protocol.sip.SipLogger.logError().133 Error from the JAIN-SIP stack: Creating server transaction for ACK -- makes no sense!
2020-03-19 15:48:48.347 SEVERE: [1817] impl.protocol.sip.SipStackSharing.processRequest().691 couldn't create transaction, please report this to dev@jitsi.org
javax.sip.TransactionUnavailableException: Cannot create Server transaction for ACK 
	at gov.nist.javax.sip.SipProviderImpl.getNewServerTransaction(SipProviderImpl.java:482)
	at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.processRequest(SipStackSharing.java:676)
	at gov.nist.javax.sip.EventScanner.deliverRequestEvent(EventScanner.java:250)
	at gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:146)
	at gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:185)
	at gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:1324)
	at gov.nist.javax.sip.stack.SIPServerTransactionImpl.processRequest(SIPServerTransactionImpl.java:811)
	at gov.nist.javax.sip.stack.UDPMessageChannel.processMessage(UDPMessageChannel.java:568)
	at gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:514)
	at gov.nist.javax.sip.stack.UDPMessageChannel.run(UDPMessageChannel.java:319)
	at java.base/java.lang.Thread.run(Thread.java:834)
2020-03-19 15:48:48.368 SEVERE: [1817] impl.protocol.sip.SipStackSharing.logApplicationException().1145 An error occurred while processing event of type: javax.sip.DialogTerminatedEvent
java.lang.NullPointerException
	at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.getServiceData(SipStackSharing.java:1107)
	at net.java.sip.communicator.impl.protocol.sip.SipStackSharing.processRequest(SipStackSharing.java:699)
	at gov.nist.javax.sip.EventScanner.deliverRequestEvent(EventScanner.java:250)
	at gov.nist.javax.sip.EventScanner.deliverEvent(EventScanner.java:146)
	at gov.nist.javax.sip.SipProviderImpl.handleEvent(SipProviderImpl.java:185)
	at gov.nist.javax.sip.DialogFilter.processRequest(DialogFilter.java:1324)
	at gov.nist.javax.sip.stack.SIPServerTransactionImpl.processRequest(SIPServerTransactionImpl.java:811)
	at gov.nist.javax.sip.stack.UDPMessageChannel.processMessage(UDPMessageChannel.java:568)
	at gov.nist.javax.sip.stack.UDPMessageChannel.processIncomingDataPacket(UDPMessageChannel.java:514)
	at gov.nist.javax.sip.stack.UDPMessageChannel.run(UDPMessageChannel.java:319)
	at java.base/java.lang.Thread.run(Thread.java:834)
2020-03-19 15:48:48.371 INFO: [107] 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-19 15:48:48.371 INFO: [107] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2020-03-19 15:48:48.378 INFO: [107] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-03-19 15:48:48.528 INFO: [107] org.jitsi.jigasi.JvbConference.callStateChanged().1122 [ctx=15846293258742061342292] JVB conference call IN_PROGRESS.
2020-03-19 15:48:48.553 SEVERE: [1896] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2020-03-19 15:48:48.553 SEVERE: [1896] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@7796f62f
2020-03-19 15:48:48.565 SEVERE: [1894] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@7796f62f

2020-03-19 15:48:53.356 INFO: [1820] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().629 [ctx=15846293258742061342292] Sip call ended: Call: id=15846293258721881537828 peers=0
2020-03-19 15:48:53.358 INFO: [1820] org.jitsi.jigasi.JvbConference.stop().500 [ctx=15846293258742061342292] Removing account Jabber:21dc895b@jitsi.domain.tld/21dc895b
2020-03-19 15:48:53.362 INFO: [1799] impl.protocol.jabber.ChatRoomJabberImpl.left().1300 bus@conference.jitsi.domain.tld/21dc895b has left the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:53.362 INFO: [1799] org.jitsi.jigasi.JvbConference.memberPresenceChanged().916 [ctx=1584626598293930107717] Member left : MEMBER knzmqmpbqtsxduqn@jitsi.domain.tld/kWNF5Vt1
2020-03-19 15:48:53.362 INFO: [1800] impl.protocol.jabber.ChatRoomJabberImpl.left().1300 bus@conference.jitsi.domain.tld/21dc895b has left the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:53.362 INFO: [1800] org.jitsi.jigasi.JvbConference.memberPresenceChanged().916 [ctx=15846289034049679986] Member left : MEMBER knzmqmpbqtsxduqn@jitsi.domain.tld/kWNF5Vt1
2020-03-19 15:48:53.370 INFO: [1801] impl.protocol.jabber.ChatRoomJabberImpl.left().1300 bus@conference.jitsi.domain.tld/21dc895b has left the bus@conference.jitsi.domain.tld chat room.
2020-03-19 15:48:53.370 INFO: [1801] org.jitsi.jigasi.JvbConference.memberPresenceChanged().916 [ctx=15846292800972021722145] Member left : MEMBER knzmqmpbqtsxduqn@jitsi.domain.tld/kWNF5Vt1
2020-03-19 15:48:53.386 SEVERE: [1825] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /172.16.4.182:10000:java.io.IOException: No active socket.
2020-03-19 15:48:53.413 INFO: [1820] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().132 Jingle : OFF 
2020-03-19 15:48:53.413 INFO: [1820] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=15846293258742061342292] Removed session for call. Sessions:3
2020-03-19 15:48:53.414 SEVERE: [1824] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /172.16.4.182:10000:java.io.IOException: No active socket.
2020-03-19 15:48:53.421 SEVERE: [108] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /172.16.4.182:10000:java.io.IOException: No active socket.

The jitsi server is avaible at jitsi.domain.tld (with domain.tld beeing a valid domain).

Extract of the config:

org.jitsi.jigasi.DEFAULT_JVB_ROOM_NAME=BUS

net.java.sip.communicator.impl.protocol.SingleCallInProgressPolicy.enabled=false

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=acc1403273890647
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.ACCOUNT_UID=SIP\:jitsi@172.16.2.10
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.PASSWORD=NOPE
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.PROTOCOL_NAME=SIP
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.SERVER_ADDRESS=172.16.2.10
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.USER_ID=jitsi@172.16.2.10
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=true
net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DEFAULT_ENCRYPTION=false

net.java.sip.communicator.impl.protocol.sip.acc1403273890647.DOMAIN_BASE=jitsi.domain.tld

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.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
@damencho
Copy link
Member

These exceptions can happen if your sip protocol provider goes in unregistered or connection_failed state. I don't see such entries in your logs you had shared, the only thing that seems suspicious is 2020-03-19 15:48:48.313 SEVERE: [1816] impl.protocol.sip.OperationSetBasicTelephonySipImpl.processResponse().634 Received error: 491 Request Pending
Not sure what is that and why you get it ...

@MiningPickaxe
Copy link
Author

I just did some research on the 491 Code, here a quote from the original RFC:

The request was received by a UAS that had a pending request within the same dialog. Section 14.2 describes how such "glare" situations are resolved.

This can happen when an INVITE is sent and then a RE-INVITE before it recieved a OK or a UPDATE event hasn't been processed yet but another one was sent. Issues on the internet mostly seem to be the racing INVITEs.

I did a tcpdump during a failed call now, this is the flow:
sip_debug.pdf
Seems like it is sending a INVITE, then reciving a 407 which is acknowledged.
The following INVITE does include Proxy-Authorization and a OK gets sent as well.
Following that is a 491, probably because the 172.16.2.10 didn't send a OK in the meantime?

Is that an issue?

@damencho
Copy link
Member

Can you try adding this config and see does it behave better: net.java.sip.communicator.impl.protocol.sip.SKIP_REINVITE_ON_FOCUS_CHANGE_PROP=true

@MiningPickaxe
Copy link
Author

Just included that in the config and did about 15 testcalls with different phones, no issues connecting to the meeting! Thank you very much!

@MiningPickaxe
Copy link
Author

Just another quick addition: I set up another instance of jitsi on my local computer and linked it to a asterisk which is also running on my computer, had the problem that it would end the call after 30 seconds because the call-in participant didnt respond... none of the error messages in log I had before though. Added the line you sent just as a desperate try of troubleshooting and voila: It works.

Could you explain what exactly the REINVITE_ON_FOCUS_CHANGE_PROP does and why it is there?

@damencho
Copy link
Member

Sends a reinvite when there is a focus in the conferenece, just adds a isfocus param in the contact header, or when focus changes. This is something used for sip conference calls that are implemented in Jitsi Desktop.

@albe albe mentioned this issue Apr 5, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@damencho @MiningPickaxe