[Freeswitch-dev] Eror: 488 Not Acceptable Here while connecting two JS-SIP clients

6 Oct 2022

      Hi

perfectly agree that there are so many queries to this end and almost all
pointers are towards codec negotiation failures. i still have this issue
after i see that codec negotiation goes through.

i have set up 2 Js-SIP clients. webrtc.
i am able to connect and register both clients (can see those in *sofia
status profile external reg*)

however when i place a call from one client (extension 1000) to another
(extension 1001), i receive a "488 Not Acceptable Here" message and the
call ends with "Bad Media Description" error and i never get the call on
receiver side

i am completely at the surface still and have given it a try with all
solutions posted to this end

attaching the entire log in a file here. please help

here are some important bits from the file:

INVITE sip

INVITE sip:1001@11.22.33.44 SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK7948245
Max-Forwards: 69
To: <sip:1001@11.22.33.44>
From: <sip:1000@11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
X-Test: tester-tested
Contact: <sip:1000@11.22.33.44;ob>
Content-Type: application/sdp
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: ice,replaces,outbound
User-Agent: JsSIP 3.9.1
Content-Length: 1950

v=0
o=- 8689874841498562319 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112 113
126
c=IN IP4 192.168.1.64
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host
generation 0 network-id 1 network-cost 10
a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host
generation 0 network-id 2 network-cost 50
a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype
active generation 0 network-id 1 network-cost 10
a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype
active generation 0 network-id 2 network-cost 50
a=ice-ufrag:KQsy
a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
a=ice-options:trickle
a=fingerprint:sha-256
C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3
http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=sendrecv
a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2
a=rtcp-mux
a=rtpmap:111 opus/48000/2
a=rtcp-fb:111 transport-cc
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:63 red/48000/2
a=fmtp:63 111/111
a=rtpmap:103 ISAC/16000
a=rtpmap:104 ISAC/32000
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:106 CN/32000
a=rtpmap:105 CN/16000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:112 telephone-event/32000
a=rtpmap:113 telephone-event/16000
a=rtpmap:126 telephone-event/8000
a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2

=================

Remote SDP:

2022-10-06 10:18:15.078122 99.83% [NOTICE] switch_channel.c:1123 New
Channel sofia/external/1000@11.22.33.44 []
 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581
(sofia/external/1000@11.22.33.44) Running State Change CS_NEW (Cur 1 Tot 11)
 2022-10-06 10:18:15.078122 99.83% [INFO] sofia.c:10465 sofia/external/
1000@11.22.33.44 receiving invite from 3.7.130.46:54985 version: 1.10.8-dev
git 98d2e62 2022-09-09 13:32:35Z 64bit call-id: aoc0tkcjs47mrj5n1jl4
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:11674 Setting NAT mode
based on websockets
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7499 Channel
sofia/external/1000@11.22.33.44 entering state [received][100]
 2022-10-06 10:18:15.078122 99.83% [DEBUG] sofia.c:7509 Remote SDP:
 v=0
 o=- 8689874841498562319 2 IN IP4 127.0.0.1
 s=-
 t=0 0
 a=group:BUNDLE 0
 a=extmap-allow-mixed
 a=msid-semantic: WMS qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
 m=audio 59566 UDP/TLS/RTP/SAVPF 111 63 103 104 9 0 8 106 105 13 110 112
113 126
 c=IN IP4 192.168.1.64
 a=rtpmap:111 opus/48000/2
 a=fmtp:111 minptime=10;useinbandfec=1
 a=rtpmap:63 red/48000/2
 a=fmtp:63 111/111
 a=rtpmap:103 ISAC/16000
 a=rtpmap:104 ISAC/32000
 a=rtpmap:9 G722/8000
 a=rtpmap:0 PCMU/8000
 a=rtpmap:8 PCMA/8000
 a=rtpmap:106 CN/32000
 a=rtpmap:105 CN/16000
 a=rtpmap:13 CN/8000
 a=rtpmap:110 telephone-event/48000
 a=rtpmap:112 telephone-event/32000
 a=rtpmap:113 telephone-event/16000
 a=rtpmap:126 telephone-event/8000
 a=rtcp:9 IN IP4 0.0.0.0
 a=candidate:3460887983 1 udp 2122260223 192.168.1.64 59566 typ host
generation 0 network-id 1 network-cost 10
 a=candidate:2403671225 1 udp 2122194687 172.27.239.86 55376 typ host
generation 0 network-id 2 network-cost 50
 a=candidate:2160789855 1 tcp 1518280447 192.168.1.64 9 typ host tcptype
active generation 0 network-id 1 network-cost 10
 a=candidate:3251036233 1 tcp 1518214911 172.27.239.86 9 typ host tcptype
active generation 0 network-id 2 network-cost 50
 a=ice-ufrag:KQsy
 a=ice-pwd:oTFySc5ArZ1oxVZ+qb+errt5
 a=ice-options:trickle
 a=fingerprint:sha-256
C9:60:D5:F6:7C:26:A5:2B:A5:1C:C5:23:0A:36:4B:E2:CE:D5:C8:15:8A:AD:35:DB:2C:E3:7D:C4:E8:7C:D3:E2
 a=setup:actpass
 a=mid:0
 a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
 a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
 a=extmap:3
