[asterisk-bugs] [JIRA] (ASTERISK-22717) SRTP audio stream rejected, 'Could not set SRTP policies'

Sat Nov 23 09:14:03 CST 2013

    [ https://issues.asterisk.org/jira/browse/ASTERISK-22717?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=212199#comment-212199 ] 

Miguel Oyarzo edited comment on ASTERISK-22717 at 11/23/13 9:13 AM:
--------------------------------------------------------------------

'Could not set SRTP policies' error looks come from the media-level SDP subsystem (audio).

I have compiled asterisk version 1.8, 11.5, 11.6, 11.7 and 12+pjproject (beta), using 

./configure --with-crypto --with-ssl=ssl --with-srtp 
In all of them I have got the same error. 

Here is a comparison between a two asterisk (1st the wrong one and 2nd a good one)

1) debug info for 'Could not set SRTP policies' in v 11.5, 11.6 and 11.7 :
--------------------------------------------------------------------------
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 120.151.131.182... OK.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtcp:35536 IN IP4 120.151.131.182... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=candidate:2880323124 1 udp 2113937151 192.168.1.116 35536 typ host generation 0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=candidate:2880323124 2 udp 2113937151 192.168.1.116 35536 typ host generation 0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=candidate:719730816 1 udp 1845501695 120.151.131.182 35536 typ srflx raddr 192.168.1.116 rport 35536 generation 0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=candidate:719730816 2 udp 1845501695 120.151.131.182 35536 typ srflx raddr 192.168.1.116 rport 35536 generation 0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=candidate:3844981444 1 tcp 1509957375 192.168.1.116 0 typ host generation 0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=candidate:3844981444 2 tcp 1509957375 192.168.1.116 0 typ host generation 0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:1CP3jxtzuJ2E0abs... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:+G+gGovtGtJpvtR7Vwu8rUrR... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ice-options:google-ice... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] sip/sdp_crypto.c: local_key64 hk/mNH3lyP3zZdqPcN/baYi0bseGDhxpx7dSU5ym len 40
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=crypto:0 AES_CM_128_HMAC_SHA1_32 inline:cco12sJzvfVhfEH+Zin5D+8gIIh5aGdp6L+EG3KR... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:iAo1Cwh1p+bbAxcWrptG5//JMOf8Hfla5PZmHRLt... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] rtp_engine.c: Unsetting payload 111 on 0x7eff3809d5f0
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 minptime=10... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] rtp_engine.c: Unsetting payload 103 on 0x7eff3809d5f0
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] rtp_engine.c: Unsetting payload 104 on 0x7eff3809d5f0
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] rtp_engine.c: Unsetting payload 107 on 0x7eff3809d5f0
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 CN/48000... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] rtp_engine.c: Unsetting payload 106 on 0x7eff3809d5f0
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] rtp_engine.c: Unsetting payload 105 on 0x7eff3809d5f0
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=maxptime:60... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3099275212 cname:KbyN6wgr0l08loow... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3099275212 msid:9vab82wO7bfv5ZEOebNaBGOcP7gpKoXJIjD8 9vab82wO7bfv5ZEOebNaBGOcP7gpKoXJIjD8a0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3099275212 mslabel:9vab82wO7bfv5ZEOebNaBGOcP7gpKoXJIjD8... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Processing media-level (audio) SDP a=ssrc:3099275212 label:9vab82wO7bfv5ZEOebNaBGOcP7gpKoXJIjD8a0... UNSUPPORTED OR FAILED.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id  #530
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: Trying to put 'SIP/2.0 488' onto UDP socket destined for 10.10.1.105:5061
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: No compatible codecs for this SIP call.
[Nov 19 16:31:56] DEBUG[2496][C-00000009] chan_sip.c: SIP message could not be handled, bad request: 46e28c96-b72c-5e45-59c4-44c153800ac0
---------------------------------------------------------------------

2) debug info for Asterisk 11.4 (it accepts the ICE candidates and  SRTP policy are activated accordingly):
--------------------------------------------------------------------------------------------------------------

