Process_sdp: Rejecting non-primary audio stream

kasper.leth.jensen · April 4, 2017, 7:25am

Hi,

I’m testing SRTP on asterisk 1.8.15.0. This version is a custom patched version we use, why we’re currently not running later versions. This problem could be related to this version, in that case please let me know as I’m not able to test one-to-one on a newer asterisk. No chances has been made to the audio processing in any of the patches.

When our asterisk receives an INVITE (from a 3CX server), asterisk is rejecting the INVITE. From what I understand related bugs in other fora, this could be because the INVITE contains multiple audio streams.

When asterisk receives the INVITE, it write this in the console:

warning: WARNING[424]: chan_sip.c:8960 process_sdp: Rejecting non-primary audio stream: audio 19524 RTP/AVP 0 8 3 101

The SDP contents:

v=0
o=3cxPS 125359357952 171698028545 IN IP4 100.119.0.8
s=3cxPS Audio call
c=IN IP4 100.119.0.8
t=0 0
a=ice-lite
m=audio 10802 RTP/SAVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=rtcp:10803
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:9nTAinUWB4Cc1HY9KchESAbXlLY2qpuMeM/M34k+
a=setup:actpass
a=fingerprint:sha-1 10:80:3B:D5:24:AA:EB:BF:6E:71:8F:62:67:D9:9B:56:CD:05:C3:38
a=ice-ufrag:u4nVW7k4
a=ice-pwd:dJpsV81T3sH4ughr9F2ZNZlg1G9X
a=candidate:xO6HGWGzjlhzrcCB 1 UDP 2130706431 100.119.0.8 10802 typ host
a=candidate:xO6HGWGzjlhzrcCB 2 UDP 2130706430 100.119.0.8 10803 typ host
m=audio 10828 RTP/AVP 0 8 3 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:101 telephone-event/8000
a=sendrecv
a=rtcp:10829
a=ice-ufrag:OtZ1bor4
a=ice-pwd:vrXyTCAlSRM0vMZiLkyKZHFN9EMk
a=candidate:xO6HGWGzjlhzrcCB 1 UDP 2130706431 100.119.0.8 10828 typ host
a=candidate:xO6HGWGzjlhzrcCB 2 UDP 2130706430 100.119.0.8 10829 typ host

As you can see, two media streams are present; one regular RTP and one SRTP.

Asterisk console with debug, when it receives the INVITE:

