[Freeswitch-users] ReINVITE - 488 Not Acceptable Here

Sergio García sergio.garcia at quobis.com
Thu Jul 23 15:17:56 MSD 2015


Hello all,

I am using *FreeSwitch* as a *WebRTC gateway* thanks to its Websocket
support (in my case WSS), but I'm facing this strange problem. Audio and
Video calls are working perfectly fine, but when I try to set a call On
Hold, FreeSwitch replies with "488 Not Acceptable Here" error to the
ReINVITE I'm sending.

The only error I can see in the logs is:


* [ERR] sofia.c:7280 Reinvite Codec Error!*

The only difference between the original INVITE and this ReINVITE is that I
try to set IP address to *0.0.0.0*, port to *0* and media attribute to
*inactive*. I don't understand what part of the SDP, FS doesn't "like".

Attached you can find a more detailed log file.

Thank you very much in advance.

Regards,
-- 

*Sergio García Ramos *
VoIP Engineer @ Quobis <http://www.quobis.com/> | e:
sergio.garcia at quobis.com | t: +34902999465
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20150723/196fd463/attachment-0001.html 
-------------- next part --------------
freeswitch at internal> tport.c:2773 tport_wakeup() tport_wakeup(0x2a06f20): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x2a06f20)
tport.c:2296 tport_set_secondary_timer() tport(0x2a06f20): reset timer
tport.c:2773 tport_wakeup() tport_wakeup(0x2a06f20): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x2a06f20)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x2a06f20) msg 0x2aac4d0 from (wss/1.1.1.1:47606) has 2933 bytes, veclen = 1
recv 2933 bytes from wss/[1.1.1.1]:47606 at 12:26:13.086659:
   ------------------------------------------------------------------------
   INVITE sip:mod_sofia at 2.2.2.2:5060 SIP/2.0
   Via: SIP/2.0/WSS s0puhni5qlgc.invalid;branch=z9hG4bK6674273
   Max-Forwards: 69
   To: <sip:1013 at demo.example.com>;tag=7jUFmHeD0pvXF
   From: <sip:b1encs3k at s0puhni5qlgc.invalid;transport=ws>;tag=hl91vpapon
   Call-ID: 0c13533c-abc8-1233-50b5-00505685769c
   CSeq: 6856 INVITE
   Contact: <sip:b1encs3k at s0puhni5qlgc.invalid;transport=ws>
   Content-Type: application/sdp
   Supported: path, outbound, gruu
   User-Agent: WebRTC Client
   Content-Length: 2428
   
   v=0
   o=- 4384031540968842851 2 IN IP4 127.0.0.1
   s=-
   t=0 0
   a=group:BUNDLE audio video
   a=msid-semantic: WMS XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7
   m=audio 0 RTP/SAVPF 111 103 104 9 0 8 106 105 13 126
   c=IN IP4 0.0.0.0
   a=rtcp:9 IN IP4 0.0.0.0
   a=ice-ufrag:UcnaZ9epkI/tHZKA
   a=ice-pwd:a4LSyQfKaE0Ew0fMuaqwc6d5
   a=fingerprint:sha-256 28:B0:00:4B:84:71:00:59:71:CE:1F:6C:6B:5C:16:E9:C4:F8:68:EF:74:7E:0D:33:6C:03:C6:22:27:98:AA:76
   a=setup:actpass
   a=mid:audio
   a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
   a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
   a=inactive
   a=rtcp-mux
   a=rtpmap:111 opus/48000/2
   a=fmtp:111 minptime=10; useinbandfec=1
   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:126 telephone-event/8000
   a=maxptime:60
   a=ssrc:3092381274 cname:e48ww6lOt72QPsQY
   a=ssrc:3092381274 msid:XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7 f5acaa72-5a7e-46b6-a36b-21d993912d02
   a=ssrc:3092381274 mslabel:XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7
   a=ssrc:3092381274 label:f5acaa72-5a7e-46b6-a36b-21d993912d02
   m=video 0 RTP/SAVPF 100 116 117 96
   c=IN IP4 0.0.0.0
   a=rtcp:9 IN IP4 0.0.0.0
   a=ice-ufrag:UcnaZ9epkI/tHZKA
   a=ice-pwd:a4LSyQfKaE0Ew0fMuaqwc6d5
   a=fingerprint:sha-256 28:B0:00:4B:84:71:00:59:71:CE:1F:6C:6B:5C:16:E9:C4:F8:68:EF:74:7E:0D:33:6C:03:C6:22:27:98:AA:76
   a=setup:actpass
   a=mid:video
   a=extmap:2 urn:ietf:params:rtp-hdrext:toffset
   a=extmap:3 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
   a=extmap:4 urn:3gpp:video-orientation
   a=inactive
   a=rtcp-mux
   a=rtpmap:100 VP8/90000
   a=rtcp-fb:100 ccm fir
   a=rtcp-fb:100 nack
   a=rtcp-fb:100 nack pli
   a=rtcp-fb:100 goog-remb
   a=rtpmap:116 red/90000
   a=rtpmap:117 ulpfec/90000
   a=rtpmap:96 rtx/90000
   a=fmtp:96 apt=100
   a=ssrc-group:FID 850102287 3335913892
   a=ssrc:850102287 cname:e48ww6lOt72QPsQY
   a=ssrc:850102287 msid:XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7 f73531ae-a55f-4d53-8cd6-7d336ec7e02b
   a=ssrc:850102287 mslabel:XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7
   a=ssrc:850102287 label:f73531ae-a55f-4d53-8cd6-7d336ec7e02b
   a=ssrc:3335913892 cname:e48ww6lOt72QPsQY
   a=ssrc:3335913892 msid:XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7 f73531ae-a55f-4d53-8cd6-7d336ec7e02b
   a=ssrc:3335913892 mslabel:XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7
   a=ssrc:3335913892 label:f73531ae-a55f-4d53-8cd6-7d336ec7e02b
   ------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x2a06f20): msg 0x2aac4d0 (2933 bytes) from wss/1.1.1.1:47606/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received INVITE sip:mod_sofia at 2.2.2.2:5060 SIP/2.0 (CSeq 6856)
