2008-04-08 20:19:50 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [407][Proxy Authentication Required] session: n/a 2008-04-08 20:19:50 [NOTICE] switch_channel.c:531 switch_channel_set_name() New Channel sofia/default/0002*23@192.168.1.128:5065 [0821700d-67c1-46dc-8d9e-8e2b77f8d9a0] 2008-04-08 20:19:50 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [received] 2008-04-08 20:19:50 [DEBUG] sofia.c:1599 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 3416667593 3416667593 IN IP4 192.168.1.101 s=SJphone c=IN IP4 192.168.1.101 t=0 0 m=audio 49152 RTP/AVP 8 101 c=IN IP4 192.168.1.101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=setup:active 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[G722:9:8000] 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA:8:8000] 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:1333 sofia_glue_tech_set_codec() Set Codec sofia/default/0002*23@192.168.1.128:5065 PCMA/8000 20 ms 160 samples 2008-04-08 20:19:50 [DEBUG] sofia_glue.c:1975 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-04-08 20:19:50 [DEBUG] sofia.c:1736 sofia_handle_sip_i_state() sofia/default/0002*23@192.168.1.128:5065 State Change CS_NEW -> CS_INIT 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_INIT 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State INIT 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/default/0002*23@192.168.1.128:5065 SOFIA INIT 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/default/0002*23@192.168.1.128:5065 State Change CS_INIT -> CS_RING 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State INIT going to sleep 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_RING 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23@192.168.1.128:5065 SOFIA RING 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:50 [INFO] mod_dialplan_xml.c:223 dialplan_hunt() Processing unknown->23@default 2008-04-08 20:19:50 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(23) =~ /^.*$/ 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:96 switch_core_standard_on_ring() sofia/default/0002*23@192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING going to sleep 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_EXECUTE 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23@192.168.1.128:5065 SOFIA EXECUTE 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(forward_counter=1) 2008-04-08 20:19:50 [DEBUG] mod_dptools.c:493 set_function() SET [forward_counter]=[1] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(forward_counter=1) 2008-04-08 20:19:50 [DEBUG] mod_dptools.c:626 export_function() EXPORT [forward_counter]=[1] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute respond(181 Call is being forwarded) 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:990 sofia_receive_message() Responding with 181 Call is being forwarded 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(sip_h_Diversion=;reason=uncoditional;counter=1) 2008-04-08 20:19:50 [DEBUG] mod_dptools.c:626 export_function() EXPORT [sip_h_Diversion]=[;reason=uncoditional;counter=1] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute transfer(24) 2008-04-08 20:19:50 [DEBUG] switch_ivr.c:1007 switch_ivr_session_transfer() sofia/default/0002*23@192.168.1.128:5065 State Change CS_EXECUTE -> CS_RING 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:50 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:50 [NOTICE] switch_ivr.c:1013 switch_ivr_session_transfer() Transfer sofia/default/0002*23@192.168.1.128:5065 to XML[24@default] 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE going to sleep 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_RING 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING 2008-04-08 20:19:50 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23@192.168.1.128:5065 SOFIA RING 2008-04-08 20:19:50 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:50 [INFO] mod_dialplan_xml.c:223 dialplan_hunt() Processing unknown->24@default 2008-04-08 20:19:50 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [181][Call is being forwarded] session: sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:51 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(24) =~ /^.*$/ 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:96 switch_core_standard_on_ring() sofia/default/0002*23@192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING going to sleep 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23@192.168.1.128:5065 SOFIA EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(forward_counter=2) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [forward_counter]=[2] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(forward_counter=2) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function() EXPORT [forward_counter]=[2] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute respond(181 Call is being forwarded) 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:990 sofia_receive_message() Responding with 181 Call is being forwarded 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(sip_h_Diversion=;reason=uncoditional;counter=2) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function() EXPORT [sip_h_Diversion]=[;reason=uncoditional;counter=2] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute transfer(22) 2008-04-08 20:19:51 [DEBUG] switch_ivr.c:1007 switch_ivr_session_transfer() sofia/default/0002*23@192.168.1.128:5065 State Change CS_EXECUTE -> CS_RING 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [NOTICE] switch_ivr.c:1013 switch_ivr_session_transfer() Transfer sofia/default/0002*23@192.168.1.128:5065 to XML[22@default] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE going to sleep 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_RING 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [early] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23@192.168.1.128:5065 SOFIA RING 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:51 [INFO] mod_dialplan_xml.c:223 dialplan_hunt() Processing unknown->22@default 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [181][Call is being forwarded] session: sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:51 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(22) =~ /^.*$/ 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:96 switch_core_standard_on_ring() sofia/default/0002*23@192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING going to sleep 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23@192.168.1.128:5065 SOFIA EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(forward_counter=3) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [forward_counter]=[3] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(forward_counter=3) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function() EXPORT [forward_counter]=[3] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute respond(181 Call is being forwarded) 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [early] 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:990 sofia_receive_message() Responding with 181 Call is being forwarded 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(sip_h_Diversion=;reason=uncoditional;counter=3) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function() EXPORT [sip_h_Diversion]=[;reason=uncoditional;counter=3] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute transfer(21) 2008-04-08 20:19:51 [DEBUG] switch_ivr.c:1007 switch_ivr_session_transfer() sofia/default/0002*23@192.168.1.128:5065 State Change CS_EXECUTE -> CS_RING 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [NOTICE] switch_ivr.c:1013 switch_ivr_session_transfer() Transfer sofia/default/0002*23@192.168.1.128:5065 to XML[21@default] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE going to sleep 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_RING 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*23@192.168.1.128:5065 SOFIA RING 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:51 [INFO] mod_dialplan_xml.c:223 dialplan_hunt() Processing unknown->21@default 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [181][Call is being forwarded] session: sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:51 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(21) =~ /^.*$/ 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:96 switch_core_standard_on_ring() sofia/default/0002*23@192.168.1.128:5065 State Change CS_RING -> CS_EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State RING going to sleep 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/0002*23@192.168.1.128:5065 SOFIA EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(dialed_ext=21) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [dialed_ext]=[21] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(dialed_ext=21) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function() EXPORT [dialed_ext]=[21] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute export(dst_user=0002*21) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:626 export_function() EXPORT [dst_user]=[0002*21] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(call_timeout=10) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [call_timeout]=[10] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(sip_exclude_contact=${network_addr}) 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [early] 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:984 switch_core_session_execute_application() sofia/default/0002*23@192.168.1.128:5065 Expanded String set(sip_exclude_contact=192.168.1.101) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [sip_exclude_contact]=[192.168.1.101] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(hangup_after_bridge=true) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [hangup_after_bridge]=[true] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute set(continue_on_fail=true) 2008-04-08 20:19:51 [DEBUG] mod_dptools.c:493 set_function() SET [continue_on_fail]=[true] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:139 switch_core_standard_on_execute() sofia/default/0002*23@192.168.1.128:5065 Execute bridge(sofia/default/${dst_user}%192.168.1.128) 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:984 switch_core_session_execute_application() sofia/default/0002*23@192.168.1.128:5065 Expanded String bridge(sofia/default/0002*21%192.168.1.128) 2008-04-08 20:19:51 [NOTICE] switch_channel.c:531 switch_channel_set_name() New Channel sofia/default/0002*21 [0ded99a5-5044-48d2-96ab-66f43af1a03c] 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:1829 sofia_outgoing_channel() sofia/default/0002*21 State Change CS_NEW -> CS_INIT 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*21 Running State Change CS_INIT 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/0002*21) State INIT 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:80 sofia_on_init() sofia/default/0002*21 SOFIA INIT 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [0][INVITE sent] session: sofia/default/0002*21 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:107 sofia_on_init() sofia/default/0002*21 State Change CS_INIT -> CS_RING 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/0002*21) State INIT going to sleep 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*21 entering state [calling] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*21 Running State Change CS_RING 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*21) State RING 2008-04-08 20:19:51 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/0002*21 SOFIA RING 2008-04-08 20:19:51 [DEBUG] switch_ivr_originate.c:55 originate_on_ring() sofia/default/0002*21 State Change CS_RING -> CS_HOLD 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:418 switch_core_session_run() (sofia/default/0002*21) State RING going to sleep 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*21 Running State Change CS_HOLD 2008-04-08 20:19:51 [DEBUG] switch_core_state_machine.c:440 switch_core_session_run() (sofia/default/0002*21) State HOLD 2008-04-08 20:19:51 [DEBUG] switch_ivr_originate.c:951 switch_ivr_originate() Raw Codec Activation Success L16@8000hz 1 channel 20ms 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_r_invite] status [180][Ringing] session: sofia/default/0002*21 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [180][Ringing] session: sofia/default/0002*21 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*21 entering state [proceeding] 2008-04-08 20:19:51 [NOTICE] sofia.c:1633 sofia_handle_sip_i_state() Ring-Ready sofia/default/0002*21! 2008-04-08 20:19:51 [NOTICE] mod_sofia.c:1017 sofia_receive_message() Ring-Ready sofia/default/0002*23@192.168.1.128:5065! 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [NOTICE] switch_ivr_originate.c:1026 switch_ivr_originate() Ring Ready sofia/default/0002*23@192.168.1.128:5065! 2008-04-08 20:19:51 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:51 [DEBUG] sofia.c:219 sofia_event_callback() event [nua_i_state] status [180][Ringing] session: sofia/default/0002*23@192.168.1.128:5065 2008-04-08 20:19:51 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [early] 2008-04-08 20:19:53 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*21 entering state [ready] 2008-04-08 20:19:53 [DEBUG] sofia.c:1599 sofia_handle_sip_i_state() Remote SDP: v=0 o=- 18939677 18939677 IN IP4 192.168.1.151 s=- c=IN IP4 192.168.1.151 t=0 0 m=audio 16424 RTP/AVP 8 100 101 a=rtpmap:8 PCMA/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:2011 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMA:8:8000]/[PCMA:8:8000] 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1333 sofia_glue_tech_set_codec() Set Codec sofia/default/0002*21 PCMA/8000 20 ms 160 samples 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1975 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1523 sofia_glue_activate_rtp() AUDIO RTP [sofia/default/0002*21] 192.168.1.128:26702->192.168.1.151:16424 codec: 8 ms: 20 2008-04-08 20:19:53 [DEBUG] switch_rtp.c:716 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2008-04-08 20:19:53 [DEBUG] switch_channel.c:1506 switch_channel_perform_mark_answered() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:53 [NOTICE] sofia.c:1945 sofia_handle_sip_i_state() Channel [sofia/default/0002*21] has been answered 2008-04-08 20:19:53 [DEBUG] sofia_glue.c:1523 sofia_glue_activate_rtp() AUDIO RTP [sofia/default/0002*23@192.168.1.128:5065] 192.168.1.128:22042->192.168.1.101:49152 codec: 8 ms: 20 2008-04-08 20:19:53 [DEBUG] switch_rtp.c:716 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms 2008-04-08 20:19:53 [DEBUG] mod_sofia.c:376 sofia_answer_channel() Local SDP sofia/default/0002*23@192.168.1.128:5065: v=0 o=FreeSWITCH 1207656751 1207656752 IN IP4 192.168.1.128 s=FreeSWITCH c=IN IP4 192.168.1.128 t=0 0 a=sendrecv m=audio 22042 RTP/AVP 8 101 13 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=rtpmap:13 CN/8000 a=ptime:20 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:53 [NOTICE] switch_ivr_originate.c:1171 switch_ivr_originate() Channel [sofia/default/0002*23@192.168.1.128:5065] has been answered 2008-04-08 20:19:53 [DEBUG] switch_ivr_originate.c:1205 switch_ivr_originate() Originate Resulted in Success: [sofia/default/0002*21] 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:19:53 [DEBUG] switch_ivr_bridge.c:756 switch_ivr_multi_threaded_bridge() sofia/default/0002*21 State Change CS_HOLD -> CS_LOOPBACK 2008-04-08 20:19:53 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:19:53 [DEBUG] switch_core_state_machine.c:440 switch_core_session_run() (sofia/default/0002*21) State HOLD going to sleep 2008-04-08 20:19:53 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*21 Running State Change CS_LOOPBACK 2008-04-08 20:19:53 [DEBUG] switch_core_state_machine.c:431 switch_core_session_run() (sofia/default/0002*21) State LOOPBACK 2008-04-08 20:19:53 [DEBUG] mod_sofia.c:314 sofia_on_loopback() SOFIA LOOPBACK 2008-04-08 20:19:53 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [completed] 2008-04-08 20:19:53 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*23@192.168.1.128:5065 entering state [ready] 2008-04-08 20:20:08 [DEBUG] sofia.c:1595 sofia_handle_sip_i_state() Channel sofia/default/0002*21 entering state [terminated] 2008-04-08 20:20:08 [NOTICE] sofia.c:1992 sofia_handle_sip_i_state() Hangup sofia/default/0002*21 [CS_LOOPBACK] [NORMAL_CLEARING] 2008-04-08 20:20:08 [DEBUG] switch_channel.c:1355 switch_channel_perform_hangup() Kill sofia/default/0002*21 [KILL] 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:275 audio_bridge_thread() read: sofia/default/0002*21 Bad Frame.... Bubye! 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:344 audio_bridge_thread() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:347 audio_bridge_thread() BRIDGE THREAD DONE [sofia/default/0002*21] 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:431 switch_core_session_run() (sofia/default/0002*21) State LOOPBACK going to sleep 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*21 Running State Change CS_HANGUP 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392 switch_core_session_run() (sofia/default/0002*21) State HANGUP 2008-04-08 20:20:08 [DEBUG] mod_sofia.c:255 sofia_on_hangup() Channel sofia/default/0002*21 hanging up, cause: NORMAL_CLEARING 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() Standard HANGUP sofia/default/0002*21, cause: NORMAL_CLEARING 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392 switch_core_session_run() (sofia/default/0002*21) State HANGUP going to sleep 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:730 switch_core_session_thread() Session 2 (sofia/default/0002*21) Locked, Waiting on external entities 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:383 switch_core_session_receive_message() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:344 audio_bridge_thread() Kill sofia/default/0002*21 [BREAK] 2008-04-08 20:20:08 [DEBUG] switch_ivr_bridge.c:347 audio_bridge_thread() BRIDGE THREAD DONE [sofia/default/0002*23@192.168.1.128:5065] 2008-04-08 20:20:08 [NOTICE] switch_ivr_bridge.c:802 switch_ivr_multi_threaded_bridge() Hangup sofia/default/0002*23@192.168.1.128:5065 [CS_EXECUTE] [NORMAL_CLEARING] 2008-04-08 20:20:08 [DEBUG] switch_channel.c:1355 switch_channel_perform_hangup() Kill sofia/default/0002*23@192.168.1.128:5065 [KILL] 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:670 switch_core_session_signal_state_change() Kill sofia/default/0002*23@192.168.1.128:5065 [BREAK] 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:428 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State EXECUTE going to sleep 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:364 switch_core_session_run() sofia/default/0002*23@192.168.1.128:5065 Running State Change CS_HANGUP 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State HANGUP 2008-04-08 20:20:08 [DEBUG] mod_sofia.c:255 sofia_on_hangup() Channel sofia/default/0002*23@192.168.1.128:5065 hanging up, cause: NORMAL_CLEARING 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:748 switch_core_session_thread() Session 2 (sofia/default/0002*21) Ended 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:750 switch_core_session_thread() Close Channel sofia/default/0002*21 [CS_HANGUP] 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() Standard HANGUP sofia/default/0002*23@192.168.1.128:5065, cause: NORMAL_CLEARING 2008-04-08 20:20:08 [DEBUG] switch_core_state_machine.c:392 switch_core_session_run() (sofia/default/0002*23@192.168.1.128:5065) State HANGUP going to sleep 2008-04-08 20:20:08 [DEBUG] switch_core_session.c:730 switch_core_session_thread() Session 1 (sofia/default/0002*23@192.168.1.128:5065) Locked, Waiting on external entities 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:748 switch_core_session_thread() Session 1 (sofia/default/0002*23@192.168.1.128:5065) Ended 2008-04-08 20:20:08 [NOTICE] switch_core_session.c:750 switch_core_session_thread() Close Channel sofia/default/0002*23@192.168.1.128:5065 [CS_HANGUP]