unable to make call - Termination Rate not found!

2016-08-31 18:17:32.220087 [DEBUG] sofia.c:9543 IP XX:XX:XX:XX Rejected by acl "default". Falling back to Digest auth.
2016-08-31 18:17:32.260081 [DEBUG] sofia.c:6858 Channel sofia/default/7724558832@XX:XX:XX:XX entering state [received][100]
2016-08-31 18:17:32.260081 [DEBUG] sofia.c:6868 Remote SDP:
v=0
o=- 4 2 IN IP4 XXXXXXXXXX
s=CounterPath X-Lite 3.0
c=IN IP4 XXXXXXXXXX
t=0 0
m=audio 44230 RTP/AVP 107 119 0 98 8 3 101
a=rtpmap:107 BV32/16000
a=rtpmap:119 BV32-FEC/16000
a=rtpmap:98 iLBC/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=alt:1 3 : 85v3XCWk Bd4ZW4Cc 192.168.247.1 44230
a=alt:2 2 : jeUGOIc3 Q2Gk2GNW 192.168.12.1 44230
a=alt:3 1 : FJKlyDwo hc+8oK3d 192.168.1.6 44230

2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [BV32:107:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [BV32:107:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [BV32-FEC:119:16000:20:0:1]/[PCMA:8:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [BV32-FEC:119:16000:20:0:1]/[PCMU:0:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [iLBC:98:8000:30:13330:1]/[PCMA:8:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [iLBC:98:8000:30:13330:1]/[PCMU:0:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:3090 Set Codec sofia/default/7724558832@XX:XX:XX:XX PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2016-08-31 18:17:32.260081 [DEBUG] switch_core_codec.c:111 sofia/default/7724558832@XX:XX:XX:XX Original read codec set to PCMU:0
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000
2016-08-31 18:17:32.260081 [DEBUG] switch_core_media.c:4681 sofia/default/7724558832@XX:XX:XX:XX Set 2833 dtmf send payload to 101 recv payload to 101
2016-08-31 18:17:32.260081 [DEBUG] sofia.c:7248 (sofia/default/7724558832@XX:XX:XX:XX) State Change CS_NEW -> CS_INIT
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:543 (sofia/default/7724558832@XX:XX:XX:XX) Running State Change CS_INIT
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:586 (sofia/default/7724558832@XX:XX:XX:XX) State INIT
2016-08-31 18:17:32.260081 [DEBUG] mod_sofia.c:89 sofia/default/7724558832@XX:XX:XX:XX SOFIA INIT
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:40 sofia/default/7724558832@XX:XX:XX:XX Standard INIT
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:48 (sofia/default/7724558832@XX:XX:XX:XX) State Change CS_INIT -> CS_ROUTING
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:586 (sofia/default/7724558832@XX:XX:XX:XX) State INIT going to sleep
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:543 (sofia/default/7724558832@XX:XX:XX:XX) Running State Change CS_ROUTING
2016-08-31 18:17:32.260081 [DEBUG] switch_channel.c:2249 (sofia/default/7724558832@XX:XX:XX:XX) Callstate Change DOWN -> RINGING
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:602 (sofia/default/7724558832@XX:XX:XX:XX) State ROUTING
2016-08-31 18:17:32.260081 [DEBUG] mod_sofia.c:142 sofia/default/7724558832@XX:XX:XX:XX SOFIA ROUTING
2016-08-31 18:17:32.260081 [DEBUG] switch_core_state_machine.c:236 sofia/default/7724558832@XX:XX:XX:XX Standard ROUTING
2016-08-31 18:17:32.260081 [INFO] mod_dialplan_xml.c:637 Processing 7724558832 <7724558832>->91XXXXXXXXXX in context default
2016-08-31 18:17:32.280047 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f62fc0ec750 Connected.
2016-08-31 18:17:32.280047 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard')
2016-08-31 18:17:32.280047 [INFO] switch_cpp.cpp:1360 [ASTPP] [Dialplan] Dialed number : 91XXXXXXXXXX
2016-08-31 18:17:32.280047 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,A.number as did_number,A.connectcost,A.includedseconds,A.cost,A.inc,A.extensions,A.maxchannels,A.call_type,A.city,A.province,A.init_inc FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="91XXXXXXXXXX" LIMIT 1
2016-08-31 18:17:32.300049 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.username as username,number as accountcode,sip_devices.accountid as accountid FROM sip_devices as sip_devices,accounts as accounts WHERE accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND username="91XXXXXXXXXX" limit 1
2016-08-31 18:17:32.300049 [INFO] switch_cpp.cpp:1360 [ASTPP] [Dialplan] Call direction : outbound
2016-08-31 18:17:32.300049 [NOTICE] switch_cpp.cpp:1360 [ASTPP] [Accountcode : 7724558832]
2016-08-31 18:17:32.300049 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "7724558832" OR id="7724558832") AND status=0 AND deleted=0 AND (expiry >= '2016-08-31 18:17:32' OR expiry = '0000-00-00 00:00:00') limit 1
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [CHECK_BLOCKED_PREFIX] Query :SELECT * FROM block_patterns WHERE (blocked_patterns ='^91XXXXXXXXXX.' OR blocked_patterns ='^91XXXXXXXXXX19.' OR blocked_patterns ='^91XXXXXXXXXX1.' OR blocked_patterns ='^91XXXXXXXXXX.' OR blocked_patterns ='^91XXXX20.' OR blocked_patterns ='^91XXXX2.' OR blocked_patterns ='^91XXXX.' OR blocked_patterns ='^91971.' OR blocked_patterns ='^9197.' OR blocked_patterns ='^919.' OR blocked_patterns ='^91.' OR blocked_patterns ='^9.' OR blocked_patterns ='--') AND accountid = 4 limit 1
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT * FROM packages as P inner join package_patterns as PKGPTR on P.id = PKGPTR.package_id WHERE (patterns ='^91XXXXXXXXXX.' OR patterns ='^91XXXXXXXXXX19.' OR patterns ='^91XXXXXXXXXX1.' OR patterns ='^91XXXXXXXXXX.' OR patterns ='^91XXXX20.' OR patterns ='^91XXXX2.' OR patterns ='^91XXXX.' OR patterns ='^91971.' OR patterns ='^9197.' OR patterns ='^919.' OR patterns ='^91.' OR patterns ='^9.' OR patterns ='--') AND status = 0 AND pricelist_id = 1 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] =============== Account Information ===================
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] User id : 4
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Account code : 7724558832
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Balance : 5
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Type : 0 [0:prepaid,1:postpaid]
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Ratecard id : 1
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] ========================================================
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern ='^91XXXXXXXXXX.' OR pattern ='^91XXXXXXXXXX19.' OR pattern ='^91XXXXXXXXXX1.' OR pattern ='^91XXXXXXXXXX.' OR pattern ='^91XXXX20.' OR pattern ='^91XXXX2.' OR pattern ='^91XXXX.' OR pattern ='^91971.' OR pattern ='^9197.' OR pattern ='^919.' OR pattern ='^91.' OR pattern ='^9.' OR pattern ='--') AND status = 0 AND pricelist_id = 1 ORDER BY LENGTH(pattern) DESC,cost DESC LIMIT 1
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] =============== Rates Information ===================
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] ID : 2
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Connectcost : 0.00000
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Includedseconds : 0
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Cost : 0.40000
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] comment : India
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Accid : 4
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] ================================================================
2016-08-31 18:17:32.340041 [INFO] switch_cpp.cpp:1360 [ASTPP] Call Max length duration : 12.5 minutes
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_CARRIER_RATES_TRUNKS] Query :SELECT GROUP_CONCAT(trunk_id) as ids FROM routing WHERE pricelist_id=1
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_CARRIER_RATES] Query :SELECT TK.id as trunk_id,TK.codec,GW.name as path,GW.dialplan_variable,TK.provider_id,TR.init_inc,TK.status,TK.dialed_modify,TK.maxchannels,TR.pattern,TR.id as outbound_route_id,TR.connectcost,TR.comment,TR.includedseconds,TR.cost,TR.inc,TR.prepend,TR.strip,(select name from gateways where status=0 AND id = TK.failover_gateway_id) as path1,(select name from gateways where status=0 AND id = TK.failover_gateway_id1) as path2 FROM outbound_routes as TR,trunks as TK,gateways as GW WHERE GW.status=0 AND GW.id= TK.gateway_id AND TK.status=0 AND TK.id= TR.trunk_id AND (pattern ='^91XXXXXXXXXX.' OR pattern ='^91XXXXXXXXXX19.' OR pattern ='^91XXXXXXXXXX1.' OR pattern ='^91XXXXXXXXXX.' OR pattern ='^91XXXX20.' OR pattern ='^91XXXX2.' OR pattern ='^91XXXX.' OR pattern ='^91971.' OR pattern ='^9197.' OR pattern ='^919.' OR pattern ='^91.' OR pattern ='^9.' OR pattern ='--') AND TR.status = 0 AND TR.trunk_id IN (0) ORDER by LENGTH (pattern) DESC,TR.cost ASC,TR.precedence ASC, TK.precedence
2016-08-31 18:17:32.340041 [NOTICE] switch_cpp.cpp:1360 [ASTPP] [Dialplan] No termination rates found...!!!
2016-08-31 18:17:32.340041 [DEBUG] switch_cpp.cpp:1360 [ASTPP] Generated XML:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<document type="freeswitch/xml">
<section name="dialplan" description="ASTPP Dialplan">
<context name="default">
<extension name="91XXXXXXXXXX">
<condition field="destination_number" expression="91XXXXXXXXXX">
<action application="log" data="WARNING Accountcode 7724558832. Dialed number (91XXXXXXXXXX) termination rates not found!!"/>
<action application="playback" data="/usr/local/freeswitch/sounds/en/us/callie/astpp-badphone.wav"/>
<action application="set" data="error_cdr=1"/>
<action application="set" data="callstart=2016-08-31 18:17:32"/>
<action application="set" data="account_id=4"/>
<action application="set" data="call_direction=outbound"/>
<action application="set" data="sip_ignore_remote_cause=true"/>
<action application="set" data="call_processed=internal"/>
<action application="set" data="effective_destination_number=91XXXXXXXXXX"/>
<action application="set" data="last_bridge_hangup_cause=TERMINATION_RATE_NOT_FOUND"/>
<action application="hangup" data="TERMINATION_RATE_NOT_FOUND"/>
</condition>
</extension>
</context>
</section>
</document>
2016-08-31 18:17:32.340041 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f62fc0ec750 released.
Dialplan: sofia/default/7724558832@XX:XX:XX:XX parsing [default->91XXXXXXXXXX] continue=false
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Regex (PASS) [91XXXXXXXXXX] destination_number(91XXXXXXXXXX) =~ /91XXXXXXXXXX/ break=on-false
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action log(WARNING Accountcode 7724558832. Dialed number (91XXXXXXXXXX) termination rates not found!!)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action playback(/usr/local/freeswitch/sounds/en/us/callie/astpp-badphone.wav)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(error_cdr=1)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(callstart=2016-08-31 18:17:32)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(account_id=4)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(call_direction=outbound)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(sip_ignore_remote_cause=true)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(call_processed=internal)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(effective_destination_number=91XXXXXXXXXX)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action set(last_bridge_hangup_cause=TERMINATION_RATE_NOT_FOUND)
Dialplan: sofia/default/7724558832@XX:XX:XX:XX Action hangup(TERMINATION_RATE_NOT_FOUND)
2016-08-31 18:17:32.340041 [DEBUG] switch_core_state_machine.c:286 (sofia/default/7724558832@XX:XX:XX:XX) State Change CS_ROUTING -> CS_EXECUTE
2016-08-31 18:17:32.340041 [DEBUG] switch_core_state_machine.c:602 (sofia/default/7724558832@XX:XX:XX:XX) State ROUTING going to sleep
2016-08-31 18:17:32.340041 [DEBUG] switch_core_state_machine.c:543 (sofia/default/7724558832@XX:XX:XX:XX) Running State Change CS_EXECUTE
2016-08-31 18:17:32.340041 [DEBUG] switch_core_state_machine.c:609 (sofia/default/7724558832@XX:XX:XX:XX) State EXECUTE
2016-08-31 18:17:32.340041 [DEBUG] mod_sofia.c:197 sofia/default/7724558832@XX:XX:XX:XX SOFIA EXECUTE
2016-08-31 18:17:32.340041 [DEBUG] switch_core_state_machine.c:328 sofia/default/7724558832@XX:XX:XX:XX Standard EXECUTE
EXECUTE sofia/default/7724558832@XX:XX:XX:XX log(WARNING Accountcode 7724558832. Dialed number (91XXXXXXXXXX) termination rates not found!!)
2016-08-31 18:17:32.340041 [WARNING] mod_dptools.c:1713 Accountcode 7724558832. Dialed number (91XXXXXXXXXX) termination rates not found!!
2016-08-31 18:17:32.340041 [DEBUG] switch_core_session.c:2628 Application playback Requires media! pre_answering channel sofia/default/7724558832@XX:XX:XX:XX
2016-08-31 18:17:32.340041 [INFO] switch_core_session.c:2630 Sending early media
2016-08-31 18:17:32.340041 [DEBUG] switch_core_media.c:6464 AUDIO RTP [sofia/default/7724558832@XX:XX:XX:XX] XX:XX:XX:XX port 16412 -> XXXXXXXXXX port 44230 codec: 0 ms: 20
2016-08-31 18:17:32.340041 [DEBUG] switch_rtp.c:3832 Starting timer [soft] 160 bytes per 20ms
2016-08-31 18:17:32.340041 [DEBUG] switch_core_media.c:6763 sofia/default/7724558832@XX:XX:XX:XX Set 2833 dtmf send payload to 101
2016-08-31 18:17:32.340041 [DEBUG] switch_core_media.c:6770 sofia/default/7724558832@XX:XX:XX:XX Set 2833 dtmf receive payload to 101
2016-08-31 18:17:32.340041 [DEBUG] switch_core_media.c:6793 sofia/default/7724558832@XX:XX:XX:XX Set rtp dtmf delay to 40
2016-08-31 18:17:32.340041 [DEBUG] mod_sofia.c:2367 Ring SDP:
v=0
o=FreeSWITCH 1472651040 1472651041 IN IP4 XX:XX:XX:XX
s=FreeSWITCH
c=IN IP4 XX:XX:XX:XX
t=0 0
m=audio 16412 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

