2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[PCMU:0]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[PCMA:8]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[speex:98]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[speex:99]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[speex:102]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [telephone-event:101]/[L16:10]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [SPEEX:114]/[PCMU:0]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [SPEEX:114]/[PCMA:8]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [SPEEX:114]/[speex:98]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1838 negotiate_sdp() Codec Compare [SPEEX:114]/[speex:99]
2006-10-13 02:22:27 [INFO] mod_sofia.c:1185 tech_set_codec() Set Codec sofia/test/10001@pbx.jabbim.cz PCMU/16000 20 ms
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:2149 sip_i_state() sofia/test/10001@pbx.jabbim.cz State Change CS_NEW -> CS_INIT
2006-10-13 02:22:27 [DEBUG] switch_core.c:2730 switch_core_session_run() (sofia/test/10001@pbx.jabbim.cz) State INIT
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:942 sofia_on_init() SOFIA INIT
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:959 sofia_on_init() sofia/test/10001@pbx.jabbim.cz State Change CS_INIT -> CS_RING
2006-10-13 02:22:27 [DEBUG] switch_core.c:2766 switch_core_session_run() (sofia/test/10001@pbx.jabbim.cz) State RING
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:975 sofia_on_ring() SOFIA RING
2006-10-13 02:22:27 [DEBUG] switch_core.c:2441 switch_core_standard_on_ring() Standard RING sofia/test/10001@pbx.jabbim.cz
2006-10-13 02:22:27 [INFO] mod_dialplan_xml.c:273 dialplan_hunt() Processing Jan Pinkas->455!
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:194 parse_exten() test conditions destination_number(455) =~ /^(18(0{2}|8{2}|7{2}|6{2})\d{7})$/
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:196 parse_exten() Regex mismatch
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:194 parse_exten() test conditions destination_number(455) =~ /^1234$/
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:196 parse_exten() Regex mismatch
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:194 parse_exten() test conditions destination_number(455) =~ /^1000$/
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:196 parse_exten() Regex mismatch
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:194 parse_exten() test conditions destination_number(455) =~ /^2000$/
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:196 parse_exten() Regex mismatch
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:194 parse_exten() test conditions source(mod_sofia) =~ /mod_sofia/
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:194 parse_exten() test conditions destination_number(455) =~ /^4(\d+)/
2006-10-13 02:22:27 [DEBUG] mod_dialplan_xml.c:321 dialplan_hunt() sofia/test/10001@pbx.jabbim.cz State Change CS_RING -> CS_EXECUTE
2006-10-13 02:22:27 [DEBUG] switch_core.c:2802 switch_core_session_run() (sofia/test/10001@pbx.jabbim.cz) State EXECUTE
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:993 sofia_on_execute() SOFIA EXECUTE
2006-10-13 02:22:27 [DEBUG] switch_core.c:2475 switch_core_standard_on_execute() Standard EXECUTE
2006-10-13 02:22:27 [NOTICE] switch_core.c:2484 switch_core_standard_on_execute() Execute answer()
2006-10-13 02:22:27 [INFO] mod_sofia.c:808 tech_choose_port() Stun Success [82.208.10.91]:[16400]
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1147 tech_set_codec() Already using speex
2006-10-13 02:22:27 [INFO] mod_sofia.c:1229 activate_rtp() RTP [sofia/test/10001@pbx.jabbim.cz] 82.208.10.91:16400->213.192.24.101:5002 codec: 99 ms: 20
2006-10-13 02:22:27 [DEBUG] switch_rtp.c:495 switch_rtp_create() Starting timer [soft] 0 bytes per 20000ms
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:1321 sofia_answer_channel() Local SDP sofia/test/10001@pbx.jabbim.cz:
v=0
o=FreeSWITCH 164001160698947959313 164001160698947959313 IN IP4 82.208.10.91
s=FreeSWITCH
c=IN IP4 82.208.10.91
t=0 0
a=sendrecv
m=audio 16400 RTP/AVP 114 101
a=rtpmap:114 SPEEX/16000
a=ptime:20
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

