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>
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>
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:7001 Standard 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:7001 Standard 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 Execute 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:7001 receive 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>;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:7001 receive 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:7001 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@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>;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>;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>;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>;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:7001 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@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
------------------------------------------------------------------------