[2017-03-31 13:52:19.247] DEBUG[424]: rtp_engine.c:350 ast_rtp_instance_new: Using engine 'asterisk' for RTP instance '0x7f6268056d88'
[2017-03-31 13:52:19.247] DEBUG[424]: res_rtp_asterisk.c:556 ast_rtp_new: Allocated port 19284 for RTP instance '0x7f6268056d88'
[2017-03-31 13:52:19.247] DEBUG[424]: rtp_engine.c:359 ast_rtp_instance_new: RTP instance '0x7f6268056d88' is setup and ready to go
[2017-03-31 13:52:19.247] DEBUG[424]: res_rtp_asterisk.c:2528 ast_rtp_prop_set: Setup RTCP on RTP instance '0x7f6268056d88'
[2017-03-31 13:52:19.247]   == Using SIP RTP TOS bits 184
[2017-03-31 13:52:19.247]   == Using SIP RTP CoS mark 5
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:5093 do_setnat: Setting NAT on RTP to Off
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:8918 process_sdp: Processing session-level SDP v=0... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:8918 process_sdp: Processing session-level SDP o=3cxPS 208373022720 410974683137 IN IP4 100.119.0.8... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:8918 process_sdp: Processing session-level SDP s=3cxPS Audio call... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: netsock2.c:138 ast_sockaddr_split_hostport: Splitting '100.119.0.8' into...
[2017-03-31 13:52:19.247] DEBUG[424]: netsock2.c:192 ast_sockaddr_split_hostport: ...host '100.119.0.8' and port ''.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:8918 process_sdp: Processing session-level SDP c=IN IP4 100.119.0.8... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:8918 process_sdp: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247]   == Using UDPTL TOS bits 184
[2017-03-31 13:52:19.247]   == Using UDPTL CoS mark 5
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:6842 initialize_udptl: Setting NAT on UDPTL to Off
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:8918 process_sdp: Processing session-level SDP a=ice-lite... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 0 based on m type on 0x7f6271de3750
[2017-03-31 13:52:19.247] DEBUG[424]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 8 based on m type on 0x7f6271de3750
[2017-03-31 13:52:19.247] DEBUG[424]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 3 based on m type on 0x7f6271de3750
[2017-03-31 13:52:19.247] DEBUG[424]: rtp_engine.c:541 ast_rtp_codecs_payloads_set_m_type: Setting payload 101 based on m type on 0x7f6271de3750
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=rtpmap:3 GSM/8000... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=sendrecv... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=rtcp:19695... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: sip/sdp_crypto.c:103 sdp_crypto_setup: local_key64 SpjrlB9b9jowKaV58uIN8xHXqpUMX/XvpVkUK+K9 len 40
[2017-03-31 13:52:19.247] DEBUG[424]: res_srtp.c:503 ast_srtp_add_stream: Adding new policy for SSRC 1373821135
[2017-03-31 13:52:19.247] DEBUG[424]: sip/sdp_crypto.c:172 sdp_crypto_activate: SRTP policy activated
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:xYUbaw99GBVHWSR5wVujslNjMRuT7hoRsLZrbvqh... OK.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=setup:actpass... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=fingerprint:sha-1 10:80:3B:D5:24:AA:EB:BF:6E:71:8F:62:67:D9:9B:56:CD:05:C3:38... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=ice-ufrag:QH4y8bwu... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=ice-pwd:lLLoihgIZNIXWMilgCVvjlD73FDb... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=candidate:xO6HGWGzjlhzrcCB 1 UDP 2130706431 100.119.0.8 19694 typ host... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] DEBUG[424]: chan_sip.c:9189 process_sdp: Processing media-level (audio) SDP a=candidate:xO6HGWGzjlhzrcCB 2 UDP 2130706430 100.119.0.8 19695 typ host... UNSUPPORTED OR FAILED.
[2017-03-31 13:52:19.247] WARNING[424]: chan_sip.c:8960 process_sdp: Rejecting non-primary audio stream: audio 19726 RTP/AVP 0 8 3 101

As you can see, asterisk rejects the call as soon as it starts processing the second audio stream (m=).
In sip.conf I’ve enabled encryption (encryption=yes) for the host and module res_srtp.so is loaded.

This leads me to the following questions:

Doesn’t asterisk support multiple media stream (as specified in rfc4566)?
Could the problem be something else, like wrong configuration? It seems quite plain forward, but maybe I’ve missed something.
If it’s asterisk that fails for some reason (and not configuration), will it work in a later asterisk version?

Let me know if more details are needed.

Kind regards,
Kasper Leth

jcolp · April 4, 2017, 10:01am

Asterisk only supports a single audio stream and a single video stream. The other streams will be rejected. Work is being done for 15 to improve this for the core and the new PJSIP channel driver. In your case I’d expect it to still have worked, just with the stream rejected but with such an old version of chan_sip I don’t know really know what it will do.

kasper.leth.jensen · April 4, 2017, 10:10am

Hi jcolp,

Thanks for your reply. I too expected that it would still work with the first audio stream, but it seems like the rejection of the second stream makes asterisk reject the call itself, for some reason.

I know the version is an issue and I don’t expect it to be fixed in that old a version, but knowing that it’s a known problem at least helps me not wasting time on further debugging.

From what you write, it doesn’t sound like it’s fixed in later versions yet?

jcolp · April 4, 2017, 10:21am

I really don’t know if the behavior of chan_sip was changed in that regard. It went through a few different fixes, so it’s entirely possible it was changed.

kasper.leth.jensen · April 4, 2017, 12:09pm

Ok. I think I’ll use some time testing a newer version - then we can decide where to go from there.

Thanks for your answer and time Have a nice day.

Topic		Replies	Views
TLS, SRTP and SRTCP Asterisk Support	1	635	April 17, 2014
Multiple Audio Stream Supports Asterisk Support	2	72	October 11, 2024
Failed to receive SDP offer Asterisk Support	1	3380	May 7, 2015
Asterisk 15 chan_sip TLS SRTP - no audio no RTP packets between IP Phones Asterisk SIP	16	2237	February 12, 2023
Asterisk TLS/SRTP problem Asterisk Support	11	1667	July 17, 2012

Process_sdp: Rejecting non-primary audio stream

Related topics