nta.c:3174 agent_check_request_via() nta: Via check: received=1.1.1.1
nta.c:3060 agent_recv_request() nta: INVITE (6856) going to existing leg
nta.c:1348 set_timeout() nta: timer shortened to 2000 ms
nua_server.c:102 nua_stack_process_request() nua: nua_stack_process_request: entering
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x27af900) called
soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x27af900, (nil), 0x2a39919, 2428) called
tport.c:3257 tport_tsend() tport_tsend(0x2a06f20) tpn = WSS/1.1.1.1:47606
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x279b050 116 (116)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2a397d1 71 (71)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2a397a0 49 (49)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2a39818 66 (66)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x279b0c4 71 (71)
tport.c:3594 tport_vsend() tport_vsend(0x2a06f20): 373 bytes of 373 to wss/1.1.1.1:47606
tport.c:3492 tport_send_msg() tport_vsend returned 373
send 373 bytes to wss/[1.1.1.1]:47606 at 12:26:13.086909:
   ------------------------------------------------------------------------
   SIP/2.0 100 Trying
   Via: SIP/2.0/WSS s0puhni5qlgc.invalid;branch=z9hG4bK6674273;received=1.1.1.1;rport=47606
   From: <sip:b1encs3k at s0puhni5qlgc.invalid;transport=ws>;tag=hl91vpapon
   To: <sip:1013 at demo.example.com>;tag=7jUFmHeD0pvXF
   Call-ID: 0c13533c-abc8-1233-50b5-00505685769c
   CSeq: 6856 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.4.20-34~64bit
   Content-Length: 0
   
   ------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x2a06f20): reset timer
