freeswitch@localhost.localdomain> tport_wakeup_pri(0x95c2aa0): events IN tport_recv_event(0x95c2aa0) tport_recv_iovec(0x95c2aa0) msg 0xb066da88 from (udp/192.168.1.105:5060) has 886 bytes, veclen = 1 tport_deliver(0x95c2aa0): msg 0xb066da88 (886 bytes) from udp/192.168.1.220:5060/sip next=(nil) nta: received INVITE sip:300@192.168.1.105 SIP/2.0 (CSeq 101) nta: canonizing sip:300@192.168.1.105 with contact nta: INVITE (101) going to a default leg nta: timer set to 200 ms nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x95bebc8, 0x95bda20, 0xb06664a8) called soa_set_params(static::0xb0666790, ...) called nta_leg_tcreate(0xb0666ad8) soa_init_offer_answer(static::0xb0666790) called soa_set_remote_sdp(static::0xb0666790, (nil), 0xb0665749, 397) called nua(0xb06664a8): adding session usage tport_tsend(0x95c2aa0) tpn = UDP/192.168.1.220:5061 tport_resolve addrinfo = 192.168.1.220:5061 tport_by_addrinfo(0x95c2aa0): not found by name UDP/192.168.1.220:5061 tport_vsend returned 293 nta: sent 100 Trying for INVITE (101) nua(0xb06664a8): call state changed: init -> received, received offer soa_get_remote_sdp(static::0xb0666790, [0xb1128ba0], [0xb1128b9c], [(nil)]) called nua: nua_application_event: entering nua: nua_respond: entering nua(0xb06664a8): signal r_respond nua: nua_application_event: entering nua: nua_stack_set_params: entering soa_set_params(static::0xb0666790, ...) called nua: nua_invite_server_respond: entering soa_clear_remote_sdp(static::0xb0666790) called tport_tsend(0x95c2aa0) tpn = UDP/192.168.1.220:5061 tport_resolve addrinfo = 192.168.1.220:5061 tport_by_addrinfo(0x95c2aa0): not found by name UDP/192.168.1.220:5061 tport_vsend returned 639 nta: sent 407 Proxy Authentication Required for INVITE (101) nua(0xb06664a8): removing session usage nua(0xb06664a8): call state changed: received -> terminated soa_destroy(static::0xb0666790) called nta_leg_destroy(0xb0666ad8) nua: nua_application_event: entering 2008-03-16 23:40:57 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [407][Proxy Authentication Required] session: n/a nua: nua_handle_bind: entering nua: nua_handle_destroy: entering nua(0xb06664a8): signal r_destroy nua: nua_application_event: entering nta_leg_destroy((nil)) tport_wakeup_pri(0x95c2aa0): events IN tport_recv_event(0x95c2aa0) tport_recv_iovec(0x95c2aa0) msg 0xb06681c0 from (udp/192.168.1.105:5060) has 370 bytes, veclen = 1 tport_deliver(0x95c2aa0): msg 0xb06681c0 (370 bytes) from udp/192.168.1.220:5060/sip next=(nil) nta: received ACK sip:300@192.168.1.105 SIP/2.0 (CSeq 101) nta: ACK (101) is going to INVITE (101) tport_wakeup_pri(0x95c2aa0): events IN tport_recv_event(0x95c2aa0) tport_recv_iovec(0x95c2aa0) msg 0xb06681c0 from (udp/192.168.1.105:5060) has 1122 bytes, veclen = 1 tport_deliver(0x95c2aa0): msg 0xb06681c0 (1122 bytes) from udp/192.168.1.220:5060/sip next=(nil) nta: received INVITE sip:300@192.168.1.105 SIP/2.0 (CSeq 102) nta: canonizing sip:300@192.168.1.105 with contact nta: INVITE (102) going to a default leg nua: nua_stack_process_request: entering nua: nh_create: entering nua: nh_create_handle: entering nua: nua_stack_set_params: entering soa_clone(static::0x95bebc8, 0x95bda20, 0xb06677e0) called soa_set_params(static::0xb0667b00, ...) called nta_leg_tcreate(0xb0667e80) soa_init_offer_answer(static::0xb0667b00) called soa_set_remote_sdp(static::0xb0667b00, (nil), 0xb066689d, 397) called nua(0xb06677e0): adding session usage tport_tsend(0x95c2aa0) tpn = UDP/192.168.1.220:5061 tport_resolve addrinfo = 192.168.1.220:5061 tport_by_addrinfo(0x95c2aa0): not found by name UDP/192.168.1.220:5061 tport_vsend returned 293 nta: sent 100 Trying for INVITE (102) nua(0xb06677e0): call state changed: init -> received, received offer soa_get_remote_sdp(static::0xb0667b00, [0xb1128ba0], [0xb1128b9c], [(nil)]) called nua: nua_application_event: entering 2008-03-16 23:40:57 [NOTICE] switch_channel.c:531 switch_channel_set_name() New Channel sofia/192.168.1.105/500@192.168.1.105:5060 [9e0c3255-aa5e-48ff-b1da-25a791118f1a] nua: nua_handle_bind: entering nua: nua_application_event: entering 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:403 switch_core_session_run() sofia/192.168.1.105/500@192.168.1.105:5060 Running State Change CS_NEW 2008-03-16 23:40:57 [DEBUG] sofia.c:1552 sofia_handle_sip_i_state() Channel sofia/192.168.1.105/500@192.168.1.105:5060 entering state [received] 2008-03-16 23:40:57 [DEBUG] sofia.c:1556 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 376367 376367 IN IP4 192.168.1.220 s=- c=IN IP4 192.168.1.220 t=0 0 m=audio 16386 RTP/AVP 0 2 4 8 18 96 97 98 101 a=rtpmap:0 PCMU/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:4 G723/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729a/8000 a=rtpmap:96 G726-40/8000 a=rtpmap:97 G726-24/8000 a=rtpmap:98 G726-16/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[G722:9:8000] 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000] 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMA:8:8000] 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[GSM:3:8000] 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:2049 sofia_glue_negotiate_sdp() Substituting codec PCMU@30ms 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:1334 sofia_glue_tech_set_codec() Set Codec sofia/192.168.1.105/500@192.168.1.105:5060 PCMU/8000 30 ms 240 samples 2008-03-16 23:40:57 [DEBUG] sofia_glue.c:1975 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-03-16 23:40:57 [DEBUG] sofia.c:1693 sofia_handle_sip_i_state() sofia/192.168.1.105/500@192.168.1.105:5060 State Change CS_NEW -> CS_INIT 2008-03-16 23:40:57 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/192.168.1.105/500@192.168.1.105:5060 [BREAK] 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:407 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State NEW 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:403 switch_core_session_run() sofia/192.168.1.105/500@192.168.1.105:5060 Running State Change CS_INIT 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:452 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State INIT 2008-03-16 23:40:57 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/192.168.1.105/500@192.168.1.105:5060 SOFIA INIT 2008-03-16 23:40:57 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/192.168.1.105/500@192.168.1.105:5060 State Change CS_INIT -> CS_RING 2008-03-16 23:40:57 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/192.168.1.105/500@192.168.1.105:5060 [BREAK] 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:452 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State INIT going to sleep 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:403 switch_core_session_run() sofia/192.168.1.105/500@192.168.1.105:5060 Running State Change CS_RING 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:457 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State RING 2008-03-16 23:40:57 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/192.168.1.105/500@192.168.1.105:5060 SOFIA RING 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/192.168.1.105/500@192.168.1.105:5060 2008-03-16 23:40:57 [INFO] mod_dialplan_xml.c:223 dialplan_hunt() Processing 500->300@home 2008-03-16 23:40:57 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(300) =~ /^([0-9][0-9][0-9])$/ 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:96 switch_core_standard_on_ring() sofia/192.168.1.105/500@192.168.1.105:5060 State Change CS_RING -> CS_EXECUTE 2008-03-16 23:40:57 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/192.168.1.105/500@192.168.1.105:5060 [BREAK] 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:457 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State RING going to sleep 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:403 switch_core_session_run() sofia/192.168.1.105/500@192.168.1.105:5060 Running State Change CS_EXECUTE 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:467 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State EXECUTE 2008-03-16 23:40:57 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/192.168.1.105/500@192.168.1.105:5060 SOFIA EXECUTE 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:129 switch_core_standard_on_execute() Standard EXECUTE 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/192.168.1.105/500@192.168.1.105:5060 Execute set(dest_ext=300) 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/192.168.1.105/500@192.168.1.105:5060 Execute bridge() 2008-03-16 23:40:57 [NOTICE] switch_core_state_machine.c:195 switch_core_standard_on_execute() Hangup sofia/192.168.1.105/500@192.168.1.105:5060 [CS_EXECUTE] [NORMAL_CLEARING] 2008-03-16 23:40:57 [DEBUG] switch_channel.c:1355 switch_channel_perform_hangup() Kill sofia/192.168.1.105/500@192.168.1.105:5060 [KILL] 2008-03-16 23:40:57 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/192.168.1.105/500@192.168.1.105:5060 [BREAK] tport_tsend(0x95c2aa0) tpn = UDP/192.168.1.220:5061 tport_resolve addrinfo = 192.168.1.220:5061 tport_by_addrinfo(0x95c2aa0): not found by name UDP/192.168.1.220:5061 tport_vsend returned 557 nta: sent 480 Temporarily Unavailable for INVITE (102) nua(0xb06677e0): removing session usage nua(0xb06677e0): call state changed: received -> terminated soa_destroy(static::0xb0667b00) called nua: nua_application_event: entering nta_leg_destroy(0xb0667e80) 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:467 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State EXECUTE going to sleep 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:403 switch_core_session_run() sofia/192.168.1.105/500@192.168.1.105:5060 Running State Change CS_HANGUP 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:431 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State HANGUP 2008-03-16 23:40:57 [DEBUG] mod_sofia.c:255 sofia_on_hangup() Channel sofia/192.168.1.105/500@192.168.1.105:5060 hanging up, cause: NORMAL_CLEARING 2008-03-16 23:40:57 [DEBUG] mod_sofia.c:294 sofia_on_hangup() Responding to INVITE with: 480 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() Standard HANGUP sofia/192.168.1.105/500@192.168.1.105:5060, cause: NORMAL_CLEARING 2008-03-16 23:40:57 [DEBUG] switch_core_state_machine.c:431 switch_core_session_run() (sofia/192.168.1.105/500@192.168.1.105:5060) State HANGUP going to sleep 2008-03-16 23:40:57 [DEBUG] switch_core_session.c:730 switch_core_session_thread() Session 21 (sofia/192.168.1.105/500@192.168.1.105:5060) Locked, Waiting on external entities 2008-03-16 23:40:57 [NOTICE] switch_core_session.c:748 switch_core_session_thread() Session 21 (sofia/192.168.1.105/500@192.168.1.105:5060) Ended nua: nua_handle_bind: entering nua: nua_handle_destroy: entering nua(0xb06677e0): signal r_destroy nua: nua_application_event: entering nta_leg_destroy((nil)) 2008-03-16 23:40:57 [NOTICE] switch_core_session.c:750 switch_core_session_thread() Close Channel sofia/192.168.1.105/500@192.168.1.105:5060 [CS_HANGUP] 2008-03-16 23:40:57 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [480][Temporarily Unavailable] session: n/a tport_wakeup_pri(0x95c2aa0): events IN tport_recv_event(0x95c2aa0) tport_recv_iovec(0x95c2aa0) msg 0xb2902ab8 from (udp/192.168.1.105:5060) has 606 bytes, veclen = 1 tport_deliver(0x95c2aa0): msg 0xb2902ab8 (606 bytes) from udp/192.168.1.220:5060/sip next=(nil) nta: received ACK sip:300@192.168.1.105 SIP/2.0 (CSeq 102) nta: ACK (102) is going to INVITE (102) nta: timer set next to 4810 ms nta: timer I fired, terminate 407 response incoming_reclaim_all((nil), (nil), 0xb11291dc) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/2 term, 1/2 free nta: timer set next to 63 ms nta: timer I fired, terminate 480 response incoming_reclaim_all((nil), (nil), 0xb11291dc) nta_incoming_timer: 0/0 resent, 0/0 tout, 1/1 term, 1/1 free nta: timer not set