Jigasi fails to negotiate SRTP and throws an exception "Failed to create an SDP description"

We have a working Asterisk (v13.18) integration (pjsip) with Jigasi (v1.1-107), operating perfectly with SIP TLS and normal RTP.

However attempting to enable SRTP breaks the RTP negotiation and Jigasi throws an exception “Failed to create an SDP description for an OK response to an INVITE request!”. If I remove the requirement for SDES on Asterisk then the call establishes but of course, doesn’t negotiate SDES.

I’ll include the relevant files and SIP traces below but we can see Asterisk is sending an INVITE with a SAVP SDP offer which includes the cipher and key. Jigasi responds with a 100TRYING and 180RINGING but when it should be responding with a 200 OK and connecting the media path, instead it throws an excecption and responds with a “488 Not Acceptable here”.

I’ve reviewed all similar issues and posts on getting SRTP work on the community forums, without much luck. I’m not much of an expert of the inner workings of Jitsi but am beginning to suspect something downstream towards the video bridges.

Any idea or thoughts welcome!

Jigasi logs…

2020-05-25 18:00:54.020 INFO: [51] org.jitsi.jigasi.SipGateway.incomingCallReceived().216 [ctx=15904224540201935172111] Incoming call received...
2020-05-25 18:00:55.021 INFO: [804] org.jitsi.jigasi.SipGatewaySession.run().1490 [ctx=15904224540201935172111] Wait thread cancelled
2020-05-25 18:00:55.021 INFO: [51] org.jitsi.jigasi.JvbConference.start().430 [ctx=15904224540201935172111] Starting JVB conference room: 1234-1234-roomname
2020-05-25 18:00:55.022 INFO: [51] org.jitsi.jigasi.JvbConference.setXmppProvider().561 [ctx=15904224540201935172111] Using ProtocolProviderServiceJabberImpl(Jabber:157ccf59@start.dev.secretdomain.com/157ccf59)
2020-05-25 18:00:55.152 INFO: [805] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().127 Jingle : ON 
2020-05-25 18:00:55.160 INFO: [805] org.jitsi.jigasi.JvbConference.registrationStateChanged().612 [ctx=15904224540201935172111] Registering XMPP.
2020-05-25 18:00:55.208 INFO: [805] impl.protocol.jabber.ProtocolProviderServiceJabberImpl.authenticated().2535 Authenticated: false
2020-05-25 18:00:55.213 INFO: [805] org.jitsi.jigasi.JvbConference.joinConferenceRoom().700 [ctx=15904224540201935172111] Joining JVB conference room: 1234-1234-roomname
2020-05-25 18:00:55.274 INFO: [810] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 1234-1234-roomname@conference.start.dev.secretdomain.com/52055323 has joined the 1234-1234-roomname@conference.start.dev.secretdomain.com chat room.
2020-05-25 18:00:55.283 INFO: [810] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 1234-1234-roomname@conference.start.dev.secretdomain.com/1aa58691 has joined the 1234-1234-roomname@conference.start.dev.secretdomain.com chat room.
2020-05-25 18:00:55.284 INFO: [810] impl.protocol.jabber.ChatRoomJabberImpl.joined().1256 1234-1234-roomname@conference.start.dev.secretdomain.com/focus has joined the 1234-1234-roomname@conference.start.dev.secretdomain.com chat room.
2020-05-25 18:00:55.316 INFO: [827] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().254 Auto discovered harvester is null
2020-05-25 18:00:55.320 INFO: [827] impl.protocol.jabber.IceUdpTransportManager.createIceAgent().346 End gathering harvester within 4 ms
2020-05-25 18:00:56.449 INFO: [827] impl.protocol.jabber.CallPeerMediaHandlerJabberImpl.harvestCandidates().1198 End candidate harvest within 1128 ms
2020-05-25 18:00:56.453 INFO: [827] org.jitsi.jigasi.JvbConference.incomingCallReceived().1077 [ctx=15904224540201935172111] Got invite from focus
2020-05-25 18:00:56.470 SEVERE: [114] 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.impl.protocol.sip.CallPeerMediaHandlerSipImpl.updateMediaDescriptionForSDes(CallPeerMediaHandlerSipImpl.java:1149)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerMediaHandlerSipImpl.setAndAddPreferredEncryptionProtocol(CallPeerMediaHandlerSipImpl.java:1881)
        at net.java.sip.communicator.impl.protocol.sip.CallPeerMediaHandlerSipImpl.createMediaDescriptionsForAnswer(CallPeerMediaHandlerSipImpl.java:763)
        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-25 18:00:56.474 INFO: [114] org.jitsi.jigasi.SipGatewaySession.handleCallState().1391 [ctx=15904224540201935172111] SIP call ended: CallPeerChangeEvent: type=CallPeerStatusChange oldV=net.java.sip.communicator.service.protocol.CallPeerState:Incoming Call newV=net.java.sip.communicator.service.protocol.CallPeerState:Failed for peer=31102902929 <31102902929@10.211.46.235>;status=Failed
