2017-03-14 16:10:15.227400 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1002@192.168.0.104:5060 [693e04e7-7fe7-414b-ac7c-74bdc3422141]
2017-03-14 16:10:15.227400 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_NEW (Cur 1 Tot 16)
2017-03-14 16:10:15.227400 [DEBUG] sofia.c:10016 sofia/internal/1002@192.168.0.104:5060 receiving invite from 192.168.0.105:59753 version: 1.9.0 git 91d62b7 2017-02-24 22:49:43Z 64bit
2017-03-14 16:10:15.227400 [DEBUG] sofia.c:10187 IP 192.168.0.105 Rejected by acl "domains". Falling back to Digest auth.
2017-03-14 16:10:15.227400 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/1002@192.168.0.104:5060) State NEW
2017-03-14 16:10:15.237401 [DEBUG] sofia.c:2405 detaching session 693e04e7-7fe7-414b-ac7c-74bdc3422141
2017-03-14 16:10:15.237401 [DEBUG] sofia.c:2514 Re-attaching to session 693e04e7-7fe7-414b-ac7c-74bdc3422141
2017-03-14 16:10:15.247407 [DEBUG] sofia.c:10016 sofia/internal/1002@192.168.0.104:5060 receiving invite from 192.168.0.105:59753 version: 1.9.0 git 91d62b7 2017-02-24 22:49:43Z 64bit
2017-03-14 16:10:15.257443 [DEBUG] sofia.c:10187 IP 192.168.0.105 Rejected by acl "domains". Falling back to Digest auth.
2017-03-14 16:10:15.257443 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [received][100]
2017-03-14 16:10:15.257443 [DEBUG] sofia.c:7251 Remote SDP:
v=0
o=Zoiper 0 0 IN IP4 192.168.0.105
s=Zoiper
c=IN IP4 192.168.0.105
t=0 0
m=audio 54518 RTP/AVP 3 0 8 101
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16