2006-10-13 02:22:27 [NOTICE] mod_dptools.c:67 answer_function() Answer sofia/test/10001@pbx.jabbim.cz!
2006-10-13 02:22:27 [NOTICE] switch_core.c:2484 switch_core_standard_on_execute() Execute playback(/usr/share/asterisk/sounds/beep.gsm)
2006-10-13 02:22:27 [INFO] mod_native_file.c:81 native_file_file_open() Opening File [/usr/share/asterisk/sounds/beep.gsm] 8000hz
2006-10-13 02:22:27 [DEBUG] switch_ivr.c:683 switch_ivr_play_file() OPEN FILE /usr/share/asterisk/sounds/beep.gsm 8000hz 1 channels
TITLE=
COPYRIGHT=
SOFTWARE=
ARTIST=
COMMENT=
DATE=
2006-10-13 02:22:27 [DEBUG] switch_ivr.c:720 switch_ivr_play_file() Codec Activated L16@8000hz 1 channels 20ms
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:3108 event_callback() event [nua_i_state] status [200][OK] session: sofia/test/10001@pbx.jabbim.cz
2006-10-13 02:22:27 [DEBUG] mod_sofia.c:2035 sip_i_state() Channel sofia/test/10001@pbx.jabbim.cz entering state [completed]
2006-10-13 02:22:28 [NOTICE] switch_resample.c:69 switch_resample_create() Activate Resampler 8000->16000 2.000000
resample_process: in=160, out=12800 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 28 Xp: 28 lastFlag: 0
new len=160 Nx=132
Nout: 264
New Xread=56
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=0, out=12536 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
2006-10-13 02:22:28 [DEBUG] switch_core.c:1978 switch_core_session_write_frame() Engaging Write Buffer at 640 bytes to accomodate 528->640
resample_process: in=160, out=12800 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=160 Nx=160
Nout: 320
New Xread=56
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=0, out=12480 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=160, out=12800 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=160 Nx=160
Nout: 320
New Xread=56
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=0, out=12480 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=160, out=12800 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=160 Nx=160
Nout: 320
New Xread=56
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=0, out=12480 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=160, out=12800 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=160 Nx=160
Nout: 320
New Xread=56
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=0, out=12480 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=58, out=12800 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=58 Nx=58
Nout: 116
New Xread=56
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
resample_process: in=0, out=12684 lastFlag=0
XSize: 4096 Xoff: 28 Xread: 56 Xp: 28 lastFlag: 0
new len=0 Nx=0
2006-10-13 02:22:28 [DEBUG] switch_ivr.c:920 switch_ivr_play_file() done playing file
2006-10-13 02:22:28 [NOTICE] switch_core.c:2526 switch_core_standard_on_execute() Hangup sofia/test/10001@pbx.jabbim.cz [CS_EXECUTE] [NORMAL_CLEARING]
2006-10-13 02:22:28 [INFO] switch_channel.c:926 switch_channel_perform_hangup() Kill sofia/test/10001@pbx.jabbim.cz [1]
2006-10-13 02:22:28 [DEBUG] switch_core.c:2693 switch_core_session_run() (sofia/test/10001@pbx.jabbim.cz) State HANGUP
2006-10-13 02:22:28 [DEBUG] mod_sofia.c:1069 sofia_on_hangup() Channel sofia/test/10001@pbx.jabbim.cz hanging up, cause: NORMAL_CLEARING
2006-10-13 02:22:28 [DEBUG] mod_sofia.c:1082 sofia_on_hangup() Sending BYE
2006-10-13 02:22:28 [DEBUG] switch_core.c:2431 switch_core_standard_on_hangup() Standard HANGUP sofia/test/10001@pbx.jabbim.cz, cause: NORMAL_CLEARING
2006-10-13 02:22:28 [DEBUG] switch_core.c:3100 switch_core_session_thread() Session 10 (sofia/test/10001@pbx.jabbim.cz) Locked, Waiting on external entities
2006-10-13 02:22:28 [INFO] switch_core.c:3107 switch_core_session_thread() Session 10 (sofia/test/10001@pbx.jabbim.cz) Ended
2006-10-13 02:22:28 [NOTICE] switch_core.c:2980 switch_core_session_destroy() Close Channel sofia/test/10001@pbx.jabbim.cz
2006-10-13 02:22:46 [DEBUG] mod_sofia.c:3108 event_callback() event [nua_i_register] status [100][Trying] session: n/a
2006-10-13 02:22:46 [DEBUG] mod_sofia.c:2558 handle_register() Register from [10001@pbx.jabbim.cz] contact [10001@213.192.24.101] expires 3600
2006-10-13 02:22:46 [DEBUG] mod_sofia.c:3108 event_callback() event [nua_i_subscribe] status [489][Bad Event] session: n/a
nua: respond with invalid handle (nil)