Not responding to ICE initial offer

brian_j_murrell · May 18, 2021, 12:33pm

Using Asterisk 18.2.2, a client trying to negotiate ICE doesn’t get any ICE offer back from Asterisk when it sends it’s initial offer. The client is sending in it’s SDP:

v=0
o=brian_redmi4 3934 1533 IN IP4 5.4.2.6
s=Talk
c=IN IP4 5.4.2.6
t=0 0
a=ice-pwd:a4a187c90f5ad80db4fb78a3
a=ice-ufrag:8b9aa83f
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7078 RTP/AVP 96 97 98 0 8 3 9 99 100 102 10 11 101 103 104 105 106
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 speex/16000
a=fmtp:97 vbr=on
a=rtpmap:98 speex/8000
a=fmtp:98 vbr=on
a=rtpmap:99 iLBC/8000
a=fmtp:99 mode=30
a=rtpmap:100 iSAC/16000
a=rtpmap:102 speex/32000
a=fmtp:102 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:103 telephone-event/16000
a=rtpmap:104 telephone-event/8000
a=rtpmap:105 telephone-event/32000
a=rtpmap:106 telephone-event/44100
a=rtcp-fb:* trr-int 1000
a=rtcp-fb:* ccm tmmbr

and Asterisk responds with:

v=0
o=- 3934 1535 IN IP4 7.3.7.1
s=Asterisk
c=IN IP4 7.3.7.1
t=0 0
m=audio 12072 RTP/AVP 96 0 8 3 10 98 97 102 99 9 104
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:10 L16/8000
a=rtpmap:98 speex/8000
a=rtpmap:97 speex/16000
a=rtpmap:102 speex/32000
a=rtpmap:99 iLBC/8000
a=fmtp:99 mode=30
a=rtpmap:9 G722/8000
a=rtpmap:104 telephone-event/8000
a=fmtp:104 0-16
a=ptime:20
a=maxptime:20
a=sendrecv

which seems to be lacking any response to the client’s initial ICE offer.

A core set debug 5 log for the call.

Any ideas why Asterisk is not responding to the ICE initial offer?

jcolp · May 18, 2021, 12:36pm

There’s no ICE candidates in the INVITE, so it doesn’t respond with ICE[1].

[1] [ASTERISK-27957] PJSIP proposes ICE candidates on answer even if not in offer - Digium/Asterisk JIRA

brian_j_murrell · May 18, 2021, 4:19pm

OK. So I have the client now sending candidates:

v=0
o=my_sip_account 3818 1657 IN IP4 5.4.2.6
s=Talk
c=IN IP4 5.4.2.6
t=0 0
a=ice-pwd:53eccddb7de15358d644d550
a=ice-ufrag:b9c4aef2
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 65143 RTP/AVPF 96 97 98 0 8 3 9 99 100 102 10 11 101 103 104 105 106
c=IN IP4 4.4.8.5
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 speex/16000
a=fmtp:97 vbr=on
a=rtpmap:98 speex/8000
a=fmtp:98 vbr=on
a=rtpmap:99 iLBC/8000
a=fmtp:99 mode=30
a=rtpmap:100 iSAC/16000
a=rtpmap:102 speex/32000
a=fmtp:102 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:103 telephone-event/16000
a=rtpmap:104 telephone-event/8000
a=rtpmap:105 telephone-event/32000
a=rtpmap:106 telephone-event/44100
a=rtcp:65124
a=candidate:1 1 UDP 2130706303 5.4.2.6 7078 typ host
a=candidate:1 2 UDP 2130706302 5.4.2.6 7079 typ host
a=candidate:2 1 UDP 1694498687 4.4.8.5 65143 typ srflx raddr 5.4.2.6 rport 7078
a=candidate:2 2 UDP 1694498686 4.4.8.5 65124 typ srflx raddr 5.4.2.6 rport 7079
a=rtcp-fb:* trr-int 1000
a=rtcp-fb:* ccm tmmbr

but Asterisk responds with a SIP/2.0 488 Not Acceptable Here:

SIP/2.0 100 Trying
Via: SIP/2.0/TCP 5.4.2.6:42348;rport=65142;received=4.4.8.5;branch=z9hG4bK.UKd61wWh4
Call-ID: Bj-HXXhTLV
From: "[redacted]" <sip:my_sip_account@example.com>;tag=o2WP2YaUn
To: <sip:[redacted]@example.com>
CSeq: 20 INVITE
Server: Asterisk PBX 18.2.2
Content-Length:  0

SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/TCP 5.4.2.6:42348;rport=65142;received=4.4.8.5;branch=z9hG4bK.UKd61wWh4
Call-ID: Bj-HXXhTLV
From: "[redacted]" <sip:my_sip_account@example.com>;tag=o2WP2YaUn
To: <sip:[redacted]@example.com>;tag=2a3a428b-9723-4e03-803d-5cd82ba9a399
CSeq: 20 INVITE
Server: Asterisk PBX 18.2.2
Content-Length:  0

The Asterisk debug for the above is:

[May 18 11:27:39] DEBUG[19102] res_pjsip/pjsip_distributor.c: Could not find matching transaction for Request msg INVITE/cseq=20 (rdata0x7f5b54001868)
[May 18 11:27:39] DEBUG[19102] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000043 to use for Request msg INVITE/cseq=20 (rdata0x7f5b54001868)
[May 18 11:27:39] DEBUG[7246] netsock2.c: Splitting '4.4.8.5' into...
[May 18 11:27:39] DEBUG[7246] netsock2.c: ...host '4.4.8.5' and port ''.
[May 18 11:27:39] DEBUG[7246] res_pjsip_endpoint_identifier_user.c: Attempting identify by From username 'my_sip_account' domain 'example.com'
[May 18 11:27:39] DEBUG[7246] res_pjsip_endpoint_identifier_user.c: Identified by From username 'my_sip_account' domain 'example.com'
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  (null session) Request: INVITE 
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Request: 
[May 18 11:27:39] DEBUG[7246] res_pjsip/pjsip_distributor.c: Calculated serializer pjsip/distributor-00000043 to use for Request msg INVITE/cseq=20 (rdata0x7f5b54037d28)
[May 18 11:27:39] DEBUG[7246] chan_pjsip.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] chan_pjsip.c:  Direct media no glare mitigation
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Call (TCP:4.4.8.5:65142) to extension '600' sending 100 Trying
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Method is INVITE, Response is 100 Trying
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account Event: TSX_STATE  Inv State: INCOMING
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The state change pertains to the endpoint 'my_sip_account()'
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f5b4c010638)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: There is no transaction involved in this state change
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The current inv state is INCOMING
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: my_sip_account: Source of transaction state change is TX_MSG
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account TSX State: Proceeding  Inv State: INCOMING
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The state change pertains to the endpoint 'my_sip_account()'
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f5b4c010638)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f5b4c010638
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The current transaction state is Proceeding
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The transaction state change event is TX_MSG
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The current inv state is INCOMING
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Nothing delayed
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account TSX State: Proceeding  Inv State: INCOMING
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Topology: Pending: (null topology)  Active: (null topology)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Media count: 1
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Processing stream 0
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Using audio-0 for new stream name
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Using new stream 0:audio-0:audio:sendrecv (nothing)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account Adding position 0
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Creating new media session
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Setting media session as default for audio
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Done
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Negotiating incoming SDP media stream 0:audio-0:audio:sendrecv (nothing) using audio SDP handler
[May 18 11:27:39] DEBUG[7246] res_pjsip_sdp_rtp.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] res_pjsip_sdp_rtp.c:  Incompatible transport
[May 18 11:27:39] ERROR[7246] res_pjsip_session.c:  my_sip_account: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:   my_sip_account: Couldn't negotiate stream 0:audio-0:audio:sendrecv (nothing)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Handled? no
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account: Method is INVITE, Response is 488 Not Acceptable Here
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account Event: TSX_STATE  Inv State: DISCONNCTD
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: Function session_inv_on_state_changed called on event TSX_STATE
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The state change pertains to the endpoint 'my_sip_account()'
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f5b4c010638)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: There is no transaction involved in this state change
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The current inv state is DISCONNCTD
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: my_sip_account: Source of transaction state change is TX_MSG
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account TSX State: Completed  Inv State: DISCONNCTD
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: Function session_inv_on_tsx_state_changed called on event TSX_STATE
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The state change pertains to the endpoint 'my_sip_account()'
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The inv session still has an invite_tsx (0x7f5b4c010638)
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The UAS INVITE transaction involved in this state change is 0x7f5b4c010638
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The current transaction state is Completed
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The transaction state change event is TX_MSG
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: The current inv state is DISCONNCTD
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Disconnected
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  (null session) TSX State: Completed  Inv State: DISCONNCTD
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  Request:  Session: my_sip_account
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c:  (null session) Handled request INVITE  ? yes
[May 18 11:27:39] DEBUG[7246] chan_pjsip.c:  my_sip_account
[May 18 11:27:39] DEBUG[7246] chan_pjsip.c:  No channel
[May 18 11:27:39] DEBUG[7246] res_pjsip_session.c: my_sip_account: Destroying SIP session