2017-03-14 16:10:15.257443 [DEBUG] sofia.c:7643 (sofia/internal/1002@192.168.0.104:5060) State Change CS_NEW -> CS_INIT
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_INIT (Cur 1 Tot 16)
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@192.168.0.104:5060) State INIT
2017-03-14 16:10:15.257443 [DEBUG] mod_sofia.c:93 sofia/internal/1002@192.168.0.104:5060 SOFIA INIT
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1002@192.168.0.104:5060 Standard INIT
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1002@192.168.0.104:5060) State Change CS_INIT -> CS_ROUTING
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1002@192.168.0.104:5060) State INIT going to sleep
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_ROUTING (Cur 1 Tot 16)
2017-03-14 16:10:15.257443 [DEBUG] switch_channel.c:2249 (sofia/internal/1002@192.168.0.104:5060) Callstate Change DOWN -> RINGING
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@192.168.0.104:5060) State ROUTING
2017-03-14 16:10:15.257443 [DEBUG] mod_sofia.c:154 sofia/internal/1002@192.168.0.104:5060 SOFIA ROUTING
2017-03-14 16:10:15.257443 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1002@192.168.0.104:5060 Standard ROUTING
2017-03-14 16:10:15.257443 [INFO] mod_dialplan_xml.c:637 Processing 1002 <1002>->1000 in context default
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1002@192.168.0.104:5060 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(open=true) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1002@192.168.0.104:5060 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global-intercept] destination_number(1000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [group-intercept] destination_number(1000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [intercept-ext] destination_number(1000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->redial] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [redial] destination_number(1000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->global] continue=true
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${default_password}(12345) =~ /^1234$/ break=never
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [global] ${switch_r_sdp}(v=0
o=Zoiper 0 0 IN IP4 192.168.0.105
s=Zoiper
c=IN IP4 192.168.0.105
t=0 0
m=audio 54518 RTP/AVP 3 0 8 101
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1002@192.168.0.104:5060 Absolute Condition [global]
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial/global/${uuid}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [snom-demo-2] destination_number(1000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [snom-demo-1] destination_number(1000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [call_return] destination_number(1000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [del-group] destination_number(1000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [add-group] destination_number(1000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [call-group-simo] destination_number(1000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [call-group-order] destination_number(1000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (FAIL) [extension-intercom] destination_number(1000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Regex (PASS) [Local_Extension] destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action export(dialed_extension=1000) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(1 b s execute_extension::dx XML features) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(3 b s execute_extension::cf XML features) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bind_meta_app(4 b s execute_extension::att_xfer XML features) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(ringback=${us-ring}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(transfer_ringback=local_stream://moh) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(call_timeout=30) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(hangup_after_bridge=true) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(continue_on_fail=true) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial_ext/global/${uuid}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bridge(user/${dialed_extension}@${domain_name}) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action answer() 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action sleep(1000) 
Dialplan: sofia/internal/1002@192.168.0.104:5060 Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension}) 
2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1002@192.168.0.104:5060) State Change CS_ROUTING -> CS_EXECUTE
2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1002@192.168.0.104:5060) State ROUTING going to sleep
2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_EXECUTE (Cur 1 Tot 16)
2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1002@192.168.0.104:5060) State EXECUTE
2017-03-14 16:10:15.267391 [DEBUG] mod_sofia.c:209 sofia/internal/1002@192.168.0.104:5060 SOFIA EXECUTE
2017-03-14 16:10:15.267391 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1002@192.168.0.104:5060 Standard EXECUTE
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(open=true)
2017-03-14 16:10:15.267391 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [open]=[true]
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-spymap/1002/693e04e7-7fe7-414b-ac7c-74bdc3422141)
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial/1002/1000)
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial/global/693e04e7-7fe7-414b-ac7c-74bdc3422141)
EXECUTE sofia/internal/1002@192.168.0.104:5060 export(RFC2822_DATE=Tue, 14 Mar 2017 16:10:15 +0000)
2017-03-14 16:10:15.267391 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000]
EXECUTE sofia/internal/1002@192.168.0.104:5060 export(dialed_extension=1000)
2017-03-14 16:10:15.267391 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[1000]
EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(1 b s execute_extension::dx XML features)
2017-03-14 16:10:15.267391 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1002.2017-03-14-16-10-15.wav)
2017-03-14 16:10:15.267391 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1002.2017-03-14-16-10-15.wav
EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(3 b s execute_extension::cf XML features)
2017-03-14 16:10:15.277399 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1002@192.168.0.104:5060 bind_meta_app(4 b s execute_extension::att_xfer XML features)
2017-03-14 16:10:15.277399 [INFO] switch_ivr_async.c:4247 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(ringback=%(2000,4000,440,480))
2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(transfer_ringback=local_stream://moh)
2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(call_timeout=30)
2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [call_timeout]=[30]
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(hangup_after_bridge=true)
2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(continue_on_fail=true)
2017-03-14 16:10:15.277399 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [continue_on_fail]=[true]
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-call_return/1000/1002)
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial_ext/1000/693e04e7-7fe7-414b-ac7c-74bdc3422141)
EXECUTE sofia/internal/1002@192.168.0.104:5060 set(called_party_callgroup=techsupport)
2017-03-14 16:10:15.287426 [DEBUG] mod_dptools.c:1567 SET sofia/internal/1002@192.168.0.104:5060 [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial_ext/techsupport/693e04e7-7fe7-414b-ac7c-74bdc3422141)
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial_ext/global/693e04e7-7fe7-414b-ac7c-74bdc3422141)
EXECUTE sofia/internal/1002@192.168.0.104:5060 hash(insert/192.168.0.104-last_dial/techsupport/693e04e7-7fe7-414b-ac7c-74bdc3422141)
EXECUTE sofia/internal/1002@192.168.0.104:5060 bridge(user/1000@192.168.0.104)
2017-03-14 16:10:15.287426 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000] to event
2017-03-14 16:10:15.287426 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [dialed_extension]=[1000] to event
2017-03-14 16:10:15.287426 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
2017-03-14 16:10:15.297424 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000] to event
2017-03-14 16:10:15.297424 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [dialed_extension]=[1000] to event
2017-03-14 16:10:15.297424 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
2017-03-14 16:10:15.297424 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1000@df7jal23ls0d.invalid [3c8be0a6-04bd-4dbe-bdb8-591b291a690d]
2017-03-14 16:10:15.297424 [DEBUG] mod_sofia.c:5002 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_NEW -> CS_INIT
2017-03-14 16:10:15.297424 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_INIT (Cur 2 Tot 17)
2017-03-14 16:10:15.297424 [NOTICE] switch_ivr_originate.c:2846 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED]
2017-03-14 16:10:15.297424 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@df7jal23ls0d.invalid) State INIT
2017-03-14 16:10:15.297424 [DEBUG] mod_sofia.c:93 sofia/internal/1000@df7jal23ls0d.invalid SOFIA INIT
2017-03-14 16:10:15.307415 [DEBUG] sofia_glue.c:1267 sips:1000@192.168.0.108:54417;rtcweb-breaker=yes;transport=wss Setting proxy route to sofia/internal/1000@df7jal23ls0d.invalid
2017-03-14 16:10:15.307415 [DEBUG] sofia_glue.c:1296 sofia/internal/1000@df7jal23ls0d.invalid sending invite version: 1.9.0 git 91d62b7 2017-02-24 22:49:43Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1489481037 1489481038 IN IP4 192.168.0.104
s=FreeSWITCH
c=IN IP4 192.168.0.104
t=0 0
a=msid-semantic: WMS UhujOL2NXyzeJCda1YFCSMeQvIaqHZxs
m=audio 26778 RTP/SAVPF 0 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fingerprint:sha-256 18:87:44:40:A4:B1:1B:D2:30:EC:DD:94:D7:73:09:EA:90:12:88:69:9F:15:0A:1B:A9:1A:C7:FD:07:48:82:72
a=setup:actpass
a=rtcp-mux
a=rtcp:26778 IN IP4 192.168.0.104
a=ssrc:2899064633 cname:7RCMtvphTOmthqu9
a=ssrc:2899064633 msid:UhujOL2NXyzeJCda1YFCSMeQvIaqHZxs a0
a=ssrc:2899064633 mslabel:UhujOL2NXyzeJCda1YFCSMeQvIaqHZxs
a=ssrc:2899064633 label:UhujOL2NXyzeJCda1YFCSMeQvIaqHZxsa0
a=ice-ufrag:eZBXCFDXeDeMtC5r
a=ice-pwd:ky3ETiLDXXX5dh4i7w5z2zn7
a=candidate:4650138928 1 udp 659136 192.168.0.104 26778 typ host generation 0
a=candidate:4650138928 2 udp 659136 192.168.0.104 26778 typ host generation 0
a=ptime:20
a=sendrecv