http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
 a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
 a=msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2
 a=rtcp-mux
 a=rtcp-fb:111 transport-cc
 a=ssrc:3961239200 cname:Bb33wRyqhUohexBZ
 a=ssrc:3961239200 msid:qikHHSycCzJUUpbTJgCfWpaVC44ukpKp5iAX
871ec968-71eb-4810-a9ff-dcd4c80705b2

=============================================
codec negotiation. i have removed OPUS as it was giving me bitrate mismatch
*G722, PCMU, PCMA are exact match*

 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [opus:111:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [red:63:48000:20:0:2]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [red:63:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [red:63:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:103:16000:30:32000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:103:16000:30:32000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:103:16000:30:32000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:104:32000:30:32000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:104:32000:30:32000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [ISAC:104:32000:30:32000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio
Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio
Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5718 Audio
Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:105:16000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:105:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:105:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:13:8000:20:0:1]/[G722:9:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:13:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_core_media.c:5663 Audio
Codec Compare [CN:13:8000:20:0:1]/[PCMA:8:8000:20:64000:1]

=======================================================

SIP to receiver

2022-10-06 10:18:25.018122 99.80% [DEBUG] mod_sofia.c:913 Local SDP
sofia/external/1000@11.22.33.44:
 v=0
 o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
 s=FreeSWITCH
 c=IN IP4 11.22.33.44
 t=0 0
 a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
 m=audio 29876 UDP/AVPF 9 126
 a=rtpmap:9 G722/8000
 a=rtpmap:126 telephone-event/8000
 a=ptime:20
 a=sendrecv
 a=rtcp:29877 IN IP4 11.22.33.44
 a=ice-ufrag:0OsMZPPHcIga8KUi
 a=ice-pwd:XaZYj9vC6oyD4TjUxCxnhcUk
 a=candidate:0153546995 1 udp 2130706431 11.22.33.44 29876 typ host
generation 0
 a=candidate:0153546995 2 udp 2130706430 11.22.33.44 29877 typ host
generation 0
 a=end-of-candidates
 a=ssrc:3007569695 cname:kmpRbjjGt625HQuP
 a=ssrc:3007569695 msid:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET a0
 a=ssrc:3007569695 mslabel:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
 a=ssrc:3007569695 label:VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zETa0

 2022-10-06 10:18:25.018122 99.80% [NOTICE] mod_dptools.c:1408 Channel
[sofia/external/1000@11.22.33.44] has been answered
send 985 bytes to wss/[3.7.130.46]:54985 at 10:18:25.032155:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/WSS
11.22.33.44;branch=z9hG4bK7948245;received=3.7.130.46;rport=54985
From: <sip:1000@11.22.33.44>;tag=jimkkm04qn
To: <sip:1001@11.22.33.44>;tag=0jtBBc4ryZ8Zg
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 INVITE
Contact: <sip:1001@11.22.33.44:5080;transport=udp>
User-Agent:
FreeSWITCH-mod_sofia/1.10.8-dev+git~20220909T133235Z~98d2e6212c~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER,
REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Session-Expires: 120;refresher=uas
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 196
Remote-Party-ID: "1001" <sip:1001@11.22.33.44
...
;party=calling;privacy=off;screen=no
v=0
o=FreeSWITCH 1665021629 1665021630 IN IP4 11.22.33.44
s=FreeSWITCH
c=IN IP4 11.22.33.44
t=0 0
a=msid-semantic: WMS VUSFGZ4CEjXvMLYzijtMWkwcRx3I8zET
*m=audio 0 UDP/TLS/RTP/SAVPF 19*

 2022-10-06 10:18:25.018122 99.80% [DEBUG] switch_channel.c:3950
(sofia/external/1000@11.22.33.44) Callstate Change EARLY -> ACTIVE
 2022-10-06 10:18:25.018122 99.80% [DEBUG] sofia.c:7499 Channel
sofia/external/1000@11.22.33.44 entering state [completed][200]
 EXECUTE [depth=0] sofia/external/1000@11.22.33.44 sleep(1000)

==============================================

and then the BYE

------------------------------------------------------------------------
ACK sip:1001@11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK8228266
Max-Forwards: 69
To: <sip:1001@11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000@11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3752 ACK
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

recv 462 bytes from wss/[3.7.130.46]:54985 at 10:18:26.584127:
------------------------------------------------------------------------
BYE sip:1001@11.22.33.44:5080;transport=udp SIP/2.0
Via: SIP/2.0/WSS 11.22.33.44;branch=z9hG4bK162798
Max-Forwards: 69
To: <sip:1001@11.22.33.44>;tag=0jtBBc4ryZ8Zg
From: <sip:1000@11.22.33.44>;tag=jimkkm04qn
Call-ID: aoc0tkcjs47mrj5n1jl4
CSeq: 3753 BYE
*Reason: SIP ;cause=488; text="Not Acceptable Here"*
Allow: INVITE,ACK,CANCEL,BYE,UPDATE,MESSAGE,OPTIONS,REFER,INFO,NOTIFY
Supported: outbound
User-Agent: JsSIP 3.9.1
Content-Length: 0

-- 
Shwetank

shwetank singh

tags

participants (1)