2008-03-07 10:07:29 [NOTICE] switch_channel.c:531 switch_channel_set_name() New Channel sofia/default/1001@192.168.1.95:5060 [7324559f-e4bb-4c39-8b27-13346dde9a8c]
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State NEW
2008-03-07 10:07:29 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [received]
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:111:16000]/[G722:9:8000]
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:111:16000]/[PCMU:0:8000]
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:110:8000]/[G722:9:8000]
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:110:8000]/[PCMU:0:8000]
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[G722:9:8000]
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000]
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] sofia_glue.c:1924 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:2074 sofia_glue_negotiate_sdp() Video Codec Compare [theora:97]/[H263-1998:115]
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:2074 sofia_glue_negotiate_sdp() Video Codec Compare [H263-1998:98]/[H263-1998:115]
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [DEBUG] switch_core_state_machine.c:442 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State INIT
2008-03-07 10:07:29 [DEBUG] mod_sofia.c:82 sofia_on_init() sofia/default/1001@192.168.1.95:5060 SOFIA INIT
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [DEBUG] switch_core_state_machine.c:447 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State RING
2008-03-07 10:07:29 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/1001@192.168.1.95:5060 SOFIA RING
2008-03-07 10:07:29 [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 10:07:29 [INFO] mod_dialplan_xml.c:222 dialplan_hunt() Processing 1001->3000@default
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${unroll_loops}(true) =~ /^true$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${sip_looped_call}() =~ /^true$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${strftime(%H%M)}(1007) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^886$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^\*\*(\d+)$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^870$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${network_addr}(192.168.1.100) =~ /^$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${numbering_plan}() =~ /^$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${call_debug}(false) =~ /^true$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^88(.*)$|^\*0(.*)$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^\*69$|^869$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^80(\d{2})$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^81(\d{2})$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^82(\d{2})$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^83(\d{2})$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^8(10[01][0-9])$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^(10[01][0-9])$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^sip:(.*)$/
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:29 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^(30\d{2})$/
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [DEBUG] switch_core_state_machine.c:457 switch_core_session_run() (sofia/default/1001@192.168.1.95:5060) State EXECUTE
2008-03-07 10:07:29 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/1001@192.168.1.95:5060 SOFIA EXECUTE
2008-03-07 10:07:29 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] mod_dptools.c:417 set_function() SET [open]=[true]
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [DEBUG] mod_dptools.c:417 set_function() SET [use_profile]=[nat]
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [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/7324559f-e4bb-4c39-8b27-13346dde9a8c)
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [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/7324559f-e4bb-4c39-8b27-13346dde9a8c)
2008-03-07 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [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 10:07:29 [DEBUG] sofia_glue.c:1481 sofia_glue_activate_rtp() AUDIO RTP [sofia/default/1001@192.168.1.95:5060] 192.168.1.95:29282->192.168.1.100:7078 codec: 0 ms: 20
2008-03-07 10:07:29 [DEBUG] switch_rtp.c:715 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms
2008-03-07 10:07:29 [DEBUG] switch_rtp.c:715 switch_rtp_create() Starting timer [soft] 1 bytes per 10000ms
2008-03-07 10:07:29 [DEBUG] sofia_glue.c:1642 sofia_glue_activate_rtp() VIDEO RTP [sofia/default/1001@192.168.1.95:5060] 192.168.1.95:23446->192.168.1.100:9078 codec: 98 ms: 0 [SUCCESS]
2008-03-07 10:07:29 [INFO] mod_sofia.c:1044 sofia_receive_message() Ring SDP:
v=0
o=FreeSWITCH 1204873167 1204873168 IN IP4 192.168.1.95
s=FreeSWITCH
c=IN IP4 192.168.1.95
t=0 0
a=sendrecv
m=audio 29282 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 23446 RTP/AVP 98
a=rtpmap:98 H263-1998/90000

2008-03-07 10:07:29 [NOTICE] switch_channel.c:1383 switch_channel_perform_mark_pre_answered() Ring-Ready sofia/default/1001@192.168.1.95:5060!
2008-03-07 10:07:29 [NOTICE] mod_sofia.c:1047 sofia_receive_message() Pre-Answer sofia/default/1001@192.168.1.95:5060!
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:29 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [early]
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'mute' bound to '0'.
2008-03-07 10:07:29 [DEBUG] switch_ivr.c:1085 switch_ivr_digit_stream_parser_set_event() max len 1
2008-03-07 10:07:29 [DEBUG] switch_ivr.c:1089 switch_ivr_digit_stream_parser_set_event() min len 1
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'deaf mute' bound to '*'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'energy up' bound to '9'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'energy equ' bound to '8'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'energy dn' bound to '7'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'vol talk up' bound to '3'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'vol talk zero' bound to '2'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'vol talk dn' bound to '1'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'vol listen up' bound to '6'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'vol listen zero' bound to '5'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'vol listen dn' bound to '4'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4542 conf_default_controls() Installing default caller control action 'hangup' bound to '#'.
2008-03-07 10:07:29 [DEBUG] mod_conference.c:832 conference_thread_run() setup timer success interval: 20  samples: 160
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4255 conference_function() Raw Codec Activation Success L16@8000hz 1 channel 20ms
2008-03-07 10:07:29 [DEBUG] mod_conference.c:4302 conference_function() Raw Codec Activation Success L16@8000hz 1 channel 20ms
2008-03-07 10:07:29 [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 10:07:29 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:29 [DEBUG] mod_conference.c:1666 conference_loop_output() setup timer soft success interval: 20  samples: 160
2008-03-07 10:07:29 [DEBUG] mod_conference.c:1755 conference_loop_output() CLFAG_ANSWERED set, answering inbound channel
2008-03-07 10:07:29 [DEBUG] mod_sofia.c:380 sofia_answer_channel() Local SDP sofia/default/1001@192.168.1.95:5060:
v=0
o=FreeSWITCH 1204873167 1204873169 IN IP4 192.168.1.95
s=FreeSWITCH
c=IN IP4 192.168.1.95
t=0 0
a=sendrecv
m=audio 29282 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 23446 RTP/AVP 98
a=rtpmap:98 H263-1998/90000

2008-03-07 10:07:29 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1001@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:29 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [completed]
2008-03-07 10:07:29 [NOTICE] mod_conference.c:1756 conference_loop_output() Channel [sofia/default/1001@192.168.1.95:5060] has been answered
2008-03-07 10:07:29 [DEBUG] mod_local_stream.c:281 local_stream_file_open() Opening Stream [moh/8000] 8000hz
2008-03-07 10:07:29 [DEBUG] mod_conference.c:742 conference_video_thread_run() Video thread started for conference 3000
2008-03-07 10:07:29 [DEBUG] switch_core_io.c:325 switch_core_session_read_frame() Engaging Read Buffer at 320 bytes
2008-03-07 10:07:30 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1001@192.168.1.95:5060 entering state [ready]
2008-03-07 10:07:34 [DEBUG] sofia.c:221 sofia_event_callback() event [nua_i_state] status [407][Proxy Authentication Required] session: n/a
2008-03-07 10:07:34 [NOTICE] switch_channel.c:531 switch_channel_set_name() New Channel sofia/default/1000@192.168.1.95:5060 [e52c5ead-ede2-4612-a77d-0c7057ad67a5]
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1000@192.168.1.95:5060 Running State Change CS_NEW
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:413 switch_core_session_run() (sofia/default/1000@192.168.1.95:5060) State NEW
2008-03-07 10:07:34 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1000@192.168.1.95:5060 entering state [received]
2008-03-07 10:07:34 [DEBUG] sofia.c:1477 sofia_handle_sip_i_state() Remote SDP:
v=0
o=1000 123456 654321 IN IP4 192.168.1.99
s=A conversation
c=IN IP4 192.168.1.99
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 10:07:34 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:111:16000]/[G722:9:8000]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:111:16000]/[PCMU:0:8000]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:110:8000]/[G722:9:8000]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [speex:110:8000]/[PCMU:0:8000]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[G722:9:8000]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1960 sofia_glue_negotiate_sdp() Audio Codec Compare [PCMU:0:8000]/[PCMU:0:8000]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1298 sofia_glue_tech_set_codec() Set Codec sofia/default/1000@192.168.1.95:5060 PCMU/8000 20 ms 160 samples
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1924 sofia_glue_negotiate_sdp() Set 2833 dtmf payload to 101
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:2074 sofia_glue_negotiate_sdp() Video Codec Compare [theora:97]/[H263-1998:115]
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:2074 sofia_glue_negotiate_sdp() Video Codec Compare [H263-1998:98]/[H263-1998:115]
2008-03-07 10:07:34 [DEBUG] sofia.c:1614 sofia_handle_sip_i_state() sofia/default/1000@192.168.1.95:5060 State Change CS_NEW -> CS_INIT
2008-03-07 10:07:34 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1000@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1000@192.168.1.95:5060 Running State Change CS_INIT
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:442 switch_core_session_run() (sofia/default/1000@192.168.1.95:5060) State INIT
2008-03-07 10:07:34 [DEBUG] mod_sofia.c:82 sofia_on_init() sofia/default/1000@192.168.1.95:5060 SOFIA INIT
2008-03-07 10:07:34 [DEBUG] mod_sofia.c:108 sofia_on_init() sofia/default/1000@192.168.1.95:5060 State Change CS_INIT -> CS_RING
2008-03-07 10:07:34 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1000@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1000@192.168.1.95:5060 Running State Change CS_RING
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:447 switch_core_session_run() (sofia/default/1000@192.168.1.95:5060) State RING
2008-03-07 10:07:34 [DEBUG] mod_sofia.c:119 sofia_on_ring() sofia/default/1000@192.168.1.95:5060 SOFIA RING
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:65 switch_core_standard_on_ring() Standard RING sofia/default/1000@192.168.1.95:5060
2008-03-07 10:07:34 [INFO] mod_dialplan_xml.c:222 dialplan_hunt() Processing 1000->3000@default
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${unroll_loops}(true) =~ /^true$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${sip_looped_call}() =~ /^true$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${strftime(%H%M)}(1007) =~ /^((09|1[0-7])[0-5][0-9]|1800)$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^886$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^\*\*(\d+)$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^870$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${network_addr}(192.168.1.99) =~ /^$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${numbering_plan}() =~ /^$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions ${call_debug}(false) =~ /^true$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [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 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^88(.*)$|^\*0(.*)$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^\*69$|^869$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^80(\d{2})$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^81(\d{2})$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^82(\d{2})$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^83(\d{2})$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^8(10[01][0-9])$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^(10[01][0-9])$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^sip:(.*)$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:109 parse_exten() Regex mismatch
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:107 parse_exten() test conditions destination_number(3000) =~ /^(30\d{2})$/
2008-03-07 10:07:34 [DEBUG] mod_dialplan_xml.c:278 dialplan_hunt() sofia/default/1000@192.168.1.95:5060 State Change CS_RING -> CS_EXECUTE
2008-03-07 10:07:34 [DEBUG] switch_core_session.c:655 switch_core_session_signal_state_change() Kill sofia/default/1000@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:409 switch_core_session_run() sofia/default/1000@192.168.1.95:5060 Running State Change CS_EXECUTE
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:457 switch_core_session_run() (sofia/default/1000@192.168.1.95:5060) State EXECUTE
2008-03-07 10:07:34 [DEBUG] mod_sofia.c:156 sofia_on_execute() sofia/default/1000@192.168.1.95:5060 SOFIA EXECUTE
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:128 switch_core_standard_on_execute() Standard EXECUTE
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute set(open=true)
2008-03-07 10:07:34 [DEBUG] mod_dptools.c:417 set_function() SET [open]=[true]
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute set(use_profile=${cond(${is_lan_addr(${network_addr})} == yes ? nat : default)})
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Expanded String set(use_profile=nat)
2008-03-07 10:07:34 [DEBUG] mod_dptools.c:417 set_function() SET [use_profile]=[nat]
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute set_user(default@${domain})
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Expanded String set_user(default@192.168.1.95)
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute db(insert/spymap/${caller_id_number}/${uuid})
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Expanded String db(insert/spymap/1000/e52c5ead-ede2-4612-a77d-0c7057ad67a5)
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute db(insert/last_dial/${caller_id_number}/${destination_number})
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Expanded String db(insert/last_dial/1000/3000)
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute db(insert/last_dial/global/${uuid})
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:170 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Expanded String db(insert/last_dial/global/e52c5ead-ede2-4612-a77d-0c7057ad67a5)
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:142 switch_core_standard_on_execute() sofia/default/1000@192.168.1.95:5060 Execute conference(3000@default)
2008-03-07 10:07:34 [DEBUG] switch_core_state_machine.c:162 switch_core_standard_on_execute() Application conference Requires media! pre_answering channel sofia/default/1000@192.168.1.95:5060
2008-03-07 10:07:34 [INFO] mod_sofia.c:1002 sofia_receive_message() Asked to send early media by sofia/default/1000@192.168.1.95:5060
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1224 sofia_glue_tech_set_video_codec() Set VIDEO Codec sofia/default/1000@192.168.1.95:5060 H263-1998/90000 0 ms
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1481 sofia_glue_activate_rtp() AUDIO RTP [sofia/default/1000@192.168.1.95:5060] 192.168.1.95:17640->192.168.1.99:7078 codec: 0 ms: 20
2008-03-07 10:07:34 [DEBUG] switch_rtp.c:715 switch_rtp_create() Starting timer [soft] 160 bytes per 20000ms
2008-03-07 10:07:34 [DEBUG] switch_rtp.c:715 switch_rtp_create() Starting timer [soft] 1 bytes per 10000ms
2008-03-07 10:07:34 [DEBUG] sofia_glue.c:1642 sofia_glue_activate_rtp() VIDEO RTP [sofia/default/1000@192.168.1.95:5060] 192.168.1.95:24508->192.168.1.99:9078 codec: 98 ms: 0 [SUCCESS]
2008-03-07 10:07:34 [INFO] mod_sofia.c:1044 sofia_receive_message() Ring SDP:
v=0
o=FreeSWITCH 1204884814 1204884815 IN IP4 192.168.1.95
s=FreeSWITCH
c=IN IP4 192.168.1.95
t=0 0
a=sendrecv
m=audio 17640 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 24508 RTP/AVP 98
a=rtpmap:98 H263-1998/90000

2008-03-07 10:07:34 [NOTICE] switch_channel.c:1383 switch_channel_perform_mark_pre_answered() Ring-Ready sofia/default/1000@192.168.1.95:5060!
2008-03-07 10:07:34 [NOTICE] mod_sofia.c:1047 sofia_receive_message() Pre-Answer sofia/default/1000@192.168.1.95:5060!
2008-03-07 10:07:34 [DEBUG] sofia.c:221 sofia_event_callback() event [nua_i_state] status [183][Session Progress] session: sofia/default/1000@192.168.1.95:5060
2008-03-07 10:07:34 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1000@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:34 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1000@192.168.1.95:5060 entering state [early]
2008-03-07 10:07:34 [DEBUG] mod_conference.c:4255 conference_function() Raw Codec Activation Success L16@8000hz 1 channel 20ms
2008-03-07 10:07:34 [DEBUG] mod_conference.c:4302 conference_function() Raw Codec Activation Success L16@8000hz 1 channel 20ms
2008-03-07 10:07:34 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1000@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:34 [DEBUG] mod_conference.c:1666 conference_loop_output() setup timer soft success interval: 20  samples: 160
2008-03-07 10:07:34 [DEBUG] mod_conference.c:1755 conference_loop_output() CLFAG_ANSWERED set, answering inbound channel
2008-03-07 10:07:34 [DEBUG] mod_sofia.c:380 sofia_answer_channel() Local SDP sofia/default/1000@192.168.1.95:5060:
v=0
o=FreeSWITCH 1204884814 1204884816 IN IP4 192.168.1.95
s=FreeSWITCH
c=IN IP4 192.168.1.95
t=0 0
a=sendrecv
m=audio 17640 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 24508 RTP/AVP 98
a=rtpmap:98 H263-1998/90000

2008-03-07 10:07:34 [DEBUG] switch_core_session.c:368 switch_core_session_receive_message() Kill sofia/default/1000@192.168.1.95:5060 [BREAK]
2008-03-07 10:07:34 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1000@192.168.1.95:5060 entering state [completed]
2008-03-07 10:07:34 [NOTICE] mod_conference.c:1756 conference_loop_output() Channel [sofia/default/1000@192.168.1.95:5060] has been answered
2008-03-07 10:07:34 [DEBUG] sofia.c:1473 sofia_handle_sip_i_state() Channel sofia/default/1000@192.168.1.95:5060 entering state [ready]
2008-03-07 10:07:34 [DEBUG] switch_core_io.c:325 switch_core_session_read_frame() Engaging Read Buffer at 320 bytes