2012-03-13 21:08:17.511681 [DEBUG] sofia.c:7091 IP 10.99.30.15 Approved by acl "domains[]". Access Granted.
2012-03-13 21:08:17.511681 [NOTICE] switch_channel.c:911 New Channel sofia/internal/
495xx...@10.99.30.15 [2092b9b4-6d2f-11e1-8a7b-63e81eb30493]
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_NEW
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:380 (sofia/internal/
495xx...@10.99.30.15) State NEW
2012-03-13 21:08:17.511681 [DEBUG] sofia.c:5174 Channel sofia/internal/
495xx...@10.99.30.15 entering state [received][100]
2012-03-13 21:08:17.511681 [DEBUG] sofia.c:5185 Remote SDP:
v=0
o=CiscoSystemsSIP-GW-UserAgent 1079 6988 IN IP4 10.99.30.15
s=SIP Call
c=IN IP4 10.99.30.15
t=0 0
m=audio 18298 RTP/AVP 8 0 101
c=IN IP4 10.99.30.15
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:4298 Activate Buggy RFC2833 Mode!
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:115:32000:20:48000]
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [PCMA:8:8000:20:64000]/[G7221:107:16000:20:32000]
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:4715 Audio Codec Compare [PCMA:8:8000:20:64000]/[PCMA:8:8000:20:64000]
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:2842 Set Codec sofia/internal/
495xx...@10.99.30.15 PCMA/8000 20 ms 160 samples 64000 bits
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:4836 Set 2833 dtmf send/recv payload to 101
2012-03-13 21:08:17.511681 [DEBUG] sofia.c:5384 (sofia/internal/
495xx...@10.99.30.15) State Change CS_NEW -> CS_INIT
2012-03-13 21:08:17.511681 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_INIT
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/
495xx...@10.99.30.15) State INIT
2012-03-13 21:08:17.511681 [DEBUG] mod_sofia.c:125 (sofia/internal/
495xx...@10.99.30.15) State Change CS_INIT -> CS_ROUTING
2012-03-13 21:08:17.511681 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:401 (sofia/internal/
495xx...@10.99.30.15) State INIT going to sleep
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_ROUTING
2012-03-13 21:08:17.511681 [DEBUG] switch_channel.c:1840 (sofia/internal/
495xx...@10.99.30.15) Callstate Change DOWN -> RINGING
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/
495xx...@10.99.30.15) State ROUTING
2012-03-13 21:08:17.511681 [DEBUG] mod_sofia.c:148 sofia/internal/
495xx...@10.99.30.15 SOFIA ROUTING
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:104 sofia/internal/
495xx...@10.99.30.15 Standard ROUTING
2012-03-13 21:08:17.511681 [INFO] mod_dialplan_xml.c:336 Processing 495xxxxx70 <495xxxxx70>->495xxxxx25 in context public
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [public_extensions] destination_number(495xxxxx25) =~ /^(1/d{3})$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [public_did] destination_number(495xxxxx25) =~ /^(5551212)$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [inbound_hipath] destination_number(495xxxxx25) =~ /^(\d{4})$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [to5106714] destination_number(495xxxxx25) =~ /^(4955106714)$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (FAIL) [to5140700] destination_number(495xxxxx25) =~ /^(4955140700)$/ break=on-false
Dialplan: sofia/internal/
495xx...@10.99.30.15 Regex (PASS) [to5891025] destination_number(495xxxxx25) =~ /^(495xxxxx25)$/ break=on-false
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:154 (sofia/internal/
495xx...@10.99.30.15) State Change CS_ROUTING -> CS_EXECUTE
2012-03-13 21:08:17.511681 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:410 (sofia/internal/
495xx...@10.99.30.15) State ROUTING going to sleep
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_EXECUTE
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/
495xx...@10.99.30.15) State EXECUTE
2012-03-13 21:08:17.511681 [DEBUG] mod_sofia.c:241 sofia/internal/
495xx...@10.99.30.15 SOFIA EXECUTE
2012-03-13 21:08:17.511681 [DEBUG] switch_core_state_machine.c:192 sofia/internal/
495xx...@10.99.30.15 Standard EXECUTE
2012-03-13 21:08:17.511681 [DEBUG] mod_dptools.c:1176 sofia/internal/
495xx...@10.99.30.15 SET [outside_call]=[true]
2012-03-13 21:08:17.511681 [DEBUG] mod_dptools.c:1176 sofia/internal/
495xx...@10.99.30.15 SET [domain_name]=[10.99.30.20]
2012-03-13 21:08:17.511681 [DEBUG] switch_core_session.c:2081 Application ivr Requires media! pre_answering channel sofia/internal/
495xx...@10.99.30.15
2012-03-13 21:08:17.511681 [INFO] switch_core_session.c:2083 Sending early media
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:3094 AUDIO RTP [sofia/internal/
495xx...@10.99.30.15] 10.99.30.20 port 27546 -> 10.99.30.15 port 18298 codec: 8 ms: 20
2012-03-13 21:08:17.511681 [DEBUG] switch_rtp.c:1642 Starting timer [soft] 160 bytes per 20ms
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:3357 Set 2833 dtmf send payload to 101
2012-03-13 21:08:17.511681 [DEBUG] sofia_glue.c:3363 Set 2833 dtmf receive payload to 101
2012-03-13 21:08:17.511681 [DEBUG] mod_sofia.c:2463 Ring SDP:
v=0
o=FreeSWITCH 1331630951 1331630952 IN IP4 10.99.30.20
s=FreeSWITCH
c=IN IP4 10.99.30.20
t=0 0
m=audio 27546 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv
2012-03-13 21:08:17.511681 [NOTICE] mod_sofia.c:2466 Pre-Answer sofia/internal/
495xx...@10.99.30.15!
2012-03-13 21:08:17.511681 [DEBUG] switch_channel.c:2877 (sofia/internal/
495xx...@10.99.30.15) Callstate Change RINGING -> EARLY
2012-03-13 21:08:17.511681 [DEBUG] switch_core_session.c:724 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:17.511681 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:665 switch_ivr_menu_stack_xml_add binding 'menu-exit'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:665 switch_ivr_menu_stack_xml_add binding 'menu-sub'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:665 switch_ivr_menu_stack_xml_add binding 'menu-exec-app'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:665 switch_ivr_menu_stack_xml_add binding 'menu-play-sound'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:665 switch_ivr_menu_stack_xml_add binding 'menu-back'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:665 switch_ivr_menu_stack_xml_add binding 'menu-top'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:796 building menu 'nt_ivr01'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:857 binding menu action 'menu-exec-app' to '1'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:857 binding menu action 'menu-exec-app' to '2'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:857 binding menu action 'menu-exec-app' to '3'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:857 binding menu action 'menu-exec-app' to '4'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:857 binding menu action 'menu-exec-app' to '/^(1\d{3})$/'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:857 binding menu action 'menu-top' to '9'
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:433 Executing IVR menu nt_ivr01
2012-03-13 21:08:17.511681 [DEBUG] sofia.c:5167 Channel sofia/internal/
495xx...@10.99.30.15 skipping state [early][183]
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr_menu.c:585 IVR menu 'nt_ivr01' no input detected
2012-03-13 21:08:17.511681 [DEBUG] switch_ivr.c:190 Codec Activated L16@8000hz 1 channels 20ms
2012-03-13 21:08:17.571688 [DEBUG] switch_rtp.c:3181 Correct ip/port confirmed.
2012-03-13 21:08:18.531639 [DEBUG] switch_core_file.c:180 File /usr/local/freeswitch/sounds/custom/nt.wav sample rate 44100 doesn't match requested rate 8000
2012-03-13 21:08:18.531639 [WARNING] switch_core_file.c:193 File has 2 channels, muxing to mono will occur.
2012-03-13 21:08:18.531639 [DEBUG] switch_ivr_play_say.c:1302 Codec Activated L16@8000hz 2 channels 20ms
2012-03-13 21:08:34.810959 [DEBUG] switch_ivr_play_say.c:1672 done playing file
2012-03-13 21:08:34.810959 [DEBUG] switch_ivr_menu.c:348 waiting for 4/4 digits t/o 2000
2012-03-13 21:08:43.274864 [WARNING] sofia_reg.c:406 Timeout Registering
sipnet.ru
2012-03-13 21:08:44.814800 [DEBUG] switch_ivr_menu.c:395 digits ''
2012-03-13 21:08:44.814800 [DEBUG] switch_core_file.c:180 File /usr/local/freeswitch/sounds/custom/nt.wav sample rate 44100 doesn't match requested rate 8000
2012-03-13 21:08:44.814800 [WARNING] switch_core_file.c:193 File has 2 channels, muxing to mono will occur.
2012-03-13 21:08:44.814800 [DEBUG] switch_ivr_play_say.c:1302 Codec Activated L16@8000hz 2 channels 20ms
2012-03-13 21:08:45.274780 [WARNING] sofia_reg.c:430
sipnet.ru Failed Registration [0], setting retry to 30 seconds.
2012-03-13 21:08:47.595683 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:47.595683 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:47.595683 [DEBUG] switch_core_session.c:870 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:47.615683 [DEBUG] sofia.c:5174 Channel sofia/internal/
495xx...@10.99.30.15 entering state [terminated][487]
2012-03-13 21:08:47.615683 [DEBUG] switch_channel.c:2800 (sofia/internal/
495xx...@10.99.30.15) Callstate Change EARLY -> HANGUP
2012-03-13 21:08:47.615683 [NOTICE] sofia.c:5915 Hangup sofia/internal/
495xx...@10.99.30.15 [CS_EXECUTE] [ORIGINATOR_CANCEL]
2012-03-13 21:08:47.615683 [DEBUG] switch_channel.c:2816 Send signal sofia/internal/
495xx...@10.99.30.15 [KILL]
2012-03-13 21:08:47.615683 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:47.615683 [DEBUG] switch_ivr_play_say.c:1672 done playing file
2012-03-13 21:08:47.615683 [DEBUG] switch_ivr_menu.c:348 waiting for 4/4 digits t/o 2000
2012-03-13 21:08:47.615683 [DEBUG] switch_ivr_menu.c:395 digits ''
2012-03-13 21:08:47.615683 [DEBUG] switch_ivr_menu.c:585 IVR menu 'nt_ivr01' no input detected
2012-03-13 21:08:48.615641 [DEBUG] switch_ivr_menu.c:599 exit-sound '(null)'
2012-03-13 21:08:48.615641 [DEBUG] switch_core_session.c:2233 sofia/internal/
495xx...@10.99.30.15 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:417 (sofia/internal/
495xx...@10.99.30.15) State EXECUTE going to sleep
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_HANGUP
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/
495xx...@10.99.30.15) State HANGUP
2012-03-13 21:08:48.615641 [DEBUG] mod_sofia.c:454 sofia/internal/
495xx...@10.99.30.15 Overriding SIP cause 487 with 487 from the other leg
2012-03-13 21:08:48.615641 [DEBUG] mod_sofia.c:460 Channel sofia/internal/
495xx...@10.99.30.15 hanging up, cause: ORIGINATOR_CANCEL
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:47 sofia/internal/
495xx...@10.99.30.15 Standard HANGUP, cause: ORIGINATOR_CANCEL
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:602 (sofia/internal/
495xx...@10.99.30.15) State HANGUP going to sleep
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:393 (sofia/internal/
495xx...@10.99.30.15) State Change CS_HANGUP -> CS_REPORTING
2012-03-13 21:08:48.615641 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:362 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_REPORTING
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/
495xx...@10.99.30.15) State REPORTING
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:79 sofia/internal/
495xx...@10.99.30.15 Standard REPORTING, cause: ORIGINATOR_CANCEL
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/
495xx...@10.99.30.15) State REPORTING going to sleep
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:387 (sofia/internal/
495xx...@10.99.30.15) State Change CS_REPORTING -> CS_DESTROY
2012-03-13 21:08:48.615641 [DEBUG] switch_core_session.c:1175 Send signal sofia/internal/
495xx...@10.99.30.15 [BREAK]
2012-03-13 21:08:48.615641 [DEBUG] switch_core_session.c:1349 Session 33677 (sofia/internal/
495xx...@10.99.30.15) Locked, Waiting on external entities
2012-03-13 21:08:48.615641 [NOTICE] switch_core_session.c:1367 Session 33677 (sofia/internal/
495xx...@10.99.30.15) Ended
2012-03-13 21:08:48.615641 [NOTICE] switch_core_session.c:1369 Close Channel sofia/internal/
495xx...@10.99.30.15 [CS_DESTROY]
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/
495xx...@10.99.30.15) Callstate Change HANGUP -> DOWN
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:494 (sofia/internal/
495xx...@10.99.30.15) Running State Change CS_DESTROY
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/
495xx...@10.99.30.15) State DESTROY
2012-03-13 21:08:48.615641 [DEBUG] mod_sofia.c:365 sofia/internal/
495xx...@10.99.30.15 SOFIA DESTROY
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:86 sofia/internal/
495xx...@10.99.30.15 Standard DESTROY
2012-03-13 21:08:48.615641 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/
495xx...@10.99.30.15) State DESTROY going to sleep