2016-11-22 11:23:46.838618 [NOTICE] switch_channel.c:1104 New Channel sofia/astpp/
c...@1.2.3.4 [c091d830-b09d-11e6-a1f1-edf8a63e77f2]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_NEW
2016-11-22 11:23:46.838618 [DEBUG] sofia.c:9376 sofia/astpp/
c...@1.2.3.4 receiving invite from
10.10.10.53:5060 version: 1.6.8 git 99de0ad 2016-05-05 15:38:32Z 64bit
2016-11-22 11:23:46.838618 [DEBUG] sofia.c:9488 IP 10.10.10.53 Approved by acl "default[]". Access Granted.
2016-11-22 11:23:46.838618 [DEBUG] sofia.c:6858 Channel sofia/astpp/
c...@1.2.3.4 entering state [received][100]
2016-11-22 11:23:46.838618 [DEBUG] sofia.c:6868 Remote SDP:
v=0
o=root 158768.... 158768.... IN IP4 10.10.10.53
s=Asterisk PBX 13.9.1
c=IN IP4 10.10.10.53
t=0 0
m=audio 14914 RTP/AVP 18 0 8 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=maxptime:150
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4410 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4355 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4271 Set telephone-event payload to 101@8000
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:3090 Set Codec sofia/astpp/
c...@1.2.3.4 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2016-11-22 11:23:46.838618 [DEBUG] switch_core_codec.c:111 sofia/astpp/
c...@1.2.3.4 Original read codec set to PCMU:0
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4623 Set telephone-event payload to 101@8000
2016-11-22 11:23:46.838618 [DEBUG] switch_core_media.c:4681 sofia/astpp/
c...@1.2.3.4 Set 2833 dtmf send payload to 101 recv payload to 101
2016-11-22 11:23:46.838618 [DEBUG] sofia.c:7248 (sofia/astpp/
c...@1.2.3.4) State Change CS_NEW -> CS_INIT
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:562 (sofia/astpp/
c...@1.2.3.4) State NEW
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_INIT
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:586 (sofia/astpp/
c...@1.2.3.4) State INIT
2016-11-22 11:23:46.838618 [DEBUG] mod_sofia.c:89 sofia/astpp/
c...@1.2.3.4 SOFIA INIT
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:40 sofia/astpp/
c...@1.2.3.4 Standard INIT
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:48 (sofia/astpp/
c...@1.2.3.4) State Change CS_INIT -> CS_ROUTING
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:586 (sofia/astpp/
c...@1.2.3.4) State INIT going to sleep
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_ROUTING
2016-11-22 11:23:46.838618 [DEBUG] switch_channel.c:2249 (sofia/astpp/
c...@1.2.3.4) Callstate Change DOWN -> RINGING
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:602 (sofia/astpp/
c...@1.2.3.4) State ROUTING
2016-11-22 11:23:46.838618 [DEBUG] mod_sofia.c:142 sofia/astpp/
c...@1.2.3.4 SOFIA ROUTING
2016-11-22 11:23:46.838618 [DEBUG] switch_core_state_machine.c:236 sofia/astpp/
c...@1.2.3.4 Standard ROUTING
2016-11-22 11:23:46.838618 [INFO] mod_dialplan_xml.c:637 Processing cid <cid>->33412345678 in context default
2016-11-22 11:23:46.838618 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f71ec27f080 Connected.
2016-11-22 11:23:46.838618 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard')
2016-11-22 11:23:46.838618 [INFO] switch_cpp.cpp:1360 [ASTPP] [Dialplan] Dialed number : 33412345678
2016-11-22 11:23:46.838618 [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 ="33412345678" LIMIT 1
2016-11-22 11:23:46.838618 [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="33412345678" limit 1
2016-11-22 11:23:46.838618 [INFO] switch_cpp.cpp:1360 [ASTPP] [Dialplan] Call direction : outbound
2016-11-22 11:23:46.838618 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [IPAUTHENTICATION] Query :SELECT ip_map.*, (SELECT number FROM accounts where id=accountid AND status=0 AND deleted=0) AS account_code FROM ip_map WHERE SUBSTRING( ip, 1, CHAR_LENGTH( ip ) -3 ) = "10.10.10.53" AND prefix IN (NULL,'') OR SUBSTRING( ip, 1, CHAR_LENGTH( ip ) -3 ) = "10.10.10.53" AND "33412345678" RLIKE prefix ORDER BY LENGTH(prefix) DESC LIMIT 1
2016-11-22 11:23:46.838618 [NOTICE] switch_cpp.cpp:1360 [ASTPP] [Accountcode : 2709........]
2016-11-22 11:23:46.838618 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "2709........" OR id="2709........") AND status=0 AND deleted=0 AND (expiry >= '2016-11-22 10:23:46' OR expiry = '0000-00-00 00:00:00') limit 1
2016-11-22 11:23:46.858597 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [CHECK_BLOCKED_PREFIX] Query :SELECT * FROM block_patterns WHERE (blocked_patterns ='^33412345678.*' OR blocked_patterns ='^
3348336802.*' OR blocked_patterns ='^334833680.*' OR blocked_patterns ='^33483368.*' OR blocked_patterns ='^3348336.*' OR blocked_patterns ='^334833.*' OR blocked_patterns ='^33483.*' OR blocked_patterns ='^3348.*' OR blocked_patterns ='^334.*' OR blocked_patterns ='^33.*' OR blocked_patterns ='^3.*' OR blocked_patterns ='--') AND accountid = 5 limit 1
2016-11-22 11:23:46.858597 [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 ='^33412345678.*' OR patterns ='^
3348336802.*' OR patterns ='^334833680.*' OR patterns ='^33483368.*' OR patterns ='^3348336.*' OR patterns ='^334833.*' OR patterns ='^33483.*' OR patterns ='^3348.*' OR patterns ='^334.*' OR patterns ='^33.*' OR patterns ='^3.*' OR patterns ='--') AND status = 0 AND pricelist_id = 2 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] =============== Account Information ===================
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] User id : 5
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Account code : 2709........
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Balance : 9.32836
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Type : 0 [0:prepaid,1:postpaid]
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Ratecard id : 2
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] ========================================================
2016-11-22 11:23:46.858597 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 2 AND status = 0
2016-11-22 11:23:46.858597 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern ='^33412345678.*' OR pattern ='^
3348336802.*' OR pattern ='^334833680.*' OR pattern ='^33483368.*' OR pattern ='^3348336.*' OR pattern ='^334833.*' OR pattern ='^33483.*' OR pattern ='^3348.*' OR pattern ='^334.*' OR pattern ='^33.*' OR pattern ='^3.*' OR pattern ='--') AND status = 0 AND pricelist_id = 2 ORDER BY LENGTH(pattern) DESC,cost DESC LIMIT 1
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] =============== Rates Information ===================
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] ID : 5
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Connectcost : 0.00000
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Includedseconds : 0
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Cost : 0.00382
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] comment : France Fix
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Accid : 5
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] ================================================================
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] [FIND_MAXLENGTH] LIMITING CALL TO CONFIG MAX LENGTH 24!!!
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Call Max length duration : 24 minutes
2016-11-22 11:23:46.858597 [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 ='^33412345678.*' OR pattern ='^3348336802.*' OR pattern ='^334833680.*' OR pattern ='^33483368.*' OR pattern ='^3348336.*' OR pattern ='^334833.*' OR pattern ='^33483.*' OR pattern ='^3348.*' OR pattern ='^334.*' OR pattern ='^33.*' OR pattern ='^3.*' OR pattern ='--') AND TR.status = 0 AND TR.trunk_id=3 ORDER by LENGTH (pattern) DESC,TR.cost ASC,TR.precedence ASC, TK.precedence
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] =============== Termination Rates Information ===================
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] ID : 5
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Code : ^334.*
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Destination : France Fix
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Connectcost : 0.00000
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Free Seconds : 0
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Prefix : ^334.*
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Strip :
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Prepend :
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Carrier id : 3
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] carrier_name : astpp_GW
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] dialplan_variable :
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Failover gateway :
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Vendor id : 5
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Number Translation :
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] Max channels : 0
2016-11-22 11:23:46.858597 [INFO] switch_cpp.cpp:1360 [ASTPP] ========================END OF TERMINATION RATES=======================
2016-11-22 11:23:46.858597 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [GET_OVERRIDE_CALLERID] Query :SELECT callerid_name as cid_name,callerid_number as cid_number,accountid FROM accounts_callerid WHERE accountid = 5 AND status=0 LIMIT 1
2016-11-22 11:23:46.858597 [DEBUG] switch_cpp.cpp:1360 [ASTPP] [Dialplan] 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="33412345678">
<condition field="destination_number" expression="33412345678">
<action application="set" data="effective_destination_number=33412345678"/>
<action application="sched_hangup" data="+1440 normal_clearing"/>
<action application="set" data="callstart=2016-11-22 10:23:46"/>
<action application="set" data="hangup_after_bridge=true"/>
<action application="set" data="continue_on_fail=true"/>
<action application="set" data="account_id=5"/>
<action application="set" data="parent_id=0"/>
<action application="set" data="entity_id=3"/>
<action application="set" data="call_processed=internal"/>
<action application="set" data="call_direction=outbound"/>
<action application="set" data="accountname=freepbx"/>
<action application="export" data="t38_passthru=true"/>
<action application="set" data="fax_enable_t38=true"/>
<action application="set" data="fax_enable_t38_request=true"/>
<action application="set" data="origination_rates=ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00382|INC:60|INITIALBLOCK:0|RATEGROUP:2|MARKUP:0|ACCID:5"/>
<action application="export" data="is_recording=1"/>
<action application="export" data="media_bug_answer_req=true"/>
<action application="export" data="RECORD_STEREO=true"/>
<action application="export" data="record_sample_rate=8000"/>
<action application="export" data="execute_on_answer=record_session $${base_dir}/recordings/${strftime(%Y-%m-%d-%H:%M:%S)}_2709.........wav"/>
<action application="set" data="calltype=STANDARD"/>
<action application="set" data="termination_rates=ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00373|INC:60|INITIALBLOCK:0|TRUNK:3|PROVIDER:5"/>
<action application="set" data="trunk_id=3"/>
<action application="set" data="provider_id=5"/>
<action application="set" data="absolute_codec_string=PCMA,PCMU,G729"/>
<action application="bridge" data="sofia/gateway/astpp_GW/33412345678"/>
</condition>
</extension>
</context>
</section>
</document>
2016-11-22 11:23:46.858597 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f71ec27f080 released.
Dialplan: sofia/astpp/
c...@1.2.3.4 parsing [default->33412345678] continue=false
Dialplan: sofia/astpp/
c...@1.2.3.4 Regex (PASS) [33412345678] destination_number(33412345678) =~ /33412345678/ break=on-false
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(effective_destination_number=33412345678)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action sched_hangup(+1440 normal_clearing)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(callstart=2016-11-22 10:23:46)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(hangup_after_bridge=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(continue_on_fail=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(call_processed=internal)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(call_direction=outbound)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(accountname=freepbx)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action export(t38_passthru=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(fax_enable_t38=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(fax_enable_t38_request=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(origination_rates=ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00382|INC:60|INITIALBLOCK:0|RATEGROUP:2|MARKUP:0|ACCID:5)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action export(is_recording=1)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action export(media_bug_answer_req=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action export(RECORD_STEREO=true)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action export(record_sample_rate=8000)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action export(execute_on_answer=record_session $${base_dir}/recordings/${strftime(%Y-%m-%d-%H:%M:%S)}_2709.........wav)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(calltype=STANDARD)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(termination_rates=ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00373|INC:60|INITIALBLOCK:0|TRUNK:3|PROVIDER:5)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(provider_id=5)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action set(absolute_codec_string=PCMA,PCMU,G729)
Dialplan: sofia/astpp/
c...@1.2.3.4 Action bridge(sofia/gateway/astpp_GW/33412345678)
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:286 (sofia/astpp/
c...@1.2.3.4) State Change CS_ROUTING -> CS_EXECUTE
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:602 (sofia/astpp/
c...@1.2.3.4) State ROUTING going to sleep
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_EXECUTE
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:609 (sofia/astpp/
c...@1.2.3.4) State EXECUTE
2016-11-22 11:23:46.858597 [DEBUG] mod_sofia.c:197 sofia/astpp/
c...@1.2.3.4 SOFIA EXECUTE
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:328 sofia/astpp/
c...@1.2.3.4 Standard EXECUTE
EXECUTE sofia/astpp/
c...@1.2.3.4 set(effective_destination_number=33412345678)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [effective_destination_number]=[33412345678]
EXECUTE sofia/astpp/
c...@1.2.3.4 sched_hangup(+1440 normal_clearing)
2016-11-22 11:23:46.858597 [DEBUG] switch_scheduler.c:249 Added task 26 switch_ivr_schedule_hangup (c091d830-b09d-11e6-a1f1-edf8a63e77f2) to run at 1479811666
EXECUTE sofia/astpp/
c...@1.2.3.4 set(callstart=2016-11-22 10:23:46)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [callstart]=[2016-11-22 10:23:46]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(hangup_after_bridge=true)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [hangup_after_bridge]=[true]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [continue_on_fail]=[true]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [account_id]=[5]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [parent_id]=[0]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [entity_id]=[3]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(call_processed=internal)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [call_processed]=[internal]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(call_direction=outbound)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [call_direction]=[outbound]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [accountname]=[freepbx]
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [t38_passthru]=[true]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [fax_enable_t38]=[true]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(fax_enable_t38_request=true)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [fax_enable_t38_request]=[true]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(origination_rates=ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00382|INC:60|INITIALBLOCK:0|RATEGROUP:2|MARKUP:0|ACCID:5)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [origination_rates]=[ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00382|INC:60|INITIALBLOCK:0|RATEGROUP:2|MARKUP:0|ACCID:5]
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [is_recording]=[1]
EXECUTE sofia/astpp/
c...@1.2.3.4 export(media_bug_answer_req=true)
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [media_bug_answer_req]=[true]
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RECORD_STEREO]=[true]
EXECUTE sofia/astpp/
c...@1.2.3.4 export(record_sample_rate=8000)
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [record_sample_rate]=[8000]
EXECUTE sofia/astpp/
c...@1.2.3.4 export(execute_on_answer=record_session /usr/local/freeswitch/recordings/2016-11-22-11:23:46_2709.........wav)
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [execute_on_answer]=[record_session ...../freeswitch/recordings/2016-11-22-11:23:46_2709.........wav]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [calltype]=[STANDARD]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(termination_rates=ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00373|INC:60|INITIALBLOCK:0|TRUNK:3|PROVIDER:5)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [termination_rates]=[ID:5|CODE:^334.*|DESTINATION:France Fix|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00373|INC:60|INITIALBLOCK:0|TRUNK:3|PROVIDER:5]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [trunk_id]=[3]
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [provider_id]=[5]
EXECUTE sofia/astpp/
c...@1.2.3.4 set(absolute_codec_string=PCMA,PCMU,G729)
2016-11-22 11:23:46.858597 [DEBUG] mod_dptools.c:1519 SET sofia/astpp/
c...@1.2.3.4 [absolute_codec_string]=[PCMA,PCMU,G729]
EXECUTE sofia/astpp/
c...@1.2.3.4 bridge(sofia/gateway/astpp_GW/33412345678)
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1250 sofia/astpp/
c...@1.2.3.4 EXPORTING[export_vars] [t38_passthru]=[true] to event
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1250 sofia/astpp/
c...@1.2.3.4 EXPORTING[export_vars] [is_recording]=[1] to event
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1250 sofia/astpp/
c...@1.2.3.4 EXPORTING[export_vars] [media_bug_answer_req]=[true] to event
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1250 sofia/astpp/
c...@1.2.3.4 EXPORTING[export_vars] [RECORD_STEREO]=[true] to event
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1250 sofia/astpp/
c...@1.2.3.4 EXPORTING[export_vars] [record_sample_rate]=[8000] to event
2016-11-22 11:23:46.858597 [DEBUG] switch_channel.c:1250 sofia/astpp/
c...@1.2.3.4 EXPORTING[export_vars] [execute_on_answer]=[record_session /usr/local/freeswitch/recordings/2016-11-22-11:23:46_2709.........wav] to event
2016-11-22 11:23:46.858597 [DEBUG] switch_ivr_originate.c:2127 Parsing global variables
2016-11-22 11:23:46.858597 [NOTICE] switch_channel.c:1104 New Channel sofia/astpp/33412345678 [c094cb4e-b09d-11e6-a20f-edf8a63e77f2]
2016-11-22 11:23:46.858597 [DEBUG] mod_sofia.c:4813 (sofia/astpp/33412345678) State Change CS_NEW -> CS_INIT
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/33412345678) Running State Change CS_INIT
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:586 (sofia/astpp/33412345678) State INIT
2016-11-22 11:23:46.858597 [DEBUG] mod_sofia.c:89 sofia/astpp/33412345678 SOFIA INIT
2016-11-22 11:23:46.858597 [DEBUG] sofia_glue.c:1257 sofia/astpp/33412345678 sending invite version: 1.6.8 git 99de0ad 2016-05-05 15:38:32Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1479783368 1479783369 IN IP4 1.2.3.4
s=FreeSWITCH
c=IN IP4 1.2.3.4
t=0 0
m=audio 26858 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-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:40 sofia/astpp/33412345678 Standard INIT
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:48 (sofia/astpp/33412345678) State Change CS_INIT -> CS_ROUTING
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:586 (sofia/astpp/33412345678) State INIT going to sleep
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/33412345678) Running State Change CS_ROUTING
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:602 (sofia/astpp/33412345678) State ROUTING
2016-11-22 11:23:46.858597 [DEBUG] mod_sofia.c:142 sofia/astpp/33412345678 SOFIA ROUTING
2016-11-22 11:23:46.858597 [DEBUG] switch_ivr_originate.c:67 (sofia/astpp/33412345678) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:602 (sofia/astpp/33412345678) State ROUTING going to sleep
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/33412345678) Running State Change CS_CONSUME_MEDIA
2016-11-22 11:23:46.858597 [DEBUG] sofia.c:6858 Channel sofia/astpp/33412345678 entering state [calling][0]
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:621 (sofia/astpp/33412345678) State CONSUME_MEDIA
2016-11-22 11:23:46.858597 [DEBUG] switch_core_state_machine.c:621 (sofia/astpp/33412345678) State CONSUME_MEDIA going to sleep
send 1119 bytes to udp/[111.222.333.444]:5060 at 11:23:46.924454:
------------------------------------------------------------------------
Via: SIP/2.0/UDP 1.2.3.4;rport;branch=z9hG4bK1HvQj0971t2mg
Max-Forwards: 69
Call-ID: 97f326b2-2b40-1235-888c-020000ef2ecb
CSeq: 99569049 INVITE
Contact: <sip:gw+as...@1.2.3.4:5060;transport=udp;gw=astpp_GW>
User-Agent: ASTPP
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 224
v=0
o=FreeSWITCH 1479783368 1479783369 IN IP4 1.2.3.4
s=FreeSWITCH
c=IN IP4 1.2.3.4
t=0 0
m=audio 26858 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
------------------------------------------------------------------------
recv 496 bytes from udp/[111.222.333.444]:5060 at 11:23:46.930643:
------------------------------------------------------------------------
SIP/2.0 488 Not acceptable here
Via: SIP/2.0/UDP 1.2.3.4;branch=z9hG4bK1HvQj0971t2mg;received=1.2.3.4;rport=5060
Call-ID: 97f326b2-2b40-1235-888c-020000ef2ecb
CSeq: 99569049 INVITE
Server: Asterisk PBX 13.6.0
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0
------------------------------------------------------------------------
send 346 bytes to udp/[111.222.333.444]:5060 at 11:23:46.930812:
------------------------------------------------------------------------
Via: SIP/2.0/UDP 1.2.3.4;rport;branch=z9hG4bK1HvQj0971t2mg
Max-Forwards: 69
Call-ID: 97f326b2-2b40-1235-888c-020000ef2ecb
CSeq: 99569049 ACK
Content-Length: 0
------------------------------------------------------------------------
2016-11-22 11:23:46.918624 [DEBUG] sofia.c:6858 Channel sofia/astpp/33412345678 entering state [terminated][488]
2016-11-22 11:23:46.918624 [NOTICE] sofia.c:7881 Hangup sofia/astpp/33412345678 [CS_CONSUME_MEDIA] [INCOMPATIBLE_DESTINATION]
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/33412345678) Running State Change CS_HANGUP
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:809 (sofia/astpp/33412345678) Callstate Change DOWN -> HANGUP
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:811 (sofia/astpp/33412345678) State HANGUP
2016-11-22 11:23:46.918624 [DEBUG] mod_sofia.c:437 Channel sofia/astpp/33412345678 hanging up, cause: INCOMPATIBLE_DESTINATION
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:60 sofia/astpp/33412345678 Standard HANGUP, cause: INCOMPATIBLE_DESTINATION
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:811 (sofia/astpp/33412345678) State HANGUP going to sleep
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:578 (sofia/astpp/33412345678) State Change CS_HANGUP -> CS_REPORTING
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/33412345678) Running State Change CS_REPORTING
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:897 (sofia/astpp/33412345678) State REPORTING
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:174 sofia/astpp/33412345678 Standard REPORTING, cause: INCOMPATIBLE_DESTINATION
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:897 (sofia/astpp/33412345678) State REPORTING going to sleep
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:569 (sofia/astpp/33412345678) State Change CS_REPORTING -> CS_DESTROY
2016-11-22 11:23:46.918624 [DEBUG] switch_core_session.c:1646 Session 58 (sofia/astpp/33412345678) Locked, Waiting on external entities
2016-11-22 11:23:46.918624 [DEBUG] switch_ivr_originate.c:3750 Originate Resulted in Error Cause: 88 [INCOMPATIBLE_DESTINATION]
2016-11-22 11:23:46.918624 [NOTICE] switch_core_session.c:1664 Session 58 (sofia/astpp/33412345678) Ended
2016-11-22 11:23:46.918624 [NOTICE] switch_core_session.c:1668 Close Channel sofia/astpp/33412345678 [CS_DESTROY]
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:700 (sofia/astpp/33412345678) Running State Change CS_DESTROY
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:710 (sofia/astpp/33412345678) State DESTROY
2016-11-22 11:23:46.918624 [DEBUG] mod_sofia.c:342 sofia/astpp/33412345678 SOFIA DESTROY
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:181 sofia/astpp/33412345678 Standard DESTROY
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:710 (sofia/astpp/33412345678) State DESTROY going to sleep
2016-11-22 11:23:46.918624 [INFO] mod_dptools.c:3401 Originate Failed. Cause: INCOMPATIBLE_DESTINATION
2016-11-22 11:23:46.918624 [NOTICE] switch_core_state_machine.c:385 sofia/astpp/
c...@1.2.3.4 has executed the last dialplan instruction, hanging up.
2016-11-22 11:23:46.918624 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/astpp/
c...@1.2.3.4 [CS_EXECUTE] [NORMAL_CLEARING]
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:609 (sofia/astpp/
c...@1.2.3.4) State EXECUTE going to sleep
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_HANGUP
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:809 (sofia/astpp/
c...@1.2.3.4) Callstate Change RINGING -> HANGUP
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:811 (sofia/astpp/
c...@1.2.3.4) State HANGUP
2016-11-22 11:23:46.918624 [DEBUG] mod_sofia.c:431 sofia/astpp/
c...@1.2.3.4 Overriding SIP cause 480 with 488 from the other leg
2016-11-22 11:23:46.918624 [DEBUG] mod_sofia.c:437 Channel sofia/astpp/
c...@1.2.3.4 hanging up, cause: NORMAL_CLEARING
2016-11-22 11:23:46.918624 [DEBUG] mod_sofia.c:574 Responding to INVITE with: 488
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:60 sofia/astpp/
c...@1.2.3.4 Standard HANGUP, cause: NORMAL_CLEARING
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:811 (sofia/astpp/
c...@1.2.3.4) State HANGUP going to sleep
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:578 (sofia/astpp/
c...@1.2.3.4) State Change CS_HANGUP -> CS_REPORTING
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:543 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_REPORTING
send 723 bytes to udp/[10.10.10.53]:5060 at 11:23:46.933638:
------------------------------------------------------------------------
SIP/2.0 488 Not Acceptable Here
Via: SIP/2.0/UDP 10.10.10.53:5060;branch=z9hG4bK1ac6b862;rport=5060
Max-Forwards: 70
CSeq: 102 INVITE
User-Agent: ASTPP
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0
2016-11-22 11:23:46.918624 [DEBUG] switch_core_state_machine.c:897 (sofia/astpp/
c...@1.2.3.4) State REPORTING
------------------------------------------------------------------------
2016-11-22 11:23:46.918624 [INFO] mod_json_cdr.c:271 Process [c091d830-b09d-11e6-a1f1-edf8a63e77f2.cdr.json]
recv 417 bytes from udp/[10.10.10.53]:5060 at 11:23:46.934019:
------------------------------------------------------------------------
Via: SIP/2.0/UDP 10.10.10.53:5060;branch=z9hG4bK1ac6b862;rport
Max-Forwards: 70
CSeq: 102 ACK
User-Agent: FPBX-13.0.169(13.9.1)
Content-Length: 0
------------------------------------------------------------------------
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:174 sofia/astpp/
c...@1.2.3.4 Standard REPORTING, cause: NORMAL_CLEARING
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:897 (sofia/astpp/
c...@1.2.3.4) State REPORTING going to sleep
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:569 (sofia/astpp/
c...@1.2.3.4) State Change CS_REPORTING -> CS_DESTROY
2016-11-22 11:23:46.938623 [DEBUG] switch_core_session.c:1646 Session 57 (sofia/astpp/
c...@1.2.3.4) Locked, Waiting on external entities
2016-11-22 11:23:46.938623 [NOTICE] switch_core_session.c:1664 Session 57 (sofia/astpp/
c...@1.2.3.4) Ended
2016-11-22 11:23:46.938623 [NOTICE] switch_core_session.c:1668 Close Channel sofia/astpp/
c...@1.2.3.4 [CS_DESTROY]
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:700 (sofia/astpp/
c...@1.2.3.4) Running State Change CS_DESTROY
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:710 (sofia/astpp/
c...@1.2.3.4) State DESTROY
2016-11-22 11:23:46.938623 [DEBUG] mod_sofia.c:342 sofia/astpp/
c...@1.2.3.4 SOFIA DESTROY
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:181 sofia/astpp/
c...@1.2.3.4 Standard DESTROY
2016-11-22 11:23:46.938623 [DEBUG] switch_core_state_machine.c:710 (sofia/astpp/
c...@1.2.3.4) State DESTROY going to sleep
2016-11-22 11:23:47.358621 [DEBUG] switch_scheduler.c:144 Deleting task 26 switch_ivr_schedule_hangup (c091d830-b09d-11e6-a1f1-edf8a63e77f2)
send 625 bytes to udp/[111.222.333.444]:5060 at 11:24:18.481463:
------------------------------------------------------------------------
Via: SIP/2.0/UDP 1.2.3.4;rport;branch=z9hG4bK2tNgmUtBZ3r7B
Max-Forwards: 70
Call-ID: aaca6a05-2b40-1235-888c-020000ef2ecb
CSeq: 99565669 OPTIONS
User-Agent: ASTPP
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: path, replaces
Allow-Events: talk, hold, conference, presence, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0