2020-05-25 18:00:56.482 INFO: [114] org.jitsi.jigasi.SipGatewaySession.peerStateChanged().1457 [ctx=15904224540201935172111] SIP peer state: Failed
2020-05-25 18:00:56.520 INFO: [134] 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-25 18:00:56.520 INFO: [134] service.protocol.media.MediaHandler.registerDynamicPTsWithStream().1020 PT overrides [103->104 ]
2020-05-25 18:00:56.523 INFO: [134] service.protocol.media.CallPeerMediaHandler.start().1961 Starting
2020-05-25 18:00:56.622 INFO: [134] org.jitsi.jigasi.JvbConference.callStateChanged().1182 [ctx=15904224540201935172111] JVB conference call IN_PROGRESS.
2020-05-25 18:00:56.699 SEVERE: [907] net.sf.fmj.media.Log.error()   Unable to handle format: LINEAR, 48000.0 Hz, 16-bit, Mono, LittleEndian, Signed
2020-05-25 18:00:56.699 SEVERE: [907] net.sf.fmj.media.Log.error() Failed to prefetch: net.sf.fmj.media.ProcessEngine@2a0c846c
2020-05-25 18:00:56.703 SEVERE: [906] net.sf.fmj.media.Log.error() Error: Unable to prefetch net.sf.fmj.media.ProcessEngine@2a0c846c

2020-05-25 18:01:01.490 INFO: [840] org.jitsi.jigasi.SipGatewaySession.sipCallEnded().584 [ctx=15904224540201935172111] Sip call ended: Call: id=1590422454018978262852 peers=0
2020-05-25 18:01:01.491 INFO: [840] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15904224540201935172111] Member left : OWNER 3cp5jdsvt0j4n1t6@start.dev.secretdomain.com/-UZ9EG4_
2020-05-25 18:01:01.492 INFO: [840] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15904224540201935172111] Member left : OWNER focus@auth.start.dev.secretdomain.com/focus19946621027
2020-05-25 18:01:01.492 INFO: [840] org.jitsi.jigasi.JvbConference.memberPresenceChanged().994 [ctx=15904224540201935172111] Focus left! - stopping
2020-05-25 18:01:01.492 SEVERE: [840] org.jitsi.jigasi.JvbConference.stop().491 [ctx=15904224540201935172111] Already stopped !
2020-05-25 18:01:01.492 INFO: [840] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15904224540201935172111] Member left : GUEST 157ccf59@start.dev.secretdomain.com
2020-05-25 18:01:01.492 INFO: [840] org.jitsi.jigasi.JvbConference.memberPresenceChanged().986 [ctx=15904224540201935172111] Member left : MEMBER _86nnlhkhm55ujj1@start.dev.secretdomain.com/TqzAf433
2020-05-25 18:01:01.492 INFO: [840] org.jitsi.jigasi.AbstractGateway.notifyCallEnded().128 [ctx=15904224540201935172111] Removed session for call. Sessions:0
2020-05-25 18:01:01.512 SEVERE: [844] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /10.211.45.243:10000:java.io.IOException: No active socket.
2020-05-25 18:01:01.513 SEVERE: [115] org.jitsi.impl.neomedia.RTPConnectorOutputStream.log() Failed to send a packet to target /10.211.45.243:10000:java.io.IOException: No active socket.
2020-05-25 18:01:01.527 INFO: [115] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF 
2020-05-25 18:01:01.527 INFO: [115] org.jitsi.jigasi.CallManager$HangupCallThread.run().597 [ctx=15904224540201935172111] Removing account Jabber:157ccf59@start.dev.secretdomain.com/157ccf59
2020-05-25 18:01:01.528 INFO: [115] impl.protocol.jabber.OperationSetBasicTelephonyJabberImpl.registrationStateChanged().134 Jingle : OFF 

SIP Trace as follows…

