vswitch@mypc> 2011-07-12 16:28:07.779375 [DEBUG] sofia.c:6539 IP 192.168.200.100 Rejected by acl "172.28.0.0/16". Falling back to Digest auth.
2011-07-12 16:28:07.782375 [WARNING] sofia_reg.c:1246 SIP auth challenge (INVITE) on sofia profile 'internal' for [1001@192.168.200.100] from ip 192.1
68.200.100
2011-07-12 16:28:07.853379 [DEBUG] sofia.c:6539 IP 192.168.200.100 Rejected by acl "172.28.0.0/16". Falling back to Digest auth.
2011-07-12 16:28:07.884381 [NOTICE] switch_channel.c:812 New Channel sofia/internal/1005@192.168.200.100 [4201fb5a-c6ee-451a-bf5b-18614ce9353b]
2011-07-12 16:28:07.885381 [DEBUG] sofia.c:4760 Channel sofia/internal/1005@192.168.200.100 entering state [received][100]
2011-07-12 16:28:07.885381 [DEBUG] sofia.c:4771 Remote SDP:
v=0
o=- 111347976 111347994 IN IP4 192.168.200.100
s=eyeBeam
c=IN IP4 192.168.200.100
t=0 0
m=audio 6200 RTP/AVP 100 6 0 8 3 18 98 97 5 102 101
a=rtpmap:100 speex/16000
a=rtpmap:98 ilbc/8000
a=rtpmap:97 speex/8000
a=rtpmap:102 l16/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 1 : 0730C003 366B174B 192.168.200.100 6200