nta.c:6791 incoming_reply() nta: sent 100 Trying for INVITE (6856)
nua_stack.c:271 nua_stack_event() nua(0x27af3f0): event i_invite 100 Trying
nua_session.c:4145 signal_call_state_change() nua(0x27af3f0): ready call updated: received received offer
soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x27af900, [0x7f5c0b8555c8], [0x7f5c0b8555d0], [(nil)]) called
nua_stack.c:271 nua_stack_event() nua(0x27af3f0): event i_state 100 Trying
tport.c:2296 tport_set_secondary_timer() tport(0x2a06f20): reset timer
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-07-23 12:26:13.080456 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/b1encs3k at s0puhni5qlgc.invalid [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-07-23 12:26:13.080456 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/b1encs3k at s0puhni5qlgc.invalid [BREAK]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-07-23 12:26:13.100449 [DEBUG] sofia.c:6627 Channel sofia/internal/b1encs3k at s0puhni5qlgc.invalid entering state [received][100]
2015-07-23 12:26:13.100449 [DEBUG] sofia.c:6637 Remote SDP:
v=0
o=- 4384031540968842851 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE audio video
a=msid-semantic: WMS XwpcRKYmZydaZ7CgK4sgklgodNEj3584GuB7
m=audio 0 RTP/SAVPF 111 103 104 9 0 8 106 105 13 126
c=IN IP4 0.0.0.0
m=video 0 RTP/SAVPF 100 116 117 96
c=IN IP4 0.0.0.0

2015-07-23 12:26:13.100449 [INFO] switch_core_media.c:3047 Activating audio RTCP PORT 38567
2015-07-23 12:26:13.100449 [DEBUG] switch_rtp.c:3919 RTCP send rate is: 10000 and packet rate is: 20000 Remote Port: 38567
2015-07-23 12:26:13.100449 [DEBUG] switch_rtp.c:2349 Setting RTCP remote addr to 2.2.2.3:38567
2015-07-23 12:26:13.100449 [INFO] switch_core_media.c:3047 Activating video RTCP PORT 39403
2015-07-23 12:26:13.100449 [DEBUG] switch_rtp.c:3919 RTCP send rate is: 10000 and packet rate is: 90000 Remote Port: 39403
2015-07-23 12:26:13.100449 [DEBUG] switch_rtp.c:2349 Setting RTCP remote addr to 2.2.2.3:39403
2015-07-23 12:26:13.100449 [ERR] sofia.c:7280 Reinvite Codec Error!
nua.c:879 nua_respond() nua: nua_respond: entering
nua_stack.c:573 nua_stack_signal() nua(0x27af3f0): recv signal r_respond 488 Not Acceptable Here
nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:403 soa_set_params() soa_set_params(static::0x27af900, ...) called
nua_session.c:2320 nua_invite_server_respond() nua: nua_invite_server_respond: entering
soa.c:1214 soa_clear_remote_sdp() soa_clear_remote_sdp(static::0x27af900) called
tport.c:3257 tport_tsend() tport_tsend(0x2a06f20) tpn = WSS/1.1.1.1:47606
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x27086f0 129 (129)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2a397d1 71 (71)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2a397a0 49 (49)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2a39818 66 (66)
tport_type_ws.c:311 tport_send_stream_ws() tport_ws_writevec: vec 0x2a07110 0x2708771 213 (213)
tport.c:3594 tport_vsend() tport_vsend(0x2a06f20): 528 bytes of 528 to wss/1.1.1.1:47606
tport.c:3492 tport_send_msg() tport_vsend returned 528
send 528 bytes to wss/[1.1.1.1]:47606 at 12:26:13.104835:
   ------------------------------------------------------------------------
   SIP/2.0 488 Not Acceptable Here
   Via: SIP/2.0/WSS s0puhni5qlgc.invalid;branch=z9hG4bK6674273;received=1.1.1.1;rport=47606
   From: <sip:b1encs3k at s0puhni5qlgc.invalid;transport=ws>;tag=hl91vpapon
   To: <sip:1013 at demo.example.com>;tag=7jUFmHeD0pvXF
   Call-ID: 0c13533c-abc8-1233-50b5-00505685769c
   CSeq: 6856 INVITE
   User-Agent: FreeSWITCH-mod_sofia/1.4.20-34~64bit
   Accept: application/sdp
   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
   Supported: path, replaces
   Content-Length: 0
   
   ------------------------------------------------------------------------
tport.c:2296 tport_set_secondary_timer() tport(0x2a06f20): reset timer
nta.c:6791 incoming_reply() nta: sent 488 Not Acceptable Here for INVITE (6856)
nua_session.c:4145 signal_call_state_change() nua(0x27af3f0): ready call updated: init
nua_stack.c:271 nua_stack_event() nua(0x27af3f0): event i_state 488 Not Acceptable Here
nua_stack.c:271 nua_stack_event() nua(0x27af3f0): event i_active 488 Call active
soa.c:1302 soa_init_offer_answer() soa_init_offer_answer(static::0x27af900) called
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-07-23 12:26:13.100449 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/b1encs3k at s0puhni5qlgc.invalid [BREAK]
nua_stack.c:359 nua_application_event() nua: nua_application_event: entering
2015-07-23 12:26:13.100449 [DEBUG] switch_core_session.c:1061 Send signal sofia/internal/b1encs3k at s0puhni5qlgc.invalid [BREAK]
nua_stack.c:529 nua_signal() nua(0x27af3f0): sent signal r_respond
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
2015-07-23 12:26:13.100449 [DEBUG] sofia.c:6627 Channel sofia/internal/b1encs3k at s0puhni5qlgc.invalid entering state [ready][488]
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
tport.c:2773 tport_wakeup() tport_wakeup(0x2a06f20): events IN
tport.c:2864 tport_recv_event() tport_recv_event(0x2a06f20)
tport.c:3205 tport_recv_iovec() tport_recv_iovec(0x2a06f20) msg 0x2673c20 from (wss/1.1.1.1:47606) has 292 bytes, veclen = 1
recv 292 bytes from wss/[1.1.1.1]:47606 at 12:26:13.145877:
   ------------------------------------------------------------------------
   ACK sip:mod_sofia at 2.2.2.2:5060 SIP/2.0
   Via: SIP/2.0/WSS s0puhni5qlgc.invalid;branch=z9hG4bK6674273
   To: <sip:1013 at demo.example.com>;tag=7jUFmHeD0pvXF
   From: <sip:b1encs3k at s0puhni5qlgc.invalid;transport=ws>;tag=hl91vpapon
   Call-ID: 0c13533c-abc8-1233-50b5-00505685769c
   CSeq: 6856 ACK
   
   ------------------------------------------------------------------------
tport.c:3023 tport_deliver() tport_deliver(0x2a06f20): bad msg 0x2673c20 (292 bytes) from wss/1.1.1.1:47606/sips next=(nil)
nta.c:2880 agent_recv_request() nta: received ACK sip:mod_sofia at 2.2.2.2:5060 SIP/2.0 (CSeq 6856)
tport.c:2296 tport_set_secondary_timer() tport(0x2a06f20): reset timer
nta.c:1296 agent_timer() nta: timer set next to 14116 ms
/exit


Join us at ClueCon 2016 Aug 8-12, 2016
More information about the FreeSWITCH-users mailing list