[asterisk-users] asterisk 13.9 with PJSIP -rejects with 488 Not Acceptable Here on invite with SRTP

Yaron Nachum nachum.yaron at gmail.com
Thu Jun 9 09:14:52 CDT 2016 

Hi Everyone,
I am trying to setup an Audio Call from firefox WebRTC to Asterisk. The
Flow is:
PC -> SIPoWS -> KAMAILIO -> SIPoUDP -> ASTERISK
Regular call (no srtp)  works fine. However when I setup SRTP the asterisk
replies with 488 Not Acceptable Here.
I followed the Secure Calling Tutorial, but nothing seems to solve the
issue.

Below you can see the endpoint configuration + debug output.
Any help would be appreciated.

[acme]
type=endpoint
transport=transport-udp
context=app-router
disallow=all
allow=alaw
allow=ulaw
aors=acme
direct_media=no
media_encryption=dtls
dtls_verify=no
dtls_cert_file = /etc/asterisk/keys/asterisk.pem
dtls_private_key = /etc/asterisk/keys/asterisk.pem
dtls_setup=actpass
use_avpf=yes
ice_support=yes
media_use_received_transport=yes



<--- Received SIP request (2019 bytes) from UDP:10.25.133.209:5064 --->
INVITE sip:001111 at ipcentrex.bezeq.com:5060 SIP/2.0
Via: SIP/2.0/UDP 10.25.133.209:5064;branch=z9hG4bK258keq2010n19mk406d1.1
Via: SIP/2.0/TCP 147.235.160.240:443
;branch=z9hG4bKd954.785f69fdfe198df7cabc66c0132a6b4c.0
Max-Forwards: 68
To: <sip:001111 at ipcentrex.bezeq.com>
From: "1000" <sip:1000 at ipcentrex.bezeq.com>;tag=1800vui39b
Call-ID: abars16ecm7s7icq4asq
CSeq: 3488 INVITE
Contact: <sip:1000 at 10.25.133.209:5064
;ob;alias=62.219.92.9~53008~5;alias=62.219.92.9~53008~5;transport=udp>
Allow: ACK,CANCEL,INVITE,MESSAGE,BYE,OPTIONS,INFO,NOTIFY
Content-Type: application/sdp
Supported: outbound
User-Agent: SIP.js/0.7.3
Content-Length: 1366

v=0
o=mozilla...THIS_IS_SDPARTA-46.0.1 4701336699161149943 0 IN IP4
10.25.133.241
s=-
t=0 0
a=sendrecv
a=fingerprint:sha-256
A8:CD:3D:44:3E:98:38:4F:3C:92:B7:05:B0:2B:91:0F:0F:39:7A:49:1F:8B:FB:26:18:1B:26:16:6B:2A:9C:03
a=ice-options:trickle
a=msid-semantic:WMS *
m=audio 20582 UDP/TLS/RTP/SAVPF 109 9 0 8
c=IN IP4 10.25.133.241
a=candidate:0 1 UDP 2122187007 147.235.159.2 58553 typ host
a=candidate:2 1 UDP 2122121471 2002:93eb:9f02::93eb:9f02 58554 typ host
a=candidate:4 1 UDP 2122252543 10.2.0.15 58555 typ host
a=candidate:0 2 UDP 2122187006 147.235.159.2 58556 typ host
a=candidate:2 2 UDP 2122121470 2002:93eb:9f02::93eb:9f02 58557 typ host
a=candidate:4 2 UDP 2122252542 10.2.0.15 58558 typ host
a=candidate:5 1 UDP 1686052863 62.219.92.9 58555 typ srflx raddr 10.2.0.15
rport 58555
a=candidate:5 2 UDP 1686052862 62.219.92.9 58558 typ srflx raddr 10.2.0.15
rport 58558
a=sendrecv
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=fmtp:109 maxplaybackrate=48000;stereo=1
a=ice-pwd:446b46366a44a35b757dbec6a85a06a7
a=ice-ufrag:8d8969e7
a=mid:sdparta_0
a=msid:{60af682c-6e6d-4ad9-a165-02ce89d3ca8a}
{37d6a8a7-78c0-42b4-b52e-cdec5b076b1f}
a=rtcp-mux
a=rtpmap:109 opus/48000/2
a=rtpmap:9 G722/8000/1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=setup:actpass
a=ssrc:2150808732 cname:{4c9490b5-d183-4f6f-954a-56b87f361da2}

