root@gw-broll:~# tail -f /var/log/freeswitch/freeswitch.log | grep -i test
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.701338 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/test2@10.250.0.26 [130da42b-2c25-405c-b9a5-622d238e1cbc]
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.701338 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/test2@10.250.0.26) Running State Change CS_NEW (Cur 23 Tot 43086)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.701338 [DEBUG] sofia.c:9815 sofia/internal/test2@10.250.0.26 receiving invite from 154.118.255.150:43332 version: 1.6.14 -23-e460bf8 64bit
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.701338 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/test2@10.250.0.26) State NEW
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.821352 [DEBUG] sofia.c:9815 sofia/internal/test2@10.250.0.26 receiving invite from 154.118.255.150:43332 version: 1.6.14 -23-e460bf8 64bit
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.821352 [DEBUG] sofia.c:7041 Channel sofia/internal/test2@10.250.0.26 entering state [received][100]
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_media.c:3043 Set Codec sofia/internal/test2@10.250.0.26 G729/8000 20 ms 160 samples 8000 bits 1 channels
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_codec.c:111 sofia/internal/test2@10.250.0.26 Original read codec set to G729:18
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_media.c:4696 sofia/internal/test2@10.250.0.26 Set 2833 dtmf send payload to 101 recv payload to 101
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] sofia.c:7464 (sofia/internal/test2@10.250.0.26) State Change CS_NEW -> CS_INIT
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/test2@10.250.0.26) Running State Change CS_INIT (Cur 23 Tot 43086)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/test2@10.250.0.26) State INIT
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] mod_sofia.c:90 sofia/internal/test2@10.250.0.26 SOFIA INIT
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:40 sofia/internal/test2@10.250.0.26 Standard INIT
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/test2@10.250.0.26) State Change CS_INIT -> CS_ROUTING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/test2@10.250.0.26) State INIT going to sleep
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/test2@10.250.0.26) Running State Change CS_ROUTING (Cur 23 Tot 43086)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_channel.c:2249 (sofia/internal/test2@10.250.0.26) Callstate Change DOWN -> RINGING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/test2@10.250.0.26) State ROUTING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] mod_sofia.c:143 sofia/internal/test2@10.250.0.26 SOFIA ROUTING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [DEBUG] switch_core_state_machine.c:236 sofia/internal/test2@10.250.0.26 Standard ROUTING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.841348 [INFO] mod_dialplan_xml.c:637 Processing test2 <test2>->0105914607 in context 10.250.0.26
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->user_exists] continue=true
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (PASS) [user_exists] () =~ // break=on-false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(user_exists=${user_exists id ${destination_number} ${domain_name}}) INLINE
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(user_exists=false)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [user_exists]=[false]
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (FAIL) [user_exists] ${user_exists}(false) =~ /^true$/ break=on-false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->call-direction] continue=true
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (FAIL) [call-direction] ${call_direction}() =~ /^(inbound|outbound|local)$/ break=never
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 ANTI-Action set(call_direction=local)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->variables] continue=true
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (PASS) [variables] () =~ // break=on-false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action export(origination_callee_id_name=${destination_number})
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->user_record] continue=true
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->redial] continue=true
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (FAIL) [redial] destination_number(0105914607) =~ /^(redial|\*870)$/ break=on-true
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (PASS) [redial] () =~ // break=never
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->speed_dial] continue=false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (FAIL) [speed_dial] destination_number(0105914607) =~ /^\*0(.*)$/ break=on-false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 parsing [10.250.0.26->brollheadoffice2.10d] continue=false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (PASS) [brollheadoffice2.10d] ${toll_allow}(test) =~ /test/ break=on-false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (FAIL) [brollheadoffice2.10d] ${sip_from_user}(test2) =~ /test22/ break=never
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Regex (PASS) [brollheadoffice2.10d] destination_number(0105914607) =~ /^(\d{10})$/ break=on-false
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(sip_h_X-accountcode=${accountcode})
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(call_direction=outbound)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(hangup_after_bridge=true)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(effective_caller_id_name=${outbound_caller_id_name})
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(effective_caller_id_number=54321)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(inherit_codec=true)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(ignore_display_updates=true)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action set(callee_id_number=0105914607)
130da42b-2c25-405c-b9a5-622d238e1cbc Dialplan: sofia/internal/test2@10.250.0.26 Action bridge(sofia/gateway/4664a203-ad95-4333-9941-ba18f566a1d4/0105914607)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/test2@10.250.0.26) State Change CS_ROUTING -> CS_EXECUTE
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/test2@10.250.0.26) State ROUTING going to sleep
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/test2@10.250.0.26) Running State Change CS_EXECUTE (Cur 23 Tot 43086)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/test2@10.250.0.26) State EXECUTE
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] mod_sofia.c:198 sofia/internal/test2@10.250.0.26 SOFIA EXECUTE
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] switch_core_state_machine.c:328 sofia/internal/test2@10.250.0.26 Standard EXECUTE
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(call_direction=local)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.881346 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [call_direction]=[local]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 export(origination_callee_id_name=0105914607)
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(RFC2822_DATE=Thu, 16 Feb 2017 15:51:03 +0200)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [RFC2822_DATE]=[Thu, 16 Feb 2017 15:51:03 +0200]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 hash(insert/10.250.0.26-last_dial/test2/0105914607)
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(sip_h_X-accountcode=10.250.0.26)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [sip_h_X-accountcode]=[10.250.0.26]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(call_direction=outbound)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [call_direction]=[outbound]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(hangup_after_bridge=true)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [hangup_after_bridge]=[true]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(effective_caller_id_name=)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [effective_caller_id_name]=[UNDEF]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(effective_caller_id_number=54321)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [effective_caller_id_number]=[54321]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(inherit_codec=true)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [inherit_codec]=[true]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(ignore_display_updates=true)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [ignore_display_updates]=[true]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 set(callee_id_number=0105914607)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] mod_dptools.c:1527 SET sofia/internal/test2@10.250.0.26 [callee_id_number]=[0105914607]
130da42b-2c25-405c-b9a5-622d238e1cbc EXECUTE sofia/internal/test2@10.250.0.26 bridge(sofia/gateway/4664a203-ad95-4333-9941-ba18f566a1d4/0105914607)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] switch_channel.c:1250 sofia/internal/test2@10.250.0.26 EXPORTING[export_vars] [domain_name]=[10.250.0.26] to event
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:03.901336 [DEBUG] switch_channel.c:1250 sofia/internal/test2@10.250.0.26 EXPORTING[export_vars] [origination_callee_id_name]=[0105914607] to event
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:04.101357 [NOTICE] mod_sofia.c:2262 Ring-Ready sofia/internal/test2@10.250.0.26!
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:04.101357 [DEBUG] sofia.c:7041 Channel sofia/internal/test2@10.250.0.26 entering state [early][180]
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:04.101357 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/internal/test2@10.250.0.26!
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.541353 [DEBUG] sofia.c:7041 Channel sofia/internal/test2@10.250.0.26 entering state [terminated][487]
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.541353 [NOTICE] sofia.c:8212 Hangup sofia/internal/test2@10.250.0.26 [CS_EXECUTE] [ORIGINATOR_CANCEL]
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_session.c:2797 sofia/internal/test2@10.250.0.26 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/test2@10.250.0.26) State EXECUTE going to sleep
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/test2@10.250.0.26) Running State Change CS_HANGUP (Cur 23 Tot 43087)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/test2@10.250.0.26) Callstate Change RINGING -> HANGUP
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/test2@10.250.0.26) State HANGUP
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] mod_sofia.c:438 Channel sofia/internal/test2@10.250.0.26 hanging up, cause: ORIGINATOR_CANCEL
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:60 sofia/internal/test2@10.250.0.26 Standard HANGUP, cause: ORIGINATOR_CANCEL
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/test2@10.250.0.26) State HANGUP going to sleep
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/test2@10.250.0.26) State Change CS_HANGUP -> CS_REPORTING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/test2@10.250.0.26) Running State Change CS_REPORTING (Cur 23 Tot 43087)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/test2@10.250.0.26) State REPORTING
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:174 sofia/internal/test2@10.250.0.26 Standard REPORTING, cause: ORIGINATOR_CANCEL
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/test2@10.250.0.26) State REPORTING going to sleep
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/test2@10.250.0.26) State Change CS_REPORTING -> CS_DESTROY
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_session.c:1647 Session 43086 (sofia/internal/test2@10.250.0.26) Locked, Waiting on external entities
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [NOTICE] switch_core_session.c:1665 Session 43086 (sofia/internal/test2@10.250.0.26) Ended
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [NOTICE] switch_core_session.c:1669 Close Channel sofia/internal/test2@10.250.0.26 [CS_DESTROY]
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/test2@10.250.0.26) Running State Change CS_DESTROY (Cur 22 Tot 43087)
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/test2@10.250.0.26) State DESTROY
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] mod_sofia.c:343 sofia/internal/test2@10.250.0.26 SOFIA DESTROY
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:181 sofia/internal/test2@10.250.0.26 Standard DESTROY
130da42b-2c25-405c-b9a5-622d238e1cbc 2017-02-16 15:51:05.561333 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/test2@10.250.0.26) State DESTROY going to sleep
^C
root@gw-broll:~#