2016-08-31 18:17:32.340041 [NOTICE] mod_sofia.c:2370 Pre-Answer sofia/default/7724558832@XX:XX:XX:XX!
2016-08-31 18:17:32.340041 [DEBUG] switch_channel.c:3471 (sofia/default/7724558832@XX:XX:XX:XX) Callstate Change RINGING -> EARLY
2016-08-31 18:17:32.340041 [DEBUG] sofia.c:6858 Channel sofia/default/7724558832@XX:XX:XX:XX entering state [early][183]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX playback(/usr/local/freeswitch/sounds/en/us/callie/astpp-badphone.wav)
2016-08-31 18:17:32.340041 [DEBUG] switch_core_file.c:330 File /usr/local/freeswitch/sounds/en/us/callie/astpp-badphone.wav sample rate 16000 doesn't match requested rate 8000
2016-08-31 18:17:32.340041 [DEBUG] switch_ivr_play_say.c:1467 Codec Activated L16@8000hz 1 channels 20ms
2016-08-31 18:17:32.580167 [DEBUG] switch_rtp.c:6707 Correct audio ip/port confirmed.
2016-08-31 18:17:33.780100 [DEBUG] switch_ivr_play_say.c:1910 done playing file /usr/local/freeswitch/sounds/en/us/callie/astpp-badphone.wav
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(error_cdr=1)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [error_cdr]=[1]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(callstart=2016-08-31 18:17:32)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [callstart]=[2016-08-31 18:17:32]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(account_id=4)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [account_id]=[4]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(call_direction=outbound)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [call_direction]=[outbound]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(sip_ignore_remote_cause=true)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [sip_ignore_remote_cause]=[true]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(call_processed=internal)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [call_processed]=[internal]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(effective_destination_number=91XXXXXXXXXX)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [effective_destination_number]=[91XXXXXXXXXX]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX set(last_bridge_hangup_cause=TERMINATION_RATE_NOT_FOUND)
2016-08-31 18:17:33.780100 [DEBUG] mod_dptools.c:1519 SET sofia/default/7724558832@XX:XX:XX:XX [last_bridge_hangup_cause]=[TERMINATION_RATE_NOT_FOUND]
EXECUTE sofia/default/7724558832@XX:XX:XX:XX hangup(TERMINATION_RATE_NOT_FOUND)
2016-08-31 18:17:33.780100 [NOTICE] mod_dptools.c:1283 Hangup sofia/default/7724558832@XX:XX:XX:XX [CS_EXECUTE] [NORMAL_CLEARING]
2016-08-31 18:17:33.780100 [DEBUG] switch_core_session.c:2796 sofia/default/7724558832@XX:XX:XX:XX skip receive message [PHONE_EVENT|channel is hungup already]
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:609 (sofia/default/7724558832@XX:XX:XX:XX) State EXECUTE going to sleep
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:543 (sofia/default/7724558832@XX:XX:XX:XX) Running State Change CS_HANGUP
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:809 (sofia/default/7724558832@XX:XX:XX:XX) Callstate Change EARLY -> HANGUP
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:811 (sofia/default/7724558832@XX:XX:XX:XX) State HANGUP
2016-08-31 18:17:33.780100 [DEBUG] mod_sofia.c:437 Channel sofia/default/7724558832@XX:XX:XX:XX hanging up, cause: NORMAL_CLEARING
2016-08-31 18:17:33.780100 [DEBUG] mod_sofia.c:574 Responding to INVITE with: 480
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:60 sofia/default/7724558832@XX:XX:XX:XX Standard HANGUP, cause: NORMAL_CLEARING
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:811 (sofia/default/7724558832@XX:XX:XX:XX) State HANGUP going to sleep
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:578 (sofia/default/7724558832@XX:XX:XX:XX) State Change CS_HANGUP -> CS_REPORTING
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:543 (sofia/default/7724558832@XX:XX:XX:XX) Running State Change CS_REPORTING
2016-08-31 18:17:33.780100 [DEBUG] switch_core_state_machine.c:897 (sofia/default/7724558832@XX:XX:XX:XX) State REPORTING
2016-08-31 18:17:33.780100 [INFO] mod_json_cdr.c:271 Process [2ef6be90-6fa7-11e6-b836-f96d931a8344.cdr.json]
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:174 sofia/default/7724558832@XX:XX:XX:XX Standard REPORTING, cause: NORMAL_CLEARING
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:897 (sofia/default/7724558832@XX:XX:XX:XX) State REPORTING going to sleep
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:569 (sofia/default/7724558832@XX:XX:XX:XX) State Change CS_REPORTING -> CS_DESTROY
2016-08-31 18:17:33.820054 [DEBUG] switch_core_session.c:1646 Session 2 (sofia/default/7724558832@XX:XX:XX:XX) Locked, Waiting on external entities
2016-08-31 18:17:33.820054 [NOTICE] switch_core_session.c:1664 Session 2 (sofia/default/7724558832@XX:XX:XX:XX) Ended
2016-08-31 18:17:33.820054 [NOTICE] switch_core_session.c:1668 Close Channel sofia/default/7724558832@XX:XX:XX:XX [CS_DESTROY]
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:700 (sofia/default/7724558832@XX:XX:XX:XX) Running State Change CS_DESTROY
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:710 (sofia/default/7724558832@XX:XX:XX:XX) State DESTROY
2016-08-31 18:17:33.820054 [DEBUG] mod_sofia.c:342 sofia/default/7724558832@XX:XX:XX:XX SOFIA DESTROY
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:181 sofia/default/7724558832@XX:XX:XX:XX Standard DESTROY
2016-08-31 18:17:33.820054 [DEBUG] switch_core_state_machine.c:710 (sofia/default/7724558832@XX:XX:XX:XX) State DESTROY going to sleep