2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1000@df7jal23ls0d.invalid Standard INIT
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_INIT -> CS_ROUTING
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1000@df7jal23ls0d.invalid) State INIT going to sleep
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_ROUTING (Cur 2 Tot 17)
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@df7jal23ls0d.invalid) State ROUTING
2017-03-14 16:10:15.307415 [DEBUG] mod_sofia.c:154 sofia/internal/1000@df7jal23ls0d.invalid SOFIA ROUTING
2017-03-14 16:10:15.307415 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1000@df7jal23ls0d.invalid) State ROUTING going to sleep
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 17)
2017-03-14 16:10:15.307415 [DEBUG] sofia.c:7241 Channel sofia/internal/1000@df7jal23ls0d.invalid entering state [calling][0]
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1000@df7jal23ls0d.invalid) State CONSUME_MEDIA
2017-03-14 16:10:15.307415 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1000@df7jal23ls0d.invalid) State CONSUME_MEDIA going to sleep
2017-03-14 16:10:15.957397 [DEBUG] sofia.c:7241 Channel sofia/internal/1000@df7jal23ls0d.invalid entering state [proceeding][180]
2017-03-14 16:10:15.957397 [NOTICE] sofia.c:7349 Ring-Ready sofia/internal/1000@df7jal23ls0d.invalid!
2017-03-14 16:10:15.967419 [DEBUG] switch_channel.c:3353 (sofia/internal/1000@df7jal23ls0d.invalid) Callstate Change DOWN -> RINGING
2017-03-14 16:10:15.967419 [INFO] switch_ivr_originate.c:1220 Sending early media
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:4974 Set telephone-event payload to 101@8000
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:3414 Set Codec sofia/internal/1002@192.168.0.104:5060 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-03-14 16:10:15.967419 [DEBUG] switch_core_codec.c:111 sofia/internal/1002@192.168.0.104:5060 Original read codec set to PCMU:0
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5317 Set telephone-event payload to 101@8000
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:5376 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:7978 AUDIO RTP [sofia/internal/1002@192.168.0.104:5060] 192.168.0.104 port 19080 -> 192.168.0.105 port 54518 codec: 0 ms: 20
2017-03-14 16:10:15.967419 [DEBUG] switch_rtp.c:3888 Starting timer [soft] 160 bytes per 20ms
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:8286 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf send payload to 101
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:8293 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf receive payload to 101
2017-03-14 16:10:15.967419 [DEBUG] switch_core_media.c:8316 sofia/internal/1002@192.168.0.104:5060 Set rtp dtmf delay to 40
2017-03-14 16:10:15.967419 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1002@192.168.0.104:5060!
2017-03-14 16:10:15.977391 [DEBUG] switch_channel.c:3481 (sofia/internal/1002@192.168.0.104:5060) Callstate Change RINGING -> EARLY
2017-03-14 16:10:15.977391 [DEBUG] switch_core_media.c:7961 Audio params are unchanged for sofia/internal/1002@192.168.0.104:5060.
2017-03-14 16:10:15.977391 [DEBUG] mod_sofia.c:2502 Ring SDP:
v=0
o=FreeSWITCH 1489488735 1489488736 IN IP4 192.168.0.104
s=FreeSWITCH
c=IN IP4 192.168.0.104
t=0 0
m=audio 19080 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2017-03-14 16:10:15.977391 [DEBUG] switch_ivr_originate.c:1278 Raw Codec Activation Success L16@8000hz 1 channel 20ms
2017-03-14 16:10:15.977391 [DEBUG] switch_core_codec.c:223 sofia/internal/1002@192.168.0.104:5060 Push codec L16:100
2017-03-14 16:10:15.977391 [DEBUG] switch_ivr_originate.c:1347 Play Ringback Tone [%(2000,4000,440,480)]
2017-03-14 16:10:15.997389 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [early][183]
2017-03-14 16:10:16.367406 [DEBUG] switch_rtp.c:7020 Correct audio ip/port confirmed.
2017-03-14 16:10:45.007401 [DEBUG] switch_core_codec.c:248 sofia/internal/1002@192.168.0.104:5060 Restore previous codec PCMU:0.
2017-03-14 16:10:45.007401 [NOTICE] switch_ivr_originate.c:3606 Hangup sofia/internal/1000@df7jal23ls0d.invalid [CS_CONSUME_MEDIA] [NO_ANSWER]
2017-03-14 16:10:45.007401 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_HANGUP (Cur 2 Tot 17)
2017-03-14 16:10:45.007401 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1000@df7jal23ls0d.invalid) Callstate Change RINGING -> HANGUP
2017-03-14 16:10:45.007401 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@df7jal23ls0d.invalid) State HANGUP
2017-03-14 16:10:45.007401 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1000@df7jal23ls0d.invalid hanging up, cause: NO_ANSWER
2017-03-14 16:10:45.017409 [NOTICE] switch_ivr_originate.c:2846 Cannot create outgoing channel of type [user] cause: [NO_ANSWER]
2017-03-14 16:10:45.017409 [DEBUG] switch_ivr_originate.c:3834 Originate Resulted in Error Cause: 19 [NO_ANSWER]
2017-03-14 16:10:45.017409 [DEBUG] mod_sofia.c:513 Sending CANCEL to sofia/internal/1000@df7jal23ls0d.invalid
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1000@df7jal23ls0d.invalid Standard HANGUP, cause: NO_ANSWER
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1000@df7jal23ls0d.invalid) State HANGUP going to sleep
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_HANGUP -> CS_REPORTING
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_REPORTING (Cur 2 Tot 17)
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@df7jal23ls0d.invalid) State REPORTING
2017-03-14 16:10:45.017409 [INFO] mod_dptools.c:3481 Originate Failed.  Cause: NO_ANSWER
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1000@df7jal23ls0d.invalid Standard REPORTING, cause: NO_ANSWER
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1000@df7jal23ls0d.invalid) State REPORTING going to sleep
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1000@df7jal23ls0d.invalid) State Change CS_REPORTING -> CS_DESTROY
2017-03-14 16:10:45.017409 [DEBUG] switch_core_session.c:1712 Session 17 (sofia/internal/1000@df7jal23ls0d.invalid) Locked, Waiting on external entities
EXECUTE sofia/internal/1002@192.168.0.104:5060 answer()
2017-03-14 16:10:45.017409 [NOTICE] switch_core_session.c:1730 Session 17 (sofia/internal/1000@df7jal23ls0d.invalid) Ended
2017-03-14 16:10:45.017409 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1000@df7jal23ls0d.invalid [CS_DESTROY]
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1000@df7jal23ls0d.invalid) Running State Change CS_DESTROY (Cur 1 Tot 17)
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@df7jal23ls0d.invalid) State DESTROY
2017-03-14 16:10:45.017409 [DEBUG] mod_sofia.c:354 sofia/internal/1000@df7jal23ls0d.invalid SOFIA DESTROY
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1000@df7jal23ls0d.invalid Standard DESTROY
2017-03-14 16:10:45.017409 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1000@df7jal23ls0d.invalid) State DESTROY going to sleep
2017-03-14 16:10:45.017409 [DEBUG] switch_core_media.c:7961 Audio params are unchanged for sofia/internal/1002@192.168.0.104:5060.
2017-03-14 16:10:45.017409 [DEBUG] mod_sofia.c:881 Local SDP sofia/internal/1002@192.168.0.104:5060:
v=0
o=FreeSWITCH 1489488735 1489488737 IN IP4 192.168.0.104
s=FreeSWITCH
c=IN IP4 192.168.0.104
t=0 0
m=audio 19080 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2017-03-14 16:10:45.017409 [NOTICE] mod_dptools.c:1349 Channel [sofia/internal/1002@192.168.0.104:5060] has been answered
2017-03-14 16:10:45.017409 [DEBUG] switch_channel.c:3780 (sofia/internal/1002@192.168.0.104:5060) Callstate Change EARLY -> ACTIVE
2017-03-14 16:10:45.017409 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [completed][200]
EXECUTE sofia/internal/1002@192.168.0.104:5060 sleep(1000)
2017-03-14 16:10:45.047403 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [ready][200]
2017-03-14 16:10:45.347407 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [received][100]
2017-03-14 16:10:45.347407 [DEBUG] sofia.c:7251 Remote SDP:
v=0
o=Zoiper 0 1 IN IP4 192.168.0.105
s=Zoiper
c=IN IP4 192.168.0.105
t=0 0
m=audio 54518 RTP/AVP 0 3 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
m=video 54520 RTP/AVP 116 115
a=rtpmap:116 VP8/90000
a=rtpmap:115 H263-1998/90000

