Here the detail trace for this problem, please notice the highlighted line. Thanks alot for all your help. 2009-01-19 13:40:30 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10110@192.168.1.122:7001 entering state [ready] recv 787 bytes from udp/[192.168.1.122]:5060 at 18:40:30.915571: ------------------------------------------------------------------------ INVITE sip:0010111@192.168.1.116:5070 SIP/2.0 Record-Route: <sip:192.168.1.122;lr=on;ftag=112> Via: SIP/2.0/UDP 192.168.1.122;branch=z9hG4bK855f.d0dc6ad1.0 Via: SIP/2.0/UDP 192.168.1.103:7001 From: 10111 <sip:10111@192.168.1.122:7001>;tag=112 To: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>> Call-ID: 112-26869@192.168.1.103 CSeq: 2 INVITE Contact: <sip:10111@192.168.1.103:7001> Max-Forwards: 69 User-Agent: Performance Test Content-Type: application/sdp Content-Length: 276 P-hint: inbound->inbound v=0 o=user1 53655765 2353687637 IN IP4 192.168.1.103 s=- t=0 0 c=IN IP4 192.168.1.103 m=audio 6444 RTP/AVP 0 9 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv ------------------------------------------------------------------------ send 364 bytes to udp/[192.168.1.122]:5060 at 18:40:30.916041: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.122;branch=z9hG4bK855f.d0dc6ad1.0 Via: SIP/2.0/UDP 192.168.1.103:7001 Record-Route: <sip:192.168.1.122;lr=on;ftag=112> From: 10111 <sip:10111@192.168.1.122:7001>;tag=112 To: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>> Call-ID: 112-26869@192.168.1.103 CSeq: 2 INVITE User-Agent: FREESWITCH Media Gateway Content-Length: 0 ------------------------------------------------------------------------ 2009-01-19 13:40:30 [DEBUG] sofia.c:3762 sofia_handle_sip_i_invite() IP 192.168.1.122 Approved by acl "lan[]". Access Granted. 2009-01-19 13:40:30 [NOTICE] switch_channel.c:565 switch_channel_set_name() New Channel sofia/internal/10111@192.168.1.122:7001[a61933bc-e658-11dd-b62c-5db88ae44bdf] 2009-01-19 13:40:30 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111@192.168.1.122:7001 entering state [received] 2009-01-19 13:40:30 [DEBUG] sofia.c:2533 sofia_handle_sip_i_state() Remote SDP: v=0 o=user1 53655765 2353687637 IN IP4 192.168.1.103 s=- c=IN IP4 192.168.1.103 t=0 0 m=audio 6444 RTP/AVP 0 9 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2009-01-19 13:40:30 [DEBUG] sofia_glue.c:2409 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[G722:9:8000] 2009-01-19 13:40:30 [DEBUG] sofia_glue.c:2409 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000] 2009-01-19 13:40:30 [DEBUG] sofia_glue.c:1601 sofia_glue_tech_set_codec() Set Codec sofia/internal/10111@192.168.1.122:7001 PCMU/8000 20 ms 160 samples 2009-01-19 13:40:30 [DEBUG] sofia_glue.c:2373 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2009-01-19 13:40:30 [DEBUG] sofia.c:2685 sofia_handle_sip_i_state() (sofia/internal/10111@192.168.1.122:7001) State Change CS_NEW -> CS_INIT 2009-01-19 13:40:30 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:30 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) Running State Change CS_INIT 2009-01-19 13:40:30 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State INIT 2009-01-19 13:40:30 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/ 10111@192.168.1.122:7001 SOFIA INIT 2009-01-19 13:40:30 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/ 10111@192.168.1.122:7001) State Change CS_INIT -> CS_ROUTING 2009-01-19 13:40:30 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:30 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State INIT going to sleep 2009-01-19 13:40:30 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) Running State Change CS_ROUTING 2009-01-19 13:40:30 [DEBUG] switch_core_state_machine.c:435 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State ROUTING 2009-01-19 13:40:30 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/internal/10111@192.168.1.122:7001 SOFIA ROUTING 2009-01-19 13:40:30 [DEBUG] switch_core_state_machine.c:64 switch_core_standard_on_routing() sofia/internal/10111@192.168.1.122:7001Standard ROUTING 2009-01-19 13:40:30 [INFO] mod_dialplan_xml.c:233 dialplan_hunt() Processing 10111->0010111 in context public 2009-01-19 13:40:31 [CONSOLE] mod_xml_curl.c:236 xml_url_fetch() XML response is in /tmp/a619aae0-e658-11dd-b62c-5db88ae44bdf.tmp.xml 2009-01-19 13:40:31 [DEBUG] mod_dialplan_xml.c:117 parse_exten() Regex: [test9] destination_number(0010111) =~ /^(.*)$/ 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:100 switch_core_standard_on_routing() (sofia/internal/10111@192.168.1.122:7001) State Change CS_ROUTING -> CS_EXECUTE 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:435 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State ROUTING going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) Running State Change CS_EXECUTE 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:442 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State EXECUTE 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:173 sofia_on_execute() sofia/internal/10111@192.168.1.122:7001 SOFIA EXECUTE 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:137 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Standard EXECUTE 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute export(hold_music=silence) 2009-01-19 13:40:31 [DEBUG] mod_dptools.c:819 export_function() EXPORT [hold_music]=[silence] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute set(call_timeout=120) 2009-01-19 13:40:31 [DEBUG] mod_dptools.c:681 set_function() sofia/internal/ 10111@192.168.1.122:7001 SET [call_timeout]=[120] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute set(hangup_after_bridge=true) 2009-01-19 13:40:31 [DEBUG] mod_dptools.c:681 set_function() sofia/internal/ 10111@192.168.1.122:7001 SET [hangup_after_bridge]=[true] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute set(continue_on_fail=true) 2009-01-19 13:40:31 [DEBUG] mod_dptools.c:681 set_function() sofia/internal/ 10111@192.168.1.122:7001 SET [continue_on_fail]=[true] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute set(language=zh) 2009-01-19 13:40:31 [DEBUG] mod_dptools.c:681 set_function() sofia/internal/ 10111@192.168.1.122:7001 SET [language]=[zh] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute set(ringback=%(2000, 4000, 440.0, 480.0)) 2009-01-19 13:40:31 [DEBUG] mod_dptools.c:681 set_function() sofia/internal/ 10111@192.168.1.122:7001 SET [ringback]=[%(2000, 4000, 440.0, 480.0)] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bind_meta_app(1 a s execute_extension::a_record XML features) 2009-01-19 13:40:31 [INFO] switch_ivr_async.c:1570 switch_ivr_bind_dtmf_meta_session() Bound A-Leg: 1 execute_extension::a_record XML features 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bind_meta_app(2 a s execute_extension::a_stoprecord XML features) 2009-01-19 13:40:31 [INFO] switch_ivr_async.c:1570 switch_ivr_bind_dtmf_meta_session() Bound A-Leg: 2 execute_extension::a_stoprecord XML features 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bind_meta_app(3 a s execute_extension::a_att_xfer XML features) 2009-01-19 13:40:31 [INFO] switch_ivr_async.c:1570 switch_ivr_bind_dtmf_meta_session() Bound A-Leg: 3 execute_extension::a_att_xfer XML features 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bind_meta_app(1 b s execute_extension::b_record XML features) 2009-01-19 13:40:31 [INFO] switch_ivr_async.c:1577 switch_ivr_bind_dtmf_meta_session() Bound B-Leg: 1 execute_extension::b_record XML features 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bind_meta_app(2 b s execute_extension::b_stoprecord XML features) 2009-01-19 13:40:31 [INFO] switch_ivr_async.c:1577 switch_ivr_bind_dtmf_meta_session() Bound B-Leg: 2 execute_extension::b_stoprecord XML features 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bind_meta_app(3 b s execute_extension::b_att_xfer XML features) 2009-01-19 13:40:31 [INFO] switch_ivr_async.c:1577 switch_ivr_bind_dtmf_meta_session() Bound B-Leg: 3 execute_extension::b_att_xfer XML features 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:152 switch_core_standard_on_execute() sofia/internal/10111@192.168.1.122:7001Execute bridge(sofia/gateway/openser/10111) 2009-01-19 13:40:31 [NOTICE] switch_channel.c:565 switch_channel_set_name() New Channel sofia/internal/10111 [a6274970-e658-11dd-b62c-5db88ae44bdf] 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:2495 sofia_outgoing_channel() (sofia/internal/10111) State Change CS_NEW -> CS_INIT 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111) Running State Change CS_INIT 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/10111) State INIT 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/10111 SOFIA INIT 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/10111) State Change CS_INIT -> CS_ROUTING 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:432 switch_core_session_run() (sofia/internal/10111) State INIT going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111) Running State Change CS_ROUTING 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:435 switch_core_session_run() (sofia/internal/10111) State ROUTING 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:130 sofia_on_routing() sofia/internal/10111 SOFIA ROUTING 2009-01-19 13:40:31 [DEBUG] switch_ivr_originate.c:52 originate_on_routing() (sofia/internal/10111) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:435 switch_core_session_run() (sofia/internal/10111) State ROUTING going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111) Running State Change CS_CONSUME_MEDIA 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:454 switch_core_session_run() (sofia/internal/10111) State CONSUME_MEDIA 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:454 switch_core_session_run() (sofia/internal/10111) State CONSUME_MEDIA going to sleep send 1229 bytes to udp/[192.168.1.122]:5060 at 18:40:31.010618: ------------------------------------------------------------------------ INVITE sip:10111@192.168.1.122:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.116:5070;rport;branch=z9hG4bKDvK1NF3F0K70m Max-Forwards: 68 From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060> Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076879 INVITE Contact: <sip:FREESWITCHMediaGateway@192.168.1.116:5070;transport=udp> User-Agent: FREESWITCH Media Gateway Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Min-SE: 120 Content-Type: application/sdp Content-Disposition: session Content-Length: 335 P-hint: inbound->inbound Remote-Party-ID: "10111" <sip:10111@openser>;screen=yes;privacy=off v=0 o=FreeSWITCH 5124756122584252723 8222947971594082779 IN IP4 192.168.1.116 s=FreeSWITCH c=IN IP4 192.168.1.116 t=0 0 m=audio 12396 RTP/AVP 0 9 8 3 101 13 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 ------------------------------------------------------------------------ 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111 entering state [calling] recv 354 bytes from udp/[192.168.1.122]:5060 at 18:40:31.031915: ------------------------------------------------------------------------ SIP/2.0 100 Giving a try Via: SIP/2.0/UDP 192.168.1.116:5070;rport=5070;branch=z9hG4bKDvK1NF3F0K70m From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060> Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076879 INVITE Server: OpenSIPS (1.4.3-notls (x86_64/linux)) Content-Length: 0 ------------------------------------------------------------------------ recv 382 bytes from udp/[192.168.1.122]:5060 at 18:40:31.035869: ------------------------------------------------------------------------ SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.116:5070 ;received=192.168.1.116;rport=5070;branch=z9hG4bKDvK1NF3F0K70m From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060>;tag=117 Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076879 INVITE Contact: <sip:192.168.1.107:7000;transport=UDP> Content-Length: 0 ------------------------------------------------------------------------ recv 688 bytes from udp/[192.168.1.122]:5060 at 18:40:31.036002: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.116:5070 ;received=192.168.1.116;rport=5070;branch=z9hG4bKDvK1NF3F0K70m From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060>;tag=117 Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076879 INVITE Contact: <sip:192.168.1.107:7000;transport=UDP> Content-Type: application/sdp Content-Length: 276 v=0 o=user1 53655765 2353687637 IN IP4 192.168.1.107 s=- c=IN IP4 192.168.1.107 t=0 0 m=audio 6000 RTP/AVP 0 9 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111 entering state [proceeding] ------------------------------------------------------------------------ 2009-01-19 13:40:31 [NOTICE] sofia.c:2583 sofia_handle_sip_i_state() Ring-Ready sofia/internal/10111! send 414 bytes to udp/[192.168.1.107]:7000 at 18:40:31.036398: ------------------------------------------------------------------------ ACK sip:192.168.1.107:7000;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.116:5070;rport;branch=z9hG4bKe5ctQamKXvXKg Max-Forwards: 70 From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060>;tag=117 Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076879 ACK Contact: <sip:FREESWITCHMediaGateway@192.168.1.116:5070;transport=udp> Content-Length: 0 ------------------------------------------------------------------------ 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111 entering state [ready] 2009-01-19 13:40:31 [DEBUG] sofia.c:2533 sofia_handle_sip_i_state() Remote SDP: v=0 o=user1 53655765 2353687637 IN IP4 192.168.1.107 s=- c=IN IP4 192.168.1.107 t=0 0 m=audio 6000 RTP/AVP 0 9 8 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 2009-01-19 13:40:31 [DEBUG] sofia_glue.c:2409 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000] 2009-01-19 13:40:31 [DEBUG] sofia_glue.c:1601 sofia_glue_tech_set_codec() Set Codec sofia/internal/10111 PCMU/8000 20 ms 160 samples 2009-01-19 13:40:31 [DEBUG] sofia_glue.c:2373 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2009-01-19 13:40:31 [DEBUG] sofia_glue.c:1825 sofia_glue_activate_rtp() AUDIO RTP [sofia/internal/10111] 192.168.1.116 port 12396 -> 192.168.1.107 port 6000 codec: 0 ms: 20 2009-01-19 13:40:31 [DEBUG] switch_rtp.c:859 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2009-01-19 13:40:31 [DEBUG] switch_channel.c:1710 switch_channel_perform_mark_answered() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [NOTICE] sofia.c:3018 sofia_handle_sip_i_state() Channel [sofia/internal/10111] has been answered 2009-01-19 13:40:31 [DEBUG] switch_channel.c:177 switch_channel_audio_sync() sofia/internal/10111 receive message [SWITCH_MESSAGE_INDICATE_AUDIO_SYNC] 2009-01-19 13:40:31 [DEBUG] switch_channel.c:1631 switch_channel_perform_pre_answer() sofia/internal/10111@192.168.1.122:7001receive message [SWITCH_MESSAGE_INDICATE_PROGRESS] 2009-01-19 13:40:31 [INFO] mod_sofia.c:1272 sofia_receive_message() Asked to send early media by sofia/internal/10111@192.168.1.122:7001 2009-01-19 13:40:31 [DEBUG] sofia_glue.c:1825 sofia_glue_activate_rtp() AUDIO RTP [sofia/internal/10111@192.168.1.122:7001] 192.168.1.116 port 12410 -> 192.168.1.103 port 6444 codec: 0 ms: 20 2009-01-19 13:40:31 [DEBUG] switch_rtp.c:859 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2009-01-19 13:40:31 [INFO] mod_sofia.c:1313 sofia_receive_message() Ring SDP: v=0 o=FreeSWITCH 1232378021 1232378022 IN IP4 192.168.1.116 s=FreeSWITCH c=IN IP4 192.168.1.116 t=0 0 m=audio 12410 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2009-01-19 13:40:31 [NOTICE] mod_sofia.c:1316 sofia_receive_message() Ring-Ready sofia/internal/10111@192.168.1.122:7001! 2009-01-19 13:40:31 [NOTICE] mod_sofia.c:1316 sofia_receive_message() Pre-Answer sofia/internal/10111@192.168.1.122:7001! 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_ivr_originate.c:1287 switch_ivr_originate() Raw Codec Activation Success L16@8000hz 1 channel 20ms 2009-01-19 13:40:31 [DEBUG] switch_ivr_originate.c:1345 switch_ivr_originate() Play Ringback Tone [%(2000, 4000, 440.0, 480.0)] send 1094 bytes to udp/[192.168.1.122]:5060 at 18:40:31.121578: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 192.168.1.122;branch=z9hG4bK855f.d0dc6ad1.0 Via: SIP/2.0/UDP 192.168.1.103:7001 Record-Route: <sip:192.168.1.122;lr=on;ftag=112> From: 10111 <sip:10111@192.168.1.122:7001>;tag=112 To: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>
;tag=235vcFp8gSHtF Call-ID: 112-26869@192.168.1.103 CSeq: 2 INVITE Contact: <sip:mod_sofia@192.168.1.116:5070;transport=udp> User-Agent: FREESWITCH Media Gateway Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Allow-Events: talk, presence, dialog, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Type: application/sdp Content-Disposition: session Content-Length: 267
v=0 o=FreeSWITCH 3481863127924572429 7277142438139379053 IN IP4 192.168.1.116 s=FreeSWITCH c=IN IP4 192.168.1.116 t=0 0 m=audio 12410 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 ------------------------------------------------------------------------ 2009-01-19 13:40:31 [DEBUG] switch_channel.c:1768 switch_channel_perform_answer() sofia/internal/10111@192.168.1.122:7001receive message [SWITCH_MESSAGE_INDICATE_ANSWER] 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:503 sofia_answer_channel() Local SDP sofia/internal/10111@192.168.1.122:7001: v=0 o=FreeSWITCH 1232378021 1232378023 IN IP4 192.168.1.116 s=FreeSWITCH c=IN IP4 192.168.1.116 t=0 0 m=audio 12410 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [NOTICE] switch_ivr_originate.c:1581 switch_ivr_originate() Channel [sofia/internal/10111@192.168.1.122:7001] has been answered 2009-01-19 13:40:31 [DEBUG] switch_channel.c:177 switch_channel_audio_sync() sofia/internal/10111@192.168.1.122:7001 receive message [SWITCH_MESSAGE_INDICATE_AUDIO_SYNC] 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111@192.168.1.122:7001 entering state [early] 2009-01-19 13:40:31 [DEBUG] switch_ivr_originate.c:1621 switch_ivr_originate() Originate Resulted in Success: [sofia/internal/10111] 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111@192.168.1.122:7001 entering state [completed] 2009-01-19 13:40:31 [DEBUG] switch_channel.c:177 switch_channel_audio_sync() sofia/internal/10111 receive message [SWITCH_MESSAGE_INDICATE_AUDIO_SYNC] 2009-01-19 13:40:31 [DEBUG] switch_channel.c:177 switch_channel_audio_sync() sofia/internal/10111@192.168.1.122:7001 receive message [SWITCH_MESSAGE_INDICATE_AUDIO_SYNC] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:862 switch_ivr_multi_threaded_bridge() sofia/internal/10111 receive message [SWITCH_MESSAGE_INDICATE_BRIDGE] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:869 switch_ivr_multi_threaded_bridge() sofia/internal/10111@192.168.1.122:7001receive message [SWITCH_MESSAGE_INDICATE_BRIDGE] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:913 switch_ivr_multi_threaded_bridge() (sofia/internal/10111) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111) Running State Change CS_EXCHANGE_MEDIA 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:445 switch_core_session_run() (sofia/internal/10111) State EXCHANGE_MEDIA 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:404 sofia_on_exchange_media() SOFIA LOOPBACK 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:293 audio_bridge_thread() sofia/internal/10111@192.168.1.122:7001 receive message [SWITCH_MESSAGE_INDICATE_RINGING] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] send 658 bytes to udp/[192.168.1.122]:5060 at 18:40:31.154213: ------------------------------------------------------------------------ BYE sip:10111@192.168.1.103:7001 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.116:5070;rport;branch=z9hG4bKFe6jS54pt5K6B Route: <sip:192.168.1.122;lr=on;ftag=112> Max-Forwards: 70 From: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>
;tag=235vcFp8gSHtF To: 10111 <sip:10111@192.168.1.122:7001>;tag=112 Call-ID: 112-26869@192.168.1.103 CSeq: 110076879 BYE Contact: <sip:mod_sofia@192.168.1.116:5070;transport=udp> User-Agent: FREESWITCH Media Gateway Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Reason: SIP;cause=408;text="ACK Timeout" Content-Length: 0
------------------------------------------------------------------------ 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111@192.168.1.122:7001 entering state [terminating] send 316 bytes to udp/[192.168.1.122]:5060 at 18:40:31.154944: ------------------------------------------------------------------------ SIP/2.0 500 Internal Server Error Via: SIP/2.0/UDP 192.168.1.122;branch=z9hG4bK855f.d0dc6ad1.0 Via: SIP/2.0/UDP 192.168.1.103:7001 From: 10111 <sip:10111@192.168.1.122:7001>;tag=112 To: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>
;tag=235vcFp8gSHtF Call-ID: 112-26869@192.168.1.103 CSeq: 2 INVITE Content-Length: 0
------------------------------------------------------------------------ 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:360 audio_bridge_thread() sofia/internal/10111@192.168.1.122:7001 ending bridge by request from read function 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:409 audio_bridge_thread() sofia/internal/10111@192.168.1.122:7001 receive message [SWITCH_MESSAGE_INDICATE_UNBRIDGE] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:435 audio_bridge_thread() BRIDGE THREAD DONE [sofia/internal/10111@192.168.1.122:7001] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:439 audio_bridge_thread() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:409 audio_bridge_thread() sofia/internal/10111 receive message [SWITCH_MESSAGE_INDICATE_UNBRIDGE] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:510 switch_core_session_perform_receive_message() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:435 audio_bridge_thread() BRIDGE THREAD DONE [sofia/internal/10111] 2009-01-19 13:40:31 [DEBUG] switch_ivr_bridge.c:439 audio_bridge_thread() Send signal sofia/internal/10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [NOTICE] switch_ivr_bridge.c:470 audio_bridge_on_exchange_media() Hangup sofia/internal/10111 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2009-01-19 13:40:31 [DEBUG] switch_channel.c:1494 switch_channel_perform_hangup() Send signal sofia/internal/10111 [KILL] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/10111 [BREAK] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:445 switch_core_session_run() (sofia/internal/10111) State EXCHANGE_MEDIA going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111) Running State Change CS_HANGUP 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:400 switch_core_session_run() (sofia/internal/10111) State HANGUP 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:287 sofia_on_hangup() Channel sofia/internal/10111 hanging up, cause: NORMAL_CLEARING 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:344 sofia_on_hangup() Sending BYE to sofia/internal/10111 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/10111 Standard HANGUP, cause: NORMAL_CLEARING 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:400 switch_core_session_run() (sofia/internal/10111) State HANGUP going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:938 switch_core_session_thread() Session 805 (sofia/internal/10111) Locked, Waiting on external entities recv 351 bytes from udp/[192.168.1.122]:5060 at 18:40:31.177548: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.116:5070 ;received=192.168.1.116;rport=5070;branch=z9hG4bKFe6jS54pt5K6B From: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>
;tag=235vcFp8gSHtF To: 10111 <sip:10111@192.168.1.122:7001>;tag=112 Call-ID: 112-26869@192.168.1.103 CSeq: 110076879 BYE Contact: <sip:192.168.1.103:7001;transport=UDP> Content-Length: 0
------------------------------------------------------------------------ 2009-01-19 13:40:31 [DEBUG] sofia.c:2529 sofia_handle_sip_i_state() Channel sofia/internal/10111@192.168.1.122:7001 entering state [terminated] send 657 bytes to udp/[192.168.1.107]:7000 at 18:40:31.178007: ------------------------------------------------------------------------ BYE sip:192.168.1.107:7000;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.116:5070;rport;branch=z9hG4bKgQZBU0NtQeaSQ Max-Forwards: 70 From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060>;tag=117 Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076880 BYE Contact: <sip:FREESWITCHMediaGateway@192.168.1.116:5070;transport=udp> User-Agent: FREESWITCH Media Gateway Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ recv 354 bytes from udp/[192.168.1.122]:5060 at 18:40:31.178123: ------------------------------------------------------------------------ ACK sip:0010111@192.168.1.116:5070 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.122;branch=z9hG4bK855f.d0dc6ad1.0 From: 10111 <sip:10111@192.168.1.122:7001>;tag=112 Call-ID: 112-26869@192.168.1.103 To: 0010111 <sip:0010111@192.168.1.122 <sip%3A0010111@192.168.1.122>
;tag=235vcFp8gSHtF CSeq: 2 ACK Max-Forwards: 70 User-Agent: OpenSIPS (1.4.3-notls (x86_64/linux)) Content-Length: 0
------------------------------------------------------------------------ 2009-01-19 13:40:31 [NOTICE] switch_ivr_bridge.c:954 switch_ivr_multi_threaded_bridge() Hangup sofia/internal/ 10111@192.168.1.122:7001 [CS_EXECUTE] [NORMAL_CLEARING] 2009-01-19 13:40:31 [DEBUG] switch_channel.c:1494 switch_channel_perform_hangup() Send signal sofia/internal/ 10111@192.168.1.122:7001 [KILL] 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:806 switch_core_session_signal_state_change() Send signal sofia/internal/ 10111@192.168.1.122:7001 [BREAK] 2009-01-19 13:40:31 [NOTICE] switch_core_session.c:956 switch_core_session_thread() Session 805 (sofia/internal/10111) Ended 2009-01-19 13:40:31 [NOTICE] switch_core_session.c:958 switch_core_session_thread() Close Channel sofia/internal/10111 [CS_HANGUP] 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:442 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State EXECUTE going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:369 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) Running State Change CS_HANGUP 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:400 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State HANGUP 2009-01-19 13:40:31 [DEBUG] mod_sofia.c:287 sofia_on_hangup() Channel sofia/internal/10111@192.168.1.122:7001 hanging up, cause: NORMAL_CLEARING 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() sofia/internal/10111@192.168.1.122:7001Standard HANGUP, cause: NORMAL_CLEARING 2009-01-19 13:40:31 [DEBUG] switch_core_state_machine.c:400 switch_core_session_run() (sofia/internal/10111@192.168.1.122:7001) State HANGUP going to sleep 2009-01-19 13:40:31 [DEBUG] switch_core_session.c:938 switch_core_session_thread() Session 804 (sofia/internal/ 10111@192.168.1.122:7001) Locked, Waiting on external entities 2009-01-19 13:40:31 [NOTICE] switch_core_session.c:956 switch_core_session_thread() Session 804 (sofia/internal/ 10111@192.168.1.122:7001) Ended 2009-01-19 13:40:31 [NOTICE] switch_core_session.c:958 switch_core_session_thread() Close Channel sofia/internal/ 10111@192.168.1.122:7001 [CS_HANGUP] send 657 bytes to udp/[192.168.1.107]:7000 at 18:40:31.677674: ------------------------------------------------------------------------ BYE sip:192.168.1.107:7000;transport=UDP SIP/2.0 Via: SIP/2.0/UDP 192.168.1.116:5070;rport;branch=z9hG4bKgQZBU0NtQeaSQ Max-Forwards: 70 From: "10111" <sip:FREESWITCHMediaGateway@openser ;transport=udp>;tag=3cZNea7Be27cB To: <sip:10111@192.168.1.122:5060>;tag=117 Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28 CSeq: 110076880 BYE Contact: <sip:FREESWITCHMediaGateway@192.168.1.116:5070;transport=udp> User-Agent: FREESWITCH Media Gateway Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, PRACK, MESSAGE, SUBSCRIBE, NOTIFY, REFER, UPDATE, REGISTER, INFO, PUBLISH Supported: timer, precondition, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------