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@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@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@226.59.129.221:5060 [BREAK] 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/5596@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@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@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@226.59.129.221:5060) State ROUTING 2011-04-12 15:29:06.285484 [DEBUG] mod_sofia.c:147 sofia/internal/5596@226.59.129.221:5060 SOFIA ROUTING 2011-04-12 15:29:06.285484 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/5596@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@226.59.129.221:5060 [BREAK] 2011-04-12 15:29:06.285484 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/5596@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@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@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@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@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@226.59.129.221:5060 Update Callee ID to "5596" <sip:5596@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@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@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@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@226.59.129.221:5060 [KILL] 2011-04-12 15:29:36.002806 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/5596@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@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@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@226.59.129.221:5060) State HANGUP EXECUTE sofia/external/1009@fs2000.lightyear.net answer() 2011-04-12 15:29:36.003897 [DEBUG] sofia_glue.c:3014 AUDIO RTP [sofia/external/1009@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@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@fs2000.lightyear.net: v=0 o=FreeSWITCH 1302609304 1302609305 IN IP4 226.59.129.223 s=FreeSWITCH c=IN IP4 226.59.129.223