2017-03-14 16:10:45.347407 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5058 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5113 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:4974 Set telephone-event payload to 101@8000
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5317 Set telephone-event payload to 101@8000
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5376 sofia/internal/1002@192.168.0.104:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5659 Video Codec Compare [VP8:116]/[VP8:99]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5691 Video Codec Compare [VP8:116] +++ is saved as a match
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:5659 Video Codec Compare [H263-1998:115]/[VP8:99]
2017-03-14 16:10:45.357402 [DEBUG] switch_vpx.c:627 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7
2017-03-14 16:10:45.357402 [DEBUG] switch_vpx.c:627 VPX VER:v1.6.0 VPX_IMAGE_ABI_VERSION:4 VPX_CODEC_ABI_VERSION:7
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:3224 Set VIDEO Codec sofia/internal/1002@192.168.0.104:5060 VP8/90000 0 ms
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:7961 Audio params are unchanged for sofia/internal/1002@192.168.0.104:5060.
2017-03-14 16:10:45.357402 [DEBUG] switch_rtp.c:3899 Starting video timer.
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:8816 VIDEO RTP [sofia/internal/1002@192.168.0.104:5060] 192.168.0.104:32376->192.168.0.105:54520 codec: 116 ms: 0 [SUCCESS]
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:6977 sofia/internal/1002@192.168.0.104:5060 Starting Video thread
2017-03-14 16:10:45.357402 [DEBUG] sofia.c:8144 Processing updated SDP
2017-03-14 16:10:45.357402 [DEBUG] switch_core_media.c:6843 sofia/internal/1002@192.168.0.104:5060 Video thread started. Echo is off
2017-03-14 16:10:45.367394 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [completed][200]
2017-03-14 16:10:45.407397 [DEBUG] sofia.c:7241 Channel sofia/internal/1002@192.168.0.104:5060 entering state [ready][200]
2017-03-14 16:10:45.407397 [NOTICE] switch_vpx.c:402 VPX reset encoder picture from 320x240 to 352x288 1024 BW
2017-03-14 16:10:45.807396 [DEBUG] switch_rtp.c:7020 Correct video ip/port confirmed.
2017-03-14 16:10:45.827399 [DEBUG] switch_rtp.c:7020 Correct audio ip/port confirmed.
EXECUTE sofia/internal/1002@192.168.0.104:5060 bridge(loopback/app=voicemail:default 192.168.0.104 1000)
2017-03-14 16:10:46.027393 [DEBUG] switch_channel.c:1823 (sofia/internal/1002@192.168.0.104:5060) Callstate Change ACTIVE -> RING_WAIT
2017-03-14 16:10:46.037416 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [RFC2822_DATE]=[Tue, 14 Mar 2017 16:10:15 +0000] to event
2017-03-14 16:10:46.037416 [DEBUG] switch_channel.c:1250 sofia/internal/1002@192.168.0.104:5060 EXPORTING[export_vars] [dialed_extension]=[1000] to event
2017-03-14 16:10:46.037416 [DEBUG] switch_ivr_originate.c:2143 Parsing global variables
2017-03-14 16:10:46.037416 [NOTICE] switch_channel.c:1104 New Channel loopback/app=voicemail:default 192.168.0.104 1000-a [40d5a7ce-344b-42df-8c28-b4f8dd5c2d0f]
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:158 loopback/app=voicemail:default 192.168.0.104 1000-a setup codec PCMU/8000/20
2017-03-14 16:10:46.037416 [NOTICE] switch_channel.c:1102 Rename Channel loopback/app=voicemail:default 192.168.0.104 1000-a->loopback/voicemail-a [40d5a7ce-344b-42df-8c28-b4f8dd5c2d0f]
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:1176 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_INIT (Cur 2 Tot 18)
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT
2017-03-14 16:10:46.037416 [NOTICE] switch_channel.c:1104 New Channel loopback/voicemail-b [25db1ead-5b83-4bc1-b5bd-7c78e6661bc5]
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:158 loopback/voicemail-b setup codec PCMU/8000/20
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:276 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:364 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_INIT (Cur 3 Tot 19)
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-a) State INIT going to sleep
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:364 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:627 (loopback/voicemail-b) State INIT going to sleep
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_ROUTING (Cur 3 Tot 19)
2017-03-14 16:10:46.037416 [DEBUG] switch_channel.c:2249 (loopback/voicemail-b) Callstate Change DOWN -> RINGING
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_ROUTING (Cur 3 Tot 19)
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:396 loopback/voicemail-b CHANNEL ROUTING
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:415 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:396 loopback/voicemail-a CHANNEL ROUTING
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-b) State ROUTING going to sleep
2017-03-14 16:10:46.037416 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_EXECUTE (Cur 3 Tot 19)
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:643 (loopback/voicemail-a) State ROUTING going to sleep
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA (Cur 3 Tot 19)
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:438 loopback/voicemail-b CHANNEL EXECUTE
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:328 loopback/voicemail-b Standard EXECUTE
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA
EXECUTE loopback/voicemail-b pre_answer()
2017-03-14 16:10:46.037416 [DEBUG] mod_loopback.c:663 CHANNEL CONSUME_MEDIA
2017-03-14 16:10:46.037416 [DEBUG] switch_core_state_machine.c:662 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep
2017-03-14 16:10:46.037416 [NOTICE] mod_loopback.c:963 Pre-Answer loopback/voicemail-a!
2017-03-14 16:10:46.047392 [DEBUG] switch_channel.c:3481 (loopback/voicemail-a) Callstate Change DOWN -> EARLY
2017-03-14 16:10:46.047392 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:46.047392 [NOTICE] mod_dptools.c:1392 Pre-Answer loopback/voicemail-b!
2017-03-14 16:10:46.047392 [DEBUG] switch_channel.c:3481 (loopback/voicemail-b) Callstate Change RINGING -> EARLY
2017-03-14 16:10:46.047392 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
EXECUTE loopback/voicemail-b voicemail(default 192.168.0.104 1000)
2017-03-14 16:10:46.047392 [DEBUG] switch_ivr_originate.c:3691 Originate Resulted in Success: [loopback/voicemail-a]
2017-03-14 16:10:46.047392 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.057401 [DEBUG] switch_channel.c:2047 (sofia/internal/1002@192.168.0.104:5060) Callstate Change RING_WAIT -> ACTIVE
2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.057401 [DEBUG] switch_ivr_bridge.c:1696 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:46.057401 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA (Cur 3 Tot 19)
2017-03-14 16:10:46.057401 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA
2017-03-14 16:10:46.057401 [DEBUG] mod_loopback.c:625 CHANNEL LOOPBACK
2017-03-14 16:10:46.157407 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2017-03-14 16:10:46.207422 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
2017-03-14 16:10:46.207422 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:46.207422 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-03-14 16:10:47.537399 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
2017-03-14 16:10:47.637403 [DEBUG] switch_ivr_play_say.c:250 Handle say:[1000] (en:en)
2017-03-14 16:10:47.647409 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:47.647409 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-03-14 16:10:49.937414 [DEBUG] switch_ivr_play_say.c:1942 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/0.wav
2017-03-14 16:10:50.057402 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-not_available.wav] (en:en)
2017-03-14 16:10:50.067409 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:50.067409 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-03-14 16:10:51.037398 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav
2017-03-14 16:10:51.137427 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2017-03-14 16:10:51.187391 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-record_message.wav] (en:en)
2017-03-14 16:10:51.187391 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:51.187391 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-03-14 16:10:52.497420 [NOTICE] sofia.c:1079 Hangup sofia/internal/1002@192.168.0.104:5060 [CS_EXECUTE] [NORMAL_CLEARING]
2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:792 sofia/internal/1002@192.168.0.104:5060 ending bridge by request from write function
2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:882 BRIDGE THREAD DONE [loopback/voicemail-a]
2017-03-14 16:10:52.497420 [DEBUG] switch_core_media.c:13560 sofia/internal/1002@192.168.0.104:5060 skip receive message [DISPLAY] (channel is hungup already)
2017-03-14 16:10:52.497420 [NOTICE] switch_ivr_bridge.c:984 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:653 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_HANGUP (Cur 3 Tot 19)
2017-03-14 16:10:52.497420 [DEBUG] switch_core_media.c:6944 sofia/internal/1002@192.168.0.104:5060 Video thread ended
2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:882 BRIDGE THREAD DONE [sofia/internal/1002@192.168.0.104:5060]
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP
2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:550 loopback/voicemail-a CHANNEL HANGUP
2017-03-14 16:10:52.497420 [NOTICE] mod_loopback.c:566 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL]
2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:1795 loopback/voicemail-a skip receive message [TRANSFER] (channel is hungup already)
2017-03-14 16:10:52.497420 [DEBUG] switch_ivr_bridge.c:1798 sofia/internal/1002@192.168.0.104:5060 skip receive message [TRANSFER] (channel is hungup already)
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-a) State HANGUP going to sleep
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-a) Running State Change CS_REPORTING (Cur 3 Tot 19)
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_session.c:2884 sofia/internal/1002@192.168.0.104:5060 skip receive message [PHONE_EVENT] (channel is hungup already)
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-a) State REPORTING going to sleep
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1002@192.168.0.104:5060) State EXECUTE going to sleep
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_HANGUP (Cur 3 Tot 19)
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY
2017-03-14 16:10:52.497420 [DEBUG] mod_loopback.c:603 loopback/voicemail-a CHANNEL KILL
2017-03-14 16:10:52.497420 [DEBUG] switch_core_session.c:1712 Session 18 (loopback/voicemail-a) Locked, Waiting on external entities
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1002@192.168.0.104:5060) Callstate Change ACTIVE -> HANGUP
2017-03-14 16:10:52.497420 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@192.168.0.104:5060) State HANGUP
2017-03-14 16:10:52.497420 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1002@192.168.0.104:5060 hanging up, cause: NORMAL_CLEARING
2017-03-14 16:10:52.507397 [DEBUG] switch_core_session.c:2884 loopback/voicemail-b skip receive message [PHONE_EVENT] (channel is hungup already)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:650 (loopback/voicemail-b) State EXECUTE going to sleep
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_HANGUP (Cur 3 Tot 19)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1002@192.168.0.104:5060 Standard HANGUP, cause: NORMAL_CLEARING
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:850 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1002@192.168.0.104:5060) State HANGUP going to sleep
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP
2017-03-14 16:10:52.507397 [DEBUG] mod_loopback.c:550 loopback/voicemail-b CHANNEL HANGUP
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:852 (loopback/voicemail-b) State HANGUP going to sleep
2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1730 Session 18 (loopback/voicemail-a) Ended
2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1734 Close Channel loopback/voicemail-a [CS_DESTROY]
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:619 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING
2017-03-14 16:10:52.507397 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:584 (loopback/voicemail-b) Running State Change CS_REPORTING (Cur 2 Tot 19)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1002@192.168.0.104:5060) State Change CS_HANGUP -> CS_REPORTING
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:174 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (loopback/voicemail-b) State REPORTING going to sleep
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_REPORTING (Cur 2 Tot 19)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-a) Running State Change CS_DESTROY (Cur 2 Tot 19)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:610 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY
2017-03-14 16:10:52.507397 [DEBUG] mod_loopback.c:603 loopback/voicemail-b CHANNEL KILL
2017-03-14 16:10:52.507397 [DEBUG] switch_core_session.c:1712 Session 19 (loopback/voicemail-b) Locked, Waiting on external entities
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-a Standard DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-a) State DESTROY going to sleep
2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1730 Session 19 (loopback/voicemail-b) Ended
2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1734 Close Channel loopback/voicemail-b [CS_DESTROY]
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@192.168.0.104:5060) State REPORTING
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:741 (loopback/voicemail-b) Running State Change CS_DESTROY (Cur 1 Tot 19)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1002@192.168.0.104:5060 Standard REPORTING, cause: NORMAL_CLEARING
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1002@192.168.0.104:5060) State REPORTING going to sleep
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:181 loopback/voicemail-b Standard DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (loopback/voicemail-b) State DESTROY going to sleep
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1002@192.168.0.104:5060) State Change CS_REPORTING -> CS_DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_session.c:1712 Session 16 (sofia/internal/1002@192.168.0.104:5060) Locked, Waiting on external entities
2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1730 Session 16 (sofia/internal/1002@192.168.0.104:5060) Ended
2017-03-14 16:10:52.507397 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1002@192.168.0.104:5060 [CS_DESTROY]
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1002@192.168.0.104:5060) Running State Change CS_DESTROY (Cur 0 Tot 19)
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@192.168.0.104:5060) State DESTROY
2017-03-14 16:10:52.507397 [DEBUG] mod_sofia.c:354 sofia/internal/1002@192.168.0.104:5060 SOFIA DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1002@192.168.0.104:5060 Standard DESTROY
2017-03-14 16:10:52.507397 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1002@192.168.0.104:5060) State DESTROY going to sleep