Hi All,
I tried with 1.4, but it is still not working. The issue is FS is not setting call with Leg-B. I have made following config changes

1. In var.xml, set following
<X-PRE-PROCESS cmd="set" data="rtp_secure_media=optional"/>
2. In default.xml set following
<action application="export" data="rtp_secure_media=true"/>

In logs, I can see following error (while calling 1000 from 1001) -

2014-10-05 23:09:36.007270 [DEBUG] switch_ivr_originate.c:3695 Originate Resulted in Error Cause: 19 [NO_ANSWER]

But 1000 does not receive any INVITE message

Any pointer on this?

Please find below logs from FS console -

freeswitch@atul-amd>
freeswitch@atul-amd>
freeswitch@atul-amd> show registrations

reg_user,realm,token,url,expires,network_ip,network_port,network_proto,hostname,metadata
1001,192.168.0.103,2893d7a0-0605-4030-8094-e28be54c076f,sofia/internal/sip:1001@192.168.0.103:7001;transport=TLS;ob,1412531006,192.168.0.103,48732,tls,atul-amd,
1000,192.168.0.103,8d115512-6ee5-47bc-8dfe-1ff980e66166,sofia/internal/sip:1000@192.168.0.103:6001;transport=TLS;ob,1412531010,192.168.0.103,49206,tls,atul-amd,

2 total.

freeswitch@atul-amd> 2014-10-05 23:08:55.967291 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/1001@pbx.myfreeswitch.org [24cb8d75-8119-4814-8530-d6b262194dfe]
2014-10-05 23:08:55.967291 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:55.967291 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_NEW
2014-10-05 23:08:55.967291 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:55.967291 [DEBUG] sofia.c:8570 sofia/internal/1001@pbx.myfreeswitch.org receiving invite from 192.168.0.103:48732 version: 1.4.8 git 498f586 2014-08-25 16:34:46Z 32bit
2014-10-05 23:08:55.967291 [DEBUG] sofia.c:8737 IP 192.168.0.103 Rejected by acl "domains". Falling back to Digest auth.
2014-10-05 23:08:55.967291 [DEBUG] switch_core_state_machine.c:491 (sofia/internal/1001@pbx.myfreeswitch.org) State NEW
2014-10-05 23:08:55.967291 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:55.967291 [DEBUG] sofia.c:2062 detaching session 24cb8d75-8119-4814-8530-d6b262194dfe
2014-10-05 23:08:56.007269 [DEBUG] sofia.c:2169 Re-attaching to session 24cb8d75-8119-4814-8530-d6b262194dfe
2014-10-05 23:08:56.007269 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:56.007269 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:56.027269 [DEBUG] sofia.c:8570 sofia/internal/1001@pbx.myfreeswitch.org receiving invite from 192.168.0.103:48732 version: 1.4.8 git 498f586 2014-08-25 16:34:46Z 32bit
2014-10-05 23:08:56.027269 [DEBUG] sofia.c:8737 IP 192.168.0.103 Rejected by acl "domains". Falling back to Digest auth.
2014-10-05 23:08:56.027269 [DEBUG] sofia.c:6408 Channel sofia/internal/1001@pbx.myfreeswitch.org entering state [received][100]
2014-10-05 23:08:56.027269 [DEBUG] sofia.c:6418 Remote SDP:
v=0
o=- 3621519535 3621519535 IN IP4 192.168.0.103
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 9000 RTP/SAVP 98 97 99 104 3 0 8 9 96
c=IN IP4 192.168.0.103
b=AS:64000
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:99 speex/32000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=rtcp:9001 IN IP4 192.168.0.103
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:/RZABbN0vRSybRtruRATkMrKo/P6wezyNcSkp0AX

