2008-03-07 09:41:33 [DEBUG] sofia_reg.c:484 sofia_reg_handle_register() send challange for [107@192.168.1.95]
2008-03-07 09:41:35 [DEBUG] sofia.c:221 sofia_event_callback() event [nua_i_state] status [407][Proxy Authentication Required] session: n/a
2008-03-07 09:41:35 [NOTICE] switch_channel.c:531 switch_channel_set_name() New Channel sofia/default/1001@192.168.1.95:5060 [b5538b99-13c1-4bb2-b866-4be6888a94d1]
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1001@192.168.1.95:5060 Running State Change CS_NEW
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State NEW
2008-03-07 09:41:35 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [received]
2008-03-07 09:41:35 [DEBUG] sofia.c:1477 sofia_handle_sip_i_state() Remote SDP:
v=0
o=1001 123456 654321 IN IP4 192.168.1.100
s=A conversation
c=IN IP4 192.168.1.100
t=0 0
m=audio 7078 RTP/AVP 111 110 0 8 101
a=rtpmap:111 speex/16000/1
a=rtpmap:110 speex/8000/1
a=rtpmap:0 PCMU/8000/1
a=rtpmap:8 PCMA/8000/1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-11
m=video 9078 RTP/AVP 97 98 99 100
a=rtpmap:97 theora/90000
a=rtpmap:98 H263-1998/90000
a=fmtp:98 CIF=1;QCIF=1
a=rtpmap:99 MP4V-ES/90000
a=rtpmap:100 x-snow/90000

