[Freeswitch-users] 488 Not Acceptable Here (INCOMPATIBLE_DESTINATION) with JsSIP and OverSIP + FreeSWITCH

Thu Jan 17 10:24:25 MSK 2013

http://jira.freeswitch.org/browse/FS-4606

On Thu, 17 Jan 2013 02:05:34 +0530
Paan Singh <paan.singh.coder at gmail.com> wrote:

> New SIP capture og with FreeSWITCH log syntax highlighting :
> http://pastebin.freeswitch.com/20457
> 
> 
> On Thu, Jan 17, 2013 at 12:50 AM, Paan Singh <paan.singh.coder at gmail.com>wrote:
> 
> > Hi,
> >
> > I'm using JsSIP from a webpage to make a SIP call to FS, using OverSIP as
> > a Websocket->SIP proxy.
> >
> > I'm able to Register successfully, but when I make a call from JsSIP UA to
> > FreeSWITCH, I get a 180 Ringing, but after that I get a 488 Not Acceptable
> > here.. Please help me figure out what I'm doing wrong here.
> >
> >
> > My inbound_codec_prefs is :
> >
> > <X-PRE-PROCESS cmd="set" data="global_codec_prefs=G729,G7221 at 32000h
> > ,G7221 at 16000h,G722,PCMU,PCMA,GSM,isac at 16000h,isac,opus"/>
> >
> > Here is FreeSWITCH's log for the incoming call :
> >
> > =============================================
> > port.c:2730 tport_wakeup_pri() tport_wakeup_pri(0x26036f0): events IN
> > tport.c:2845 tport_recv_event() tport_recv_event(0x26036f0)
> > tport.c:3186 tport_recv_iovec() tport_recv_iovec(0x26036f0) msg 0x2913be0
> > from (udp/116.214.15.45:5080) has 3113 bytes, veclen = 1
> > tport.c:3004 tport_deliver() tport_deliver(0x26036f0): msg 0x2913be0 (3113
> > bytes) from udp/121.245.35.150:5080/sip next=(nil)
> > nta.c:2803 agent_recv_request() nta: received INVITE
> > sip:30201009 at 116.214.15.45 SIP/2.0 (CSeq 2141)
> > nta.c:3161 agent_aliases() nta: canonizing sip:30201009 at 116.214.15.45with contact
> > nta.c:3002 agent_recv_request() nta: INVITE (2141) going to a default leg
> > nta.c:1348 set_timeout() nta: timer set to 200 ms
> > nua_server.c:102 nua_stack_process_request() nua:
> > nua_stack_process_request: entering
> > nua_stack.c:899 nh_create() nua: nh_create: entering
> > nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
> > nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
> > soa.c:282 soa_clone() soa_clone(static::0x26122e0, 0x2606e20,
> > 0x7f91840c4c50) called
> > soa.c:405 soa_set_params() soa_set_params(static::0x7f91840b25e0, ...)
> > called
> > nta.c:4313 nta_leg_tcreate() nta_leg_tcreate(0x7f91840356d0)
> > soa.c:1302 soa_init_offer_answer()
> > soa_init_offer_answer(static::0x7f91840b25e0) called
> > soa.c:1171 soa_set_remote_sdp() soa_set_remote_sdp(static::0x7f91840b25e0,
> > (nil), 0x285676c, 2333) called
> > nua_dialog.c:338 nua_dialog_usage_add() nua(0x7f91840c4c50): adding
> > session usage
> > tport.c:3238 tport_tsend() tport_tsend(0x26036f0) tpn = UDP/
> > 121.245.35.150:5065
> > tport.c:4026 tport_resolve() tport_resolve addrinfo = 121.245.35.150:5065
> > tport.c:4660 tport_by_addrinfo() tport_by_addrinfo(0x26036f0): not found
> > by name UDP/121.245.35.150:5065
> > tport.c:3574 tport_vsend() tport_vsend(0x26036f0): 564 bytes of 564 to udp/
> > 121.245.35.150:5065
> > tport.c:3472 tport_send_msg() tport_vsend returned 564
> > nta.c:6678 incoming_reply() nta: sent 100 Trying for INVITE (2141)
> > nua_stack.c:271 nua_stack_event() nua(0x7f91840c4c50): event i_invite 100
> > Trying
> > nua_session.c:4135 signal_call_state_change() nua(0x7f91840c4c50): call
> > state changed: init -> received, received offer
> > soa.c:1098 soa_get_remote_sdp() soa_get_remote_sdp(static::0x7f91840b25e0,
> > [0x7f91aa98a5e8], [0x7f91aa98a5e0], [(nil)]) called
> > nua_stack.c:271 nua_stack_event() nua(0x7f91840c4c50): event i_state 100
> > Trying
> > nua_stack.c:359 nua_application_event() nua: nua_application_event:
> > entering
> > nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
> > 2013-01-17 00:25:27.733506 [NOTICE] switch_channel.c:968 New Channel
> > sofia/external/1000 at 116.214.15.45:5080[4aec7fd8-600e-11e2-8706-1365ba01ad52]
> > 2013-01-17 00:25:27.733506 [DEBUG] switch_core_session.c:975 Send signal
> > sofia/external/1000 at 116.214.15.45:5080 [BREAK]
> > nua_stack.c:359 nua_application_event() nua: nua_application_event:
> > entering
> > 2013-01-17 00:25:27.733506 [DEBUG] switch_core_session.c:975 Send signal
> > sofia/external/1000 at 116.214.15.45:5080 [BREAK]
> > 2013-01-17 00:25:27.733506 [DEBUG] switch_core_state_machine.c:415
> > (sofia/external/1000 at 116.214.15.45:5080) Running State Change CS_NEW
> > 2013-01-17 00:25:27.733506 [DEBUG] switch_core_state_machine.c:433
> > (sofia/external/1000 at 116.214.15.45:5080) State NEW
> > 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
> > 2013-01-17 00:25:27.753511 [DEBUG] sofia.c:5576 Channel sofia/external/
> > 1000 at 116.214.15.45:5080 entering state [received][100]
> > 2013-01-17 00:25:27.753511 [DEBUG] sofia.c:5587 Remote SDP:
> > v=0
> > o=- 2957375511 2 IN IP4 127.0.0.1
> > s=-
> > t=0 0
> > a=group:BUNDLE audio video
> > m=audio 40111 RTP/SAVPF 103 104 0 8 106 105 13 126
> > c=IN IP4 121.245.35.150
> > a=rtcp:40111 IN IP4 121.245.35.150
> > a=candidate:877273017 1 udp 2113937151 121.245.35.150 39842 typ host
> > generation 0
> > a=candidate:877273017 2 udp 2113937151 121.245.35.150 39842 typ host
> > generation 0
> > a=candidate:4173799466 1 udp 1677729535 121.245.35.150 40111 typ srflx
> > generation 0
> > a=candidate:4173799466 2 udp 1677729535 121.245.35.150 40111 typ srflx
> > generation 0
> > a=candidate:2060051273 1 tcp 1509957375 121.245.35.150 54291 typ host
> > generation 0
> > a=candidate:2060051273 2 tcp 1509957375 121.245.35.150 54291 typ host
> > generation 0
> > a=ice-ufrag:qiKF0ErbxaXldKI0
> > a=ice-pwd:XlMXg/i8jwnCAgwnuo9KyZBw
> > a=ice-options:google-ice
> > a=mid:audio
> > a=rtcp-mux
> > a=crypto:1 AES_CM_128_HMAC_SHA1_80
> > inline:bX1U9Kr56lIcZBLQvS2pmRW3nAcTG9H0uahawqj2
> > a=rtpmap:103 ISAC/16000
> > a=rtpmap:104 ISAC/32000
> > 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=ssrc:4278252985 cname:fMHr4uVHPcpHFfGu
> > a=ssrc:4278252985 mslabel:OEZOjX953DJU0k0J3IKmuasdqH13b96rGxhx
> > a=ssrc:4278252985 label:OEZOjX953DJU0k0J3IKmuasdqH13b96rGxhx00
> > m=video 40111 RTP/SAVPF 100 101 102
> > c=IN IP4 121.245.35.150
> > a=rtcp:40111 IN IP4 121.245.35.150
> > a=candidate:877273017 1 udp 2113937151 121.245.35.150 39842 typ host
> > generation 0
> > a=candidate:877273017 2 udp 2113937151 121.245.35.150 39842 typ host
> > generation 0
> > a=candidate:4173799466 1 udp 1677729535 121.245.35.150 40111 typ srflx
> > generation 0
> > a=candidate:4173799466 2 udp 1677729535 121.245.35.150 40111 typ srflx
> > generation 0
> > a=candidate:2060051273 1 tcp 1509957375 121.245.35.150 54291 typ host
> > generation 0
> > a=candidate:2060051273 2 tcp 1509957375 121.245.35.150 54291 typ host
> > generation 0
> > a=ice-ufrag:qiKF0ErbxaXldKI0
> > a=ice-pwd:XlMXg/i8jwnCAgwnuo9KyZBw
> > a=ice-options:google-ice
> > a=mid:video
> > a=rtcp-mux
> > a=crypto:1 AES_CM_128_HMAC_SHA1_80
> > inline:bX1U9Kr56lIcZBLQvS2pmRW3nAcTG9H0uahawqj2
> > a=rtpmap:100 VP8/90000
> > a=rtpmap:101 red/90000
> > a=rtpmap:102 ulpfec/90000
> > a=ssrc:169275022 cname:fMHr4uVHPcpHFfGu
> > a=ssrc:169275022 mslabel:OEZOjX953DJU0k0J3IKmuasdqH13b96rGxhx
> > a=ssrc:169275022 label:OEZOjX953DJU0k0J3IKmuasdqH13b96rGxhx10
> >
> > 2013-01-17 00:25:27.753511 [DEBUG] sofia_glue.c:4978 Set Remote Key [1
> > AES_CM_128_HMAC_SHA1_80 inline:bX1U9Kr56lIcZBLQvS2pmRW3nAcTG9H0uahawqj2]
> > 2013-01-17 00:25:27.753511 [DEBUG] sofia_glue.c:3155 Set Local Key [1
> > AES_CM_128_HMAC_SHA1_80 inline:i8vqmBeU4+/sjJBndCbEQ4G87gmpYeVnqxh8Xuzu]
> > 2013-01-17 00:25:27.753511 [DEBUG] sofia_glue.c:5277 No 2833 in SDP.
> >  Disable 2833 dtmf and switch to INFO
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_channel.c:2994
> > (sofia/external/1000 at 116.214.15:45:5080) Callstate Change DOWN -> HANGUP
> > 2013-01-17 00:25:27.753511 [NOTICE] sofia.c:5878 Hangup sofia/external/
> > 1000 at 116.214.15.45:5080 [CS_NEW] [INCOMPATIBLE_DESTINATION]
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_channel.c:3017 Send signal
> > sofia/external/1000 at 116.214.15.45:5080 [KILL]
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_session.c:1291 Send signal
> > sofia/external/1000 at 116.214.15.45:5080 [BREAK]
> > nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:415
> > (sofia/external/1000 at 116.214.15.45:5080) Running State Change CS_HANGUP
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:667
> > (sofia/external/1000 at 116.214.15.45:5080) State HANGUP
> > 2013-01-17 00:25:27.753511 [DEBUG] mod_sofia.c:503 Channel sofia/external/
> > 1000 at 116.214.15.45:5080 hanging up, cause: INCOMPATIBLE_DESTINATION
> > 2013-01-17 00:25:27.753511 [DEBUG] mod_sofia.c:633 Responding to INVITE
> > with: 488
> > nua.c:879 nua_respond() nua: nua_respond: entering
> > nua_stack.c:529 nua_signal() nua(0x7f91840c4c50): sent signal r_respond
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:48
> > sofia/external/1000 at 116.214.15.45:5080 Standard HANGUP, cause:
> > INCOMPATIBLE_DESTINATION
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:667
> > (sofia/external/1000 at 116.214.15.45:5080) State HANGUP going to sleep
> > nua_stack.c:573 nua_stack_signal() nua(0x7f91840c4c50): recv signal
> > r_respond 488 Not Acceptable Here
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:446
> > (sofia/external/1000 at 116.214.15.45:5080) State Change CS_HANGUP ->
> > CS_REPORTING
> > nua_params.c:480 nua_stack_set_params() nua: nua_stack_set_params: entering
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_session.c:1291 Send signal
> > sofia/external/1000 at 116.214.15.45:5080 [BREAK]
> > soa.c:405 soa_set_params() soa_set_params(static::0x7f91840b25e0, ...)
> > called
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:415
> > (sofia/external/1000 at 116.214.15.45:5080) Running State Change CS_REPORTING
> > nua_session.c:2316 nua_invite_server_respond() nua:
> > nua_invite_server_respond: entering
> > soa.c:1214 soa_clear_remote_sdp()
> > soa_clear_remote_sdp(static::0x7f91840b25e0) called
> > tport.c:3238 tport_tsend() tport_tsend(0x26036f0) tpn = UDP/
> > 121.245.35.150:5065
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:749
> > (sofia/external/1000 at 116.214.15.45:5080) State REPORTING
> > tport.c:4026 tport_resolve() tport_resolve addrinfo = 121.245.35.150:5065
> > tport.c:4660 tport_by_addrinfo() tport_by_addrinfo(0x26036f0): not found
> > by name UDP/121.245.35.150:5065
> > tport.c:3574 tport_vsend() tport_vsend(0x26036f0): 784 bytes of 784 to udp/
> > 121.245.35.150:5065
> > tport.c:3472 tport_send_msg() tport_vsend returned 784
> > nta.c:6678 incoming_reply() nta: sent 488 Not Acceptable Here for INVITE
> > (2141)
> > nua_dialog.c:397 nua_dialog_usage_remove_at() nua(0x7f91840c4c50):
> > removing session usage
> > nua_session.c:4135 signal_call_state_change() nua(0x7f91840c4c50): call
> > state changed: received -> terminated
> > nua_stack.c:271 nua_stack_event() nua(0x7f91840c4c50): event i_state 488
> > Not Acceptable Here
> > nua_stack.c:271 nua_stack_event() nua(0x7f91840c4c50): event i_terminated
> > 488 Not Acceptable Here
> > soa.c:358 soa_destroy() soa_destroy(static::0x7f91840b25e0) called
> > nta.c:4366 nta_leg_destroy() nta_leg_destroy(0x7f91840356d0)
> > nua_stack.c:359 nua_application_event() nua: nua_application_event:
> > entering
> > nua_stack.c:359 nua_application_event() nua: nua_application_event:
> > entering
> > nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> > nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> > nua.c:342 nua_handle_bind() nua: nua_handle_bind: entering
> > nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> > nua.c:366 nua_handle_magic() nua: nua_handle_magic: entering
> > nua.c:921 nua_handle_destroy() nua: nua_handle_destroy: entering
> > nua_stack.c:569 nua_stack_signal() nua(0x7f91840c4c50): recv signal
> > r_destroy
> > nta.c:4366 nta_leg_destroy() nta_leg_destroy((nil))
> > nua_stack.c:529 nua_signal() nua(0x7f91840c4c50): sent signal r_destroy
> > 2013-01-17 00:25:27.753511 [DEBUG] mod_cdr_sqlite.c:102 Writing SQL to DB:
> > INSERT INTO cdr VALUES ("1000","1000","30201009","public","2013-01-17
> > 00:25:27","","2013-01-17
> > 00:25:27",0,0,"INCOMPATIBLE_DESTINATION","4aec7fd8-600e-11e2-8706-1365ba01ad52","","")
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:92
> > sofia/external/1000 at 116.214.15.45:5080 Standard REPORTING, cause:
> > INCOMPATIBLE_DESTINATION
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:749
> > (sofia/external/1000 at 116.214.15.45:5080) State REPORTING going to sleep
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:440
> > (sofia/external/1000 at 116.214.15.45:5080) State Change CS_REPORTING ->
> > CS_DESTROY
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_session.c:1291 Send signal
> > sofia/external/1000 at 116.214.15.45:5080 [BREAK]
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_session.c:1499 Session 1794
> > (sofia/external/1000 at 116.214.15.45:5080) Locked, Waiting on external
> > entities
> > 2013-01-17 00:25:27.753511 [NOTICE] switch_core_session.c:1517 Session
> > 1794 (sofia/external/1000 at 116.214.15.45:5080) Ended
> > 2013-01-17 00:25:27.753511 [NOTICE] switch_core_session.c:1521 Close
> > Channel sofia/external/1000 at 116.214.15.45:5080 [CS_DESTROY]
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:556
> > (sofia/external/1000 at 116.214.15.45:5080) Callstate Change HANGUP -> DOWN
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:559
> > (sofia/external/1000 at 116.214.15.45:5080) Running State Change CS_DESTROY
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:569
> > (sofia/external/1000 at 116.214.15.45:5080) State DESTROY
> > 2013-01-17 00:25:27.753511 [DEBUG] mod_sofia.c:396 sofia/external/
> > 1000 at 116.214.15.45:5080 SOFIA DESTROY
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:99
> > sofia/external/1000 at 116.214.15.45:5080 Standard DESTROY
> > 2013-01-17 00:25:27.753511 [DEBUG] switch_core_state_machine.c:569
> > (sofia/external/1000 at 116.214.15.45:5080) State DESTROY going to sleep
> > nta.c:1294 agent_timer() nta: timer set next to 322 ms
> > tport.c:2730 tport_wakeup_pri() tport_wakeup_pri(0x26036f0): events IN
> > tport.c:2845 tport_recv_event() tport_recv_event(0x26036f0)
> > tport.c:3186 tport_recv_iovec() tport_recv_iovec(0x26036f0) msg
> > 0x7f9198220070 from (udp/116.214.15.45:5080) has 339 bytes, veclen = 1
> > tport.c:3004 tport_deliver() tport_deliver(0x26036f0): msg 0x7f9198220070
> > (339 bytes) from udp/121.245.35.150:5080/sip next=(nil)
> > nta.c:2803 agent_recv_request() nta: received ACK
> > sip:30201009 at 116.214.15.45 SIP/2.0 (CSeq 2141)
> > nta.c:2938 agent_recv_request() nta: ACK (2141) is going to INVITE (2141)
> > nta.c:1294 agent_timer() nta: timer set next to 4823 ms
> > nta.c:7010 _nta_incoming_timer() nta: timer I fired, terminate 488 response
> > nta.c:5718 incoming_reclaim_queued() incoming_reclaim_all((nil), (nil),
> > 0x7f91aa98ac20)
> > nta.c:7061 _nta_incoming_timer() nta_incoming_timer: 0/0 resent, 0/0 tout,
> > 1/1 term, 1/1 free
> > nta.c:1279 agent_timer() nta: timer not set
> > ================================================================
> >
> > Here is the Log from JsSIP in the browser that receives messages from
> > FreeSWITCH :
> > ===========================================================
> >  JsSIP | TRANSPORT | Received WebSocket text message: SIP/2.0 180 Ringing
> > Via: SIP/2.0/TCP 29.62.109.242;branch=z9hG4bK1565615 Record-Route:
> > <sip:192.168.1.8:5060;transport=udp;lr;ovid=69d4d6a0> Record-Route:
> > <sip:774f80554e at 192.168.1.8:10080;transport=ws;lr;ovid=69d4d6a0> From: <
> > sip:1000 at 116.214.15.45:5080>;tag=rj2nc38qem To: <
> > sip:30201009 at 116.214.15.45>;tag=j4X0e04aZjU2K Call-ID:
> > joshempnx2kuh7smrt3x CSeq: 1974 INVITE Contact:
> > <sip:30201009 at 116.214.15.45:5080;transport=udp> User-Agent:
> > FreeSWITCH-mod_sofia/1.3.13b+git~20130108T190107Z~30e4c71bbe Accept:
> > application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO,
> > UPDATE, REGISTER, REFER, NOTIFY Supported: timer, precondition, path,
> > replaces Allow-Events: talk, hold, conference, refer Content-Length: 0
> > P-Asserted-Identity: "30201009" <sip:30201009 at 116.214.15.45>
> > jssip-0.2.1.js:684<http://example.com:8080/static/did/tryit/jssip-0.2.1.js>
> >  JsSIP | DIALOG | New UAC dialog created: 1 jssip-0.2.1.js:2171<http://example.com:8080/static/did/tryit/jssip-0.2.1.js>
> >  JsSIP | EVENT EMITTER | Emitting event: progress jssip-0.2.1.js:170<http://example.com:8080/static/did/tryit/jssip-0.2.1.js>
> >  JsSIP | TRANSPORT | Received WebSocket text message: SIP/2.0 488 Not
> > Acceptable Here Via: SIP/2.0/TCP 29.62.109.242;branch=z9hG4bK1565615
> > Max-Forwards: 10 From: <sip:1000 at 116.214.15.45:5080>;tag=rj2nc38qem To: <
> > sip:30201009 at 116.214.15.45>;tag=j4X0e04aZjU2K Call-ID:
> > joshempnx2kuh7smrt3x CSeq: 1974 INVITE User-Agent:
> > FreeSWITCH-mod_sofia/1.3.13b+git~20130108T190107Z~30e4c71bbe Allow: INVITE,
> > ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
> > Supported: timer, precondition, path, replaces Allow-Events: talk, hold,
> > conference, refer Reason: Q.850;cause=88;text="INCOMPATIBLE_DESTINATION"
> > Content-Length: 0 P-Asserted-Identity: "30201009" <
> > sip:30201009 at 116.214.15.45>
> > =============================================================================
> >
> >
> >
> >
> >
> >
> > What am I doing wrong? Thanks,
> > Paan
> >
> >