2019-05-22 19:11:55.910784 [NOTICE] switch_channel.c:1104 New Channel sofia/gateway1/0449131272@202.10.26.1:5060 [a6ef2390-7c71-11e9-a7fe-33f71d9eef79]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_NEW (Cur 5 Tot 338354)
2019-05-22 19:11:55.910784 [DEBUG] sofia.c:9873 sofia/gateway1/0449131272@202.10.26.1:5060 receiving invite from 202.10.26.1:5060 version: 1.6.20  64bit
2019-05-22 19:11:55.910784 [DEBUG] sofia.c:9989 IP 202.10.26.1 Approved by acl "default[]". Access Granted.
2019-05-22 19:11:55.910784 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [received][100]
2019-05-22 19:11:55.910784 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=- 89383072259254 89383072259254 IN IP4 202.10.26.1
s=-
c=IN IP4 202.10.26.1
t=0 0
m=audio 43506 RTP/AVP 8 0 18 101
a=rtpmap:8 PCMA/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=ptime:20

2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:3061 Set Codec sofia/gateway1/0449131272@202.10.26.1:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2019-05-22 19:11:55.910784 [DEBUG] switch_core_codec.c:111 sofia/gateway1/0449131272@202.10.26.1:5060 Original read codec set to PCMA:8
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4767 sofia/gateway1/0449131272@202.10.26.1:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2019-05-22 19:11:55.910784 [DEBUG] sofia.c:7507 (sofia/gateway1/0449131272@202.10.26.1:5060) State Change CS_NEW -> CS_INIT
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:603 (sofia/gateway1/0449131272@202.10.26.1:5060) State NEW
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_INIT (Cur 5 Tot 338354)
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:627 (sofia/gateway1/0449131272@202.10.26.1:5060) State INIT
2019-05-22 19:11:55.910784 [DEBUG] mod_sofia.c:90 sofia/gateway1/0449131272@202.10.26.1:5060 SOFIA INIT
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:40 sofia/gateway1/0449131272@202.10.26.1:5060 Standard INIT
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:48 (sofia/gateway1/0449131272@202.10.26.1:5060) State Change CS_INIT -> CS_ROUTING
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:627 (sofia/gateway1/0449131272@202.10.26.1:5060) State INIT going to sleep
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_ROUTING (Cur 5 Tot 338354)
2019-05-22 19:11:55.910784 [DEBUG] switch_channel.c:2249 (sofia/gateway1/0449131272@202.10.26.1:5060) Callstate Change DOWN -> RINGING
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:643 (sofia/gateway1/0449131272@202.10.26.1:5060) State ROUTING
2019-05-22 19:11:55.910784 [DEBUG] mod_sofia.c:143 sofia/gateway1/0449131272@202.10.26.1:5060 SOFIA ROUTING
2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:236 sofia/gateway1/0449131272@202.10.26.1:5060 Standard ROUTING
2019-05-22 19:11:55.910784 [INFO] mod_dialplan_xml.c:637 Processing 0449131272 <0449131272>->0283965200 in context default
2019-05-22 19:11:55.910784 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f3eb406b550 Connected.
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard')
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 0283965200
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number  : 0449131272 / 0449131272
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,B.did_cid_translation as did_cid_translation,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,A.leg_timeout FROM dids AS A,accounts AS B WHERE A.status=0 AND B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="0283965200" LIMIT 1
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : inbound
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [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 INET_ATON("202.10.26.1") BETWEEN(INET_ATON(SUBSTRING_INDEX(`ip`, '/', 1)) & 0xffffffff ^((0x1 <<(32 -  SUBSTRING_INDEX(`ip`, '/', -1))) -1 )) AND(INET_ATON(SUBSTRING_INDEX(`ip`, '/', 1)) |((0x100000000 >> SUBSTRING_INDEX(`ip`,'/', -1)) -1))  AND "0283965200"  LIKE CONCAT(prefix,'%') ORDER BY LENGTH(prefix) DESC LIMIT 1
2019-05-22 19:11:55.910784 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 7335503421]
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "7335503421" OR id="7335503421") AND status=0 AND deleted=0 AND (expiry >= '2019-05-22 09:11:58' OR expiry = '0000-00-00 00:00:00') limit 1
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT * FROM packages  as P inner join package_patterns as PKGPTR on P.id = PKGPTR.package_id WHERE (patterns ='^0283965200.*' OR patterns ='^028396520.*' OR patterns ='^02839652.*' OR patterns ='^0283965.*' OR patterns ='^028396.*' OR patterns ='^02839.*' OR patterns ='^0283.*' OR patterns ='^028.*' OR patterns ='^02.*' OR patterns ='^0.*' OR patterns ='--') AND status = 0 AND pricelist_id = 1 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information ===================
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 3
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 7335503421
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Balance : 10000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 0 [0:prepaid,1:postpaid]
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 1
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ========================================================
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,B.did_cid_translation as did_cid_translation,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,A.leg_timeout FROM dids AS A,accounts AS B WHERE A.status=0 AND B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="0283965200" LIMIT 1
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information ===================
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 1209
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.00000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : 0283965200
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 3
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 1000000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 1000000 minutes
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "16" OR id="16") AND status=0 AND deleted=0 AND (expiry >= '2019-05-22 09:11:58' OR expiry = '0000-00-00 00:00:00') limit 1
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern ='^0283965200.*' OR pattern ='^028396520.*' OR pattern ='^02839652.*' OR pattern ='^0283965.*' OR pattern ='^028396.*' OR pattern ='^02839.*' OR pattern ='^0283.*' OR pattern ='^028.*' OR pattern ='^02.*' OR pattern ='^0.*' OR pattern ='--') AND status = 0 AND pricelist_id = 1  ORDER BY LENGTH(pattern) DESC,cost DESC LIMIT 1
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information ===================
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 5
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.08000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.00000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : National
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 3
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 1000000
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML:3
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Userinfo XML:3
2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML : 3
2019-05-22 19:11:55.910784 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLINBOUND] Caller ID Translation Starts
2019-05-22 19:11:55.910784 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLINBOUND] Caller ID Translation Ends
2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [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="0283965200">
<condition field="destination_number" expression="0283965200">
<action application="set" data="effective_destination_number=0283965200"/>
<action application="sched_hangup" data="+60000000 normal_clearing"/>
<action application="set" data="callstart=2019-05-22 09:11:58"/>
<action application="set" data="hangup_after_bridge=true"/>
<action application="set" data="continue_on_fail=true"/>
<action application="set" data="account_id=3"/>
<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=inbound"/>
<action application="set" data="accountname=CTS 2"/>
<action application="set" data="origination_rates_did=ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16"/>
<action application="set" data="origination_rates=ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3"/>
<action application="set" data="original_caller_id_name=0449131272"/>
<action application="set" data="original_caller_id_number=0449131272"/>
<action application="set" data="effective_caller_id_name=0449131272"/>
<action application="set" data="effective_caller_id_number=0449131272"/>
<action application="set" data="receiver_accid=16"/>
<action application="set" data="calltype=SIP-DID"/>
<action application="bridge" data="{sip_contact_user=0283965200}[leg_timeout=30]sofia/default/0283965200${regex(${sofia_contact(1976788220@${domain_name})}|^[^@]+(.*)|%1)}"/>
<condition field="${cond(${user_data 1976788220@${domain_name} param vm-enabled} == true ? YES : NO)}" expression="^YES$">
<action application="answer"/>
<action application="export" data="voicemail_alternate_greet_id=0283965200"/>
<action application="voicemail" data="default $${domain_name} 1976788220"/>
<anti-action application="hangup" data="${originate_disposition}"/>
</condition>
</condition>
</extension>
</context>
</section>
</document>
2019-05-22 19:11:55.910784 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f3eb406b550 released.
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 parsing [default->0283965200] continue=false
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Regex (PASS) [0283965200] destination_number(0283965200) =~ /0283965200/ break=on-false
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(effective_destination_number=0283965200) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action sched_hangup(+60000000 normal_clearing) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(callstart=2019-05-22 09:11:58) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(hangup_after_bridge=true) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(continue_on_fail=true) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(account_id=3) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(parent_id=0) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(entity_id=3) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(call_processed=internal) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(call_direction=inbound) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(accountname=CTS 2) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(origination_rates_did=ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(origination_rates=ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(original_caller_id_name=0449131272) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(original_caller_id_number=0449131272) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(effective_caller_id_name=0449131272) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(effective_caller_id_number=0449131272) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(receiver_accid=16) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(calltype=SIP-DID) 
Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action bridge({sip_contact_user=0283965200}[leg_timeout=30]sofia/default/0283965200${regex(${sofia_contact(1976788220@${domain_name})}|^[^@]+(.*)|%1)}) 
|--- Dialplan: Processing recursive conditions level:1 [0283965200_recur_1] require-nested=TRUE
|--- Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Regex (FAIL) [0283965200_recur_1] ${cond(${user_data 1976788220@${domain_name} param vm-enabled} == true ? YES : NO)}(NO) =~ /^YES$/ break=on-false
|--- Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 ANTI-Action hangup(${originate_disposition}) 
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:286 (sofia/gateway1/0449131272@202.10.26.1:5060) State Change CS_ROUTING -> CS_EXECUTE
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:643 (sofia/gateway1/0449131272@202.10.26.1:5060) State ROUTING going to sleep
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_EXECUTE (Cur 5 Tot 338354)
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:650 (sofia/gateway1/0449131272@202.10.26.1:5060) State EXECUTE
2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:198 sofia/gateway1/0449131272@202.10.26.1:5060 SOFIA EXECUTE
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:328 sofia/gateway1/0449131272@202.10.26.1:5060 Standard EXECUTE
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(effective_destination_number=0283965200)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [effective_destination_number]=[0283965200]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 sched_hangup(+60000000 normal_clearing)
2019-05-22 19:11:55.930798 [DEBUG] switch_scheduler.c:249 Added task 148509 switch_ivr_schedule_hangup (a6ef2390-7c71-11e9-a7fe-33f71d9eef79) to run at 1618516315
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(callstart=2019-05-22 09:11:58)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [callstart]=[2019-05-22 09:11:58]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(hangup_after_bridge=true)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [hangup_after_bridge]=[true]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(continue_on_fail=true)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [continue_on_fail]=[true]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(account_id=3)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [account_id]=[3]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(parent_id=0)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [parent_id]=[0]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(entity_id=3)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [entity_id]=[3]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(call_processed=internal)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [call_processed]=[internal]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(call_direction=inbound)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [call_direction]=[inbound]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(accountname=CTS 2)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [accountname]=[CTS 2]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(origination_rates_did=ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [origination_rates_did]=[ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(origination_rates=ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [origination_rates]=[ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(original_caller_id_name=0449131272)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [original_caller_id_name]=[0449131272]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(original_caller_id_number=0449131272)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [original_caller_id_number]=[0449131272]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(effective_caller_id_name=0449131272)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [effective_caller_id_name]=[0449131272]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(effective_caller_id_number=0449131272)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [effective_caller_id_number]=[0449131272]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(receiver_accid=16)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [receiver_accid]=[16]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(calltype=SIP-DID)
2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [calltype]=[SIP-DID]
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 bridge({sip_contact_user=0283965200}[leg_timeout=30]sofia/default/0283965200@58.96.28.252:5060;transport=UDP)
2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables
2019-05-22 19:11:55.930798 [NOTICE] switch_channel.c:1104 New Channel sofia/default/0283965200@58.96.28.252:5060 [a6f3d052-7c71-11e9-a818-33f71d9eef79]
2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:4819 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_NEW -> CS_INIT
2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:2963 sofia/default/0283965200@58.96.28.252:5060 Setting leg timeout to 30
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_INIT (Cur 6 Tot 338355)
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0283965200@58.96.28.252:5060) State INIT
2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:90 sofia/default/0283965200@58.96.28.252:5060 SOFIA INIT
2019-05-22 19:11:55.930798 [DEBUG] sofia_glue.c:1295 sofia/default/0283965200@58.96.28.252:5060 sending invite version: 1.6.20  64bit
Local SDP:
v=0
o=FreeSWITCH 1558492093 1558492094 IN IP4 59.100.179.100
s=FreeSWITCH
c=IN IP4 59.100.179.100
t=0 0
m=audio 24222 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:40 sofia/default/0283965200@58.96.28.252:5060 Standard INIT
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:48 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_INIT -> CS_ROUTING
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0283965200@58.96.28.252:5060) State INIT going to sleep
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_ROUTING (Cur 6 Tot 338355)
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0283965200@58.96.28.252:5060) State ROUTING
2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:143 sofia/default/0283965200@58.96.28.252:5060 SOFIA ROUTING
2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:67 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0283965200@58.96.28.252:5060) State ROUTING going to sleep
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_CONSUME_MEDIA (Cur 6 Tot 338355)
2019-05-22 19:11:55.930798 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [calling][0]
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:662 (sofia/default/0283965200@58.96.28.252:5060) State CONSUME_MEDIA
2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:662 (sofia/default/0283965200@58.96.28.252:5060) State CONSUME_MEDIA going to sleep
2019-05-22 19:11:56.230755 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [proceeding][183]
2019-05-22 19:11:56.230755 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=SBC 1399 1001 IN IP4 58.96.28.252
s=VoipCall
c=IN IP4 58.96.28.252
t=0 0
m=audio 16676 RTP/AVP 8 101
c=IN IP4 58.96.28.252
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=maxptime:40
a=rtcp:16677

2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/0283965200@58.96.28.252:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
2019-05-22 19:11:56.230755 [DEBUG] switch_core_codec.c:111 sofia/default/0283965200@58.96.28.252:5060 Original read codec set to PCMA:8
2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4767 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/0283965200@58.96.28.252:5060] 192.168.2.210 port 24222 -> 58.96.28.252 port 16676 codec: 8 ms: 20
2019-05-22 19:11:56.230755 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7096 Activating RTCP PORT 16677
2019-05-22 19:11:56.250767 [DEBUG] switch_rtp.c:4533 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 16677
2019-05-22 19:11:56.250767 [DEBUG] switch_rtp.c:2567 Setting RTCP remote addr to 58.96.28.252:16677 2
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7180 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7187 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf receive payload to 101
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7210 sofia/default/0283965200@58.96.28.252:5060 Set rtp dtmf delay to 40
2019-05-22 19:11:56.250767 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/0283965200@58.96.28.252:5060!
2019-05-22 19:11:56.250767 [DEBUG] switch_channel.c:3474 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change DOWN -> EARLY
2019-05-22 19:11:56.250767 [INFO] switch_ivr_originate.c:3654 Sending early media
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/gateway1/0449131272@202.10.26.1:5060] 10.239.237.34 port 23138 -> 202.10.26.1 port 43506 codec: 8 ms: 20
2019-05-22 19:11:56.250767 [DEBUG] switch_rtp.c:4159 Not using a timer
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7180 sofia/gateway1/0449131272@202.10.26.1:5060 Set 2833 dtmf send payload to 101
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7187 sofia/gateway1/0449131272@202.10.26.1:5060 Set 2833 dtmf receive payload to 101
2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7210 sofia/gateway1/0449131272@202.10.26.1:5060 Set rtp dtmf delay to 40
2019-05-22 19:11:56.250767 [DEBUG] mod_sofia.c:2364 Ring SDP:
v=0
o=FreeSWITCH 1558493178 1558493179 IN IP4 10.239.237.34
s=FreeSWITCH
c=IN IP4 10.239.237.34
t=0 0
m=audio 23138 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2019-05-22 19:11:56.250767 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/gateway1/0449131272@202.10.26.1:5060!
2019-05-22 19:11:56.250767 [DEBUG] switch_channel.c:3474 (sofia/gateway1/0449131272@202.10.26.1:5060) Callstate Change RINGING -> EARLY
2019-05-22 19:11:56.250767 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/default/0283965200@58.96.28.252:5060]
2019-05-22 19:11:56.250767 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [early][183]
2019-05-22 19:11:56.250767 [DEBUG] switch_ivr_bridge.c:1614 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2019-05-22 19:11:56.250767 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 6 Tot 338355)
2019-05-22 19:11:56.250767 [DEBUG] switch_core_state_machine.c:653 (sofia/default/0283965200@58.96.28.252:5060) State EXCHANGE_MEDIA
2019-05-22 19:11:56.250767 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
2019-05-22 19:11:56.330746 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-05-22 19:11:56.350747 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: audio ssrc[4170685508] base_seq[45584]
2019-05-22 19:11:56.510748 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [proceeding][180]
2019-05-22 19:11:56.510748 [NOTICE] sofia.c:7192 Ring-Ready sofia/default/0283965200@58.96.28.252:5060!
2019-05-22 19:11:56.510748 [DEBUG] switch_channel.c:3346 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change EARLY -> RINGING
2019-05-22 19:11:56.610748 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-05-22 19:11:56.750750 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [completing][200]
2019-05-22 19:11:56.750750 [DEBUG] sofia.c:7091 Duplicate SDP
v=0
o=SBC 1399 1001 IN IP4 58.96.28.252
s=VoipCall
c=IN IP4 58.96.28.252
t=0 0
m=audio 16676 RTP/AVP 8 101
c=IN IP4 58.96.28.252
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=maxptime:40
a=rtcp:16677