[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        sip_endpoint.c
Distributing rdata to modules: Request msg INVITE/cseq=3488
(rdata0x7f0908008b28)
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:172 ast_sockaddr_split_hostport:
Splitting '10.25.133.209' into...
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:226 ast_sockaddr_split_hostport:
...host '10.25.133.209' and port ''.
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:113
ip_identify_match_check: Source address 10.25.133.209:5064 does not match
identify 'KAMnet_TST'
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:113
ip_identify_match_check: Source address 10.25.133.209:5064 does not match
identify 'KAMnet_CBS'
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:113
ip_identify_match_check: Source address 10.25.133.209:5064 does not match
identify 'clacli_j5'
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:113
ip_identify_match_check: Source address 10.25.133.209:5064 does not match
identify 'clacli_j6'
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:113
ip_identify_match_check: Source address 10.25.133.209:5064 does not match
identify 'clacli_j7'
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:108
ip_identify_match_check: Source address 10.25.133.209:5064 matches identify
'acme'
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_endpoint_identifier_ip.c:143
ip_identify: Retrieved endpoint acme
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        tsx0x7f090001f
..Transaction created for Request msg INVITE/cseq=3488 (rdata0x7f0908008b28)
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        tsx0x7f090001f
.Incoming Request msg INVITE/cseq=3488 (rdata0x7f0908008b28) in state Null
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        tsx0x7f090001f
..State changed from Null to Trying, event=RX_MSG
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
...Transaction tsx0x7f090001f8e8 state changed to Trying
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010 .UAS
dialog created
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
.Module mod-invite added as dialog usage, data=0x7f0900015d98
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
..Session count inc to 2 by mod-invite
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        inv0x7f0900010 .UAS
invite session created for dialog dlg0x7f09000108b8
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
.Module Session Module added as dialog usage, data=(nil)
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
..Session count inc to 2 by Session Module
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_session.c:264
handle_incoming_sdp: Negotiating incoming SDP media stream 'audio' using
audio SDP handler
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:172 ast_sockaddr_split_hostport:
Splitting '10.25.133.241' into...
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:226 ast_sockaddr_split_hostport:
...host '10.25.133.241' and port ''.
[Jun  9 17:04:18] DEBUG[13281]: rtp_engine.c:435 ast_rtp_instance_new:
Using engine 'asterisk' for RTP instance '0x7f090002d0c8'
[Jun  9 17:04:18] DEBUG[13281]: res_rtp_asterisk.c:2585 ast_rtp_new:
Allocated port 17394 for RTP instance '0x7f090002d0c8'
[Jun  9 17:04:18] DEBUG[13281]: res_rtp_asterisk.c:2612 ast_rtp_new:
Creating ICE session 0.0.0.0:17394 (17394) for RTP instance '0x7f090002d0c8'
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        icess0x7f09000 ICE
session created, comp_cnt=2, role is Unknown agent
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:172 ast_sockaddr_split_hostport:
Splitting '10.25.128.35' into...
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:226 ast_sockaddr_split_hostport:
...host '10.25.128.35' and port ''.
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        icess0x7f09000
Candidate 0 added: comp_id=1, type=host, foundation=Ha198023, addr=
10.25.128.35:17394, base=10.25.128.35:17394, prio=0x7effffff (2130706431)
[Jun  9 17:04:18] DEBUG[13281]: rtp_engine.c:444 ast_rtp_instance_new: RTP
instance '0x7f090002d0c8' is setup and ready to go
[Jun  9 17:04:18] DEBUG[13281]: res_rtp_asterisk.c:4825 ast_rtp_prop_set:
Setup RTCP on RTP instance '0x7f090002d0c8'
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:172 ast_sockaddr_split_hostport:
Splitting '10.25.128.35' into...
[Jun  9 17:04:18] DEBUG[13281]: netsock2.c:226 ast_sockaddr_split_hostport:
...host '10.25.128.35' and port ''.
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        icess0x7f09000
Candidate 1 added: comp_id=2, type=host, foundation=Ha198023, addr=
10.25.128.35:17395, base=10.25.128.35:17395, prio=0x7efffffe (2130706430)
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:              endpoint
.Response msg 488/INVITE/cseq=3488 (tdta0x7f0900009d10) created
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
.Initial answer Response msg 488/INVITE/cseq=3488 (tdta0x7f0900009d10)
[Jun  9 17:04:18] DEBUG[13281]: res_pjsip_session.c:2410
handle_outgoing_response: Method is INVITE, Response is 488 Not Acceptable
Here
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        inv0x7f0900010
.Sending Response msg 488/INVITE/cseq=3488 (tdta0x7f0900009d10)
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        dlg0x7f0900010
..Sending Response msg 488/INVITE/cseq=3488 (tdta0x7f0900009d10)
[Jun  9 17:04:18] DEBUG[13281]: pjproject:0 <?>:        tsx0x7f090001f
..Sending Response msg 488/INVITE/cseq=3488 (tdta0x7f0900009d10) in state
Trying
<--- Transmitting SIP response (473 bytes) to UDP:10.25.133.209:5064 --->
SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/UDP 10.25.133.209:5064
;rport=5064;received=10.25.133.209;branch=z9hG4bK258keq2010n19mk406d1.1
Via: SIP/2.0/TCP 147.235.160.240:443
;branch=z9hG4bKd954.785f69fdfe198df7cabc66c0132a6b4c.0
Call-ID: abars16ecm7s7icq4asq
From: "1000" <sip:1000 at ipcentrex.bezeq.com>;tag=1800vui39b
To: <sip:001111 at ipcentrex.bezeq.com
>;tag=beace8a7-b718-43be-aa98-d88cd6e966b0
CSeq: 3488 INVITE
Server: Asterisk PBX 13.9.1
Content-Length:  0
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.digium.com/pipermail/asterisk-users/attachments/20160609/cbdcff07/attachment.html>

More information about the asterisk-users mailing list