search

sipwise / rtpengine

The Sipwise media proxy for Kamailio
GNU General Public License v3.0
767 stars 363 forks source link

SRTP output wanted, but no crypto suite was negotiated #695

Closed RusYus closed 5 years ago

RusYus commented 5 years ago

Hello, I'm using rtpengine with kamailio as SRTP-RTP proxy and having difficulties with decoding SDP SIP INVITE message. For some reason rtpengine expects to send output INVITE with SRTP instead of plain RTP. Although voice is working fine in both directions, I keep getting same errors "SRTP output wanted, but no crypto suite was negotiated".

This is part of my kamailio routing config file:
#!KAMAILIO
####### Routing Logic ########

/* Main SIP request routing logic
 * - processing of any incoming SIP request starts with this route
 * - note: this is the same as route { ... } */

request_route
{
    xlog("L_INFO", "Request from:$si:$sp\n$mb\n");
   route(SIPPROXY);
}

onsend_route_reply = yes
onsend_route
{
    xlog("L_INFO", "Send to:$snd(ip):$snd(port)\n$snd(buf)\n");
    if (dst_ip == $snd(ip) && dst_port == $snd(port))
    {
        xlog("L_ERROR", "Loop Detected\n");
        drop;
    }
}

route [SIPPROXY]
{
    if (has_body("application/sdp"))
    {
        if ($si=="172.17.11.177")
        {
            rtpengine_offer("SRTP ICE=remove");
        } else
        {
            rtpengine_offer("RTP/AVP ICE=remove");
        }
 }

And here is a part of log file:

Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: INFO: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: Request from:10.97.20.182:51750#012INVITE sip:75061@kamailio-test1.acs.tlab.alcatel.ru:9818 SIP/2.0#015#012To: sip:75061@kamailio-test1.acs.tlab.alcatel.ru:9818#015#012From: "Ivan3 Ivanov3" <sip:75062@kamailio-test1.acs.tlab.alcatel.ru>;tag=28162102596556d22d4032ae4f0ab4f0#015#012Contact: "Ivan3 Ivanov3" <sip:75062@10.97.20.182:5261;transport=TLS>;expires=3600#015#012Content-Type: application/sdp#015#012Accept: application/sdp,application/media_control+xml#015#012Expires: 3600#015#012Allow-Events: talk, hold#015#012P-Alcatel-CSBU: APP_TAG_SIPUA=1548664998#015#012Supported: replaces,timer#015#012User-Agent: ALE OTC PC SQUALE v2.4.000.040#015#012Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,REFER,NOTIFY,PRACK,UPDATE,PUBLISH,INFO,SUBSCRIBE#015#012Call-ID: 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182#015#012CSeq: 2896 INVITE#015#012Via: SIP/2.0/TLS 10.97.20.182:5261;branch=z9hG4bKd791bf19412b12ce13e522cdd910ade7#015#012Max-Forwards: 70#015#012Content-Length: 383#015#012#015#012v=0#015#012o=75062 1548664998 1548664998 IN IP4 10.97.20.182#015#012s=-#015#012c=IN IP4 10.97.20.182#015#012t=0 0#015#012m=audio 32000 RTP/SAVP 0 8 18 101#015#012a=ptime:20#015#012a=maxptime:40#015#012a=rtpmap:0 PCMU/8000/1#015#012a=rtpmap:8 PCMA/8000/1#015#012a=rtpmap:18 G729/8000/1#015#012a=fmtp:18 annexb=no#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:101 0-15#015#012a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:49TKErVVw79w6t2cTT2gbBqBGaluPtt8p/gkQ1w8
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: INFO: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: SIPPROXY route
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.288872] INFO: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Received command 'offer' from 127.0.0.1:37323
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.288935] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Dump for 'offer' from 127.0.0.1:37323: { "sdp": "v=0
Jan 28 11:44:55 debian rtpengine[2854]: o=75062 1548664998 1548664998 IN IP4 10.97.20.182
Jan 28 11:44:55 debian rtpengine[2854]: s=-
Jan 28 11:44:55 debian rtpengine[2854]: c=IN IP4 10.97.20.182
Jan 28 11:44:55 debian rtpengine[2854]: t=0 0
Jan 28 11:44:55 debian rtpengine[2854]: m=audio 32000 RTP/SAVP 0 8 18 101
Jan 28 11:44:55 debian rtpengine[2854]: a=ptime:20
Jan 28 11:44:55 debian rtpengine[2854]: a=maxptime:40
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:0 PCMU/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:8 PCMA/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:18 G729/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: a=fmtp:18 annexb=no
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:101 telephone-event/8000
Jan 28 11:44:55 debian rtpengine[2854]: a=fmtp:101 0-15
Jan 28 11:44:55 debian rtpengine[2854]: a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:49TKErVVw79w6t2cTT2gbBqBGaluPtt8p/gkQ1w8
Jan 28 11:44:55 debian rtpengine[2854]: ", "ICE": "remove", "transport-protocol": "RTP/AVP", "SDES": [ "off" ], "call-id": "3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182", "received-from": [ "IP4", "10.97.20.182" ], "from-tag": "28162102596556d22d4032ae4f0ab4f0", "command": "offer" }
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289114] NOTICE: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Creating new call
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289188] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Default sink codec is PCMU/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289197] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Creating codec handler for PCMU/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289211] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Sink supports codec PCMU/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289238] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Creating codec handler for PCMA/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289244] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Sink supports codec PCMA/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289250] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Creating codec handler for G729/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289256] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Sink supports codec G729/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289267] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Creating codec handler for telephone-event/8000
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289502] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: set FILLED flag for stream 10.97.20.182:32000
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: INFO: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: RTP/AVP ICE=remove
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289523] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: [172.17.11.174:30044] Initialized incoming SRTP with SDES crypto params: suite AES_CM_128_HMAC_SHA1_80, tag 1, key 49TKErVVw79w6t2cTT2gbA== salt GoEZqW4+23yn+CRDXDw=
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289532] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: [1] Initialized outgoing SRTP with SDES crypto params: <none>
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289539] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: set FILLED flag for stream 10.97.20.182:32001
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289550] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: [172.17.11.174:30045] Initialized incoming SRTP with SDES crypto params: suite AES_CM_128_HMAC_SHA1_80, tag 1, key 49TKErVVw79w6t2cTT2gbA== salt GoEZqW4+23yn+CRDXDw=
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289558] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: [2] Initialized outgoing SRTP with SDES crypto params: <none>
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289598] INFO: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Replying to 'offer' from 127.0.0.1:37323 (elapsed time 0.000649 sec)
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.289618] DEBUG: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182]: Response dump for 'offer' to 127.0.0.1:37323: { "sdp": "v=0
Jan 28 11:44:55 debian rtpengine[2854]: o=75062 1548664998 1548664998 IN IP4 10.97.20.182
Jan 28 11:44:55 debian rtpengine[2854]: s=-
Jan 28 11:44:55 debian rtpengine[2854]: c=IN IP4 172.17.11.174
Jan 28 11:44:55 debian rtpengine[2854]: t=0 0
Jan 28 11:44:55 debian rtpengine[2854]: m=audio 30034 RTP/AVP 0 8 18 101
Jan 28 11:44:55 debian rtpengine[2854]: a=maxptime:40
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:0 PCMU/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:8 PCMA/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:18 G729/8000/1
Jan 28 11:44:55 debian rtpengine[2854]: a=rtpmap:101 telephone-event/8000
Jan 28 11:44:55 debian rtpengine[2854]: a=fmtp:18 annexb=no
Jan 28 11:44:55 debian rtpengine[2854]: a=fmtp:101 0-15
Jan 28 11:44:55 debian rtpengine[2854]: a=sendrecv
Jan 28 11:44:55 debian rtpengine[2854]: a=rtcp:30035
Jan 28 11:44:55 debian rtpengine[2854]: a=ptime:20
Jan 28 11:44:55 debian rtpengine[2854]: ", "result": "ok" }
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: WARNING: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE,from client
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: WARNING: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE, Contact modified for SBC:"Ivan3 Ivanov3" <sip:75062@10.97.20.182:5261;transport=TLS>;expires=3600
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: WARNING: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE, lookup / contact not found (retcode = -1)
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: WARNING: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE, reinvite : no suspend
Jan 28 11:44:55 debian /usr/sbin/kamailio[2888]: INFO: {1 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: Send to:172.17.11.177:5060#012INVITE sip:75061@nodeame14.acs.tlab.alcatel.ru SIP/2.0#015#012To: sip:75061@nodeame14.acs.tlab.alcatel.ru#015#012From: "Ivan3 Ivanov3" <sip:75062@nodeame14.acs.tlab.alcatel.ru>;tag=28162102596556d22d4032ae4f0ab4f0#015#012Content-Type: application/sdp#015#012Accept: application/sdp,application/media_control+xml#015#012Expires: 3600#015#012Allow-Events: talk, hold#015#012P-Alcatel-CSBU: APP_TAG_SIPUA=1548664998#015#012Supported: replaces,timer#015#012User-Agent: ALE OTC PC SQUALE v2.4.000.040#015#012Allow: INVITE,ACK,BYE,CANCEL,OPTIONS,REFER,NOTIFY,PRACK,UPDATE,PUBLISH,INFO,SUBSCRIBE#015#012Call-ID: 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182#015#012CSeq: 2896 INVITE#015#012Via: SIP/2.0/UDP 172.17.11.174:9817;branch=z9hG4bK189b.e671f0d811b6b22f3c918d5dd143e5da.0;i=2#015#012Via: SIP/2.0/TLS 10.97.20.182:5261;branch=z9hG4bKd791bf19412b12ce13e522cdd910ade7#015#012Max-Forwards: 70#015#012Content-Length: 325#015#012Contact: "Ivan3 Ivanov3" <sip:75062@172.17.11.174:9818>#015#012#015#012v=0#015#012o=75062 1548664998 1548664998 IN IP4 10.97.20.182#015#012s=-#015#012c=IN IP4 172.17.11.174#015#012t=0 0#015#012m=audio 30034 RTP/AVP 0 8 18 101#015#012a=maxptime:40#015#012a=rtpmap:0 PCMU/8000/1#015#012a=rtpmap:8 PCMA/8000/1#015#012a=rtpmap:18 G729/8000/1#015#012a=rtpmap:101 telephone-event/8000#015#012a=fmtp:18 annexb=no#015#012a=fmtp:101 0-15#015#012a=sendrecv#015#012a=rtcp:30035#015#012a=ptime:20
Jan 28 11:44:55 debian /usr/sbin/kamailio[2874]: INFO: {2 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE_REPLY
Jan 28 11:44:55 debian /usr/sbin/kamailio[2874]: INFO: {2 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE_REPLY, 100 TRYING INVITE
Jan 28 11:44:55 debian /usr/sbin/kamailio[2871]: INFO: {2 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE_REPLY
Jan 28 11:44:55 debian /usr/sbin/kamailio[2871]: INFO: {2 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: INVITE_REPLY, 180 RINGING INVITE
Jan 28 11:44:55 debian /usr/sbin/kamailio[2871]: INFO: {2 2896 INVITE 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182} <script>: Send to:10.97.20.182:5261#012SIP/2.0 180 Ringing#015#012Allow: INVITE, ACK, CANCEL, BYE, PRACK, NOTIFY, REFER, SUBSCRIBE, OPTIONS, UPDATE#015#012User-Agent: OmniPCX Enterprise R12.2 m3.402.14.d#015#012P-Asserted-Identity: "Ivanov2 Ivan2" <sip:75061@172.17.11.177;user=phone>#015#012Content-Type: application/sdp#015#012To: sip:75061@nodeame14.acs.tlab.alcatel.ru;tag=8ab534ce8619565bf61f03fe435ebe20#015#012From: "Ivan3 Ivanov3" <sip:75062@nodeame14.acs.tlab.alcatel.ru>;tag=28162102596556d22d4032ae4f0ab4f0#015#012Call-ID: 3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182#015#012CSeq: 2896 INVITE#015#012Via: SIP/2.0/TLS 10.97.20.182:5261;branch=z9hG4bKd791bf19412b12ce13e522cdd910ade7#015#012Content-Length: 218#015#012Contact: "Ivan3 Ivanov3" <sip:75061@172.17.11.174:9817>#015#012#015#012v=0#015#012o=OXE 1548664998 1548664998 IN IP4 172.17.11.177#015#012s=abs#015#012c=IN IP4 172.17.11.179#015#012t=0 0#015#012m=audio 32728 RTP/AVP 8 101#015#012a=sendrecv#015#012a=rtpmap:8 PCMA/8000#015#012a=ptime:30#015#012a=maxptime:30#015#012a=rtpmap:101 telephone-event/8000
Jan 28 11:44:55 debian rtpengine[2854]: [1548665095.402167] ERR: [3ac758e6bacf898c77801d5cc79e53ca@10.97.20.182 port 30034]: SRTP output wanted, but no crypto suite was negotiated
rfuchs commented 5 years ago

That's expected before the answer passed through rtpengine, as the crypto keys to be used for outgoing SRTP are communicated in the answer. So receiving RTP would have to send SRTP to the SRTP endpoint, but no outgoing keys were sent to it yet, so SRTP cannot be sent. Media will start flowing after the answer passes through end the error will disappear.

virmis commented 5 years ago

I have the same "problem". Sound is working fine, but still see ERR. Rtpengine Version: 7.1.1.1-1.el7

Feb  8 16:10:32 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6]: Received command 'offer' from 127.0.0.1:42640
Feb  8 16:10:32 webrtc2sip rtpengine[3193]: NOTICE: [ni6k9rj7skkvg21bcqk6]: Creating new call
Feb  8 16:10:32 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6]: Replying to 'offer' from 127.0.0.1:42640 (elapsed time 0.001769 sec)
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6]: Received command 'answer' from 127.0.0.1:45083
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6]: Replying to 'answer' from 127.0.0.1:45083 (elapsed time 0.000477 sec)
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: ERR: [ni6k9rj7skkvg21bcqk6 port 30106]: SRTP output wanted, but no crypto suite was negotiated
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: ICE negotiated: peer for component 1 is 10.163.11.26:52622
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: ICE negotiated: local interface 10.15.27.168
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: DTLS: Peer certificate accepted
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: DTLS-SRTP successfully negotiated
Feb  8 16:10:35 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: DTLS-SRTP successfully negotiated
Feb  8 16:10:39 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: Confirmed peer address as 10.163.11.26:52622
Feb  8 16:10:39 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30106]: Confirmed peer address as 10.15.27.169:16332
Feb  8 16:10:39 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30106]: Kernelizing media stream: 10.15.27.169:16332
Feb  8 16:10:39 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30122]: Kernelizing media stream: 10.163.11.26:52622
Feb  8 16:10:40 webrtc2sip rtpengine[3193]: INFO: [ni6k9rj7skkvg21bcqk6 port 30107]: Confirmed peer address as 10.15.27.169:16333
rfuchs commented 5 years ago

I'm closing this because it's not a problem. You can't send media to an SRTP endpoint before the crypto has been negotiated, so it's expected to see this error at that point.