2014-10-05 23:08:56.027269 [DEBUG] sofia.c:6673 (sofia/internal/1001@pbx.myfreeswitch.org) State Change CS_NEW -> CS_INIT
2014-10-05 23:08:56.027269 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:56.027269 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_INIT
2014-10-05 23:08:56.027269 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1001@pbx.myfreeswitch.org) State INIT
2014-10-05 23:08:56.027269 [DEBUG] mod_sofia.c:87 sofia/internal/1001@pbx.myfreeswitch.org SOFIA INIT
2014-10-05 23:08:56.027269 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@pbx.myfreeswitch.org Standard INIT
2014-10-05 23:08:56.027269 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@pbx.myfreeswitch.org) State Change CS_INIT -> CS_ROUTING
2014-10-05 23:08:56.027269 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:56.027269 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/1001@pbx.myfreeswitch.org) State INIT going to sleep
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_ROUTING
2014-10-05 23:08:56.047282 [DEBUG] switch_channel.c:2184 (sofia/internal/1001@pbx.myfreeswitch.org) Callstate Change DOWN -> RINGING
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1001@pbx.myfreeswitch.org) State ROUTING
2014-10-05 23:08:56.047282 [DEBUG] mod_sofia.c:123 sofia/internal/1001@pbx.myfreeswitch.org SOFIA ROUTING
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:166 sofia/internal/1001@pbx.myfreeswitch.org Standard ROUTING
2014-10-05 23:08:56.047282 [INFO] mod_dialplan_xml.c:558 Processing 1001 <1001>->1000 in context default
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->unloop] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Date/TimeMatch (FAIL) [tod_example] break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [global-intercept] destination_number(1000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [group-intercept] destination_number(1000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [intercept-ext] destination_number(1000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->redial] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [redial] destination_number(1000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->global] continue=true
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (PASS) [global] ${default_password}(1234) =~ /^1234$/ break=never
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action log(CRIT Open ${base_dir}/conf/vars.xml and change the default_password.)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action log(CRIT Once changed type 'reloadxml' at the console.)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action sleep(10000)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org 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/1001@pbx.myfreeswitch.org Regex (PASS) [global] ${endpoint_disposition}(DELAYED NEGOTIATION) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (PASS) [global] ${switch_r_sdp}(v=0
o=- 3621519535 3621519535 IN IP4 192.168.0.103
s=pjmedia
b=AS:84
t=0 0
a=X-nat:0
m=audio 9000 RTP/SAVP 98 97 99 104 3 0 8 9 96
c=IN IP4 192.168.0.103
b=AS:64000
a=rtpmap:98 speex/16000
a=rtpmap:97 speex/8000
a=rtpmap:99 speex/32000
a=rtpmap:104 iLBC/8000
a=fmtp:104 mode=30
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-15
a=rtcp:9001 IN IP4 192.168.0.103
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9
a=crypto:2 AES_CM_128_HMAC_SHA1_32 inline:/RZABbN0vRSybRtruRATkMrKo/P6wezyNcSkp0AX
) =~ /(AES_CM_128_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_80)/ break=never
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(rtp_secure_media=true)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Absolute Condition [global]
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-spymap/${caller_id_number}/${uuid})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-last_dial/${caller_id_number}/${destination_number})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-last_dial/global/${uuid})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action export(RFC2822_DATE=${strftime(%a, %d %b %Y %T %z)})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [snom-demo-2] destination_number(1000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [snom-demo-1] destination_number(1000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [eavesdrop] destination_number(1000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->call_return] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [call_return] destination_number(1000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->del-group] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [del-group] destination_number(1000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->add-group] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [add-group] destination_number(1000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [call-group-simo] destination_number(1000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [call-group-order] destination_number(1000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (FAIL) [extension-intercom] destination_number(1000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Regex (PASS) [Local_Extension] destination_number(1000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action export(dialed_extension=1000)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action bind_meta_app(1 b s execute_extension::dx XML features)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org 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/1001@pbx.myfreeswitch.org Action bind_meta_app(3 b s execute_extension::cf XML features)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action bind_meta_app(4 b s execute_extension::att_xfer XML features)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(ringback=${us-ring})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(transfer_ringback=local_stream://moh)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(call_timeout=30)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(hangup_after_bridge=true)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(continue_on_fail=true)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-call_return/${dialed_extension}/${caller_id_number})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-last_dial_ext/${dialed_extension}/${uuid})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action set(called_party_callgroup=${user_data(${dialed_extension}@${domain_name} var callgroup)})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-last_dial_ext/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-last_dial_ext/global/${uuid})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action hash(insert/${domain_name}-last_dial/${called_party_callgroup}/${uuid})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action bridge(user/${dialed_extension}@${domain_name})
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action answer()
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action sleep(1000)
Dialplan: sofia/internal/1001@pbx.myfreeswitch.org Action bridge(loopback/app=voicemail:default ${domain_name} ${dialed_extension})
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:216 (sofia/internal/1001@pbx.myfreeswitch.org) State Change CS_ROUTING -> CS_EXECUTE
2014-10-05 23:08:56.047282 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/1001@pbx.myfreeswitch.org) State ROUTING going to sleep
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_EXECUTE
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1001@pbx.myfreeswitch.org) State EXECUTE
2014-10-05 23:08:56.047282 [DEBUG] mod_sofia.c:178 sofia/internal/1001@pbx.myfreeswitch.org SOFIA EXECUTE
2014-10-05 23:08:56.047282 [DEBUG] switch_core_state_machine.c:258 sofia/internal/1001@pbx.myfreeswitch.org Standard EXECUTE
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2014-10-05 23:08:56.047282 [CRIT] mod_dptools.c:1628 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org log(CRIT Open /usr/local/freeswitch/conf/vars.xml and change the default_password.)
2014-10-05 23:08:56.047282 [CRIT] mod_dptools.c:1628 Open /usr/local/freeswitch/conf/vars.xml and change the default_password.
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org log(CRIT Once changed type 'reloadxml' at the console.)
2014-10-05 23:08:56.047282 [CRIT] mod_dptools.c:1628 Once changed type 'reloadxml' at the console.
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org log(CRIT WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING )
2014-10-05 23:08:56.047282 [CRIT] mod_dptools.c:1628 WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING WARNING
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org sleep(10000)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(rtp_secure_media=true)
2014-10-05 23:09:06.067267 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [rtp_secure_media]=[true]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-spymap/1001/24cb8d75-8119-4814-8530-d6b262194dfe)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-last_dial/1001/1000)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-last_dial/global/24cb8d75-8119-4814-8530-d6b262194dfe)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org export(RFC2822_DATE=Sun, 05 Oct 2014 23:09:06 +0530)
2014-10-05 23:09:06.067267 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [RFC2822_DATE]=[Sun, 05 Oct 2014 23:09:06 +0530]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org export(dialed_extension=1000)
2014-10-05 23:09:06.067267 [DEBUG] switch_channel.c:1247 EXPORT (export_vars) [dialed_extension]=[1000]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org bind_meta_app(1 b s execute_extension::dx XML features)
2014-10-05 23:09:06.067267 [INFO] switch_ivr_async.c:3661 Bound B-Leg: *1 execute_extension::dx XML features
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org bind_meta_app(2 b s record_session::/usr/local/freeswitch/recordings/1001.2014-10-05-23-09-06.wav)
2014-10-05 23:09:06.067267 [INFO] switch_ivr_async.c:3661 Bound B-Leg: *2 record_session::/usr/local/freeswitch/recordings/1001.2014-10-05-23-09-06.wav
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org bind_meta_app(3 b s execute_extension::cf XML features)
2014-10-05 23:09:06.067267 [INFO] switch_ivr_async.c:3661 Bound B-Leg: *3 execute_extension::cf XML features
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org bind_meta_app(4 b s execute_extension::att_xfer XML features)
2014-10-05 23:09:06.067267 [INFO] switch_ivr_async.c:3661 Bound B-Leg: *4 execute_extension::att_xfer XML features
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(ringback=%(2000,4000,440,480))
2014-10-05 23:09:06.067267 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [ringback]=[%(2000,4000,440,480)]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(transfer_ringback=local_stream://moh)
2014-10-05 23:09:06.067267 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [transfer_ringback]=[local_stream://moh]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(call_timeout=30)
2014-10-05 23:09:06.067267 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [call_timeout]=[30]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(hangup_after_bridge=true)
2014-10-05 23:09:06.067267 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [hangup_after_bridge]=[true]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(continue_on_fail=true)
2014-10-05 23:09:06.067267 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [continue_on_fail]=[true]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-call_return/1000/1001)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-last_dial_ext/1000/24cb8d75-8119-4814-8530-d6b262194dfe)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org set(called_party_callgroup=techsupport)
2014-10-05 23:09:06.087251 [DEBUG] mod_dptools.c:1435 sofia/internal/1001@pbx.myfreeswitch.org SET [called_party_callgroup]=[techsupport]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-last_dial_ext/techsupport/24cb8d75-8119-4814-8530-d6b262194dfe)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-last_dial_ext/global/24cb8d75-8119-4814-8530-d6b262194dfe)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org hash(insert/192.168.0.103-last_dial/techsupport/24cb8d75-8119-4814-8530-d6b262194dfe)
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org bridge(user/1000@192.168.0.103)
2014-10-05 23:09:06.087251 [DEBUG] switch_channel.c:1201 sofia/internal/1001@pbx.myfreeswitch.org EXPORTING[export_vars] [RFC2822_DATE]=[Sun, 05 Oct 2014 23:09:06 +0530] to event
2014-10-05 23:09:06.087251 [DEBUG] switch_channel.c:1201 sofia/internal/1001@pbx.myfreeswitch.org EXPORTING[export_vars] [dialed_extension]=[1000] to event
2014-10-05 23:09:06.087251 [DEBUG] switch_ivr_originate.c:2079 Parsing global variables
2014-10-05 23:09:06.087251 [DEBUG] switch_channel.c:1201 sofia/internal/1001@pbx.myfreeswitch.org EXPORTING[export_vars] [RFC2822_DATE]=[Sun, 05 Oct 2014 23:09:06 +0530] to event
2014-10-05 23:09:06.087251 [DEBUG] switch_channel.c:1201 sofia/internal/1001@pbx.myfreeswitch.org EXPORTING[export_vars] [dialed_extension]=[1000] to event
2014-10-05 23:09:06.087251 [DEBUG] switch_ivr_originate.c:2079 Parsing global variables
2014-10-05 23:09:06.087251 [DEBUG] switch_event.c:1688 Parsing variable [sip_invite_domain]=[192.168.0.103]
2014-10-05 23:09:06.087251 [DEBUG] switch_event.c:1688 Parsing variable [presence_id]=[1000@192.168.0.103]
2014-10-05 23:09:06.087251 [NOTICE] switch_channel.c:1055 New Channel sofia/internal/sip:1000@192.168.0.103:6001 [4c71ac74-e1bb-4053-b7e2-c306cc552496]
2014-10-05 23:09:06.087251 [DEBUG] mod_sofia.c:4577 (sofia/internal/sip:1000@192.168.0.103:6001) State Change CS_NEW -> CS_INIT
2014-10-05 23:09:06.087251 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:06.087251 [DEBUG] mod_sofia.c:4647 [zrtp_passthru] Setting a-leg inherit_codec=true
2014-10-05 23:09:06.087251 [DEBUG] mod_sofia.c:4650 [zrtp_passthru] Setting b-leg absolute_codec_string='GSM@8000h@20i@13200b,PCMU@8000h@20i@64000b,PCMA@8000h@20i@64000b,G722@8000h@20i@64000b'
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1000@192.168.0.103:6001) Running State Change CS_INIT
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/sip:1000@192.168.0.103:6001) State INIT
2014-10-05 23:09:06.087251 [DEBUG] mod_sofia.c:87 sofia/internal/sip:1000@192.168.0.103:6001 SOFIA INIT
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [1 AEAD_AES_256_GCM_8 inline:KVEHHfI0WMn8dY3j+9inOSCAL6i7rGi/RYP00gK1IY0aLfbL/wByWNUe/MY]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [1 AEAD_AES_256_GCM_8 inline:BoZ1mTg+ci5qrLY8Vme3tWPoF4AINFglxK+8QdvZqPdS55I4E5Nk9IThbr0]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [2 AEAD_AES_128_GCM_8 inline:u9irqfqfMzxPXAWhC47VAXn2/gZNOBuPyM16xw]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [2 AEAD_AES_128_GCM_8 inline:Q+VIFKfLIsUIjn6FHl1IaEuKhoYlhUx+vtQIfw]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [3 AES_CM_256_HMAC_SHA1_80 inline:QZblg/vbhhKyJ5WgMe4JSrnDFsXJDFYRwu+W3FzW0JCdyihzTEdyef0QAqf3BA]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [3 AES_CM_256_HMAC_SHA1_80 inline:+LVeoi/jd0DTZJe0+cDxteF+kt0HRRCtCCTK6m/OS4/mVMP8WI5nJXK6CybcKw]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [4 AES_CM_192_HMAC_SHA1_80 inline:IfPHDgSIgeEqMQCPXxOmsyYSwizeMCQGoW3JH5dGTCKLPT9SqVk]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [4 AES_CM_192_HMAC_SHA1_80 inline:5uy2A3XMR0RJ7fNtZF8rwJVFhzPn90irVu0s/xayqUZHPDQjbJA]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:XQ1YW+zu79OD/F/nbweFbsjF1vcLSqgY3uyn+kYS]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [5 AES_CM_128_HMAC_SHA1_80 inline:wzbsbwWbv63LqjR5MN87TsHNleDIqkCyeACd4UyA]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [6 AES_CM_256_HMAC_SHA1_32 inline:X2nN2U5g05vNNT4RlVMY1rcgqv0XQe9rMTg1fzURJqmQoQbwdvQv0RDsDNLKnQ]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [6 AES_CM_256_HMAC_SHA1_32 inline:FFyXNGu0vcyDhYX++uGDxCmFKDnDX6q4sSsVxWMaARWTHF2d7wyxcknZA3aI1Q]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [7 AES_CM_192_HMAC_SHA1_32 inline:xiyNA3TiFXRDvE+jN5EMOvx/txeAVrNpiUI+9DG0TlrHU3ETiEo]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [7 AES_CM_192_HMAC_SHA1_32 inline:bLr4agNy60XVpWV+hwvrsWNUYkTMos651WHAUcIJEYsHJaOtxH0]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:ca5kOm9+odVtf2GbD5w/VfF9IVuNHbevuh8NRkfO]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [8 AES_CM_128_HMAC_SHA1_32 inline:wq/MWC9DPKFJBXOarj8CUx7ULmDFO9LVM+FV70GM]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [9 AES_CM_128_NULL_AUTH inline:7PAnhG9Qw1yJUug8nqkxGpdapmls7m6wVoR5+OZU]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_media.c:922 Set Local video crypto Key [9 AES_CM_128_NULL_AUTH inline:bz7r0zGWjmDg7RLzF9vLkIBzoxM3Esswn6GlLt66]
2014-10-05 23:09:06.087251 [DEBUG] sofia_glue.c:1226 sofia/internal/sip:1000@192.168.0.103:6001 sending invite version: 1.4.8 git 498f586 2014-08-25 16:34:46Z 32bit
Local SDP:
v=0
o=FreeSWITCH 1412505862 1412505863 IN IP4 192.168.0.103
s=FreeSWITCH
c=IN IP4 192.168.0.103
t=0 0
m=audio 24884 RTP/SAVP 3 0 8 9 101 13
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=crypto:1 AEAD_AES_256_GCM_8 inline:KVEHHfI0WMn8dY3j+9inOSCAL6i7rGi/RYP00gK1IY0aLfbL/wByWNUe/MY
a=crypto:2 AEAD_AES_128_GCM_8 inline:u9irqfqfMzxPXAWhC47VAXn2/gZNOBuPyM16xw
a=crypto:3 AES_CM_256_HMAC_SHA1_80 inline:QZblg/vbhhKyJ5WgMe4JSrnDFsXJDFYRwu+W3FzW0JCdyihzTEdyef0QAqf3BA
a=crypto:4 AES_CM_192_HMAC_SHA1_80 inline:IfPHDgSIgeEqMQCPXxOmsyYSwizeMCQGoW3JH5dGTCKLPT9SqVk
a=crypto:5 AES_CM_128_HMAC_SHA1_80 inline:XQ1YW+zu79OD/F/nbweFbsjF1vcLSqgY3uyn+kYS
a=crypto:6 AES_CM_256_HMAC_SHA1_32 inline:X2nN2U5g05vNNT4RlVMY1rcgqv0XQe9rMTg1fzURJqmQoQbwdvQv0RDsDNLKnQ
a=crypto:7 AES_CM_192_HMAC_SHA1_32 inline:xiyNA3TiFXRDvE+jN5EMOvx/txeAVrNpiUI+9DG0TlrHU3ETiEo
a=crypto:8 AES_CM_128_HMAC_SHA1_32 inline:ca5kOm9+odVtf2GbD5w/VfF9IVuNHbevuh8NRkfO
a=crypto:9 AES_CM_128_NULL_AUTH inline:7PAnhG9Qw1yJUug8nqkxGpdapmls7m6wVoR5+OZU
a=ptime:20
a=sendrecv
m=audio 24884 RTP/AVP 3 0 8 9 101 13
a=rtpmap:3 GSM/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:40 sofia/internal/sip:1000@192.168.0.103:6001 Standard INIT
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/sip:1000@192.168.0.103:6001) State Change CS_INIT -> CS_ROUTING
2014-10-05 23:09:06.087251 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:512 (sofia/internal/sip:1000@192.168.0.103:6001) State INIT going to sleep
2014-10-05 23:09:06.087251 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1000@192.168.0.103:6001) Running State Change CS_ROUTING
2014-10-05 23:09:06.087251 [DEBUG] sofia.c:6408 Channel sofia/internal/sip:1000@192.168.0.103:6001 entering state [calling][0]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/sip:1000@192.168.0.103:6001) State ROUTING
2014-10-05 23:09:06.087251 [DEBUG] mod_sofia.c:123 sofia/internal/sip:1000@192.168.0.103:6001 SOFIA ROUTING
2014-10-05 23:09:06.087251 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/sip:1000@192.168.0.103:6001) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2014-10-05 23:09:06.087251 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:528 (sofia/internal/sip:1000@192.168.0.103:6001) State ROUTING going to sleep
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1000@192.168.0.103:6001) Running State Change CS_CONSUME_MEDIA
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/sip:1000@192.168.0.103:6001) State CONSUME_MEDIA
2014-10-05 23:09:06.087251 [DEBUG] switch_core_state_machine.c:547 (sofia/internal/sip:1000@192.168.0.103:6001) State CONSUME_MEDIA going to sleep
2014-10-05 23:09:36.007270 [NOTICE] switch_ivr_originate.c:3467 Hangup sofia/internal/sip:1000@192.168.0.103:6001 [CS_CONSUME_MEDIA] [NO_ANSWER]
2014-10-05 23:09:36.007270 [DEBUG] switch_channel.c:3222 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [KILL]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1000@192.168.0.103:6001) Running State Change CS_HANGUP
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/sip:1000@192.168.0.103:6001) Callstate Change DOWN -> HANGUP
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/sip:1000@192.168.0.103:6001) State HANGUP
2014-10-05 23:09:36.007270 [DEBUG] mod_sofia.c:413 Channel sofia/internal/sip:1000@192.168.0.103:6001 hanging up, cause: NO_ANSWER
2014-10-05 23:09:36.007270 [NOTICE] switch_ivr_originate.c:2708 Cannot create outgoing channel of type [user] cause: [NO_ANSWER]
2014-10-05 23:09:36.007270 [DEBUG] switch_ivr_originate.c:3695 Originate Resulted in Error Cause: 19 [NO_ANSWER]
2014-10-05 23:09:36.007270 [DEBUG] mod_sofia.c:475 Sending CANCEL to sofia/internal/sip:1000@192.168.0.103:6001
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:60 sofia/internal/sip:1000@192.168.0.103:6001 Standard HANGUP, cause: NO_ANSWER
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/sip:1000@192.168.0.103:6001) State HANGUP going to sleep
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/sip:1000@192.168.0.103:6001) State Change CS_HANGUP -> CS_REPORTING
2014-10-05 23:09:36.007270 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/sip:1000@192.168.0.103:6001) Running State Change CS_REPORTING
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/sip:1000@192.168.0.103:6001) State REPORTING
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:104 sofia/internal/sip:1000@192.168.0.103:6001 Standard REPORTING, cause: NO_ANSWER
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/sip:1000@192.168.0.103:6001) State REPORTING going to sleep
2014-10-05 23:09:36.007270 [INFO] mod_dptools.c:3234 Originate Failed.  Cause: NO_ANSWER
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/sip:1000@192.168.0.103:6001) State Change CS_REPORTING -> CS_DESTROY
2014-10-05 23:09:36.007270 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/sip:1000@192.168.0.103:6001 [BREAK]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_session.c:1615 Session 2 (sofia/internal/sip:1000@192.168.0.103:6001) Locked, Waiting on external entities
2014-10-05 23:09:36.007270 [NOTICE] switch_core_session.c:1633 Session 2 (sofia/internal/sip:1000@192.168.0.103:6001) Ended
2014-10-05 23:09:36.007270 [NOTICE] switch_core_session.c:1637 Close Channel sofia/internal/sip:1000@192.168.0.103:6001 [CS_DESTROY]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org answer()
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/sip:1000@192.168.0.103:6001) Running State Change CS_DESTROY
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/sip:1000@192.168.0.103:6001) State DESTROY
2014-10-05 23:09:36.007270 [DEBUG] mod_sofia.c:323 sofia/internal/sip:1000@192.168.0.103:6001 SOFIA DESTROY
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:111 sofia/internal/sip:1000@192.168.0.103:6001 Standard DESTROY
2014-10-05 23:09:36.007270 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/sip:1000@192.168.0.103:6001) State DESTROY going to sleep
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1185 looking for crypto suite [AEAD_AES_256_GCM_8] in [1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1185 looking for crypto suite [AEAD_AES_128_GCM_8] in [1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1185 looking for crypto suite [AES_CM_256_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1185 looking for crypto suite [AES_CM_192_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1185 looking for crypto suite [AES_CM_128_HMAC_SHA1_80] in [1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1190 Found suite AES_CM_128_HMAC_SHA1_80
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:1256 Set Remote Key [1 AES_CM_128_HMAC_SHA1_80 inline:QckTgP/H74P0S6u9sZm5ySmQ4i+zeZ/sw56endR9]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:922 Set Local audio crypto Key [1 AES_CM_128_HMAC_SHA1_80 inline:erDhB7sHda1RuOPnM6kFz2wq8cmBUUvJc7GRIY4m]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:98:16000:20:0:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:98:16000:20:0:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:98:16000:20:0:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:97:8000:20:0:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:97:8000:20:0:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:97:8000:20:0:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:99:32000:20:0:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:99:32000:20:0:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:99:32000:20:0:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:99:32000:20:0:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [speex:99:32000:20:0:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [iLBC:104:8000:30:0:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [iLBC:104:8000:30:0:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [iLBC:104:8000:30:0:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [iLBC:104:8000:30:0:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [iLBC:104:8000:30:0:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [GSM:3:8000:20:13200:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3530 Audio Codec Compare [GSM:3:8000:20:13200:1] ++++ is saved as a match
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3530 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3530 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3530 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3475 Audio Codec Compare [G722:9:8000:20:64000:1]/[GSM:3:8000:20:13200:1]
2014-10-05 23:09:36.007270 [DEBUG] switch_core_media.c:3396 Set telephone-event payload to 96
2014-10-05 23:09:36.027261 [DEBUG] switch_core_media.c:2352 Set Codec sofia/internal/1001@pbx.myfreeswitch.org GSM/8000 20 ms 160 samples 13200 bits 1 channels
2014-10-05 23:09:36.027261 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@pbx.myfreeswitch.org Original read codec set to GSM:3
2014-10-05 23:09:36.027261 [DEBUG] switch_core_media.c:3721 Set 2833 dtmf send/recv payload to 96
2014-10-05 23:09:36.027261 [DEBUG] switch_core_media.c:4941 AUDIO RTP [sofia/internal/1001@pbx.myfreeswitch.org] 192.168.0.103 port 22482 -> 192.168.0.103 port 9000 codec: 3 ms: 20
2014-10-05 23:09:36.027261 [DEBUG] switch_rtp.c:3386 Starting timer [soft] 160 bytes per 20ms
2014-10-05 23:09:36.027261 [INFO] switch_core_media.c:5158 Activating RTCP PORT 9001
2014-10-05 23:09:36.027261 [DEBUG] switch_rtp.c:3732 RTCP send rate is: 5000 and packet rate is: 20000 Remote Port: 9001
2014-10-05 23:09:36.027261 [DEBUG] switch_rtp.c:2193 Setting RTCP remote addr to 192.168.0.103:9001
2014-10-05 23:09:36.027261 [DEBUG] switch_core_media.c:5293 Set 2833 dtmf send payload to 96
2014-10-05 23:09:36.027261 [DEBUG] switch_core_media.c:5299 Set 2833 dtmf receive payload to 96
2014-10-05 23:09:36.027261 [INFO] switch_rtp.c:3203 Activating Audio Secure RTP SEND
2014-10-05 23:09:36.027261 [INFO] switch_rtp.c:3181 Activating Audio Secure RTP RECV
2014-10-05 23:09:36.027261 [DEBUG] switch_core_sqldb.c:2568 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2014-10-05 23:09:36.027261 [DEBUG] switch_core_sqldb.c:2568 Secure Type: srtp:sdes:AES_CM_128_HMAC_SHA1_80
2014-10-05 23:09:36.027261 [NOTICE] sofia_media.c:92 Pre-Answer sofia/internal/1001@pbx.myfreeswitch.org!
2014-10-05 23:09:36.027261 [DEBUG] switch_channel.c:3399 (sofia/internal/1001@pbx.myfreeswitch.org) Callstate Change RINGING -> EARLY
2014-10-05 23:09:36.027261 [DEBUG] mod_sofia.c:778 Local SDP sofia/internal/1001@pbx.myfreeswitch.org:
v=0
o=FreeSWITCH 1412508294 1412508295 IN IP4 192.168.0.103
s=FreeSWITCH
c=IN IP4 192.168.0.103
t=0 0
m=audio 22482 RTP/SAVP 3 96
a=rtpmap:3 GSM/8000
a=rtpmap:96 telephone-event/8000
a=fmtp:96 0-16
a=ptime:20
a=sendrecv
a=rtcp:22483 IN IP4 192.168.0.103
a=crypto:1 AES_CM_128_HMAC_SHA1_80 inline:erDhB7sHda1RuOPnM6kFz2wq8cmBUUvJc7GRIY4m

2014-10-05 23:09:36.027261 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:36.027261 [NOTICE] mod_dptools.c:1258 Channel [sofia/internal/1001@pbx.myfreeswitch.org] has been answered
2014-10-05 23:09:36.027261 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:36.027261 [DEBUG] switch_channel.c:3689 (sofia/internal/1001@pbx.myfreeswitch.org) Callstate Change EARLY -> ACTIVE
2014-10-05 23:09:36.027261 [DEBUG] sofia.c:6408 Channel sofia/internal/1001@pbx.myfreeswitch.org entering state [completed][200]
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org sleep(1000)
2014-10-05 23:09:36.027261 [DEBUG] switch_ivr.c:191 Codec Activated L16@8000hz 1 channels 20ms
2014-10-05 23:09:36.027261 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:36.027261 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:36.027261 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:36.047255 [DEBUG] sofia.c:6408 Channel sofia/internal/1001@pbx.myfreeswitch.org entering state [ready][200]
2014-10-05 23:09:36.067268 [DEBUG] switch_rtp.c:5644 Correct ip/port confirmed.
EXECUTE sofia/internal/1001@pbx.myfreeswitch.org bridge(loopback/app=voicemail:default 192.168.0.103 1000)
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:1766 (sofia/internal/1001@pbx.myfreeswitch.org) Callstate Change ACTIVE -> RING_WAIT
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:1201 sofia/internal/1001@pbx.myfreeswitch.org EXPORTING[export_vars] [RFC2822_DATE]=[Sun, 05 Oct 2014 23:09:06 +0530] to event
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:1201 sofia/internal/1001@pbx.myfreeswitch.org EXPORTING[export_vars] [dialed_extension]=[1000] to event
2014-10-05 23:09:37.027269 [DEBUG] switch_ivr_originate.c:2079 Parsing global variables
2014-10-05 23:09:37.027269 [NOTICE] switch_channel.c:1055 New Channel loopback/app=voicemail:default 192.168.0.103 1000-a [949e0eba-57d7-4b3b-b737-d7355bf0dc44]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:157 loopback/app=voicemail:default 192.168.0.103 1000-a setup codec GSM/8000/20
2014-10-05 23:09:37.027269 [NOTICE] switch_channel.c:1053 Rename Channel loopback/app=voicemail:default 192.168.0.103 1000-a->loopback/voicemail-a [949e0eba-57d7-4b3b-b737-d7355bf0dc44]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:1160 (loopback/voicemail-a) State Change CS_NEW -> CS_INIT
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-a) Running State Change CS_INIT
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:512 (loopback/voicemail-a) State INIT
2014-10-05 23:09:37.027269 [NOTICE] switch_channel.c:1055 New Channel loopback/voicemail-b [b26df172-6b38-46a9-8649-d1294f674be8]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:157 loopback/voicemail-b setup codec GSM/8000/20
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:273 (loopback/voicemail-b) State Change CS_NEW -> CS_INIT
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:359 (loopback/voicemail-a) State Change CS_INIT -> CS_ROUTING
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:512 (loopback/voicemail-a) State INIT going to sleep
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-b) Running State Change CS_INIT
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:512 (loopback/voicemail-b) State INIT
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:359 (loopback/voicemail-b) State Change CS_INIT -> CS_ROUTING
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:512 (loopback/voicemail-b) State INIT going to sleep
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-b) Running State Change CS_ROUTING
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:2184 (loopback/voicemail-b) Callstate Change DOWN -> RINGING
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-a) Running State Change CS_ROUTING
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:528 (loopback/voicemail-a) State ROUTING
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:528 (loopback/voicemail-b) State ROUTING
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:391 loopback/voicemail-a CHANNEL ROUTING
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:391 loopback/voicemail-b CHANNEL ROUTING
2014-10-05 23:09:37.027269 [DEBUG] switch_ivr_originate.c:67 (loopback/voicemail-a) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:410 (loopback/voicemail-b) State Change CS_ROUTING -> CS_EXECUTE
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:528 (loopback/voicemail-b) State ROUTING going to sleep
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:528 (loopback/voicemail-a) State ROUTING going to sleep
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-b) Running State Change CS_EXECUTE
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-a) Running State Change CS_CONSUME_MEDIA
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:535 (loopback/voicemail-b) State EXECUTE
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:433 loopback/voicemail-b CHANNEL EXECUTE
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:547 (loopback/voicemail-a) State CONSUME_MEDIA
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:258 loopback/voicemail-b Standard EXECUTE
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:650 CHANNEL CONSUME_MEDIA
2014-10-05 23:09:37.027269 [DEBUG] switch_core_state_machine.c:547 (loopback/voicemail-a) State CONSUME_MEDIA going to sleep
EXECUTE loopback/voicemail-b pre_answer()
2014-10-05 23:09:37.027269 [NOTICE] mod_loopback.c:947 Pre-Answer loopback/voicemail-a!
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:3395 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:3399 (loopback/voicemail-a) Callstate Change DOWN -> EARLY
2014-10-05 23:09:37.027269 [DEBUG] switch_core_session.c:908 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:37.027269 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:37.027269 [NOTICE] mod_dptools.c:1293 Pre-Answer loopback/voicemail-b!
2014-10-05 23:09:37.027269 [DEBUG] switch_channel.c:3399 (loopback/voicemail-b) Callstate Change RINGING -> EARLY
EXECUTE loopback/voicemail-b voicemail(default 192.168.0.103 1000)
2014-10-05 23:09:37.047293 [DEBUG] switch_ivr_originate.c:3552 Originate Resulted in Success: [loopback/voicemail-a]
2014-10-05 23:09:37.047293 [DEBUG] switch_channel.c:1979 (sofia/internal/1001@pbx.myfreeswitch.org) Callstate Change RING_WAIT -> ACTIVE
2014-10-05 23:09:37.047293 [DEBUG] switch_core_session.c:908 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:37.047293 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:37.047293 [DEBUG] switch_core_session.c:908 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:37.047293 [DEBUG] switch_ivr_bridge.c:1465 (loopback/voicemail-a) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2014-10-05 23:09:37.047293 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:37.047293 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:37.047293 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-a) Running State Change CS_EXCHANGE_MEDIA
2014-10-05 23:09:37.047293 [DEBUG] switch_core_state_machine.c:538 (loopback/voicemail-a) State EXCHANGE_MEDIA
2014-10-05 23:09:37.047293 [DEBUG] mod_loopback.c:612 CHANNEL LOOPBACK
2014-10-05 23:09:37.127282 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2014-10-05 23:09:37.147268 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en)
2014-10-05 23:09:37.167266 [DEBUG] switch_ivr_play_say.c:1305 Codec Activated L16@8000hz 1 channels 20ms
2014-10-05 23:09:38.487267 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-person.wav
2014-10-05 23:09:38.587267 [DEBUG] switch_ivr_play_say.c:250 Handle say:[1000] (en:en)
2014-10-05 23:09:38.587267 [DEBUG] switch_ivr_play_say.c:1305 Codec Activated L16@8000hz 1 channels 20ms
2014-10-05 23:09:40.887267 [DEBUG] switch_ivr_play_say.c:1719 done playing file file_string://digits/1.wav!digits/0.wav!digits/0.wav!digits/0.wav
2014-10-05 23:09:40.987268 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-not_available.wav] (en:en)
2014-10-05 23:09:40.987268 [DEBUG] switch_ivr_play_say.c:1305 Codec Activated L16@8000hz 1 channels 20ms
2014-10-05 23:09:41.967269 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-not_available.wav
2014-10-05 23:09:42.087269 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2014-10-05 23:09:42.127281 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-record_message.wav] (en:en)
2014-10-05 23:09:42.127281 [DEBUG] switch_ivr_play_say.c:1305 Codec Activated L16@8000hz 1 channels 20ms
2014-10-05 23:09:46.687267 [DEBUG] switch_ivr_play_say.c:1719 done playing file /usr/local/freeswitch/sounds/en/us/callie/voicemail/vm-record_message.wav
2014-10-05 23:09:46.807267 [DEBUG] switch_core_session.c:1053 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:46.827270 [NOTICE] sofia.c:947 Hangup sofia/internal/1001@pbx.myfreeswitch.org [CS_EXECUTE] [NORMAL_CLEARING]
2014-10-05 23:09:46.827270 [DEBUG] switch_channel.c:3222 Send signal sofia/internal/1001@pbx.myfreeswitch.org [KILL]
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] switch_ivr_bridge.c:579 sofia/internal/1001@pbx.myfreeswitch.org ending bridge by request from write function
2014-10-05 23:09:46.827270 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [loopback/voicemail-a]
2014-10-05 23:09:46.827270 [DEBUG] switch_ivr_bridge.c:690 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:46.827270 [NOTICE] switch_ivr_bridge.c:752 Hangup loopback/voicemail-a [CS_EXCHANGE_MEDIA] [ORIGINATOR_CANCEL]
2014-10-05 23:09:46.827270 [DEBUG] switch_channel.c:3222 Send signal loopback/voicemail-a [KILL]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:538 (loopback/voicemail-a) State EXCHANGE_MEDIA going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-a) Running State Change CS_HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:735 (loopback/voicemail-a) Callstate Change EARLY -> HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:737 (loopback/voicemail-a) State HANGUP
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:537 loopback/voicemail-a CHANNEL HANGUP
2014-10-05 23:09:46.827270 [NOTICE] mod_loopback.c:553 Hangup loopback/voicemail-b [CS_EXECUTE] [ORIGINATOR_CANCEL]
2014-10-05 23:09:46.827270 [DEBUG] switch_channel.c:3222 Send signal loopback/voicemail-b [KILL]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-a Standard HANGUP, cause: ORIGINATOR_CANCEL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:737 (loopback/voicemail-a) State HANGUP going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:504 (loopback/voicemail-a) State Change CS_HANGUP -> CS_REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-a) Running State Change CS_REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:823 (loopback/voicemail-a) State REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:104 loopback/voicemail-a Standard REPORTING, cause: ORIGINATOR_CANCEL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:823 (loopback/voicemail-a) State REPORTING going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:498 (loopback/voicemail-a) State Change CS_REPORTING -> CS_DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1615 Session 3 (loopback/voicemail-a) Locked, Waiting on external entities
2014-10-05 23:09:46.827270 [DEBUG] switch_ivr_bridge.c:660 BRIDGE THREAD DONE [sofia/internal/1001@pbx.myfreeswitch.org]
2014-10-05 23:09:46.827270 [DEBUG] switch_ivr_bridge.c:690 Send signal loopback/voicemail-a [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-a CHANNEL KILL
2014-10-05 23:09:46.827270 [WARNING] mod_voicemail.c:1238 Failed to delete file [/usr/local/freeswitch/storage/voicemail/default/192.168.0.103/1000/msg_2e38d3d7-1ca5-4cfe-a682-ffa8908d245c.wav]
2014-10-05 23:09:46.827270 [DEBUG] mod_voicemail.c:1245 Message is less than minimum record length: 3, discarding it.
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:2888 loopback/voicemail-b skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:535 (loopback/voicemail-b) State EXECUTE going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-b) Running State Change CS_HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_ivr_bridge.c:1566 sofia/internal/1001@pbx.myfreeswitch.org skip receive message [UNBRIDGE] (channel is hungup already)
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:735 (loopback/voicemail-b) Callstate Change EARLY -> HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:737 (loopback/voicemail-b) State HANGUP
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:537 loopback/voicemail-b CHANNEL HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:60 loopback/voicemail-b Standard HANGUP, cause: ORIGINATOR_CANCEL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:737 (loopback/voicemail-b) State HANGUP going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:504 (loopback/voicemail-b) State Change CS_HANGUP -> CS_REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:46.827270 [NOTICE] switch_core_session.c:1633 Session 3 (loopback/voicemail-a) Ended
2014-10-05 23:09:46.827270 [NOTICE] switch_core_session.c:1637 Close Channel loopback/voicemail-a [CS_DESTROY]
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:626 (loopback/voicemail-a) Running State Change CS_DESTROY
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:472 (loopback/voicemail-b) Running State Change CS_REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:823 (loopback/voicemail-b) State REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:104 loopback/voicemail-b Standard REPORTING, cause: ORIGINATOR_CANCEL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:823 (loopback/voicemail-b) State REPORTING going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:636 (loopback/voicemail-a) State DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:111 loopback/voicemail-a Standard DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:636 (loopback/voicemail-a) State DESTROY going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:2888 sofia/internal/1001@pbx.myfreeswitch.org skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:535 (sofia/internal/1001@pbx.myfreeswitch.org) State EXECUTE going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:498 (loopback/voicemail-b) State Change CS_REPORTING -> CS_DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal loopback/voicemail-b [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] mod_loopback.c:590 loopback/voicemail-b CHANNEL KILL
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1615 Session 4 (loopback/voicemail-b) Locked, Waiting on external entities
2014-10-05 23:09:46.827270 [NOTICE] switch_core_session.c:1633 Session 4 (loopback/voicemail-b) Ended
2014-10-05 23:09:46.827270 [NOTICE] switch_core_session.c:1637 Close Channel loopback/voicemail-b [CS_DESTROY]
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:626 (loopback/voicemail-b) Running State Change CS_DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:735 (sofia/internal/1001@pbx.myfreeswitch.org) Callstate Change ACTIVE -> HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:636 (loopback/voicemail-b) State DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1001@pbx.myfreeswitch.org) State HANGUP
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:111 loopback/voicemail-b Standard DESTROY
2014-10-05 23:09:46.827270 [DEBUG] mod_sofia.c:413 Channel sofia/internal/1001@pbx.myfreeswitch.org hanging up, cause: NORMAL_CLEARING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:636 (loopback/voicemail-b) State DESTROY going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@pbx.myfreeswitch.org Standard HANGUP, cause: NORMAL_CLEARING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:737 (sofia/internal/1001@pbx.myfreeswitch.org) State HANGUP going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:504 (sofia/internal/1001@pbx.myfreeswitch.org) State Change CS_HANGUP -> CS_REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:472 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1001@pbx.myfreeswitch.org) State REPORTING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:104 sofia/internal/1001@pbx.myfreeswitch.org Standard REPORTING, cause: NORMAL_CLEARING
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:823 (sofia/internal/1001@pbx.myfreeswitch.org) State REPORTING going to sleep
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:498 (sofia/internal/1001@pbx.myfreeswitch.org) State Change CS_REPORTING -> CS_DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1388 Send signal sofia/internal/1001@pbx.myfreeswitch.org [BREAK]
2014-10-05 23:09:46.827270 [DEBUG] switch_core_session.c:1615 Session 1 (sofia/internal/1001@pbx.myfreeswitch.org) Locked, Waiting on external entities
2014-10-05 23:09:46.827270 [NOTICE] switch_core_session.c:1633 Session 1 (sofia/internal/1001@pbx.myfreeswitch.org) Ended
2014-10-05 23:09:46.827270 [NOTICE] switch_core_session.c:1637 Close Channel sofia/internal/1001@pbx.myfreeswitch.org [CS_DESTROY]
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:626 (sofia/internal/1001@pbx.myfreeswitch.org) Running State Change CS_DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1001@pbx.myfreeswitch.org) State DESTROY
2014-10-05 23:09:46.827270 [DEBUG] mod_sofia.c:323 sofia/internal/1001@pbx.myfreeswitch.org SOFIA DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:111 sofia/internal/1001@pbx.myfreeswitch.org Standard DESTROY
2014-10-05 23:09:46.827270 [DEBUG] switch_core_state_machine.c:636 (sofia/internal/1001@pbx.myfreeswitch.org) State DESTROY going to sleep

freeswitch@atul-amd>
freeswitch@atul-amd>
freeswitch@atul-amd>
freeswitch@atul-amd>
freeswitch@atul-amd>


--