freeswitch-dev

Download

freeswitch-dev@lists.freeswitch.org

October 2022

1 participants
1 discussions

[Freeswitch-dev] Eror: 488 Not Acceptable Here while connecting two JS-SIP clients
by shwetank singh 06 Oct '22

06 Oct '22

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(a)11.22.33.44 [] 2022-10-06 10:18:15.078122 99.83% [DEBUG] switch_core_state_machine.c:581 (sofia/external/1000(a)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(a)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(a)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(a)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(a)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(a)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(a)11.22.33.44 entering state [completed][200] EXECUTE [depth=0] sofia/external/1000(a)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

1 0