2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0499080933 entering state [completing][200]
2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7091 Duplicate SDP
v=0
o=- 90353734859613 90353734859613 IN IP4 202.10.26.1
s=-
c=IN IP4 202.10.26.1
t=0 0
m=audio 43396 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0499080933 entering state [ready][200]
2019-05-22 19:11:56.770755 [NOTICE] sofia.c:8159 Channel [sofia/gateway1/0499080933] has been answered
2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [ready][200]
2019-05-22 19:11:56.770755 [DEBUG] switch_channel.c:3773 (sofia/gateway1/0499080933) Callstate Change EARLY -> ACTIVE
2019-05-22 19:11:56.770755 [NOTICE] sofia.c:8159 Channel [sofia/default/0283965200@58.96.28.252:5060] has been answered
2019-05-22 19:11:56.770755 [DEBUG] switch_channel.c:3773 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change RINGING -> ACTIVE
2019-05-22 19:11:56.790752 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/0731589144@192.168.2.210.
2019-05-22 19:11:56.790752 [DEBUG] mod_sofia.c:850 Local SDP sofia/default/0731589144@192.168.2.210:
v=0
o=FreeSWITCH 1558493939 1558493941 IN IP4 192.168.2.210
s=FreeSWITCH
c=IN IP4 192.168.2.210
t=0 0
m=audio 22368 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2019-05-22 19:11:56.790752 [NOTICE] switch_ivr_bridge.c:623 Channel [sofia/default/0731589144@192.168.2.210] has been answered
2019-05-22 19:11:56.790752 [DEBUG] switch_channel.c:3773 (sofia/default/0731589144@192.168.2.210) Callstate Change EARLY -> ACTIVE
2019-05-22 19:11:56.790752 [DEBUG] sofia.c:7084 Channel sofia/default/0731589144@192.168.2.210 entering state [completed][200]
2019-05-22 19:11:56.790752 [DEBUG] sofia.c:7084 Channel sofia/default/0731589144@192.168.2.210 entering state [ready][200]
2019-05-22 19:11:56.790752 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/gateway1/0449131272@202.10.26.1:5060.
2019-05-22 19:11:56.790752 [DEBUG] mod_sofia.c:850 Local SDP sofia/gateway1/0449131272@202.10.26.1:5060:
v=0
o=FreeSWITCH 1558493178 1558493180 IN IP4 10.239.237.34
s=FreeSWITCH
c=IN IP4 10.239.237.34
t=0 0
m=audio 23138 RTP/AVP 8 101
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2019-05-22 19:11:56.790752 [NOTICE] switch_ivr_bridge.c:623 Channel [sofia/gateway1/0449131272@202.10.26.1:5060] has been answered
2019-05-22 19:11:56.790752 [DEBUG] switch_channel.c:3773 (sofia/gateway1/0449131272@202.10.26.1:5060) Callstate Change EARLY -> ACTIVE
2019-05-22 19:11:56.790752 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [completed][200]
2019-05-22 19:11:56.830758 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [ready][200]
2019-05-22 19:11:56.830758 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-05-22 19:11:56.870749 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-05-22 19:11:56.870749 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-05-22 19:12:01.150735 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
2019-05-22 19:12:11.350750 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [received][100]
2019-05-22 19:12:11.350750 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=SBC 1399 1002 IN IP4 58.96.28.252
s=VoipCall
c=IN IP4 58.96.28.252
t=0 0
m=audio 16676 RTP/AVP 8 101 13
c=IN IP4 58.96.28.252
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=rtpmap:13 CN/8000
a=inactive
a=ptime:20
a=maxptime:40
a=rtcp:16677