[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP c=IN IP4 120.151.131.182... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtcp:41583 IN IP4 120.151.131.182... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '192.168.1.116' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '192.168.1.116' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '0' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '0' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=candidate:2880323124 1 udp 2113937151 192.168.1.116 41583 typ host generation 0... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '192.168.1.116' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '192.168.1.116' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '0' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '0' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=candidate:2880323124 2 udp 2113937151 192.168.1.116 41583 typ host generation 0... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '120.151.131.182' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '120.151.131.182' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '192.168.1.116' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '192.168.1.116' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=candidate:719730816 1 udp 1845501695 120.151.131.182 41583 typ srflx raddr 192.168.1.116 rport 41583 generation 0... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '120.151.131.182' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '120.151.131.182' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '192.168.1.116' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '192.168.1.116' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=candidate:719730816 2 udp 1845501695 120.151.131.182 41583 typ srflx raddr 192.168.1.116 rport 41583 generation 0... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '192.168.1.116' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '192.168.1.116' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '0' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '0' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=candidate:3844981444 1 tcp 1509957375 192.168.1.116 0 typ host generation 0... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '192.168.1.116' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '192.168.1.116' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: Splitting '0' into...
[Nov 21 11:17:03] DEBUG[7790][C-00000003] netsock2.c: ...host '0' and port ''.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=candidate:3844981444 2 tcp 1509957375 192.168.1.116 0 typ host generation 0... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ice-ufrag:p6+x8ZINjVEiN1gY... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ice-pwd:thFN7SEmQFzz0uVZqvKzV2R5... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ice-options:google-ice... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=mid:audio... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtcp-mux... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] sip/sdp_crypto.c: local_key64 jExVjMeWdFO1mMwtXmELA0jPcdJiDFnteK/KzlHz len 40
[Nov 21 11:17:03] DEBUG[7790][C-00000003] res_srtp.c: Adding new policy for SSRC 573868301
[Nov 21 11:17:03] DEBUG[7790][C-00000003] sip/sdp_crypto.c: SRTP policy activated
[Nov 21 11:17:03] DEBUG[7790][C-00000003] sip/sdp_crypto.c: Accepting crypto tag 0
[Nov 21 11:17:03] DEBUG[7790][C-00000003] sip/sdp_crypto.c: Crypto line: a=crypto:0 AES_CM_128_HMAC_SHA1_32 inline:jExVjMeWdFO1mMwtXmELA0jPcdJiDFnteK/KzlHz^M
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=crypto:0 AES_CM_128_HMAC_SHA1_32 inline:jZwYmXv9hmzMmJVXWH1ZxEgwMv9DTizTvKcvn40x... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:bsfQzcYvK3fInZvOvEpqa4XU5cERdNTLojrY7tZz... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Unsetting payload 111 on 0x7ff7a0156860
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 opus/48000/2... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=fmtp:111 minptime=10... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Unsetting payload 103 on 0x7ff7a0156860
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:103 ISAC/16000... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Unsetting payload 104 on 0x7ff7a0156860
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:104 ISAC/32000... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Unsetting payload 107 on 0x7ff7a0156860
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:107 CN/48000... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Unsetting payload 106 on 0x7ff7a0156860
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:106 CN/32000... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Unsetting payload 105 on 0x7ff7a0156860
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:105 CN/16000... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:13 CN/8000... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:126 telephone-event/8000... OK.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=maxptime:60... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2569575276 cname:DICVzLXRWD606Mrk... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2569575276 msid:TfuATdIY3b0t4LNqjoLwwFwKdaxNQHvgtCUg TfuATdIY3b0t4LNqjoLwwFwKdaxNQHvgtCUga0... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2569575276 mslabel:TfuATdIY3b0t4LNqjoLwwFwKdaxNQHvgtCUg... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Processing media-level (audio) SDP a=ssrc:2569575276 label:TfuATdIY3b0t4LNqjoLwwFwKdaxNQHvgtCUga0... UNSUPPORTED OR FAILED.
[Nov 21 11:17:03] DEBUG[7790][C-00000003] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7ff79801e678'
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Copying payload 0 from 0x7ff7a0156860 to 0x7ff79801e840
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Copying payload 8 from 0x7ff7a0156860 to 0x7ff79801e840
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Copying payload 13 from 0x7ff7a0156860 to 0x7ff79801e840
[Nov 21 11:17:03] DEBUG[7790][C-00000003] rtp_engine.c: Copying payload 126 from 0x7ff7a0156860 to 0x7ff79801e840
[Nov 21 11:17:03] DEBUG[7790][C-00000003] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7ff79801e678'
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: We're settling with these formats: (ulaw|alaw)
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Checking SIP call limits for device
[Nov 21 11:17:03] DEBUG[7790][C-00000003] chan_sip.c: Updating call counter for incoming call
--------------------------------------------------------------------------------

Main differences:

a) In (1) Asterisk doesn't seem to parse "a=candidates" lines reported by the WebRTC client (sipML5 in my case). (UNSUPPORTED OR FAILED)
b) In (1) this files related to SRTP policies are not called/processed:

- res_srtp.c: Adding new policy for SSRC
- sip/sdp_crypto.c: SRTP policy activated
- sip/sdp_crypto.c: Accepting crypto tag 0

c) In (2) ICE candidate is accepted (OK), unlike (1) 

Not sure, but it seems 'UNSUPPORTED OR FAILED' ICE candidates implies -> 'Could not set SRTP policies'

In adition, asterisk12 is able to process 'a=candidates' without problem, but still show the same error "Could not set SRTP policies" 

Should I provide more parameters than "./configure --with-crypto --with-ssl=ssl --with-srtp" ? 

BTW: module res_srtp was always loaded at the start without errors.

Any suggestion?

Miguel Oyarzo,
Melbourne 

      was (Author: miguelaustro at gmail.com):