and the client retries without ICE candidates:

v=0
o=my_sip_account 3818 1658 IN IP4 5.4.2.6
s=Talk
c=IN IP4 5.4.2.6
t=0 0
a=ice-pwd:be70481d7c6a691e5606e561
a=ice-ufrag:7ac3016b
a=rtcp-xr:rcvr-rtt=all:10000 stat-summary=loss,dup,jitt,TTL voip-metrics
m=audio 7078 RTP/AVP 96 97 98 0 8 3 9 99 100 102 10 11 101 103 104 105 106
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:97 speex/16000
a=fmtp:97 vbr=on
a=rtpmap:98 speex/8000
a=fmtp:98 vbr=on
a=rtpmap:99 iLBC/8000
a=fmtp:99 mode=30
a=rtpmap:100 iSAC/16000
a=rtpmap:102 speex/32000
a=fmtp:102 vbr=on
a=rtpmap:101 telephone-event/48000
a=rtpmap:103 telephone-event/16000
a=rtpmap:104 telephone-event/8000
a=rtpmap:105 telephone-event/32000
a=rtpmap:106 telephone-event/44100
a=rtcp-fb:* trr-int 1000
a=rtcp-fb:* ccm tmmbr

to which Asterisk responds (again without ICE):

v=0
o=- 3818 1660 IN IP4 7.3.7.1
s=Asterisk
c=IN IP4 7.3.7.1
t=0 0
m=audio 14660 RTP/AVP 96 0 8 3 10 98 97 102 99 9 104
a=rtpmap:96 opus/48000/2
a=fmtp:96 useinbandfec=1
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:3 GSM/8000
a=rtpmap:10 L16/8000
a=rtpmap:98 speex/8000
a=rtpmap:97 speex/16000
a=rtpmap:102 speex/32000
a=rtpmap:99 iLBC/8000
a=fmtp:99 mode=30
a=rtpmap:9 G722/8000
a=rtpmap:104 telephone-event/8000
a=fmtp:104 0-16
a=ptime:20
a=maxptime:20
a=sendrecv

So why the SIP/2.0 488 Not Acceptable Here to the first SDP?

jcolp · May 18, 2021, 4:20pm

The media stream became “RTP/AVPF” instead of “RTP/AVP”. To support “RTP/AVPF” the “use_avpf” option has to be set to “yes”.

brian_j_murrell · May 18, 2021, 4:39pm

One very significant letter in that m= line. I even side-by-side diffed the two SDP packets but didn’t see the AVP vs AVPF due to the port being different also and looking like the difference on that line.

It’s working now. Thanks!

As an aside, any advise on whether I want AVPF or not? It seems like it’s something good. Why would I not want it?

jcolp · May 18, 2021, 4:40pm

It doesn’t really matter either way.

system · June 17, 2021, 4:40pm

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Help with ICE Negotiation Debugging Asterisk WebRTC	6	1205	July 25, 2019
When ICE is enabled, when peer sent UPDATE with selected ICE candidates asterisk not giving 200 OK with selected candidates in c= line Asterisk SIP	1	431	November 28, 2019
ICE not working on Asterisk 18.8.0 Asterisk WebRTC	13	2415	January 22, 2022
ICE support problem! Asterisk Support	6	966	August 19, 2014
Not Sending response to the 200 OK IP Asterisk SIP	4	1373	May 23, 2019

Not responding to ICE initial offer

Related topics