2011-07-12 16:28:07.886381 [DEBUG] sofia.c:4916 (sofia/internal/1005@192.168.200.100) State Change CS_NEW -> CS_INIT
2011-07-12 16:28:07.886381 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:07.886381 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1005@192.168.200.100) Running State Change CS_INIT
2011-07-12 16:28:07.886381 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1005@192.168.200.100) State INIT
2011-07-12 16:28:07.886381 [DEBUG] mod_sofia.c:84 sofia/internal/1005@192.168.200.100 SOFIA INIT
2011-07-12 16:28:07.886381 [DEBUG] mod_sofia.c:124 (sofia/internal/1005@192.168.200.100) State Change CS_INIT -> CS_ROUTING
2011-07-12 16:28:07.886381 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:07.886381 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1005@192.168.200.100) State INIT going to sleep
2011-07-12 16:28:07.886381 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1005@192.168.200.100) Running State Change CS_ROUTING
2011-07-12 16:28:07.886381 [DEBUG] switch_channel.c:1668 (sofia/internal/1005@192.168.200.100) Callstate Change DOWN -> RINGING
2011-07-12 16:28:07.886381 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1005@192.168.200.100) State ROUTING
2011-07-12 16:28:07.886381 [DEBUG] mod_sofia.c:147 sofia/internal/1005@192.168.200.100 SOFIA ROUTING
2011-07-12 16:28:07.886381 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1005@192.168.200.100 Standard ROUTING
2011-07-12 16:28:07.886381 [INFO] mod_dialplan_xml.c:331 Processing 1005 <1005>->1001 in context default
Dialplan: sofia/internal/1005@192.168.200.100 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1005@192.168.200.100 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1005@192.168.200.100 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1005@192.168.200.100 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1005@192.168.200.100 Regex (PASS) [Local_Extension] destination_number(1001) =~ /^(1\d{3})$/ break=on-false
Dialplan: sofia/internal/1005@192.168.200.100 Action set(dialed_extension=1001)
Dialplan: sofia/internal/1005@192.168.200.100 Action export(dialed_extension=1001)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1005@192.168.200.100 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(call_timeout=30)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(failure_causes=USER_BUSY)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(continue_on_fail=true)
Dialplan: sofia/internal/1005@192.168.200.100 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1005@192.168.200.100 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1005@192.168.200.100 Action bridge(sofia/internal/${dialed_extension}%${domain_name})
Dialplan: sofia/internal/1005@192.168.200.100 Action answer()
Dialplan: sofia/internal/1005@192.168.200.100 Action sleep(1000)
Dialplan: sofia/internal/1005@192.168.200.100 Action play_and_get_digits(2 5 3 4000 # C:\VSWITCH/sounds/en/us/callie/conference/8000/conf-pin.wav /inv
alid.wav other_ext_var \d+)
Dialplan: sofia/internal/1005@192.168.200.100 Action transfer(${other_ext_var} XML default)
2011-07-12 16:28:07.890381 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1005@192.168.200.100) State Change CS_ROUTING -> CS_EXECUTE
2011-07-12 16:28:07.890381 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:07.890381 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1005@192.168.200.100) State ROUTING going to sleep
2011-07-12 16:28:07.890381 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1005@192.168.200.100) Running State Change CS_EXECUTE
2011-07-12 16:28:07.890381 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/1005@192.168.200.100) State EXECUTE
2011-07-12 16:28:07.890381 [DEBUG] mod_sofia.c:240 sofia/internal/1005@192.168.200.100 SOFIA EXECUTE
2011-07-12 16:28:07.890381 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1005@192.168.200.100 Standard EXECUTE
EXECUTE sofia/internal/1005@192.168.200.100 set(dialed_extension=1001)
2011-07-12 16:28:07.890381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [dialed_extension]=[1001]
EXECUTE sofia/internal/1005@192.168.200.100 export(dialed_extension=1001)
2011-07-12 16:28:07.890381 [DEBUG] switch_channel.c:961 EXPORT (export_vars) [dialed_extension]=[1001]
EXECUTE sofia/internal/1005@192.168.200.100 set(ringback=%(2000, 4000, 440.0, 480.0))
2011-07-12 16:28:07.890381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]
EXECUTE sofia/internal/1005@192.168.200.100 set(transfer_ringback=local_stream://moh)
2011-07-12 16:28:07.890381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1005@192.168.200.100 set(call_timeout=30)
2011-07-12 16:28:07.890381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [call_timeout]=[30]
EXECUTE sofia/internal/1005@192.168.200.100 set(failure_causes=USER_BUSY)
2011-07-12 16:28:07.890381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [failure_causes]=[USER_BUSY]
EXECUTE sofia/internal/1005@192.168.200.100 set(hangup_after_bridge=true)
2011-07-12 16:28:07.890381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1005@192.168.200.100 set(continue_on_fail=true)
2011-07-12 16:28:07.899381 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1005@192.168.200.100 hash(insert/192.168.200.100-last_dial_ext/1001/4201fb5a-c6ee-451a-bf5b-18614ce9353b)
EXECUTE sofia/internal/1005@192.168.200.100 hash(insert/192.168.200.100-last_dial_ext/global/4201fb5a-c6ee-451a-bf5b-18614ce9353b)
EXECUTE sofia/internal/1005@192.168.200.100 bridge(sofia/internal/1001%192.168.200.100)
2011-07-12 16:28:07.901382 [DEBUG] switch_channel.c:918 sofia/internal/1005@192.168.200.100 EXPORTING[export_vars] [dialed_extension]=[1001] to event
2011-07-12 16:28:07.901382 [NOTICE] switch_channel.c:812 New Channel sofia/internal/1001 [ffbcec4e-6366-4a97-ac52-53266512e421]
2011-07-12 16:28:07.901382 [DEBUG] mod_sofia.c:4300 (sofia/internal/1001) State Change CS_NEW -> CS_INIT
2011-07-12 16:28:07.901382 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1001 [BREAK]
2011-07-12 16:28:07.905382 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1001) Running State Change CS_INIT
2011-07-12 16:28:07.905382 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1001) State INIT
2011-07-12 16:28:07.905382 [DEBUG] mod_sofia.c:84 sofia/internal/1001 SOFIA INIT
2011-07-12 16:28:07.906382 [DEBUG] sofia_glue.c:1757 sofia/internal/1001 Patched SDP
---
v=0
o=- 111347976 111347994 IN IP4 192.168.200.100
s=eyeBeam
c=IN IP4 192.168.200.100
t=0 0
m=audio 6200 RTP/AVP 100 6 0 8 3 18 98 97 5 102 101
a=rtpmap:100 speex/16000
a=rtpmap:98 ilbc/8000
a=rtpmap:97 speex/8000
a=rtpmap:102 l16/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 1 : 0730C003 366B174B 192.168.200.100 6200