2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:111:16000]/[G722:9:8000]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:111:16000]/[PCMU:0:8000]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:110:8000]/[G722:9:8000]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:110:8000]/[PCMU:0:8000]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[G722:9:8000]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1298 sofia_glue_tech_set_codec() Set Codec sofia/default/1001@192.168.1.95:5060 PCMU/8000 20 ms 160 samples
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1924 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:2074 sofia_glue_negotiate_sdp() Video Codec Compare [theora:97]/[H263-1998:115]
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:2074 sofia_glue_negotiate_sdp() Video Codec Compare [H263-1998:98]/[H263-1998:115]
2008-03-07 09:41:35 [DEBUG] sofia.c:1614 sofia_handle_sip_i_state() sofia/default/1001@192.168.1.95:5060 State Change CS_NEW -> CS_INIT
2008-03-07 09:41:35 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1001@192.168.1.95:5060 Running State Change CS_INIT
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:442 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State INIT
2008-03-07 09:41:35 [DEBUG] mod_sofia.c:82 sofia_on_init() sofia/default/1001@192.168.1.95:5060 SOFIA INIT
2008-03-07 09:41:35 [DEBUG] mod_sofia.c:108 sofia_on_init() sofia/default/1001@192.168.1.95:5060 State Change CS_INIT -> CS_RING
2008-03-07 09:41:35 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1001@192.168.1.95:5060 Running State Change CS_RING
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:447 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State RING
2008-03-07 09:41:35 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/1001@192.168.1.95:5060 SOFIA RING
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/default/1001@192.168.1.95:5060
2008-03-07 09:41:35 [INFO] mod_dialplan_xml.c:222 dialplan_hunt() Processing 1001->3000@default
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${unroll_loops}(true) =~ /^true$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${sip_looped_call}() =~ /^true$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${strftime(%H%M)}(0941) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^886$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^\*\*(\d+)$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^870$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${network_addr}(192.168.1.100) =~ /^$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${numbering_plan}() =~ /^$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${call_debug}(false) =~ /^true$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${sip_has_crypto}() =~ /^(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^88(.*)$|^\*0(.*)$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^\*69$|^869$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^80(\d{2})$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^81(\d{2})$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^82(\d{2})$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^83(\d{2})$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^8(10[01][0-9])$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^(10[01][0-9])$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^sip:(.*)$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^(30\d{2})$/
2008-03-07 09:41:35 [DEBUG] mod_dialplan_xml.c:278 dialplan_hunt() sofia/default/1001@192.168.1.95:5060 State Change CS_RING -> CS_EXECUTE
2008-03-07 09:41:35 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1001@192.168.1.95:5060 Running State Change CS_EXECUTE
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:457 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State EXECUTE
2008-03-07 09:41:35 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/1001@192.168.1.95:5060 SOFIA EXECUTE
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute set(open=true)
2008-03-07 09:41:35 [DEBUG] mod_dptools.c:417 set_function() SET [open]=[true]
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute set(use_profile=${cond(${is_lan_addr(${network_addr})} == yes ? nat : default)})
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Expanded String set(use_profile=nat)
2008-03-07 09:41:35 [DEBUG] mod_dptools.c:417 set_function() SET [use_profile]=[nat]
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute set_user(default@${domain})
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Expanded String set_user(default@192.168.1.95)
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute db(insert/spymap/${caller_id_number}/${uuid})
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Expanded String db(insert/spymap/1001/b5538b99-13c1-4bb2-b866-4be6888a94d1)
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute db(insert/last_dial/${caller_id_number}/${destination_number})
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Expanded String db(insert/last_dial/1001/3000)
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute db(insert/last_dial/global/${uuid})
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Expanded String db(insert/last_dial/global/b5538b99-13c1-4bb2-b866-4be6888a94d1)
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1001@192.168.1.95:5060 Execute conference(3000@default)
2008-03-07 09:41:35 [DEBUG] switch_core_state_machine.c:162 switch_core_standard_on_execute() Application conference Requires media! pre_answering channel sofia/default/1001@192.168.1.95:5060
2008-03-07 09:41:35 [INFO] mod_sofia.c:1002 sofia_receive_message() Asked to send early media by sofia/default/1001@192.168.1.95:5060
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1224 sofia_glue_tech_set_video_codec() Set VIDEO Codec sofia/default/1001@192.168.1.95:5060 H263-1998/90000 0 ms
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1481 sofia_glue_activate_rtp() AUDIO RTP [sofia/default/1001@192.168.1.95:5060] 192.168.1.95:22112->192.168.1.100:7078 codec: 0 ms: 20
2008-03-07 09:41:35 [DEBUG] switch_rtp.c:715 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms
2008-03-07 09:41:35 [DEBUG] switch_rtp.c:715 switch_rtp_create() Starting timer [soft] 1 bytes per 10000ms
2008-03-07 09:41:35 [DEBUG] sofia_glue.c:1642 sofia_glue_activate_rtp() VIDEO RTP [sofia/default/1001@192.168.1.95:5060] 192.168.1.95:25412->192.168.1.100:9078 codec: 98 ms: 0 [SUCCESS]
2008-03-07 09:41:35 [INFO] mod_sofia.c:1044 sofia_receive_message() Ring SDP:
v=0
o=FreeSWITCH 1204878783 1204878784 IN IP4 192.168.1.95
s=FreeSWITCH
c=IN IP4 192.168.1.95
t=0 0
a=sendrecv
m=audio 22112 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
m=video 25412 RTP/AVP 98
a=rtpmap:98 H263-1998/90000

2008-03-07 09:41:35 [NOTICE] switch_channel.c:1383 switch_channel_perform_mark_pre_answered() Ring-Ready sofia/default/1001@192.168.1.95:5060!
2008-03-07 09:41:35 [NOTICE] mod_sofia.c:1047 sofia_receive_message() Pre-Answer sofia/default/1001@192.168.1.95:5060!
2008-03-07 09:41:35 [DEBUG] sofia.c:221 sofia_event_callback() event [nua_i_state] status [183][Session Progress] session: sofia/default/1001@192.168.1.95:5060
2008-03-07 09:41:35 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:35 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [early]
2008-03-07 09:41:35 [DEBUG] mod_conference.c:4255 conference_function() Raw Codec Activation Success L16@8000hz 1 channel 20ms
2008-03-07 09:41:35 [DEBUG] mod_conference.c:4302 conference_function() Raw Codec Activation Success L16@8000hz 1 channel 20ms
2008-03-07 09:41:35 [DEBUG] mod_sndfile.c:170 sndfile_file_open() Opening File [/usr/local/freeswitch/sounds/en/us/callie/conference/8000/conf-alone.wav] rate 8000hz
2008-03-07 09:41:35 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:35 [DEBUG] mod_conference.c:1666 conference_loop_output() setup timer soft success interval: 20  samples: 160
2008-03-07 09:41:35 [DEBUG] mod_conference.c:1755 conference_loop_output() CLFAG_ANSWERED set, answering inbound channel
2008-03-07 09:41:35 [DEBUG] mod_sofia.c:380 sofia_answer_channel() Local SDP sofia/default/1001@192.168.1.95:5060:
v=0
o=FreeSWITCH 1204878783 1204878785 IN IP4 192.168.1.95
s=FreeSWITCH
c=IN IP4 192.168.1.95
t=0 0
a=sendrecv
m=audio 22112 RTP/AVP 0 101 13
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=rtpmap:13 CN/8000
a=ptime:20
m=video 25412 RTP/AVP 98
a=rtpmap:98 H263-1998/90000

2008-03-07 09:41:35 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:35 [NOTICE] mod_conference.c:1756 conference_loop_output() Channel [sofia/default/1001@192.168.1.95:5060] has been answered
2008-03-07 09:41:35 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [completed]
2008-03-07 09:41:35 [DEBUG] switch_core_io.c:325 switch_core_session_read_frame() Engaging Read Buffer at 320 bytes
2008-03-07 09:41:37 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [ready]
2008-03-07 09:41:40 [WARNING] sofia_reg.c:894 sofia_reg_parse_auth() can't find user [101@192.168.1.95]
2008-03-07 09:41:40 [DEBUG] sofia_reg.c:484 sofia_reg_handle_register() send challange for [101@192.168.1.95]
2008-03-07 09:41:41 [WARNING] sofia_reg.c:894 sofia_reg_parse_auth() can't find user [104@192.168.1.95]
2008-03-07 09:41:41 [DEBUG] sofia_reg.c:484 sofia_reg_handle_register() send challange for [104@192.168.1.95]
2008-03-07 09:41:41 [WARNING] sofia_reg.c:894 sofia_reg_parse_auth() can't find user [105@192.168.1.95]
2008-03-07 09:41:41 [DEBUG] sofia_reg.c:484 sofia_reg_handle_register() send challange for [105@192.168.1.95]
2008-03-07 09:41:48 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [terminated]
2008-03-07 09:41:48 [NOTICE] sofia.c:1854 sofia_handle_sip_i_state() Hangup sofia/default/1001@192.168.1.95:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2008-03-07 09:41:48 [DEBUG] switch_channel.c:1358 switch_channel_perform_hangup() Kill sofia/default/1001@192.168.1.95:5060 [KILL]
2008-03-07 09:41:48 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 09:41:48 [DEBUG] mod_conference.c:1933 conference_loop_output() Channel leaving conference, cause: NORMAL_CLEARING
2008-03-07 09:41:48 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1001@192.168.1.95:5060 Running State Change CS_HANGUP
2008-03-07 09:41:48 [DEBUG] switch_core_state_machine.c:436 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State HANGUP
2008-03-07 09:41:48 [DEBUG] mod_sofia.c:258 sofia_on_hangup() Channel sofia/default/1001@192.168.1.95:5060 hanging up, cause: NORMAL_CLEARING
2008-03-07 09:41:48 [DEBUG] switch_core_state_machine.c:46 switch_core_standard_on_hangup() Standard HANGUP sofia/default/1001@192.168.1.95:5060, cause: NORMAL_CLEARING
2008-03-07 09:41:48 [DEBUG] switch_core_session.c:715 switch_core_session_thread() Session 23 (sofia/default/1001@192.168.1.95:5060) Locked, Waiting on external entities
2008-03-07 09:41:48 [NOTICE] switch_core_session.c:732 switch_core_session_thread() Session 23 (sofia/default/1001@192.168.1.95:5060) Ended
2008-03-07 09:41:48 [NOTICE] switch_core_session.c:734 switch_core_session_thread() Close Channel sofia/default/1001@192.168.1.95:5060 [CS_HANGUP]
2008-03-07 09:41:49 [WARNING] sofia_reg.c:894 sofia_reg_parse_auth() can't find user [107@192.168.1.95]