log:
vswitch@mypc> 2011-04-20 22:52:22.496001 [DEBUG] sofia.c:6539 IP 192.168.200.100 Rejected by acl "172.28.0.0/16". Falling back to Digest auth.
2011-04-20 22:52:22.496001 [WARNING] sofia_reg.c:1246 SIP auth challenge (INVITE) on sofia profile 'internal' for [9123@192.168.200.100] from ip 192.1
68.200.100
2011-04-20 22:52:22.519003 [DEBUG] sofia.c:6539 IP 192.168.200.100 Rejected by acl "172.28.0.0/16". Falling back to Digest auth.
2011-04-20 22:52:22.526003 [NOTICE] switch_channel.c:812 New Channel sofia/internal/1002@192.168.200.100 [e709297d-aae8-46b3-b75e-68b2ab63164a]
2011-04-20 22:52:22.532003 [DEBUG] sofia.c:4760 Channel sofia/internal/1002@192.168.200.100 entering state [received][100]
2011-04-20 22:52:22.532003 [DEBUG] sofia.c:4771 Remote SDP:
v=0
o=- 12947784742458999 1 IN IP4 192.168.200.100
s=CounterPath X-Lite 4.0
c=IN IP4 192.168.200.100
t=0 0
a=ice-ufrag:260f31
a=ice-pwd:2110abb4ecb2953f4600b8f332fdb1d3
m=audio 61294 RTP/AVP 0 97 8 3 101
a=rtpmap:97 SPEEX/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=candidate:1 1 UDP 659136 192.168.200.100 61294 typ host
a=candidate:1 2 UDP 659134 192.168.200.100 61295 typ host
2011-04-20 22:52:22.532003 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002@192.168.200.100) Running State Change CS_NEW
2011-04-20 22:52:22.533003 [DEBUG] switch_core_state_machine.c:343 (sofia/internal/1002@192.168.200.100) State NEW
2011-04-20 22:52:22.533003 [DEBUG] sofia.c:4916 (sofia/internal/1002@192.168.200.100) State Change CS_NEW -> CS_INIT
2011-04-20 22:52:22.533003 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@192.168.200.100 [BREAK]
2011-04-20 22:52:22.534003 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002@192.168.200.100) Running State Change CS_INIT
2011-04-20 22:52:22.534003 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1002@192.168.200.100) State INIT
2011-04-20 22:52:22.534003 [DEBUG] mod_sofia.c:84 sofia/internal/1002@192.168.200.100 SOFIA INIT
2011-04-20 22:52:22.534003 [DEBUG] mod_sofia.c:124 (sofia/internal/1002@192.168.200.100) State Change CS_INIT -> CS_ROUTING
2011-04-20 22:52:22.534003 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@192.168.200.100 [BREAK]
2011-04-20 22:52:22.534003 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1002@192.168.200.100) State INIT going to sleep
2011-04-20 22:52:22.534003 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002@192.168.200.100) Running State Change CS_ROUTING
2011-04-20 22:52:22.534003 [DEBUG] switch_channel.c:1668 (sofia/internal/1002@192.168.200.100) Callstate Change DOWN -> RINGING
2011-04-20 22:52:22.535004 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1002@192.168.200.100) State ROUTING
2011-04-20 22:52:22.535004 [DEBUG] mod_sofia.c:147 sofia/internal/1002@192.168.200.100 SOFIA ROUTING
2011-04-20 22:52:22.535004 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1002@192.168.200.100 Standard ROUTING
2011-04-20 22:52:22.535004 [INFO] mod_dialplan_xml.c:331 Processing 1002 <1002>->9123 in context default
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [Local_Extension] destination_number(9123) =~ /^(1\d{3})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [global-intercept] destination_number(9123) =~ /^\*1$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [intercept-ext] destination_number(9123) =~ /^\*2(\d{4})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->vmain] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [vmain] destination_number(9123) =~ /^vmain$|^\*3$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->9_GW] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (PASS) [9_GW] destination_number(9123) =~ /^(9\d+)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 Action set(continue_on_fail=true)
Dialplan: sofia/internal/1002@192.168.200.100 Action set(hangup_after_bridge=false)
Dialplan: sofia/internal/1002@192.168.200.100 Action bridge(sofia/internal/9123@192.168.200.201)
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [9_GW] brige_hangup_cause() =~ /UNALLOCATED_NUMBER/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->conf999] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [conf999] destination_number(9123) =~ /^999$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->DISA] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [DISA] destination_number(9123) =~ /^\*(3472)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->IVR] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [IVR] destination_number(9123) =~ /^888$/ break=on-false
Dialplan: sofia/internal/1002@192.168.200.100 parsing [default->Recordings] continue=false
Dialplan: sofia/internal/1002@192.168.200.100 Regex (FAIL) [Recordings] destination_number(9123) =~ /^\*(732673)$/ break=on-false
2011-04-20 22:52:22.540004 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1002@192.168.200.100) State Change CS_ROUTING -> CS_EXECUTE
2011-04-20 22:52:22.540004 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@192.168.200.100 [BREAK]
2011-04-20 22:52:22.540004 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1002@192.168.200.100) State ROUTING going to sleep
2011-04-20 22:52:22.540004 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002@192.168.200.100) Running State Change CS_EXECUTE
2011-04-20 22:52:22.540004 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/1002@192.168.200.100) State EXECUTE
2011-04-20 22:52:22.540004 [DEBUG] mod_sofia.c:240 sofia/internal/1002@192.168.200.100 SOFIA EXECUTE
2011-04-20 22:52:22.540004 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1002@192.168.200.100 Standard EXECUTE
EXECUTE sofia/internal/1002@192.168.200.100 set(continue_on_fail=true)
2011-04-20 22:52:22.540004 [DEBUG] mod_dptools.c:1060 sofia/internal/1002@192.168.200.100 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1002@192.168.200.100 set(hangup_after_bridge=false)
2011-04-20 22:52:22.541004 [DEBUG] mod_dptools.c:1060 sofia/internal/1002@192.168.200.100 SET [hangup_after_bridge]=[false]
EXECUTE sofia/internal/1002@192.168.200.100 bridge(sofia/internal/9123@192.168.200.201)
2011-04-20 22:52:22.542004 [NOTICE] switch_channel.c:812 New Channel sofia/internal/9123@192.168.200.201 [c817db5a-b2fd-445d-91d5-1bcf67291207]
2011-04-20 22:52:22.543004 [DEBUG] mod_sofia.c:4300 (sofia/internal/9123@192.168.200.201) State Change CS_NEW -> CS_INIT
2011-04-20 22:52:22.543004 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/9123@192.168.200.201 [BREAK]
2011-04-20 22:52:22.545004 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/9123@192.168.200.201) Running State Change CS_INIT
2011-04-20 22:52:22.545004 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/9123@192.168.200.201) State INIT
2011-04-20 22:52:22.545004 [DEBUG] mod_sofia.c:84 sofia/internal/9123@192.168.200.201 SOFIA INIT
2011-04-20 22:52:22.546004 [DEBUG] sofia_glue.c:1757 sofia/internal/9123@192.168.200.201 Patched SDP
---
v=0
o=- 12947784742458999 1 IN IP4 192.168.200.100
s=CounterPath X-Lite 4.0
c=IN IP4 192.168.200.100
t=0 0
a=ice-ufrag:260f31
a=ice-pwd:2110abb4ecb2953f4600b8f332fdb1d3
m=audio 61294 RTP/AVP 0 97 8 3 101
a=rtpmap:97 SPEEX/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=candidate:1 1 UDP 659136 192.168.200.100 61294 typ host
a=candidate:1 2 UDP 659134 192.168.200.100 61295 typ host
+++
v=0
o=FreeSWITCH 0459653255 0459653256 IN IP4 192.168.200.100
s=FreeSWITCH
c=IN IP4 192.168.200.100
t=0 0
a=ice-ufrag:260f31
a=ice-pwd:2110abb4ecb2953f4600b8f332fdb1d3
m=audio 26146 RTP/AVP 0 97 8 3 101
a=rtpmap:97 SPEEX/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=candidate:1 1 UDP 659136 192.168.200.100 61294 typ host
a=candidate:1 2 UDP 659134 192.168.200.100 61295 typ host
2011-04-20 22:52:22.546004 [DEBUG] mod_sofia.c:124 (sofia/internal/9123@192.168.200.201) State Change CS_INIT -> CS_ROUTING
2011-04-20 22:52:22.546004 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/9123@192.168.200.201 [BREAK]
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/9123@192.168.200.201) State INIT going to sleep
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/9123@192.168.200.201) Running State Change CS_ROUTING
2011-04-20 22:52:22.546004 [DEBUG] switch_channel.c:1668 (sofia/internal/9123@192.168.200.201) Callstate Change DOWN -> RINGING
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/9123@192.168.200.201) State ROUTING
2011-04-20 22:52:22.546004 [DEBUG] mod_sofia.c:147 sofia/internal/9123@192.168.200.201 SOFIA ROUTING
2011-04-20 22:52:22.546004 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/9123@192.168.200.201) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-04-20 22:52:22.546004 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/9123@192.168.200.201 [BREAK]
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/9123@192.168.200.201) State ROUTING going to sleep
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/9123@192.168.200.201) Running State Change CS_CONSUME_MEDIA
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:383 (sofia/internal/9123@192.168.200.201) State CONSUME_MEDIA
2011-04-20 22:52:22.546004 [DEBUG] switch_core_state_machine.c:383 (sofia/internal/9123@192.168.200.201) State CONSUME_MEDIA going to sleep
2011-04-20 22:52:22.547004 [DEBUG] sofia.c:4760 Channel sofia/internal/9123@192.168.200.201 entering state [calling][0]
2011-04-20 22:52:22.571006 [DEBUG] sofia.c:4760 Channel sofia/internal/9123@192.168.200.201 entering state [terminated][404]
2011-04-20 22:52:22.571006 [DEBUG] switch_channel.c:2563 (sofia/internal/9123@192.168.200.201) Callstate Change RINGING -> HANGUP
2011-04-20 22:52:22.571006 [NOTICE] sofia.c:5406 Hangup sofia/internal/9123@192.168.200.201 [CS_CONSUME_MEDIA] [UNALLOCATED_NUMBER]
2011-04-20 22:52:22.571006 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/9123@192.168.200.201 [KILL]
2011-04-20 22:52:22.571006 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/9123@192.168.200.201 [BREAK]
2011-04-20 22:52:22.573006 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/9123@192.168.200.201) Running State Change CS_HANGUP
2011-04-20 22:52:22.575006 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/9123@192.168.200.201) State HANGUP
2011-04-20 22:52:22.575006 [DEBUG] mod_sofia.c:451 sofia/internal/9123@192.168.200.201 Overriding SIP cause 404 with 404 from the other leg
2011-04-20 22:52:22.575006 [DEBUG] mod_sofia.c:457 Channel sofia/internal/9123@192.168.200.201 hanging up, cause: UNALLOCATED_NUMBER
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:46 sofia/internal/9123@192.168.200.201 Standard HANGUP, cause: UNALLOCATED_NUMBER
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/9123@192.168.200.201) State HANGUP going to sleep
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/9123@192.168.200.201) State Change CS_HANGUP -> CS_REPORTING
2011-04-20 22:52:22.579006 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/9123@192.168.200.201 [BREAK]
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/9123@192.168.200.201) Running State Change CS_REPORTING
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/9123@192.168.200.201) State REPORTING
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:53 sofia/internal/9123@192.168.200.201 Standard REPORTING, cause: UNALLOCATED_NUMBER
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/9123@192.168.200.201) State REPORTING going to sleep
2011-04-20 22:52:22.579006 [DEBUG] switch_core_state_machine.c:350 (sofia/internal/9123@192.168.200.201) State Change CS_REPORTING -> CS_DESTROY
2011-04-20 22:52:22.579006 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/9123@192.168.200.201 [BREAK]
2011-04-20 22:52:22.579006 [DEBUG] switch_core_session.c:1288 Session 14 (sofia/internal/9123@192.168.200.201) Locked, Waiting on external entities
2011-04-20 22:52:22.582006 [DEBUG] switch_ivr_originate.c:3492 Originate Resulted in Error Cause: 1 [UNALLOCATED_NUMBER]
2011-04-20 22:52:22.582006 [INFO] mod_dptools.c:2640 Originate Failed.  Cause: UNALLOCATED_NUMBER
2011-04-20 22:52:22.582006 [NOTICE] switch_core_session.c:1306 Session 14 (sofia/internal/9123@192.168.200.201) Ended
2011-04-20 22:52:22.582006 [NOTICE] switch_core_state_machine.c:189 sofia/internal/1002@192.168.200.100 has executed the last dialplan instruction, ha
nging up.
2011-04-20 22:52:22.582006 [DEBUG] switch_channel.c:2563 (sofia/internal/1002@192.168.200.100) Callstate Change RINGING -> HANGUP
2011-04-20 22:52:22.582006 [NOTICE] switch_core_state_machine.c:191 Hangup sofia/internal/1002@192.168.200.100 [CS_EXECUTE] [NORMAL_CLEARING]
2011-04-20 22:52:22.582006 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/1002@192.168.200.100 [KILL]
2011-04-20 22:52:22.582006 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@192.168.200.100 [BREAK]
2011-04-20 22:52:22.582006 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/1002@192.168.200.100) State EXECUTE going to sleep
2011-04-20 22:52:22.582006 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002@192.168.200.100) Running State Change CS_HANGUP
2011-04-20 22:52:22.582006 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/9123@192.168.200.201 [CS_DESTROY]
2011-04-20 22:52:22.585006 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1002@192.168.200.100) State HANGUP
2011-04-20 22:52:22.585006 [DEBUG] mod_sofia.c:451 sofia/internal/1002@192.168.200.100 Overriding SIP cause 480 with 404 from the other leg
2011-04-20 22:52:22.585006 [DEBUG] mod_sofia.c:457 Channel sofia/internal/1002@192.168.200.100 hanging up, cause: NORMAL_CLEARING
2011-04-20 22:52:22.585006 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/9123@192.168.200.201) Callstate Change HANGUP -> DOWN
2011-04-20 22:52:22.585006 [DEBUG] switch_core_state_machine.c:457 (sofia/internal/9123@192.168.200.201) Running State Change CS_DESTROY
2011-04-20 22:52:22.586006 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/9123@192.168.200.201) State DESTROY
2011-04-20 22:52:22.586006 [DEBUG] mod_sofia.c:362 sofia/internal/9123@192.168.200.201 SOFIA DESTROY
2011-04-20 22:52:22.586006 [DEBUG] switch_core_state_machine.c:60 sofia/internal/9123@192.168.200.201 Standard DESTROY
2011-04-20 22:52:22.586006 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/9123@192.168.200.201) State DESTROY going to sleep
2011-04-20 22:52:22.591007 [DEBUG] mod_sofia.c:519 Responding to INVITE with: 404
2011-04-20 22:52:22.591007 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002@192.168.200.100 Standard HANGUP, cause: NORMAL_CLEARING
2011-04-20 22:52:22.591007 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1002@192.168.200.100) State HANGUP going to sleep
2011-04-20 22:52:22.591007 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/1002@192.168.200.100) State Change CS_HANGUP -> CS_REPORTING
2011-04-20 22:52:22.591007 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@192.168.200.100 [BREAK]
2011-04-20 22:52:22.591007 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002@192.168.200.100) Running State Change CS_REPORTING
2011-04-20 22:52:22.591007 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/1002@192.168.200.100) State REPORTING
2011-04-20 22:52:22.785018 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002@192.168.200.100 Standard REPORTING, cause: NORMAL_CLEARING
2011-04-20 22:52:22.785018 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/1002@192.168.200.100) State REPORTING going to sleep
2011-04-20 22:52:22.786018 [DEBUG] switch_core_state_machine.c:350 (sofia/internal/1002@192.168.200.100) State Change CS_REPORTING -> CS_DESTROY
2011-04-20 22:52:22.786018 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002@192.168.200.100 [BREAK]
2011-04-20 22:52:22.786018 [DEBUG] switch_core_session.c:1288 Session 13 (sofia/internal/1002@192.168.200.100) Locked, Waiting on external entities
2011-04-20 22:52:22.786018 [NOTICE] switch_core_session.c:1306 Session 13 (sofia/internal/1002@192.168.200.100) Ended
2011-04-20 22:52:22.786018 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/1002@192.168.200.100 [CS_DESTROY]
2011-04-20 22:52:22.786018 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1002@192.168.200.100) Callstate Change HANGUP -> DOWN
2011-04-20 22:52:22.786018 [DEBUG] switch_core_state_machine.c:457 (sofia/internal/1002@192.168.200.100) Running State Change CS_DESTROY
2011-04-20 22:52:22.786018 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1002@192.168.200.100) State DESTROY
2011-04-20 22:52:22.786018 [DEBUG] mod_sofia.c:362 sofia/internal/1002@192.168.200.100 SOFIA DESTROY
2011-04-20 22:52:22.786018 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.200.100 Standard DESTROY
2011-04-20 22:52:22.786018 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1002@192.168.200.100) State DESTROY going to sleep