[Freeswitch-users] strange 503 error thrown by freeswitch
Juan Backson
juanbackson at gmail.com
Mon Jan 19 03:06:17 PST 2009
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 at 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 at 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 at 192.168.1.122:7001>;tag=112
To: 0010111 <sip:0010111 at 192.168.1.122 <sip%3A0010111 at 192.168.1.122>>
Call-ID: 112-26869 at 192.168.1.103
CSeq: 2 INVITE
Contact: <sip:10111 at 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 at 192.168.1.122:7001>;tag=112
To: 0010111 <sip:0010111 at 192.168.1.122 <sip%3A0010111 at 192.168.1.122>>
Call-ID: 112-26869 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.122:7001) State
INIT
2009-01-19 13:40:30 [DEBUG] mod_sofia.c:83 sofia_on_init() sofia/internal/
10111 at 192.168.1.122:7001 SOFIA INIT
2009-01-19 13:40:30 [DEBUG] mod_sofia.c:111 sofia_on_init() (sofia/internal/
10111 at 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 at 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 at 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 at 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 at 192.168.1.122:7001) State
ROUTING
2009-01-19 13:40:30 [DEBUG] mod_sofia.c:130 sofia_on_routing()
sofia/internal/10111 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.122:7001) State
EXECUTE
2009-01-19 13:40:31 [DEBUG] mod_sofia.c:173 sofia_on_execute()
sofia/internal/10111 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.122:7001Execute set(language=zh)
2009-01-19 13:40:31 [DEBUG] mod_dptools.c:681 set_function() sofia/internal/
10111 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 192.168.1.122:5060>
Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28
CSeq: 110076879 INVITE
Contact: <sip:FREESWITCHMediaGateway at 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 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 192.168.1.122:5060>;tag=117
Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28
CSeq: 110076879 ACK
Contact: <sip:FREESWITCHMediaGateway at 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 at 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 at 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 at 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 at 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 at 192.168.1.122:7001!
2009-01-19 13:40:31 [NOTICE] mod_sofia.c:1316 sofia_receive_message()
Pre-Answer sofia/internal/10111 at 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 at 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 at 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 at 192.168.1.122:7001>;tag=112
To: 0010111 <sip:0010111 at 192.168.1.122 <sip%3A0010111 at 192.168.1.122>
>;tag=235vcFp8gSHtF
Call-ID: 112-26869 at 192.168.1.103
CSeq: 2 INVITE
Contact: <sip:mod_sofia at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.122:7001 [BREAK]
send 658 bytes to udp/[192.168.1.122]:5060 at 18:40:31.154213:
------------------------------------------------------------------------
BYE sip:10111 at 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 at 192.168.1.122 <sip%3A0010111 at 192.168.1.122>
>;tag=235vcFp8gSHtF
To: 10111 <sip:10111 at 192.168.1.122:7001>;tag=112
Call-ID: 112-26869 at 192.168.1.103
CSeq: 110076879 BYE
Contact: <sip:mod_sofia at 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 at 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 at 192.168.1.122:7001>;tag=112
To: 0010111 <sip:0010111 at 192.168.1.122 <sip%3A0010111 at 192.168.1.122>
>;tag=235vcFp8gSHtF
Call-ID: 112-26869 at 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 at 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 at 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 at 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 at 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 at 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 at 192.168.1.122 <sip%3A0010111 at 192.168.1.122>
>;tag=235vcFp8gSHtF
To: 10111 <sip:10111 at 192.168.1.122:7001>;tag=112
Call-ID: 112-26869 at 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 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 192.168.1.122:5060>;tag=117
Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28
CSeq: 110076880 BYE
Contact: <sip:FREESWITCHMediaGateway at 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 at 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 at 192.168.1.122:7001>;tag=112
Call-ID: 112-26869 at 192.168.1.103
To: 0010111 <sip:0010111 at 192.168.1.122 <sip%3A0010111 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at 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 at openser
;transport=udp>;tag=3cZNea7Be27cB
To: <sip:10111 at 192.168.1.122:5060>;tag=117
Call-ID: 7d85cf3d-60fb-122c-f480-001517871e28
CSeq: 110076880 BYE
Contact: <sip:FREESWITCHMediaGateway at 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
------------------------------------------------------------------------
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.freeswitch.org/pipermail/freeswitch-users/attachments/20090119/874124a7/attachment-0002.html
More information about the FreeSWITCH-users
mailing list