+++
v=0
o=FreeSWITCH 0287508612 0287508613 IN IP4 192.168.200.100
s=FreeSWITCH
c=IN IP4 192.168.200.100
t=0 0
m=audio 18968 RTP/AVP 100 6 0 8 3 18 98 97 5 102 101
a=rtpmap:100 speex/16000
a=rtpmap:98 ilbc/8000
a=rtpmap:97 speex/8000
a=rtpmap:102 l16/16000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 1 : 0730C003 366B174B 192.168.200.100 6200

2011-07-12 16:28:07.906382 [DEBUG] mod_sofia.c:124 (sofia/internal/1001) State Change CS_INIT -> CS_ROUTING
2011-07-12 16:28:07.906382 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1001 [BREAK]
2011-07-12 16:28:07.906382 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1001) State INIT going to sleep
2011-07-12 16:28:07.906382 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1001) Running State Change CS_ROUTING
2011-07-12 16:28:07.906382 [DEBUG] switch_channel.c:1668 (sofia/internal/1001) Callstate Change DOWN -> RINGING
2011-07-12 16:28:07.906382 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1001) State ROUTING
2011-07-12 16:28:07.906382 [DEBUG] mod_sofia.c:147 sofia/internal/1001 SOFIA ROUTING
2011-07-12 16:28:07.906382 [DEBUG] sofia.c:4760 Channel sofia/internal/1001 entering state [calling][0]
2011-07-12 16:28:07.909382 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/1001) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-07-12 16:28:07.909382 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1001 [BREAK]
2011-07-12 16:28:07.909382 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1001) State ROUTING going to sleep
2011-07-12 16:28:07.909382 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1001) Running State Change CS_CONSUME_MEDIA
2011-07-12 16:28:07.909382 [DEBUG] switch_core_state_machine.c:383 (sofia/internal/1001) State CONSUME_MEDIA
2011-07-12 16:28:07.909382 [DEBUG] switch_core_state_machine.c:383 (sofia/internal/1001) State CONSUME_MEDIA going to sleep
2011-07-12 16:28:07.981386 [DEBUG] sofia.c:4760 Channel sofia/internal/1001 entering state [terminated][486]
2011-07-12 16:28:07.981386 [DEBUG] switch_channel.c:2563 (sofia/internal/1001) Callstate Change RINGING -> HANGUP
2011-07-12 16:28:07.982386 [NOTICE] sofia.c:5406 Hangup sofia/internal/1001 [CS_CONSUME_MEDIA] [USER_BUSY]
2011-07-12 16:28:07.982386 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/1001 [KILL]
2011-07-12 16:28:07.982386 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1001 [BREAK]
2011-07-12 16:28:07.982386 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1001) Running State Change CS_HANGUP
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1001) State HANGUP
2011-07-12 16:28:07.984386 [DEBUG] mod_sofia.c:451 sofia/internal/1001 Overriding SIP cause 486 with 486 from the other leg
2011-07-12 16:28:07.984386 [DEBUG] mod_sofia.c:457 Channel sofia/internal/1001 hanging up, cause: USER_BUSY
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1001 Standard HANGUP, cause: USER_BUSY
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1001) State HANGUP going to sleep
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/1001) State Change CS_HANGUP -> CS_REPORTING
2011-07-12 16:28:07.984386 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1001 [BREAK]
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1001) Running State Change CS_REPORTING
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/1001) State REPORTING
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1001 Standard REPORTING, cause: USER_BUSY
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/1001) State REPORTING going to sleep
2011-07-12 16:28:07.984386 [DEBUG] switch_core_state_machine.c:350 (sofia/internal/1001) State Change CS_REPORTING -> CS_DESTROY
2011-07-12 16:28:07.984386 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1001 [BREAK]
2011-07-12 16:28:07.984386 [DEBUG] switch_core_session.c:1288 Session 2 (sofia/internal/1001) Locked, Waiting on external entities
2011-07-12 16:28:07.992387 [DEBUG] switch_ivr_originate.c:3492 Originate Resulted in Error Cause: 17 [USER_BUSY]
2011-07-12 16:28:07.992387 [INFO] mod_dptools.c:2640 Originate Failed.  Cause: USER_BUSY
EXECUTE sofia/internal/1005@192.168.200.100 answer()
2011-07-12 16:28:07.993387 [DEBUG] mod_sofia.c:649 Disabling proxy mode due to call answer with no bridge
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [speex:100:16000:20:0]/[PCMA:8:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [speex:100:16000:20:0]/[PCMU:0:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [speex:100:16000:20:0]/[G722:9:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [speex:100:16000:20:0]/[GSM:3:8000:20:13200]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [DVI4:6:16000:20:0]/[PCMA:8:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [DVI4:6:16000:20:0]/[PCMU:0:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [DVI4:6:16000:20:0]/[G722:9:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [DVI4:6:16000:20:0]/[GSM:3:8000:20:13200]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMA:8:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:4637 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000]
2011-07-12 16:28:07.993387 [DEBUG] sofia_glue.c:2760 Set Codec sofia/internal/1005@192.168.200.100 PCMU/8000 20 ms 160 samples 64000 bits
2011-07-12 16:28:07.995387 [DEBUG] sofia_glue.c:4751 Set 2833 dtmf send/recv payload to 101
2011-07-12 16:28:07.995387 [DEBUG] sofia_glue.c:3001 AUDIO RTP [sofia/internal/1005@192.168.200.100] 192.168.200.100 port 20404 -> 192.168.200.100 por
t 6200 codec: 0 ms: 20
2011-07-12 16:28:07.996387 [NOTICE] switch_core_session.c:1306 Session 2 (sofia/internal/1001) Ended
2011-07-12 16:28:07.996387 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/1001 [CS_DESTROY]
2011-07-12 16:28:07.996387 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1001) Callstate Change HANGUP -> DOWN
2011-07-12 16:28:07.996387 [DEBUG] switch_core_state_machine.c:457 (sofia/internal/1001) Running State Change CS_DESTROY
2011-07-12 16:28:07.996387 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1001) State DESTROY
2011-07-12 16:28:07.996387 [DEBUG] mod_sofia.c:362 sofia/internal/1001 SOFIA DESTROY
2011-07-12 16:28:07.996387 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001 Standard DESTROY
2011-07-12 16:28:07.996387 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1001) State DESTROY going to sleep
2011-07-12 16:28:07.996387 [DEBUG] switch_rtp.c:1623 Starting timer [soft] 160 bytes per 20ms
2011-07-12 16:28:07.997387 [DEBUG] sofia_glue.c:3263 Set 2833 dtmf send payload to 101
2011-07-12 16:28:07.997387 [DEBUG] sofia_glue.c:3268 Set 2833 dtmf receive payload to 101
2011-07-12 16:28:07.997387 [NOTICE] sofia_glue.c:3772 Pre-Answer sofia/internal/1005@192.168.200.100!
2011-07-12 16:28:07.997387 [DEBUG] switch_channel.c:2639 (sofia/internal/1005@192.168.200.100) Callstate Change RINGING -> EARLY
2011-07-12 16:28:07.999387 [DEBUG] mod_sofia.c:681 Local SDP sofia/internal/1005@192.168.200.100:
v=0
o=FreeSWITCH 1310438883 1310438884 IN IP4 192.168.200.100
s=FreeSWITCH
c=IN IP4 192.168.200.100
t=0 0
m=audio 20404 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=silenceSupp:off - - - -
a=ptime:20
a=sendrecv

2011-07-12 16:28:07.999387 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:07.999387 [DEBUG] switch_channel.c:2821 (sofia/internal/1005@192.168.200.100) Callstate Change EARLY -> ACTIVE
2011-07-12 16:28:07.999387 [NOTICE] mod_dptools.c:930 Channel [sofia/internal/1005@192.168.200.100] has been answered
2011-07-12 16:28:08.000387 [DEBUG] sofia.c:4760 Channel sofia/internal/1005@192.168.200.100 entering state [completed][200]
EXECUTE sofia/internal/1005@192.168.200.100 sleep(1000)
2011-07-12 16:28:08.111394 [DEBUG] switch_rtp.c:3082 Correct ip/port confirmed.
2011-07-12 16:28:08.111394 [DEBUG] sofia.c:4760 Channel sofia/internal/1005@192.168.200.100 entering state [ready][200]
EXECUTE sofia/internal/1005@192.168.200.100 play_and_get_digits(2 5 3 4000 # C:\VSWITCH/sounds/en/us/callie/conference/8000/conf-pin.wav /invalid.wav
other_ext_var \d+)
2011-07-12 16:28:09.027446 [DEBUG] switch_ivr_play_say.c:1278 Codec Activated L16@8000hz 1 channels 20ms
2011-07-12 16:28:10.751545 [DEBUG] switch_ivr_play_say.c:1648 done playing file
2011-07-12 16:28:12.871666 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 1:800
2011-07-12 16:28:13.611708 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 0:800
2011-07-12 16:28:13.811720 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 0:960
2011-07-12 16:28:14.431755 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF 2:800
2011-07-12 16:28:15.231801 [DEBUG] switch_rtp.c:3280 RTP RECV DTMF #:800
2011-07-12 16:28:15.231801 [DEBUG] switch_ivr_play_say.c:1975 Test Regex [1002][\d+]
EXECUTE sofia/internal/1005@192.168.200.100 transfer(1002 XML default)
2011-07-12 16:28:15.239801 [DEBUG] switch_ivr.c:1600 (sofia/internal/1005@192.168.200.100) State Change CS_EXECUTE -> CS_ROUTING
2011-07-12 16:28:15.239801 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:15.239801 [DEBUG] switch_core_session.c:709 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:15.239801 [NOTICE] switch_ivr.c:1606 Transfer sofia/internal/1005@192.168.200.100 to XML[1002@default]
2011-07-12 16:28:15.239801 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/1005@192.168.200.100) State EXECUTE going to sleep
2011-07-12 16:28:15.239801 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1005@192.168.200.100) Running State Change CS_ROUTING
2011-07-12 16:28:15.239801 [DEBUG] switch_channel.c:1668 (sofia/internal/1005@192.168.200.100) Callstate Change ACTIVE -> RINGING
2011-07-12 16:28:15.239801 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1005@192.168.200.100) State ROUTING
2011-07-12 16:28:15.239801 [DEBUG] mod_sofia.c:147 sofia/internal/1005@192.168.200.100 SOFIA ROUTING
2011-07-12 16:28:15.239801 [DEBUG] switch_core_state_machine.c:77 sofia/internal/1005@192.168.200.100 Standard ROUTING
2011-07-12 16:28:15.239801 [INFO] mod_dialplan_xml.c:331 Processing 1005 <1005>->1002 in context default
Dialplan: sofia/internal/1005@192.168.200.100 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1005@192.168.200.100 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1005@192.168.200.100 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1005@192.168.200.100 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1005@192.168.200.100 Regex (PASS) [Local_Extension] destination_number(1002) =~ /^(1\d{3})$/ break=on-false
Dialplan: sofia/internal/1005@192.168.200.100 Action set(dialed_extension=1002)
Dialplan: sofia/internal/1005@192.168.200.100 Action export(dialed_extension=1002)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(ringback=${us-ring})
Dialplan: sofia/internal/1005@192.168.200.100 Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(call_timeout=30)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(failure_causes=USER_BUSY)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1005@192.168.200.100 Action set(continue_on_fail=true)
Dialplan: sofia/internal/1005@192.168.200.100 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1005@192.168.200.100 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1005@192.168.200.100 Action bridge(sofia/internal/${dialed_extension}%${domain_name})
Dialplan: sofia/internal/1005@192.168.200.100 Action answer()
Dialplan: sofia/internal/1005@192.168.200.100 Action sleep(1000)
Dialplan: sofia/internal/1005@192.168.200.100 Action play_and_get_digits(2 5 3 4000 # C:\VSWITCH/sounds/en/us/callie/conference/8000/conf-pin.wav /inv
alid.wav other_ext_var \d+)
Dialplan: sofia/internal/1005@192.168.200.100 Action transfer(${other_ext_var} XML default)
2011-07-12 16:28:15.251802 [DEBUG] switch_core_state_machine.c:119 (sofia/internal/1005@192.168.200.100) State Change CS_ROUTING -> CS_EXECUTE
2011-07-12 16:28:15.251802 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1005@192.168.200.100 [BREAK]
2011-07-12 16:28:15.251802 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1005@192.168.200.100) State ROUTING going to sleep
2011-07-12 16:28:15.251802 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1005@192.168.200.100) Running State Change CS_EXECUTE
2011-07-12 16:28:15.251802 [DEBUG] switch_channel.c:1670 (sofia/internal/1005@192.168.200.100) Callstate Change RINGING -> ACTIVE
2011-07-12 16:28:15.251802 [DEBUG] switch_core_state_machine.c:371 (sofia/internal/1005@192.168.200.100) State EXECUTE
2011-07-12 16:28:15.251802 [DEBUG] mod_sofia.c:240 sofia/internal/1005@192.168.200.100 SOFIA EXECUTE
2011-07-12 16:28:15.251802 [DEBUG] switch_core_state_machine.c:157 sofia/internal/1005@192.168.200.100 Standard EXECUTE
EXECUTE sofia/internal/1005@192.168.200.100 set(dialed_extension=1002)
2011-07-12 16:28:15.252802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [dialed_extension]=[1002]
EXECUTE sofia/internal/1005@192.168.200.100 export(dialed_extension=1002)
2011-07-12 16:28:15.252802 [DEBUG] switch_channel.c:961 EXPORT (export_vars) [dialed_extension]=[1002]
EXECUTE sofia/internal/1005@192.168.200.100 set(ringback=%(2000, 4000, 440.0, 480.0))
2011-07-12 16:28:15.253802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [ringback]=[%(2000, 4000, 440.0, 480.0)]
EXECUTE sofia/internal/1005@192.168.200.100 set(transfer_ringback=local_stream://moh)
2011-07-12 16:28:15.254802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1005@192.168.200.100 set(call_timeout=30)
2011-07-12 16:28:15.255802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [call_timeout]=[30]
EXECUTE sofia/internal/1005@192.168.200.100 set(failure_causes=USER_BUSY)
2011-07-12 16:28:15.255802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [failure_causes]=[USER_BUSY]
EXECUTE sofia/internal/1005@192.168.200.100 set(hangup_after_bridge=true)
2011-07-12 16:28:15.256802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1005@192.168.200.100 set(continue_on_fail=true)
2011-07-12 16:28:15.256802 [DEBUG] mod_dptools.c:1060 sofia/internal/1005@192.168.200.100 SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1005@192.168.200.100 hash(insert/192.168.200.100-last_dial_ext/1002/4201fb5a-c6ee-451a-bf5b-18614ce9353b)
EXECUTE sofia/internal/1005@192.168.200.100 hash(insert/192.168.200.100-last_dial_ext/global/4201fb5a-c6ee-451a-bf5b-18614ce9353b)
EXECUTE sofia/internal/1005@192.168.200.100 bridge(sofia/internal/1002%192.168.200.100)
2011-07-12 16:28:15.260802 [DEBUG] switch_channel.c:918 sofia/internal/1005@192.168.200.100 EXPORTING[export_vars] [dialed_extension]=[1002] to event
2011-07-12 16:28:15.260802 [DEBUG] switch_channel.c:918 sofia/internal/1005@192.168.200.100 EXPORTING[export_vars] [dialed_extension]=[1002] to event
2011-07-12 16:28:15.261803 [NOTICE] switch_channel.c:812 New Channel sofia/internal/1002 [84302f81-aba4-4c61-90da-45118757025e]
2011-07-12 16:28:15.261803 [DEBUG] mod_sofia.c:4300 (sofia/internal/1002) State Change CS_NEW -> CS_INIT
2011-07-12 16:28:15.261803 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002 [BREAK]
2011-07-12 16:28:15.262803 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002) Running State Change CS_INIT
2011-07-12 16:28:15.262803 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1002) State INIT
2011-07-12 16:28:15.262803 [DEBUG] mod_sofia.c:84 sofia/internal/1002 SOFIA INIT
2011-07-12 16:28:15.263803 [DEBUG] mod_sofia.c:124 (sofia/internal/1002) State Change CS_INIT -> CS_ROUTING
2011-07-12 16:28:15.263803 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002 [BREAK]
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:361 (sofia/internal/1002) State INIT going to sleep
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002) Running State Change CS_ROUTING
2011-07-12 16:28:15.263803 [DEBUG] switch_channel.c:1668 (sofia/internal/1002) Callstate Change DOWN -> RINGING
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1002) State ROUTING
2011-07-12 16:28:15.263803 [DEBUG] mod_sofia.c:147 sofia/internal/1002 SOFIA ROUTING
2011-07-12 16:28:15.263803 [DEBUG] switch_ivr_originate.c:66 (sofia/internal/1002) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2011-07-12 16:28:15.263803 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002 [BREAK]
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:364 (sofia/internal/1002) State ROUTING going to sleep
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002) Running State Change CS_CONSUME_MEDIA
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:383 (sofia/internal/1002) State CONSUME_MEDIA
2011-07-12 16:28:15.263803 [DEBUG] sofia.c:4760 Channel sofia/internal/1002 entering state [calling][0]
2011-07-12 16:28:15.263803 [DEBUG] switch_core_state_machine.c:383 (sofia/internal/1002) State CONSUME_MEDIA going to sleep
2011-07-12 16:28:15.327806 [INFO] sofia.c:739 sofia/internal/1002 Update Callee ID to "Outbound Call" <1002>
2011-07-12 16:28:15.327806 [DEBUG] sofia.c:4760 Channel sofia/internal/1002 entering state [proceeding][180]
2011-07-12 16:28:15.327806 [NOTICE] sofia.c:4838 Ring-Ready sofia/internal/1002!
2011-07-12 16:28:15.351808 [DEBUG] switch_ivr_originate.c:1150 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2011-07-12 16:28:15.351808 [DEBUG] switch_core_codec.c:116 sofia/internal/1005@192.168.200.100 Push codec L16:70
2011-07-12 16:28:15.351808 [DEBUG] switch_ivr_originate.c:1182 Play Ringback File [local_stream://moh]
2011-07-12 16:28:15.351808 [DEBUG] mod_local_stream.c:421 Opening Stream [moh/8000] 8000hz
2011-07-12 16:28:37.390068 [WARNING] sofia_reg.c:1246 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1003@company-a.org] from ip 192.1
68.200.201
2011-07-12 16:28:37.477073 [WARNING] sofia_reg.c:1246 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1002@company-a.org] from ip 192.1
68.200.201
2011-07-12 16:28:37.577079 [WARNING] sofia_reg.c:1246 SIP auth challenge (REGISTER) on sofia profile 'internal' for [1001@company-a.org] from ip 192.1
68.200.201
2011-07-12 16:28:45.011504 [DEBUG] switch_core_codec.c:141 sofia/internal/1005@192.168.200.100 Restore previous codec PCMU:0.
2011-07-12 16:28:45.011504 [DEBUG] switch_channel.c:2563 (sofia/internal/1002) Callstate Change RINGING -> HANGUP
2011-07-12 16:28:45.011504 [NOTICE] switch_ivr_originate.c:3329 Hangup sofia/internal/1002 [CS_CONSUME_MEDIA] [NO_ANSWER]
2011-07-12 16:28:45.011504 [DEBUG] switch_channel.c:2579 Send signal sofia/internal/1002 [KILL]
2011-07-12 16:28:45.011504 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002 [BREAK]
2011-07-12 16:28:45.011504 [INFO] mod_dptools.c:2640 Originate Failed.  Cause: NO_ANSWER
2011-07-12 16:28:45.011504 [DEBUG] mod_dptools.c:2671 Failure causes [USER_BUSY]:  Cause: NO_ANSWER
EXECUTE sofia/internal/1005@192.168.200.100 answer()
EXECUTE sofia/internal/1005@192.168.200.100 sleep(1000)
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002) Running State Change CS_HANGUP
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1002) State HANGUP
2011-07-12 16:28:45.011504 [DEBUG] mod_sofia.c:457 Channel sofia/internal/1002 hanging up, cause: NO_ANSWER
2011-07-12 16:28:45.011504 [DEBUG] mod_sofia.c:510 Sending CANCEL to sofia/internal/1002
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:46 sofia/internal/1002 Standard HANGUP, cause: NO_ANSWER
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:565 (sofia/internal/1002) State HANGUP going to sleep
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:356 (sofia/internal/1002) State Change CS_HANGUP -> CS_REPORTING
2011-07-12 16:28:45.011504 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002 [BREAK]
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:325 (sofia/internal/1002) Running State Change CS_REPORTING
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/1002) State REPORTING
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:53 sofia/internal/1002 Standard REPORTING, cause: NO_ANSWER
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:625 (sofia/internal/1002) State REPORTING going to sleep
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:350 (sofia/internal/1002) State Change CS_REPORTING -> CS_DESTROY
2011-07-12 16:28:45.011504 [DEBUG] switch_core_session.c:1116 Send signal sofia/internal/1002 [BREAK]
2011-07-12 16:28:45.011504 [DEBUG] switch_core_session.c:1288 Session 3 (sofia/internal/1002) Locked, Waiting on external entities
2011-07-12 16:28:45.011504 [NOTICE] switch_core_session.c:1306 Session 3 (sofia/internal/1002) Ended
2011-07-12 16:28:45.011504 [NOTICE] switch_core_session.c:1308 Close Channel sofia/internal/1002 [CS_DESTROY]
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:454 (sofia/internal/1002) Callstate Change HANGUP -> DOWN
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:457 (sofia/internal/1002) Running State Change CS_DESTROY
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1002) State DESTROY
2011-07-12 16:28:45.011504 [DEBUG] mod_sofia.c:362 sofia/internal/1002 SOFIA DESTROY
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002 Standard DESTROY
2011-07-12 16:28:45.011504 [DEBUG] switch_core_state_machine.c:467 (sofia/internal/1002) State DESTROY going to sleep
EXECUTE sofia/internal/1005@192.168.200.100 play_and_get_digits(2 5 3 4000 # C:\VSWITCH/sounds/en/us/callie/conference/8000/conf-pin.wav /invalid.wav
other_ext_var \d+)
2011-07-12 16:28:46.017562 [DEBUG] switch_ivr_play_say.c:1278 Codec Activated L16@8000hz 1 channels 20ms
2011-07-12 16:28:47.751661 [DEBUG] switch_ivr_play_say.c:1648 done playing file
2011-07-12 16:28:51.771891 [ERR] mod_sndfile.c:194 Error Opening File [/invalid.wav] [System error : 系统找不到指定的文件。
]
2011-07-12 16:28:51.771891 [DEBUG] switch_ivr_play_say.c:1278 Codec Activated L16@8000hz 1 channels 20ms
2011-07-12 16:28:53.511990 [DEBUG] switch_ivr_play_say.c:1648 done playing file
2011-07-12 16:28:57.531220 [ERR] mod_sndfile.c:194 Error Opening File [/invalid.wav] [System error : 系统找不到指定的文件。
]
2011-07-12 16:28:57.531220 [DEBUG] switch_ivr_play_say.c:1278 Codec Activated L16@8000hz 1 channels 20ms