2019-05-22 19:12:11.350750 [DEBUG] switch_channel.c:1844 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change ACTIVE -> HELD
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4373 Set comfort noise payload to 13
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4720 Set comfort noise payload to 13@8000
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4767 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/0283965200@58.96.28.252:5060.
2019-05-22 19:12:11.610733 [DEBUG] sofia.c:7999 Processing updated SDP
2019-05-22 19:12:11.630749 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [completed][200]
2019-05-22 19:12:11.630749 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [ready][200]
2019-05-22 19:12:11.650741 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [received][100]
2019-05-22 19:12:11.650741 [DEBUG] sofia.c:7094 Remote SDP:
v=0
o=SBC 1399 1003 IN IP4 58.96.28.252
s=VoipCall
c=IN IP4 58.96.28.252
t=0 0
m=audio 16676 RTP/AVP 8 101
c=IN IP4 58.96.28.252
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=maxptime:40
a=rtcp:16677

2019-05-22 19:12:11.910744 [DEBUG] switch_channel.c:2029 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change HELD -> UNHELD
2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4767 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101 recv payload to 101
2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/0283965200@58.96.28.252:5060.
2019-05-22 19:12:11.910744 [DEBUG] sofia.c:7999 Processing updated SDP
2019-05-22 19:12:11.910744 [DEBUG] switch_core_io.c:941 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change UNHELD -> ACTIVE
2019-05-22 19:12:11.910744 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [completed][200]
2019-05-22 19:12:11.910744 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [ready][200]
2019-05-22 19:12:13.090745 [DEBUG] switch_ivr.c:623 sofia/gateway1/0449131272@202.10.26.1:5060 Command Execute playback(local_stream://moh)
EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 playback(local_stream://moh)
2019-05-22 19:12:13.090745 [DEBUG] mod_local_stream.c:871 Opening Stream [moh/8000] 8000hz
2019-05-22 19:12:13.090745 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2019-05-22 19:12:35.590742 [NOTICE] sofia.c:1012 Hangup sofia/default/0283965200@58.96.28.252:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
2019-05-22 19:12:35.590742 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/0283965200@58.96.28.252:5060]
2019-05-22 19:12:35.590742 [DEBUG] switch_core_state_machine.c:653 (sofia/default/0283965200@58.96.28.252:5060) State EXCHANGE_MEDIA going to sleep
2019-05-22 19:12:35.590742 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_HANGUP (Cur 6 Tot 338355)
2019-05-22 19:12:35.590742 [DEBUG] switch_core_state_machine.c:850 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change ACTIVE -> HANGUP
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0283965200@58.96.28.252:5060) State HANGUP
2019-05-22 19:12:35.610746 [DEBUG] mod_sofia.c:438 Channel sofia/default/0283965200@58.96.28.252:5060 hanging up, cause: NORMAL_CLEARING
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:60 sofia/default/0283965200@58.96.28.252:5060 Standard HANGUP, cause: NORMAL_CLEARING
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0283965200@58.96.28.252:5060) State HANGUP going to sleep
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:619 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_HANGUP -> CS_REPORTING
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_REPORTING (Cur 6 Tot 338355)
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0283965200@58.96.28.252:5060) State REPORTING
2019-05-22 19:12:35.610746 [INFO] mod_json_cdr.c:271 Process [a6f3d052-7c71-11e9-a818-33f71d9eef79.cdr.json]
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:174 sofia/default/0283965200@58.96.28.252:5060 Standard REPORTING, cause: NORMAL_CLEARING
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0283965200@58.96.28.252:5060) State REPORTING going to sleep
2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:610 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_REPORTING -> CS_DESTROY
2019-05-22 19:12:35.610746 [DEBUG] switch_core_session.c:1665 Session 338355 (sofia/default/0283965200@58.96.28.252:5060) Locked, Waiting on external entities