<--- Transmitting SIP request (1212 bytes) to TLS:10.211.32.176:56361 --->
INVITE sip:jigasi@10.211.32.176:56361;transport=tls;registering_acc=10_211_46_235 SIP/2.0
Via: SIP/2.0/TLS 10.211.46.235:5061;rport;branch=z9hG4bKPj56e90cd2-13bf-4a5d-90fd-68ec13357524;alias
From: <sip:31102902929@10.211.46.235>;tag=d964cc17-1afe-4a6f-84aa-bc05d06dc45a
To: <sip:jigasi@10.211.32.176;registering_acc=10_211_46_235>
Contact: <sip:asterisk@10.211.46.235:5061;transport=TLS>
Call-ID: ac7d6d85-d9b6-4444-9d86-999f0ef095bd
CSeq: 15977 INVITE
Allow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REGISTER, REFER, MESSAGE
Supported: 100rel, timer, replaces, norefersub
Session-Expires: 1800
Min-SE: 90
Jitsi-Conference-Room: 1234-1234-roomname
X-Room-Name: 1234-1234-roomname
Jitsi-Conference-Room: 1122334455
Max-Forwards: 70
User-Agent: Asterisk PBX 13.18.3~dfsg-1ubuntu4
Content-Type: application/sdp
Content-Length:   324

v=0
o=- 1213907305 1213907305 IN IP4 10.211.46.235
s=Asterisk
c=IN IP4 10.211.46.235
t=0 0
m=audio 16534 RTP/SAVP 0 101
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:zlfVWLKw468/7NwYY1V0TdKUwI5ermVkWnQ9n7Dx
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
a=sendrecv

<--- Received SIP response (381 bytes) from TLS:10.211.32.176:56361 --->
SIP/2.0 100 Trying
CSeq: 15977 INVITE
Call-ID: ac7d6d85-d9b6-4444-9d86-999f0ef095bd
From: <sip:447947400000@10.211.46.235>;tag=d964cc17-1afe-4a6f-84aa-bc05d06dc45a
To: <sip:jigasi@10.211.32.176;registering_acc=10_211_46_235>
Via: SIP/2.0/TLS 10.211.46.235:5061;rport=5061;branch=z9hG4bKPj56e90cd2-13bf-4a5d-90fd-68ec13357524;alias;received=10.211.46.235
Content-Length: 0


<--- Received SIP response (532 bytes) from TLS:10.211.32.176:56361 --->
SIP/2.0 180 Ringing
CSeq: 15977 INVITE
Call-ID: ac7d6d85-d9b6-4444-9d86-999f0ef095bd
From: <sip:447947400000@10.211.46.235>;tag=d964cc17-1afe-4a6f-84aa-bc05d06dc45a
To: <sip:jigasi@10.211.32.176;registering_acc=10_211_46_235>;tag=1ee7034c
Via: SIP/2.0/TLS 10.211.46.235:5061;rport=5061;branch=z9hG4bKPj56e90cd2-13bf-4a5d-90fd-68ec13357524;alias;received=10.211.46.235
Contact: "jigasi" <sip:jigasi@10.211.32.176:56361;transport=tls;registering_acc=10_211_46_235>
User-Agent: Jigasi1.1.107-g6928850Linux
Content-Length: 0


<--- Received SIP response (544 bytes) from TLS:10.211.32.176:56361 --->
SIP/2.0 488 Not Acceptable here
CSeq: 15977 INVITE
Call-ID: ac7d6d85-d9b6-4444-9d86-999f0ef095bd
From: <sip:447947400000@10.211.46.235>;tag=d964cc17-1afe-4a6f-84aa-bc05d06dc45a
To: <sip:jigasi@10.211.32.176;registering_acc=10_211_46_235>;tag=1ee7034c
Via: SIP/2.0/TLS 10.211.46.235:5061;rport=5061;branch=z9hG4bKPj56e90cd2-13bf-4a5d-90fd-68ec13357524;alias;received=10.211.46.235
Contact: "jigasi" <sip:jigasi@10.211.32.176:56361;transport=tls;registering_acc=10_211_46_235>
User-Agent: Jigasi1.1.107-g6928850Linux
Content-Length: 0


