[Freeswitch-users] FS does not repose to SIP OK message.

Anthony Minessale anthony.minessale at gmail.com
Wed Apr 13 04:21:18 MSD 2011 

The ack is not being received.  Try your trace from the other side.
Try finding the misconfiguration and the NAT or SIP alg on your network.




On Tue, Apr 12, 2011 at 3:00 PM, Gary Chen <gchen00 at insightbb.com> wrote:
> Just update my test FS to newest snapshot: FreeSWITCH Version 1.0.head
> (git-5310735 2011-04-07 15-47-30 -0500)
> I am using SJphone softphone to call into my test FS1. This FS1 then forward
> the call to another FS2.
> FS2 will answer the call and start Music On Hold.  Basically I am using
> SJphone to initiate a SIP call  and let FS2 to answer the call with Music On
> Hold.
> It is working with older version of FS. Now after update to this newest
> version. The call sometime will not go through. The SJPhone just keep
> ringing until timeout. This happens maybe on half of the calls. I also tried
> to use Asterisk to replace FS2 for Music On Hold and it did the same thing.
> The following is the part of console sofia log info:
> 2011-04-12 15:29:06.285484 [DEBUG] mod_sofia.c:84
> sofia/internal/5596 at 226.59.129.221:5060 SOFIA INIT
> nua: nh_create_handle: entering
> nua: nua_handle_bind: entering
> nua: nua_invite: entering
> nua(0x18cc2c80): sent signal r_invite
> 2011-04-12 15:29:06.285484 [DEBUG] mod_sofia.c:124
> (sofia/internal/5596 at 226.59.129.221:5060) State Change CS_INIT -> CS_ROUTING
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_session.c:1116 Send signal
> sofia/internal/5596 at 226.59.129.221:5060 [BREAK]
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:361
> (sofia/internal/5596 at 226.59.129.221:5060) State INIT going to sleep
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:325
> (sofia/internal/5596 at 226.59.129.221:5060) Running State Change CS_ROUTING
> nua(0x18cc2c80): recv signal r_invite
> 2011-04-12 15:29:06.285484 [DEBUG] switch_channel.c:1668
> (sofia/internal/5596 at 226.59.129.221:5060) Callstate Change DOWN -> RINGING
> nua: nua_stack_set_params: entering
> soa_clone(static::0x18c66f60, 0x18c474e0, 0x18cc2c80) called
> soa_set_params(static::0x2aaabc072a60, ...) called
> soa_set_params(static::0x2aaabc072a60, ...) called
> soa_set_user_sdp(static::0x2aaabc072a60, (nil), 0x18ccb7b7, -1) called
> soa_set_capability_sdp(static::0x2aaabc072a60, (nil), 0x18ccb7b7, -1) called
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:364
> (sofia/internal/5596 at 226.59.129.221:5060) State ROUTING
> 2011-04-12 15:29:06.285484 [DEBUG] mod_sofia.c:147
> sofia/internal/5596 at 226.59.129.221:5060 SOFIA ROUTING
> 2011-04-12 15:29:06.285484 [DEBUG] switch_ivr_originate.c:66
> (sofia/internal/5596 at 226.59.129.221:5060) State Change CS_ROUTING ->
> CS_CONSUME_MEDIA
> nua(0x18cc2c80): adding session usage
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_session.c:1116 Send signal
> sofia/internal/5596 at 226.59.129.221:5060 [BREAK]
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:364
> (sofia/internal/5596 at 226.59.129.221:5060) State ROUTING going to sleep
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:325
> (sofia/internal/5596 at 226.59.129.221:5060) Running State Change
> CS_CONSUME_MEDIA
> nta_leg_tcreate(0x2aaaac05e220)
> soa_init_offer_answer(static::0x2aaabc072a60) called
> soa_generate_offer(static::0x2aaabc072a60, 0) called
> soa_static_offer_answer_action(0x2aaabc072a60, soa_generate_offer): called
> soa_static(0x2aaabc072a60, soa_generate_offer): generating local description
> soa_static(0x2aaabc072a60, soa_generate_offer): upgrade with local
> description
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:383
> (sofia/internal/5596 at 226.59.129.221:5060) State CONSUME_MEDIA
> soa_sdp_mode_set(0x406f6c60, (nil), ""): called
> 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:383
> (sofia/internal/5596 at 226.59.129.221:5060) State CONSUME_MEDIA going to sleep
> soa_static(0x2aaabc072a60, soa_generate_offer): storing local description
> soa_get_local_sdp(static::0x2aaabc072a60, [(nil)], [0x406f6dc8],
> [0x406f6dd4]) called
> nta: selecting scheme sip
> tport_tsend(0x18c69750) tpn = */226.59.129.221:5060
> tport_resolve addrinfo = 226.59.129.221:5060
> tport_by_addrinfo(0x18c69750): not found by name */226.59.129.221:5060
> tport_vsend(0x18c69750): 1245 bytes of 1245 to udp/226.59.129.221:5060
> tport_vsend returned 1245
> nta: sent INVITE (10982209) to */226.59.129.221:5060
> tport_pend(0x18c69750): pending 0x2aaaac059c30 for udp/226.59.129.223:5060
> (already 0)
> nta: timer set to 32000 ms
> nta: timer shortened to 1000 ms
> nua(0x18cc2c80): call state changed: init -> calling, sent offer
> soa_get_local_sdp(static::0x2aaabc072a60, [0x406f6db8], [0x406f6db0],
> [(nil)]) called
> nua(0x18cc2c80): event i_state INVITE sent
> nua: nua_application_event: entering
> 2011-04-12 15:29:06.285484 [DEBUG] sofia.c:4761 Channel
> sofia/internal/5596 at 226.59.129.221:5060 entering state [calling][0]
> nua: nua_handle_magic: entering
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x18c87620 from (udp/226.59.129.223:5060)
> has 344 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x18c87620 (344 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 100 Trying for INVITE (10982209)
> nta: 100 Trying is going to a transaction
> nta_outgoing: RTT is 0.765 ms
> tport_release(0x18c69750): 0x2aaaac059c30 by 0x2aaabc05da60 with 0x18c87620
> (preliminary)
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x2aaabc070b20 from
> (udp/226.59.129.223:5060) has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x2aaabc070b20 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> tport_release(0x18c69750): 0x2aaaac059c30 by 0x2aaabc05da60 with
> 0x2aaabc070b20
> soa_set_remote_sdp(static::0x2aaabc072a60, (nil), 0x2aaabc0712ac, 247)
> called
> soa_process_answer(static::0x2aaabc072a60) called
> soa_static_offer_answer_action(0x2aaabc072a60, soa_process_answer): called
> soa_sdp_mode_set(0x2aaabc070240, 0x2aaabc073500, ""): called
> soa_static(0x2aaabc072a60, soa_process_answer): upgrade codecs with remote
> description
> soa_static(0x2aaabc072a60, soa_process_answer): storing local description
> soa_activate(static::0x2aaabc072a60, (nil)) called
> nua(0x18cc2c80): INVITE: processed SDP answer in 200 OK
> nua(0x18cc2c80): event r_invite 200 OK
> nua(0x18cc2c80): call state changed: calling -> completing, received answer
> soa_get_remote_sdp(static::0x2aaabc072a60, [0x406f6828], [0x406f6820],
> [(nil)]) called
> soa_get_params(static::0x2aaabc072a60, ...) called
> nua: nua_application_event: entering
> nua(0x18cc2c80): event i_state 200 OK
> 2011-04-12 15:29:06.294311 [INFO] sofia.c:740
> sofia/internal/5596 at 226.59.129.221:5060 Update Callee ID to "5596"
> <sip:5596 at 226.59.129.221>
> nta: timer not set
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x2aaab4022620 from
> (udp/226.59.129.223:5060) has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x2aaab4022620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> nta: timer set next to 31009 ms
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x2aaab4022620 from
> (udp/226.59.129.223:5060) has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x2aaab4022620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x2aaaac060220 from
> (udp/226.59.129.223:5060) has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x2aaaac060220 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x2aaaac060220 from
> (udp/226.59.129.223:5060) has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x2aaaac060220 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x2aaaac060220 from
> (udp/226.59.129.223:5060) has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x2aaaac060220 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x18c87620 from (udp/226.59.129.223:5060)
> has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x18c87620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x18c87620 from (udp/226.59.129.223:5060)
> has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x18c87620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x18c87620 from (udp/226.59.129.223:5060)
> has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x18c87620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c4dcc0): events IN
> tport_recv_event(0x18c4dcc0)
> tport_recv_iovec(0x18c4dcc0) msg 0x2aaaac060220 from
> (udp/226.59.129.223:5080) has 876 bytes, veclen = 1
> tport_deliver(0x18c4dcc0): msg 0x2aaaac060220 (876 bytes) from
> udp/226.59.139.61:5080/sip next=(nil)
> nta: received INVITE sip:5025155596 at fs2000.lightyear.net SIP/2.0 (CSeq 1)
> nta: INVITE (1) going to existing INVITE transaction
> nta: re-received INVITE request, retransmitting 100 reply
> tport_tsend(0x18c4dcc0) tpn = UDP/226.59.139.61:5060
> tport_resolve addrinfo = 226.59.139.61:5060
> tport_by_addrinfo(0x18c4dcc0): not found by name UDP/226.59.139.61:5060
> tport_vsend(0x18c4dcc0): 397 bytes of 397 to udp/226.59.139.61:5060
> tport_vsend returned 397
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x18c87620 from (udp/226.59.129.223:5060)
> has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x18c87620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> tport_wakeup_pri(0x18c69750): events IN
> tport_recv_event(0x18c69750)
> tport_recv_iovec(0x18c69750) msg 0x18c87620 from (udp/226.59.129.223:5060)
> has 1235 bytes, veclen = 1
> tport_deliver(0x18c69750): msg 0x18c87620 (1235 bytes) from
> udp/226.59.129.221:5060/sip next=(nil)
> nta: received 200 OK for INVITE (10982209)
> nta: 200 OK is going to a transaction
> nta: 200 OK is duplicate response to 10982209 INVITE
>         Via: SIP/2.0/UDP 226.59.129.223 ;branch=z9hG4bKa9ee6QBjeKFtg
> 2011-04-12 15:29:36.002806 [DEBUG] switch_channel.c:2563
> (sofia/internal/5596 at 226.59.129.221:5060) Callstate Change RINGING -> HANGUP
> 2011-04-12 15:29:36.002806 [NOTICE] switch_ivr_originate.c:3329 Hangup
> sofia/internal/5596 at 226.59.129.221:5060 [CS_CONSUME_MEDIA] [NO_ANSWER]
> 2011-04-12 15:29:36.002806 [DEBUG] switch_channel.c:2579 Send signal
> sofia/internal/5596 at 226.59.129.221:5060 [KILL]
> 2011-04-12 15:29:36.002806 [DEBUG] switch_core_session.c:1116 Send signal
> sofia/internal/5596 at 226.59.129.221:5060 [BREAK]
> 2011-04-12 15:29:36.002806 [INFO] mod_dptools.c:2647 Originate Failed.
> Cause: NO_ANSWER
> 2011-04-12 15:29:36.002806 [DEBUG] switch_cpp.cpp:988
> sofia/external/1009 at fs2000.lightyear.net destroy/unlink session from object
> 2011-04-12 15:29:36.002806 [DEBUG] switch_core_state_machine.c:325
> (sofia/internal/5596 at 226.59.129.221:5060) Running State Change CS_HANGUP
> 2011-04-12 15:29:36.002806 [DEBUG] switch_core_state_machine.c:565
> (sofia/internal/5596 at 226.59.129.221:5060) State HANGUP
> EXECUTE sofia/external/1009 at fs2000.lightyear.net answer()
> 2011-04-12 15:29:36.003897 [DEBUG] sofia_glue.c:3014 AUDIO RTP
> [sofia/external/1009 at fs2000.lightyear.net] 226.59.129.223 port 27272 ->
> 226.59.139.61 port 49420 codec: 3 ms: 20
> nua: nua_handle_magic: entering
> 2011-04-12 15:29:36.003897 [DEBUG] switch_rtp.c:1623 Starting timer [soft]
> 160 bytes per 20ms
> nua: nua_application_event: entering
> 2011-04-12 15:29:36.003897 [DEBUG] mod_sofia.c:457 Channel
> sofia/internal/5596 at 226.59.129.221:5060 hanging up, cause: NO_ANSWER
> 2011-04-12 15:29:36.004809 [DEBUG] sofia_glue.c:3276 Set 2833 dtmf send
> payload to 101
> 2011-04-12 15:29:36.004809 [DEBUG] sofia_glue.c:3281 Set 2833 dtmf receive
> payload to 101
> 2011-04-12 15:29:36.004809 [DEBUG] mod_sofia.c:681 Local SDP
> sofia/external/1009 at fs2000.lightyear.net:
> v=0
> o=FreeSWITCH 1302609304 1302609305 IN IP4 226.59.129.223
> s=FreeSWITCH
> c=IN IP4 226.59.129.223
>
>
>
>
>
> _______________________________________________
> FreeSWITCH-users mailing list
> FreeSWITCH-users at lists.freeswitch.org
> http://lists.freeswitch.org/mailman/listinfo/freeswitch-users
> UNSUBSCRIBE:http://lists.freeswitch.org/mailman/options/freeswitch-users
> http://www.freeswitch.org
>
>



-- 
Anthony Minessale II

FreeSWITCH http://www.freeswitch.org/
ClueCon http://www.cluecon.com/
Twitter: http://twitter.com/FreeSWITCH_wire

AIM: anthm
MSN:anthony_minessale at hotmail.com
GTALK/JABBER/PAYPAL:anthony.minessale at gmail.com
IRC: irc.freenode.net #freeswitch

FreeSWITCH Developer Conference
sip:888 at conference.freeswitch.org
googletalk:conf+888 at conference.freeswitch.org
pstn:+19193869900

More information about the FreeSWITCH-users mailing list