<--- Transmitting SIP request (498 bytes) to TLS:10.211.32.176:56361 --->
ACK sip:jigasi@10.211.32.176:56361;transport=tls;registering_acc=10_211_46_235 SIP/2.0
Via: SIP/2.0/TLS 10.211.46.235:5061;rport;branch=z9hG4bKPj56e90cd2-13bf-4a5d-90fd-68ec13357524;alias
From: <sip:447947400000@10.211.46.235>;tag=d964cc17-1afe-4a6f-84aa-bc05d06dc45a
To: <sip:jigasi@10.211.32.176;registering_acc=10_211_46_235>;tag=1ee7034c
Call-ID: ac7d6d85-d9b6-4444-9d86-999f0ef095bd
CSeq: 15977 ACK
Max-Forwards: 70
User-Agent: Asterisk PBX 13.18.3~dfsg-1ubuntu4
Content-Length:  0

Finally, the jigasi configuration…

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.SKIP_REINVITE_ON_FOCUS_CHANGE_PROP=true

net.java.sip.communicator.impl.protocol.sip.acc1=acc1
net.java.sip.communicator.impl.protocol.sip.acc1.PREFERRED_TRANSPORT=TLS
net.java.sip.communicator.impl.protocol.sip.acc1.ACCOUNT_UID=SIP\:jigasi@asterisk
net.java.sip.communicator.impl.protocol.sip.acc1.PASSWORD=topsecret==
net.java.sip.communicator.impl.protocol.sip.acc1.PROTOCOL_NAME=SIP
net.java.sip.communicator.impl.protocol.sip.acc1.SERVER_ADDRESS=10.211.46.235
net.java.sip.communicator.impl.protocol.sip.acc1.SERVER_PORT=5061
net.java.sip.communicator.impl.protocol.sip.acc1.PROXY_ADDRESS=10.211.46.235
net.java.sip.communicator.impl.protocol.sip.acc1.PROXY_PORT=5061
net.java.sip.communicator.impl.protocol.sip.acc1.PROXY_ADDRESS_VALIDATED=true
net.java.sip.communicator.impl.protocol.sip.acc1.PROXY_AUTO_CONFIG=false

# force SRTP
net.java.sip.communicator.impl.protocol.sip.acc1.SAVP_OPTION=1
net.java.sip.communicator.impl.protocol.sip.acc1.DEFAULT_ENCRYPTION=true
net.java.sip.communicator.impl.protocol.sip.acc1.SDES_CHIPER_SUITES=AES_CM_128_HMAC_SHA1_80
net.java.sip.communicator.impl.protocol.sip.acc1.ENCRYPTION_PROTOCOL.ZRTP=0
net.java.sip.communicator.impl.protocol.sip.acc1.ENCRYPTION_PROTOCOL.SDES=1
net.java.sip.communicator.impl.protocol.sip.acc1.ENCRYPTION_PROTOCOL.DTLS-SRTP=2
net.java.sip.communicator.impl.protocol.sip.acc1.ENCRYPTION_PROTOCOL_STATUS.ZRTP=false
net.java.sip.communicator.impl.protocol.sip.acc1.ENCRYPTION_PROTOCOL_STATUS.SDES=true
net.java.sip.communicator.impl.protocol.sip.acc1.ENCRYPTION_PROTOCOL_STATUS.DTLS-SRTP=false

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

net.java.sip.communicator.impl.protocol.sip.acc1.DOMAIN_BASE=start.dev.secretdomain.com

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 I know you’ve got a lot of experience in this area, wondering if you’d get a chance to take a look?

Shameless bump I’m afraid, anyone able to provide some guidance on debugging this or any experience that may help? @damencho any tips from you sir?

show the log from Asterisk CLI

The log is consistent with the 488 received from Jigasi, as below:

  == Spawn extension (jitsimeet-inbound, 441133668899, 1) exited non-zero on 'PJSIP/jigasi-0000000f'
-- PJSIP/jigasi-0000000f Internal Gosub(sub-headers,caller_handler,1(1234-1234-roomname,3531106700)) complete GOSUB_RETVAL=
-- Called PJSIP/jigasi
-- PJSIP/jigasi-0000000f is ringing
-- PJSIP/jigasi-0000000f is ringing
-- PJSIP/jigasi-0000000f is ringing
== Everyone is busy/congested at this time (1:0/0/1)
-- Auto fallthrough, channel 'PJSIP/pstn-inbound-0000000e' status is 'CHANUNAVAIL'

The question has to be why Jigasi is unable to offer an SDP that supports SAVP/SRTP, and I do see some occasional socket binding issues on Jigasi just before the failed SDP creation which make me very suspicious.

2020-06-05 12:00:31.065 INFO: [174] impl.netaddr.NetworkAddressManagerServiceImpl.createDatagramSocket().549 Retrying a bind because of a failure to bind to address /10.211.35.9 and port 10004