Type /help to see a list of commands [This app Best viewed at 160x60 or more..] +OK log level [7] 2019-07-04 16:04:55.647066 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'default' for [4779206277@pbx3.inexlocal.com] from ip 192.168.1.13 2019-07-04 16:05:05.007055 [NOTICE] switch_channel.c:1104 New Channel sofia/default/8889687188@pbx3.inexlocal.com [62dee30a-9e47-11e9-94fc-2d0e45e4becc] 2019-07-04 16:05:05.007055 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_NEW (Cur 1 Tot 303) 2019-07-04 16:05:05.007055 [DEBUG] sofia.c:9873 sofia/default/8889687188@pbx3.inexlocal.com receiving invite from 192.168.1.151:5062 version: 1.6.20 64bit 2019-07-04 16:05:05.007055 [DEBUG] sofia.c:10044 IP 192.168.1.151 Rejected by acl "default". Falling back to Digest auth. 2019-07-04 16:05:05.007055 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [919724268060@pbx3.inexlocal.com] from ip 192.168.1.151 2019-07-04 16:05:05.007055 [DEBUG] switch_core_state_machine.c:603 (sofia/default/8889687188@pbx3.inexlocal.com) State NEW 2019-07-04 16:05:05.007055 [DEBUG] sofia.c:2334 detaching session 62dee30a-9e47-11e9-94fc-2d0e45e4becc 2019-07-04 16:05:05.067062 [DEBUG] sofia.c:2442 Re-attaching to session 62dee30a-9e47-11e9-94fc-2d0e45e4becc 2019-07-04 16:05:05.067062 [DEBUG] sofia.c:9873 sofia/default/8889687188@pbx3.inexlocal.com receiving invite from 192.168.1.151:5062 version: 1.6.20 64bit 2019-07-04 16:05:05.067062 [DEBUG] sofia.c:10044 IP 192.168.1.151 Rejected by acl "default". Falling back to Digest auth. 2019-07-04 16:05:05.087284 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [received][100] 2019-07-04 16:05:05.087284 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=8889687188 8001 8000 IN IP4 192.168.1.151 s=SIP Call c=IN IP4 192.168.1.151 t=0 0 m=audio 5036 RTP/AVP 0 8 4 18 9 97 2 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:9 G722/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:2 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/8889687188@pbx3.inexlocal.com PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2019-07-04 16:05:05.087284 [DEBUG] switch_core_codec.c:111 sofia/default/8889687188@pbx3.inexlocal.com Original read codec set to PCMU:0 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2019-07-04 16:05:05.087284 [DEBUG] switch_core_media.c:4767 sofia/default/8889687188@pbx3.inexlocal.com Set 2833 dtmf send payload to 101 recv payload to 101 2019-07-04 16:05:05.087284 [DEBUG] sofia.c:7507 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_NEW -> CS_INIT 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_INIT (Cur 1 Tot 303) 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:627 (sofia/default/8889687188@pbx3.inexlocal.com) State INIT 2019-07-04 16:05:05.087284 [DEBUG] mod_sofia.c:90 sofia/default/8889687188@pbx3.inexlocal.com SOFIA INIT 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:40 sofia/default/8889687188@pbx3.inexlocal.com Standard INIT 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:48 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_INIT -> CS_ROUTING 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:627 (sofia/default/8889687188@pbx3.inexlocal.com) State INIT going to sleep 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_ROUTING (Cur 1 Tot 303) 2019-07-04 16:05:05.087284 [DEBUG] switch_channel.c:2249 (sofia/default/8889687188@pbx3.inexlocal.com) Callstate Change DOWN -> RINGING 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:643 (sofia/default/8889687188@pbx3.inexlocal.com) State ROUTING 2019-07-04 16:05:05.087284 [DEBUG] mod_sofia.c:143 sofia/default/8889687188@pbx3.inexlocal.com SOFIA ROUTING 2019-07-04 16:05:05.087284 [DEBUG] switch_core_state_machine.c:236 sofia/default/8889687188@pbx3.inexlocal.com Standard ROUTING 2019-07-04 16:05:05.087284 [INFO] mod_dialplan_xml.c:637 Processing 8889687188 <8889687188>->919724268060 in context default 2019-07-04 16:05:05.087284 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f6b8805e880 Connected. 2019-07-04 16:05:05.087284 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM `system` WHERE group_title IN ('global','opensips','callingcard','calls','InternationalPrefixes') 2019-07-04 16:05:05.087284 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_ADDON_CONF] Query :SELECT package_name FROM addons 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] blind_flag: 0 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 919724268060 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_code = '919724268060' limit 1 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT access_number FROM accessnumber WHERE access_number = '919724268060' AND status=0 limit 1 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Functions] [GET_queue_INFO] Query :SELECT id,destination_number,agent_hold_file from pbx_queue WHERE destination_number = '919724268060' and status=0 LIMIT 1 2019-07-04 16:05:05.127070 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FAXER] in custom Caller ID 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number : 8889687188 / 8889687188 2019-07-04 16:05:05.127070 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,A.number as did_number,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,A.leg_timeout,A.status,A.country_id,A.call_type_vm_flag FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="919724268060" LIMIT 1 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : inbound 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 8889687188] 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE number = "8889687188" AND deleted = 0 limit 1 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_SPEEDDIAL] Query :SELECT A.number FROM speed_dial as A,accounts as B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.speed_num ="919724268060" AND A.accountid = '415' limit 1 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] SPEED DIAL NUMBER : 919724268060 2019-07-04 16:05:05.127070 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,A.number as did_number,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,A.leg_timeout,A.status,A.country_id,A.call_type_vm_flag FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="919724268060" LIMIT 1 2019-07-04 16:05:05.127070 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] New Call direction : inbound 2019-07-04 16:05:05.127070 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:05.127070 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [IS_CHECK_DID] Query :SELECT * FROM dids WHERE number ="919724268060" AND (accountid = 0 OR status = 1) LIMIT 1 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] call_direction :inbound 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] DID_ACCOUNTID :415 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT *,P.id as package_id FROM packages_view as P inner join package_patterns as PKGPTR on P.product_id = PKGPTR.product_id WHERE (patterns = '^919724268060.*' OR patterns = '^91972426806.*' OR patterns = '^9197242680.*' OR patterns = '^919724268.*' OR patterns = '^91972426.*' OR patterns = '^9197242.*' OR patterns = '^919724.*' OR patterns = '^91972.*' OR patterns = '^9197.*' OR patterns = '^919.*' OR patterns = '^91.*' OR patterns = '^9.*' OR patterns ='--') AND accountid = 415 ORDER BY LENGTH(PKGPTR.patterns) DESC 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_CALL_BARRING] Query :SELECT number,RIGHT(number,1) as lastchar,type as status_type,number_type FROM call_barring WHERE ((number = '919724268060' OR number = '91972426806' OR number = '9197242680' OR number = '919724268' OR number = '91972426' OR number = '9197242' OR number = '919724' OR number = '91972' OR number = '9197' OR number = '919' OR number = '91' OR number = '9' OR number ='--') OR (number = '919724268060*' OR number = '91972426806*' OR number = '9197242680*' OR number = '919724268*' OR number = '91972426*' OR number = '9197242*' OR number = '919724*' OR number = '91972*' OR number = '9197*' OR number = '919*' OR number = '91*' OR number = '9*' OR number ='--') OR (number = '8889687188' OR number = '888968718' OR number = '88896871' OR number = '8889687' OR number = '888968' OR number = '88896' OR number = '8889' OR number = '888' OR number = '88' OR number = '8' OR number ='--') OR (number = '8889687188*' OR number = '888968718*' OR number = '88896871*' OR number = '8889687*' OR number = '888968*' OR number = '88896*' OR number = '8889*' OR number = '888*' OR number = '88*' OR number = '8*' OR number ='--')) AND status=0 order by LENGTH(number) DESC,lastchar DESC, modified_date DESC 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] Call Barring Status : -1 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_ROUTING_INFO] Query :select id,routing_prefix,pricelist_id_admin from pricelists WHERE (routing_prefix = '919724268060' OR routing_prefix = '91972426806' OR routing_prefix = '9197242680' OR routing_prefix = '919724268' OR routing_prefix = '91972426' OR routing_prefix = '9197242' OR routing_prefix = '919724' OR routing_prefix = '91972' OR routing_prefix = '9197' OR routing_prefix = '919' OR routing_prefix = '91' OR routing_prefix = '9' OR routing_prefix ='--') AND status = 0 and reseller_id = 0 limit 1 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information =================== 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 415 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 8889687188 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Balance : 4839.9 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 1 [0:prepaid,1:postpaid] 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 4 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] CID Pool : 0 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] ======================================================== 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 4 AND status = 0 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] call_direction :inbound 2019-07-04 16:05:05.147031 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,A.number as did_number,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,A.leg_timeout,A.status,A.country_id,A.call_type_vm_flag FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="919724268060" LIMIT 1 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] call_direction:::::: inbound 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information =================== 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 13095 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 1.50000 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : test Gandhinagar 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Country Id : 88 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 415 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================ 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Your4839.9 balance Accountid 415 !!! 2019-07-04 16:05:05.147031 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Limiting call to config max length 100 mins! 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 100 minutes 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] INB_FREE:TRUE 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] free_inbound:0 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_OVERRIDE_CALLERID] Query :SELECT callerid_name as cid_name,callerid_number as cid_number,accountid FROM accounts_callerid WHERE accountid = 415 AND status=0 LIMIT 1 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE id = "415" AND deleted = 0 limit 1 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 4 AND status = 0 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] call_direction :outbound 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern = '^919724268060.*' OR pattern = '^91972426806.*' OR pattern = '^9197242680.*' OR pattern = '^919724268.*' OR pattern = '^91972426.*' OR pattern = '^9197242.*' OR pattern = '^919724.*' OR pattern = '^91972.*' OR pattern = '^9197.*' OR pattern = '^919.*' OR pattern = '^91.*' OR pattern = '^9.*' OR pattern ='--') AND status = 0 AND (pricelist_id = 4 OR accountid=415) ORDER BY accountid DESC,LENGTH(pattern) DESC,cost DESC LIMIT 1 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] call_direction:::::: outbound 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information =================== 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 11 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.60000 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : Ahmedabad-Urban 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Country Id : 88 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 415 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Trunk ID: 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] Routing type: 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================ 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Your4839.9 balance Accountid 415 !!! 2019-07-04 16:05:05.147031 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Limiting call to config max length 100 mins! 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML:415 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Userinfo XML:415 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML : 415 2019-07-04 16:05:05.147031 [INFO] switch_cpp.cpp:1365 [ASTPP] maxlength::::::::: 100 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] custom_function_name:::::::::::::::::::::::::custom_inbound_0 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts ,domains WHERE accounts.id=domains.accountid AND accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="4779206277" AND domains.domain="pbx3.inexlocal.com" limit 1 2019-07-04 16:05:05.147031 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] [GET_ROUTING_INFO] Query :SELECT * from sip_device_routing WHERE sip_device_id = 460 limit 1 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer_attended' limit 1 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer' limit 1 2019-07-04 16:05:05.167246 [WARNING] switch_cpp.cpp:1365 [ASTPP] [user_domain] user_domain beforepbx3.inexlocal.com 2019-07-04 16:05:05.167246 [WARNING] switch_cpp.cpp:1365 [ASTPP] [user_domain] pickup_group_permission pickup_str 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [NOTIFY] START: 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [NOTIFY] Query :SELECT callkit_token,mobile_type FROM dialer_device_info WHERE username='4779206277' 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts ,domains WHERE accounts.id=domains.accountid AND accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="4779206277" AND domains.domain="pbx3.inexlocal.com" limit 1 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] [GET_ROUTING_INFO] Query :SELECT * from sip_device_routing WHERE sip_device_id = 460 limit 1 2019-07-04 16:05:05.167246 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Generated XML:
2019-07-04 16:05:05.167246 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f6b8805e880 released. Dialplan: sofia/default/8889687188@pbx3.inexlocal.com parsing [default->919724268060] continue=false Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Regex (PASS) [919724268060] destination_number(919724268060) =~ /919724268060/ break=on-false Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(effective_destination_number=919724268060) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(bridge_pre_execute_bleg_app=sched_hangup) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(bridge_pre_execute_bleg_data=+6000 normal_clearing) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(callstart=2019-07-04 10:35:05) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(hangup_after_bridge=true) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(continue_on_fail=TRUE) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(account_id=415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(parent_id=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(entity_id=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(call_processed=internal) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(call_direction=inbound) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(accountname=default) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(filename1=astpp.pbx.lua) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(origination_rates_did=ID:13095|CODE:^919724268060.*|DESTINATION:test Gandhinagar|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:0|COST:1.50000|INC:1|INITIALBLOCK:1|RATEGROUP:0|MARKUP:0|CI:88|ACCID:415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(origination_rates=ID:11|CODE:^91.*|DESTINATION:Ahmedabad-Urban|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:1|COST:0.60000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|CI:88|ACCID:415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(original_caller_id_name=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(original_caller_id_number=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(effective_caller_id_name=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(effective_caller_id_number=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(receiver_accid=415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(presence_data=x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(call_type=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(calltype=DID-LOCAL) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action db(insert/pickup_any_group_${callgroup}/4779206277/${uuid}) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(dialed_extension=transfer_call) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(dialed_extension=transfer_call) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action bind_meta_app(95 b s execute_extension::transfer_call_95 XML default) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action bind_meta_app(94 b s execute_extension::transfer_call_94 XML default) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(hangup_after_bridge=true) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(did_user_domain=pbx3.inexlocal.com) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action ring_ready() Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action sleep(5000) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action bridge({sip_invite_params=user=LOCAL,sip_from_uri=4779206277@${domain_name}}[leg_timeout=30]user/4779206277@${domain_name}) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(on_busy_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(on_busy_destination=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(no_answer_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(no_answer_destination=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(not_register_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(not_register_destination=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(opensips_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(variable_sip_to_host=pbx3.inexlocal.com) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(opensips_domain=127.0.0.1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(leg_timeout=60) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(userinfo_id=415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(sip_destination_number=4779206277) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(destination_number=919724268060) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(did_number=919724268060) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action lua(astpp/lib/pbx/astpp-sipdevice-routing.lua) |--- Dialplan: Processing recursive conditions level:1 [919724268060_recur_1] require-nested=TRUE |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Regex (PASS) [919724268060_recur_1] ${cond(${user_data 4779206277@${domain_name} param vm-enabled} == true ? YES : NO)}(YES) =~ /^YES$/ break=on-false |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action answer() |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(voicemail_alternate_greet_id=919724268060) |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action voicemail(default $${domain_name} 4779206277) 2019-07-04 16:05:05.187074 [DEBUG] switch_core_state_machine.c:286 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_ROUTING -> CS_EXECUTE 2019-07-04 16:05:05.187074 [DEBUG] switch_core_state_machine.c:643 (sofia/default/8889687188@pbx3.inexlocal.com) State ROUTING going to sleep 2019-07-04 16:05:05.187074 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_EXECUTE (Cur 1 Tot 303) 2019-07-04 16:05:05.187074 [DEBUG] switch_core_state_machine.c:650 (sofia/default/8889687188@pbx3.inexlocal.com) State EXECUTE 2019-07-04 16:05:05.187074 [DEBUG] mod_sofia.c:198 sofia/default/8889687188@pbx3.inexlocal.com SOFIA EXECUTE 2019-07-04 16:05:05.187074 [DEBUG] switch_core_state_machine.c:328 sofia/default/8889687188@pbx3.inexlocal.com Standard EXECUTE EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(effective_destination_number=919724268060) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [effective_destination_number]=[919724268060] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(bridge_pre_execute_bleg_app=sched_hangup) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [bridge_pre_execute_bleg_app]=[sched_hangup] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(bridge_pre_execute_bleg_data=+6000 normal_clearing) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [bridge_pre_execute_bleg_data]=[+6000 normal_clearing] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(callstart=2019-07-04 10:35:05) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [callstart]=[2019-07-04 10:35:05] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(hangup_after_bridge=true) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [hangup_after_bridge]=[true] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(continue_on_fail=TRUE) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [continue_on_fail]=[TRUE] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(account_id=415) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [account_id]=[415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(parent_id=0) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [parent_id]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(entity_id=0) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [entity_id]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(call_processed=internal) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [call_processed]=[internal] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(call_direction=inbound) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [call_direction]=[inbound] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(accountname=default) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [accountname]=[default] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(filename1=astpp.pbx.lua) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [filename1]=[astpp.pbx.lua] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(origination_rates_did=ID:13095|CODE:^919724268060.*|DESTINATION:test Gandhinagar|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:0|COST:1.50000|INC:1|INITIALBLOCK:1|RATEGROUP:0|MARKUP:0|CI:88|ACCID:415) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [origination_rates_did]=[ID:13095|CODE:^919724268060.*|DESTINATION:test Gandhinagar|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:0|COST:1.50000|INC:1|INITIALBLOCK:1|RATEGROUP:0|MARKUP:0|CI:88|ACCID:415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(origination_rates=ID:11|CODE:^91.*|DESTINATION:Ahmedabad-Urban|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:1|COST:0.60000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|CI:88|ACCID:415) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [origination_rates]=[ID:11|CODE:^91.*|DESTINATION:Ahmedabad-Urban|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:1|COST:0.60000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|CI:88|ACCID:415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(original_caller_id_name=8889687188) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [original_caller_id_name]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(original_caller_id_number=8889687188) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [original_caller_id_number]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(effective_caller_id_name=8889687188) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [effective_caller_id_name]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(effective_caller_id_number=8889687188) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [effective_caller_id_number]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(receiver_accid=415) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [receiver_accid]=[415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(presence_data=x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID) 2019-07-04 16:05:05.187074 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [presence_data]=[x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(call_type=0) 2019-07-04 16:05:05.187074 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_type]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(calltype=DID-LOCAL) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [calltype]=[DID-LOCAL] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com db(insert/pickup_any_group_/4779206277/62dee30a-9e47-11e9-94fc-2d0e45e4becc) EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(dialed_extension=transfer_call) 2019-07-04 16:05:05.187074 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [dialed_extension]=[transfer_call] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(dialed_extension=transfer_call) 2019-07-04 16:05:05.207036 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[transfer_call] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com bind_meta_app(95 b s execute_extension::transfer_call_95 XML default) 2019-07-04 16:05:05.207036 [ERR] switch_ivr_async.c:4146 Invalid key 95 2019-07-04 16:05:05.207036 [ERR] mod_dptools.c:786 Bind Error! EXECUTE sofia/default/8889687188@pbx3.inexlocal.com bind_meta_app(94 b s execute_extension::transfer_call_94 XML default) 2019-07-04 16:05:05.207036 [ERR] switch_ivr_async.c:4146 Invalid key 94 2019-07-04 16:05:05.207036 [ERR] mod_dptools.c:786 Bind Error! EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(hangup_after_bridge=true) 2019-07-04 16:05:05.207036 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [hangup_after_bridge]=[true] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(did_user_domain=pbx3.inexlocal.com) 2019-07-04 16:05:05.207036 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [did_user_domain]=[pbx3.inexlocal.com] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com ring_ready() 2019-07-04 16:05:05.207036 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/default/8889687188@pbx3.inexlocal.com! 2019-07-04 16:05:05.207036 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [early][180] 2019-07-04 16:05:05.207036 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/default/8889687188@pbx3.inexlocal.com! EXECUTE sofia/default/8889687188@pbx3.inexlocal.com sleep(5000) EXECUTE sofia/default/8889687188@pbx3.inexlocal.com bridge({sip_invite_params=user=LOCAL,sip_from_uri=4779206277@pbx3.inexlocal.com}[leg_timeout=30]user/4779206277@pbx3.inexlocal.com) 2019-07-04 16:05:10.347021 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [presence_data]=[x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID] to event 2019-07-04 16:05:10.347021 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [call_type]=[0] to event 2019-07-04 16:05:10.347021 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [dialed_extension]=[transfer_call] to event 2019-07-04 16:05:10.347021 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [did_user_domain]=[pbx3.inexlocal.com] to event 2019-07-04 16:05:10.347021 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-07-04 16:05:10.347021 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2019-07-04 16:05:10.627063 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [presence_data]=[x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID] to event 2019-07-04 16:05:10.627063 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [call_type]=[0] to event 2019-07-04 16:05:10.627063 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [dialed_extension]=[transfer_call] to event 2019-07-04 16:05:10.627063 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [did_user_domain]=[pbx3.inexlocal.com] to event 2019-07-04 16:05:10.627063 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-07-04 16:05:10.627063 [NOTICE] switch_channel.c:1104 New Channel sofia/default/4779206277@192.168.1.13:52632 [6638483e-9e47-11e9-9529-2d0e45e4becc] 2019-07-04 16:05:10.627063 [DEBUG] mod_sofia.c:4819 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_NEW -> CS_INIT 2019-07-04 16:05:10.627063 [DEBUG] switch_ivr_originate.c:2963 sofia/default/4779206277@192.168.1.13:52632 Setting leg timeout to 30 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_INIT (Cur 2 Tot 304) 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:627 (sofia/default/4779206277@192.168.1.13:52632) State INIT 2019-07-04 16:05:10.627063 [DEBUG] mod_sofia.c:90 sofia/default/4779206277@192.168.1.13:52632 SOFIA INIT 2019-07-04 16:05:10.627063 [DEBUG] sofia_glue.c:1295 sofia/default/4779206277@192.168.1.13:52632 sending invite version: 1.6.20 64bit Local SDP: v=0 o=FreeSWITCH 1562210176 1562210177 IN IP4 192.168.1.118 s=FreeSWITCH c=IN IP4 192.168.1.118 t=0 0 m=audio 26334 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 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:40 sofia/default/4779206277@192.168.1.13:52632 Standard INIT 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:48 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_INIT -> CS_ROUTING 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:627 (sofia/default/4779206277@192.168.1.13:52632) State INIT going to sleep 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_ROUTING (Cur 2 Tot 304) 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:643 (sofia/default/4779206277@192.168.1.13:52632) State ROUTING 2019-07-04 16:05:10.627063 [DEBUG] mod_sofia.c:143 sofia/default/4779206277@192.168.1.13:52632 SOFIA ROUTING 2019-07-04 16:05:10.627063 [DEBUG] switch_ivr_originate.c:67 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:643 (sofia/default/4779206277@192.168.1.13:52632) State ROUTING going to sleep 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 304) 2019-07-04 16:05:10.627063 [DEBUG] sofia.c:7084 Channel sofia/default/4779206277@192.168.1.13:52632 entering state [calling][0] 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:662 (sofia/default/4779206277@192.168.1.13:52632) State CONSUME_MEDIA 2019-07-04 16:05:10.627063 [DEBUG] switch_core_state_machine.c:662 (sofia/default/4779206277@192.168.1.13:52632) State CONSUME_MEDIA going to sleep 2019-07-04 16:05:10.727027 [DEBUG] sofia.c:7084 Channel sofia/default/4779206277@192.168.1.13:52632 entering state [proceeding][180] 2019-07-04 16:05:10.727027 [NOTICE] sofia.c:7192 Ring-Ready sofia/default/4779206277@192.168.1.13:52632! 2019-07-04 16:05:10.727027 [DEBUG] switch_channel.c:3346 (sofia/default/4779206277@192.168.1.13:52632) Callstate Change DOWN -> RINGING 2019-07-04 16:05:10.747027 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/default/8889687188@pbx3.inexlocal.com! 2019-07-04 16:05:14.467024 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [terminated][487] 2019-07-04 16:05:14.467024 [NOTICE] sofia.c:8273 Hangup sofia/default/8889687188@pbx3.inexlocal.com [CS_EXECUTE] [ORIGINATOR_CANCEL] 2019-07-04 16:05:14.487037 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/default/4779206277@192.168.1.13:52632 [CS_CONSUME_MEDIA] [ORIGINATOR_CANCEL] 2019-07-04 16:05:14.487037 [DEBUG] switch_ivr_originate.c:3837 Originate Cancelled by originator termination Cause: 487 [ORIGINATOR_CANCEL] 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_HANGUP (Cur 2 Tot 304) 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:850 (sofia/default/4779206277@192.168.1.13:52632) Callstate Change RINGING -> HANGUP 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:852 (sofia/default/4779206277@192.168.1.13:52632) State HANGUP 2019-07-04 16:05:14.487037 [DEBUG] mod_sofia.c:432 sofia/default/4779206277@192.168.1.13:52632 Overriding SIP cause 487 with 487 from the other leg 2019-07-04 16:05:14.487037 [DEBUG] mod_sofia.c:438 Channel sofia/default/4779206277@192.168.1.13:52632 hanging up, cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.487037 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [ORIGINATOR_CANCEL] 2019-07-04 16:05:14.487037 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 487 [ORIGINATOR_CANCEL] 2019-07-04 16:05:14.487037 [INFO] mod_dptools.c:3436 Originate Failed. Cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.487037 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/default/4779206277@192.168.1.13:52632 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:60 sofia/default/4779206277@192.168.1.13:52632 Standard HANGUP, cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:852 (sofia/default/4779206277@192.168.1.13:52632) State HANGUP going to sleep 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:619 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_HANGUP -> CS_REPORTING 2019-07-04 16:05:14.487037 [DEBUG] switch_core_session.c:2815 sofia/default/8889687188@pbx3.inexlocal.com skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:650 (sofia/default/8889687188@pbx3.inexlocal.com) State EXECUTE going to sleep 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_HANGUP (Cur 2 Tot 304) 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_REPORTING (Cur 2 Tot 304) 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:850 (sofia/default/8889687188@pbx3.inexlocal.com) Callstate Change RINGING -> HANGUP 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:938 (sofia/default/4779206277@192.168.1.13:52632) State REPORTING 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:852 (sofia/default/8889687188@pbx3.inexlocal.com) State HANGUP 2019-07-04 16:05:14.487037 [DEBUG] mod_sofia.c:438 Channel sofia/default/8889687188@pbx3.inexlocal.com hanging up, cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.487037 [INFO] mod_json_cdr.c:271 Process [6638483e-9e47-11e9-9529-2d0e45e4becc.cdr.json] 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:60 sofia/default/8889687188@pbx3.inexlocal.com Standard HANGUP, cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:852 (sofia/default/8889687188@pbx3.inexlocal.com) State HANGUP going to sleep 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:619 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_HANGUP -> CS_REPORTING 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_REPORTING (Cur 2 Tot 304) 2019-07-04 16:05:14.487037 [DEBUG] switch_core_state_machine.c:938 (sofia/default/8889687188@pbx3.inexlocal.com) State REPORTING 2019-07-04 16:05:14.487037 [INFO] mod_json_cdr.c:271 Process [62dee30a-9e47-11e9-94fc-2d0e45e4becc.cdr.json] 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:174 sofia/default/4779206277@192.168.1.13:52632 Standard REPORTING, cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:938 (sofia/default/4779206277@192.168.1.13:52632) State REPORTING going to sleep 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:610 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_REPORTING -> CS_DESTROY 2019-07-04 16:05:14.506997 [DEBUG] switch_core_session.c:1665 Session 304 (sofia/default/4779206277@192.168.1.13:52632) Locked, Waiting on external entities 2019-07-04 16:05:14.506997 [NOTICE] switch_core_session.c:1683 Session 304 (sofia/default/4779206277@192.168.1.13:52632) Ended 2019-07-04 16:05:14.506997 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/4779206277@192.168.1.13:52632 [CS_DESTROY] 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:741 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_DESTROY (Cur 1 Tot 304) 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:751 (sofia/default/4779206277@192.168.1.13:52632) State DESTROY 2019-07-04 16:05:14.506997 [DEBUG] mod_sofia.c:343 sofia/default/4779206277@192.168.1.13:52632 SOFIA DESTROY 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:181 sofia/default/4779206277@192.168.1.13:52632 Standard DESTROY 2019-07-04 16:05:14.506997 [DEBUG] switch_core_state_machine.c:751 (sofia/default/4779206277@192.168.1.13:52632) State DESTROY going to sleep 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:174 sofia/default/8889687188@pbx3.inexlocal.com Standard REPORTING, cause: ORIGINATOR_CANCEL 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:938 (sofia/default/8889687188@pbx3.inexlocal.com) State REPORTING going to sleep 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:610 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_REPORTING -> CS_DESTROY 2019-07-04 16:05:14.726996 [DEBUG] switch_core_session.c:1665 Session 303 (sofia/default/8889687188@pbx3.inexlocal.com) Locked, Waiting on external entities 2019-07-04 16:05:14.726996 [NOTICE] switch_core_session.c:1683 Session 303 (sofia/default/8889687188@pbx3.inexlocal.com) Ended 2019-07-04 16:05:14.726996 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/8889687188@pbx3.inexlocal.com [CS_DESTROY] 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:741 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_DESTROY (Cur 0 Tot 304) 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:751 (sofia/default/8889687188@pbx3.inexlocal.com) State DESTROY 2019-07-04 16:05:14.726996 [DEBUG] mod_sofia.c:343 sofia/default/8889687188@pbx3.inexlocal.com SOFIA DESTROY 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:181 sofia/default/8889687188@pbx3.inexlocal.com Standard DESTROY 2019-07-04 16:05:14.726996 [DEBUG] switch_core_state_machine.c:751 (sofia/default/8889687188@pbx3.inexlocal.com) State DESTROY going to sleep 2019-07-04 16:05:21.387057 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'default' for [7100815208@pbx3.inexlocal.com] from ip 192.168.1.43 2019-07-04 16:05:33.927025 [WARNING] sofia_reg.c:2906 Can't find user [4727985745@192.168.1.118] from 192.168.1.165 You must define a domain called '192.168.1.118' in your directory and add a user with the id="4727985745" attribute and you must configure your device to use the proper domain in it's authentication credentials. 2019-07-04 16:05:33.927025 [WARNING] sofia_reg.c:1737 SIP auth failure (REGISTER) on sofia profile 'default' for [4727985745@192.168.1.118] from ip 192.168.1.165 2019-07-04 16:05:39.467047 [NOTICE] switch_channel.c:1104 New Channel sofia/default/8889687188@pbx3.inexlocal.com [7769e32e-9e47-11e9-9533-2d0e45e4becc] 2019-07-04 16:05:39.467047 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_NEW (Cur 1 Tot 305) 2019-07-04 16:05:39.467047 [DEBUG] sofia.c:9873 sofia/default/8889687188@pbx3.inexlocal.com receiving invite from 192.168.1.151:5062 version: 1.6.20 64bit 2019-07-04 16:05:39.467047 [DEBUG] sofia.c:10044 IP 192.168.1.151 Rejected by acl "default". Falling back to Digest auth. 2019-07-04 16:05:39.467047 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [919724268060@pbx3.inexlocal.com] from ip 192.168.1.151 2019-07-04 16:05:39.467047 [DEBUG] switch_core_state_machine.c:603 (sofia/default/8889687188@pbx3.inexlocal.com) State NEW 2019-07-04 16:05:39.467047 [DEBUG] sofia.c:2334 detaching session 7769e32e-9e47-11e9-9533-2d0e45e4becc 2019-07-04 16:05:39.527020 [DEBUG] sofia.c:2442 Re-attaching to session 7769e32e-9e47-11e9-9533-2d0e45e4becc 2019-07-04 16:05:39.527020 [DEBUG] sofia.c:9873 sofia/default/8889687188@pbx3.inexlocal.com receiving invite from 192.168.1.151:5062 version: 1.6.20 64bit 2019-07-04 16:05:39.527020 [DEBUG] sofia.c:10044 IP 192.168.1.151 Rejected by acl "default". Falling back to Digest auth. 2019-07-04 16:05:39.547044 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [received][100] 2019-07-04 16:05:39.547044 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=8889687188 8001 8000 IN IP4 192.168.1.151 s=SIP Call c=IN IP4 192.168.1.151 t=0 0 m=audio 5038 RTP/AVP 0 8 4 18 9 97 2 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:9 G722/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:2 G726-32/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G723:4:8000:20:6300:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [iLBC:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/8889687188@pbx3.inexlocal.com PCMU/8000 20 ms 160 samples 64000 bits 1 channels 2019-07-04 16:05:39.547044 [DEBUG] switch_core_codec.c:111 sofia/default/8889687188@pbx3.inexlocal.com Original read codec set to PCMU:0 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2019-07-04 16:05:39.547044 [DEBUG] switch_core_media.c:4767 sofia/default/8889687188@pbx3.inexlocal.com Set 2833 dtmf send payload to 101 recv payload to 101 2019-07-04 16:05:39.547044 [DEBUG] sofia.c:7507 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_NEW -> CS_INIT 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_INIT (Cur 1 Tot 305) 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:627 (sofia/default/8889687188@pbx3.inexlocal.com) State INIT 2019-07-04 16:05:39.547044 [DEBUG] mod_sofia.c:90 sofia/default/8889687188@pbx3.inexlocal.com SOFIA INIT 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:40 sofia/default/8889687188@pbx3.inexlocal.com Standard INIT 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:48 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_INIT -> CS_ROUTING 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:627 (sofia/default/8889687188@pbx3.inexlocal.com) State INIT going to sleep 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_ROUTING (Cur 1 Tot 305) 2019-07-04 16:05:39.547044 [DEBUG] switch_channel.c:2249 (sofia/default/8889687188@pbx3.inexlocal.com) Callstate Change DOWN -> RINGING 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:643 (sofia/default/8889687188@pbx3.inexlocal.com) State ROUTING 2019-07-04 16:05:39.547044 [DEBUG] mod_sofia.c:143 sofia/default/8889687188@pbx3.inexlocal.com SOFIA ROUTING 2019-07-04 16:05:39.547044 [DEBUG] switch_core_state_machine.c:236 sofia/default/8889687188@pbx3.inexlocal.com Standard ROUTING 2019-07-04 16:05:39.547044 [INFO] mod_dialplan_xml.c:637 Processing 8889687188 <8889687188>->919724268060 in context default 2019-07-04 16:05:39.547044 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f6b8805e880 Connected. 2019-07-04 16:05:39.547044 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM `system` WHERE group_title IN ('global','opensips','callingcard','calls','InternationalPrefixes') 2019-07-04 16:05:39.547044 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_ADDON_CONF] Query :SELECT package_name FROM addons 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] blind_flag: 0 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 919724268060 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_code = '919724268060' limit 1 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT access_number FROM accessnumber WHERE access_number = '919724268060' AND status=0 limit 1 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Functions] [GET_queue_INFO] Query :SELECT id,destination_number,agent_hold_file from pbx_queue WHERE destination_number = '919724268060' and status=0 LIMIT 1 2019-07-04 16:05:39.587050 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FAXER] in custom Caller ID 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number : 8889687188 / 8889687188 2019-07-04 16:05:39.587050 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,A.number as did_number,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,A.leg_timeout,A.status,A.country_id,A.call_type_vm_flag FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="919724268060" LIMIT 1 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : inbound 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 8889687188] 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE number = "8889687188" AND deleted = 0 limit 1 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_SPEEDDIAL] Query :SELECT A.number FROM speed_dial as A,accounts as B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.speed_num ="919724268060" AND A.accountid = '415' limit 1 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] SPEED DIAL NUMBER : 919724268060 2019-07-04 16:05:39.587050 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,A.number as did_number,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,A.leg_timeout,A.status,A.country_id,A.call_type_vm_flag FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="919724268060" LIMIT 1 2019-07-04 16:05:39.587050 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] New Call direction : inbound 2019-07-04 16:05:39.587050 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:39.587050 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [IS_CHECK_DID] Query :SELECT * FROM dids WHERE number ="919724268060" AND (accountid = 0 OR status = 1) LIMIT 1 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] call_direction :inbound 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] DID_ACCOUNTID :415 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT *,P.id as package_id FROM packages_view as P inner join package_patterns as PKGPTR on P.product_id = PKGPTR.product_id WHERE (patterns = '^919724268060.*' OR patterns = '^91972426806.*' OR patterns = '^9197242680.*' OR patterns = '^919724268.*' OR patterns = '^91972426.*' OR patterns = '^9197242.*' OR patterns = '^919724.*' OR patterns = '^91972.*' OR patterns = '^9197.*' OR patterns = '^919.*' OR patterns = '^91.*' OR patterns = '^9.*' OR patterns ='--') AND accountid = 415 ORDER BY LENGTH(PKGPTR.patterns) DESC 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_CALL_BARRING] Query :SELECT number,RIGHT(number,1) as lastchar,type as status_type,number_type FROM call_barring WHERE ((number = '919724268060' OR number = '91972426806' OR number = '9197242680' OR number = '919724268' OR number = '91972426' OR number = '9197242' OR number = '919724' OR number = '91972' OR number = '9197' OR number = '919' OR number = '91' OR number = '9' OR number ='--') OR (number = '919724268060*' OR number = '91972426806*' OR number = '9197242680*' OR number = '919724268*' OR number = '91972426*' OR number = '9197242*' OR number = '919724*' OR number = '91972*' OR number = '9197*' OR number = '919*' OR number = '91*' OR number = '9*' OR number ='--') OR (number = '8889687188' OR number = '888968718' OR number = '88896871' OR number = '8889687' OR number = '888968' OR number = '88896' OR number = '8889' OR number = '888' OR number = '88' OR number = '8' OR number ='--') OR (number = '8889687188*' OR number = '888968718*' OR number = '88896871*' OR number = '8889687*' OR number = '888968*' OR number = '88896*' OR number = '8889*' OR number = '888*' OR number = '88*' OR number = '8*' OR number ='--')) AND status=0 order by LENGTH(number) DESC,lastchar DESC, modified_date DESC 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] Call Barring Status : -1 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_ROUTING_INFO] Query :select id,routing_prefix,pricelist_id_admin from pricelists WHERE (routing_prefix = '919724268060' OR routing_prefix = '91972426806' OR routing_prefix = '9197242680' OR routing_prefix = '919724268' OR routing_prefix = '91972426' OR routing_prefix = '9197242' OR routing_prefix = '919724' OR routing_prefix = '91972' OR routing_prefix = '9197' OR routing_prefix = '919' OR routing_prefix = '91' OR routing_prefix = '9' OR routing_prefix ='--') AND status = 0 and reseller_id = 0 limit 1 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information =================== 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 415 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 8889687188 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Balance : 4839.9 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 1 [0:prepaid,1:postpaid] 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 4 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] CID Pool : 0 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] ======================================================== 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 4 AND status = 0 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] call_direction :inbound 2019-07-04 16:05:39.607189 [NOTICE] switch_cpp.cpp:1365 [ASTPP] HARSH2: 5 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_LOCALIZATION] Query :SELECT id,in_caller_id_originate,out_caller_id_originate,number_originate FROM localization WHERE id = 5 AND status=0 limit 1 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,A.number as did_number,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,A.leg_timeout,A.status,A.country_id,A.call_type_vm_flag FROM dids AS A,accounts AS B WHERE B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="919724268060" LIMIT 1 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] call_direction:::::: inbound 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information =================== 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 13095 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 1.50000 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : test Gandhinagar 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Country Id : 88 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 415 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================ 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Your4839.9 balance Accountid 415 !!! 2019-07-04 16:05:39.607189 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Limiting call to config max length 100 mins! 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 100 minutes 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] INB_FREE:TRUE 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] free_inbound:0 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_OVERRIDE_CALLERID] Query :SELECT callerid_name as cid_name,callerid_number as cid_number,accountid FROM accounts_callerid WHERE accountid = 415 AND status=0 LIMIT 1 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE id = "415" AND deleted = 0 limit 1 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 4 AND status = 0 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] call_direction :outbound 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern = '^919724268060.*' OR pattern = '^91972426806.*' OR pattern = '^9197242680.*' OR pattern = '^919724268.*' OR pattern = '^91972426.*' OR pattern = '^9197242.*' OR pattern = '^919724.*' OR pattern = '^91972.*' OR pattern = '^9197.*' OR pattern = '^919.*' OR pattern = '^91.*' OR pattern = '^9.*' OR pattern ='--') AND status = 0 AND (pricelist_id = 4 OR accountid=415) ORDER BY accountid DESC,LENGTH(pattern) DESC,cost DESC LIMIT 1 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] call_direction:::::: outbound 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information =================== 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 11 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.60000 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : Ahmedabad-Urban 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Country Id : 88 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 415 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Trunk ID: 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] Routing type: 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================ 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Your4839.9 balance Accountid 415 !!! 2019-07-04 16:05:39.607189 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Limiting call to config max length 100 mins! 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML:415 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Userinfo XML:415 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML : 415 2019-07-04 16:05:39.607189 [INFO] switch_cpp.cpp:1365 [ASTPP] maxlength::::::::: 100 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] custom_function_name:::::::::::::::::::::::::custom_inbound_0 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts ,domains WHERE accounts.id=domains.accountid AND accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="4779206277" AND domains.domain="pbx3.inexlocal.com" limit 1 2019-07-04 16:05:39.607189 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] [GET_ROUTING_INFO] Query :SELECT * from sip_device_routing WHERE sip_device_id = 460 limit 1 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer_attended' limit 1 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer' limit 1 2019-07-04 16:05:39.627064 [WARNING] switch_cpp.cpp:1365 [ASTPP] [user_domain] user_domain beforepbx3.inexlocal.com 2019-07-04 16:05:39.627064 [WARNING] switch_cpp.cpp:1365 [ASTPP] [user_domain] pickup_group_permission pickup_str 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [NOTIFY] START: 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [NOTIFY] Query :SELECT callkit_token,mobile_type FROM dialer_device_info WHERE username='4779206277' 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts ,domains WHERE accounts.id=domains.accountid AND accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="4779206277" AND domains.domain="pbx3.inexlocal.com" limit 1 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] [GET_ROUTING_INFO] Query :SELECT * from sip_device_routing WHERE sip_device_id = 460 limit 1 2019-07-04 16:05:39.627064 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Generated XML:
2019-07-04 16:05:39.627064 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f6b8805e880 released. Dialplan: sofia/default/8889687188@pbx3.inexlocal.com parsing [default->919724268060] continue=false Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Regex (PASS) [919724268060] destination_number(919724268060) =~ /919724268060/ break=on-false Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(effective_destination_number=919724268060) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(bridge_pre_execute_bleg_app=sched_hangup) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(bridge_pre_execute_bleg_data=+6000 normal_clearing) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(callstart=2019-07-04 10:35:39) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(hangup_after_bridge=true) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(continue_on_fail=TRUE) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(account_id=415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(parent_id=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(entity_id=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(call_processed=internal) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(call_direction=inbound) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(accountname=default) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(filename1=astpp.pbx.lua) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(origination_rates_did=ID:13095|CODE:^919724268060.*|DESTINATION:test Gandhinagar|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:0|COST:1.50000|INC:1|INITIALBLOCK:1|RATEGROUP:0|MARKUP:0|CI:88|ACCID:415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(origination_rates=ID:11|CODE:^91.*|DESTINATION:Ahmedabad-Urban|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:1|COST:0.60000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|CI:88|ACCID:415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(original_caller_id_name=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(original_caller_id_number=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(effective_caller_id_name=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(effective_caller_id_number=8889687188) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(receiver_accid=415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(presence_data=x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(call_type=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(calltype=DID-LOCAL) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action db(insert/pickup_any_group_${callgroup}/4779206277/${uuid}) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(dialed_extension=transfer_call) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(dialed_extension=transfer_call) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action bind_meta_app(95 b s execute_extension::transfer_call_95 XML default) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action bind_meta_app(94 b s execute_extension::transfer_call_94 XML default) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(hangup_after_bridge=true) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(did_user_domain=pbx3.inexlocal.com) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action ring_ready() Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action sleep(5000) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action bridge({sip_invite_params=user=LOCAL,sip_from_uri=4779206277@${domain_name}}[leg_timeout=30]user/4779206277@${domain_name}) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(on_busy_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(on_busy_destination=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(no_answer_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(no_answer_destination=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(not_register_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(not_register_destination=0) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(opensips_flag=1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(variable_sip_to_host=pbx3.inexlocal.com) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(opensips_domain=127.0.0.1) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(leg_timeout=60) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(userinfo_id=415) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(sip_destination_number=4779206277) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(destination_number=919724268060) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action set(did_number=919724268060) Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action lua(astpp/lib/pbx/astpp-sipdevice-routing.lua) |--- Dialplan: Processing recursive conditions level:1 [919724268060_recur_1] require-nested=TRUE |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Regex (PASS) [919724268060_recur_1] ${cond(${user_data 4779206277@${domain_name} param vm-enabled} == true ? YES : NO)}(YES) =~ /^YES$/ break=on-false |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action answer() |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action export(voicemail_alternate_greet_id=919724268060) |--- Dialplan: sofia/default/8889687188@pbx3.inexlocal.com Action voicemail(default $${domain_name} 4779206277) 2019-07-04 16:05:39.667045 [DEBUG] switch_core_state_machine.c:286 (sofia/default/8889687188@pbx3.inexlocal.com) State Change CS_ROUTING -> CS_EXECUTE 2019-07-04 16:05:39.667045 [DEBUG] switch_core_state_machine.c:643 (sofia/default/8889687188@pbx3.inexlocal.com) State ROUTING going to sleep 2019-07-04 16:05:39.667045 [DEBUG] switch_core_state_machine.c:584 (sofia/default/8889687188@pbx3.inexlocal.com) Running State Change CS_EXECUTE (Cur 1 Tot 305) 2019-07-04 16:05:39.667045 [DEBUG] switch_core_state_machine.c:650 (sofia/default/8889687188@pbx3.inexlocal.com) State EXECUTE 2019-07-04 16:05:39.667045 [DEBUG] mod_sofia.c:198 sofia/default/8889687188@pbx3.inexlocal.com SOFIA EXECUTE 2019-07-04 16:05:39.667045 [DEBUG] switch_core_state_machine.c:328 sofia/default/8889687188@pbx3.inexlocal.com Standard EXECUTE EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(effective_destination_number=919724268060) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [effective_destination_number]=[919724268060] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(bridge_pre_execute_bleg_app=sched_hangup) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [bridge_pre_execute_bleg_app]=[sched_hangup] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(bridge_pre_execute_bleg_data=+6000 normal_clearing) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [bridge_pre_execute_bleg_data]=[+6000 normal_clearing] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(callstart=2019-07-04 10:35:39) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [callstart]=[2019-07-04 10:35:39] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(hangup_after_bridge=true) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [hangup_after_bridge]=[true] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(continue_on_fail=TRUE) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [continue_on_fail]=[TRUE] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(account_id=415) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [account_id]=[415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(parent_id=0) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [parent_id]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(entity_id=0) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [entity_id]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(call_processed=internal) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [call_processed]=[internal] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(call_direction=inbound) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [call_direction]=[inbound] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(accountname=default) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [accountname]=[default] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(filename1=astpp.pbx.lua) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [filename1]=[astpp.pbx.lua] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(origination_rates_did=ID:13095|CODE:^919724268060.*|DESTINATION:test Gandhinagar|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:0|COST:1.50000|INC:1|INITIALBLOCK:1|RATEGROUP:0|MARKUP:0|CI:88|ACCID:415) 2019-07-04 16:05:39.667045 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [origination_rates_did]=[ID:13095|CODE:^919724268060.*|DESTINATION:test Gandhinagar|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:0|COST:1.50000|INC:1|INITIALBLOCK:1|RATEGROUP:0|MARKUP:0|CI:88|ACCID:415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(origination_rates=ID:11|CODE:^91.*|DESTINATION:Ahmedabad-Urban|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:1|COST:0.60000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|CI:88|ACCID:415) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [origination_rates]=[ID:11|CODE:^91.*|DESTINATION:Ahmedabad-Urban|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|CT:1|COST:0.60000|INC:1|INITIALBLOCK:1|RATEGROUP:4|MARKUP:0|CI:88|ACCID:415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(original_caller_id_name=8889687188) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [original_caller_id_name]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(original_caller_id_number=8889687188) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [original_caller_id_number]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(effective_caller_id_name=8889687188) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [effective_caller_id_name]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(effective_caller_id_number=8889687188) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [effective_caller_id_number]=[8889687188] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(receiver_accid=415) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [receiver_accid]=[415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(presence_data=x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID) 2019-07-04 16:05:39.686997 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [presence_data]=[x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(call_type=0) 2019-07-04 16:05:39.686997 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [call_type]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(calltype=DID-LOCAL) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [calltype]=[DID-LOCAL] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com db(insert/pickup_any_group_/4779206277/7769e32e-9e47-11e9-9533-2d0e45e4becc) EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(dialed_extension=transfer_call) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [dialed_extension]=[transfer_call] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(dialed_extension=transfer_call) 2019-07-04 16:05:39.686997 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [dialed_extension]=[transfer_call] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com bind_meta_app(95 b s execute_extension::transfer_call_95 XML default) 2019-07-04 16:05:39.686997 [ERR] switch_ivr_async.c:4146 Invalid key 95 2019-07-04 16:05:39.686997 [ERR] mod_dptools.c:786 Bind Error! EXECUTE sofia/default/8889687188@pbx3.inexlocal.com bind_meta_app(94 b s execute_extension::transfer_call_94 XML default) 2019-07-04 16:05:39.686997 [ERR] switch_ivr_async.c:4146 Invalid key 94 2019-07-04 16:05:39.686997 [ERR] mod_dptools.c:786 Bind Error! EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(hangup_after_bridge=true) 2019-07-04 16:05:39.686997 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [hangup_after_bridge]=[true] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(did_user_domain=pbx3.inexlocal.com) 2019-07-04 16:05:39.686997 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [did_user_domain]=[pbx3.inexlocal.com] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com ring_ready() 2019-07-04 16:05:39.686997 [NOTICE] mod_sofia.c:2273 Ring-Ready sofia/default/8889687188@pbx3.inexlocal.com! 2019-07-04 16:05:39.686997 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [early][180] 2019-07-04 16:05:39.686997 [NOTICE] mod_dptools.c:1028 Ring Ready sofia/default/8889687188@pbx3.inexlocal.com! EXECUTE sofia/default/8889687188@pbx3.inexlocal.com sleep(5000) EXECUTE sofia/default/8889687188@pbx3.inexlocal.com bridge({sip_invite_params=user=LOCAL,sip_from_uri=4779206277@pbx3.inexlocal.com}[leg_timeout=30]user/4779206277@pbx3.inexlocal.com) 2019-07-04 16:05:44.727017 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [presence_data]=[x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID] to event 2019-07-04 16:05:44.727017 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [call_type]=[0] to event 2019-07-04 16:05:44.727017 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [dialed_extension]=[transfer_call] to event 2019-07-04 16:05:44.727017 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [did_user_domain]=[pbx3.inexlocal.com] to event 2019-07-04 16:05:44.727017 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-07-04 16:05:44.727017 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2019-07-04 16:05:44.787026 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [presence_data]=[x|||PBX(8889687188)|||^919724268060.* // test Gandhinagar // 1.50000||||||DID] to event 2019-07-04 16:05:44.787026 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [call_type]=[0] to event 2019-07-04 16:05:44.787026 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [dialed_extension]=[transfer_call] to event 2019-07-04 16:05:44.787026 [DEBUG] switch_channel.c:1250 sofia/default/8889687188@pbx3.inexlocal.com EXPORTING[export_vars] [did_user_domain]=[pbx3.inexlocal.com] to event 2019-07-04 16:05:44.787026 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-07-04 16:05:44.787026 [NOTICE] switch_channel.c:1104 New Channel sofia/default/4779206277@192.168.1.13:52632 [7a959930-9e47-11e9-9560-2d0e45e4becc] 2019-07-04 16:05:44.787026 [DEBUG] mod_sofia.c:4819 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_NEW -> CS_INIT 2019-07-04 16:05:44.787026 [DEBUG] switch_ivr_originate.c:2963 sofia/default/4779206277@192.168.1.13:52632 Setting leg timeout to 30 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_INIT (Cur 2 Tot 306) 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:627 (sofia/default/4779206277@192.168.1.13:52632) State INIT 2019-07-04 16:05:44.787026 [DEBUG] mod_sofia.c:90 sofia/default/4779206277@192.168.1.13:52632 SOFIA INIT 2019-07-04 16:05:44.787026 [DEBUG] sofia_glue.c:1295 sofia/default/4779206277@192.168.1.13:52632 sending invite version: 1.6.20 64bit Local SDP: v=0 o=FreeSWITCH 1562215530 1562215531 IN IP4 192.168.1.118 s=FreeSWITCH c=IN IP4 192.168.1.118 t=0 0 m=audio 21014 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 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:40 sofia/default/4779206277@192.168.1.13:52632 Standard INIT 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:48 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_INIT -> CS_ROUTING 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:627 (sofia/default/4779206277@192.168.1.13:52632) State INIT going to sleep 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_ROUTING (Cur 2 Tot 306) 2019-07-04 16:05:44.787026 [DEBUG] sofia.c:7084 Channel sofia/default/4779206277@192.168.1.13:52632 entering state [calling][0] 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:643 (sofia/default/4779206277@192.168.1.13:52632) State ROUTING 2019-07-04 16:05:44.787026 [DEBUG] mod_sofia.c:143 sofia/default/4779206277@192.168.1.13:52632 SOFIA ROUTING 2019-07-04 16:05:44.787026 [DEBUG] switch_ivr_originate.c:67 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_ROUTING -> CS_CONSUME_MEDIA 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:643 (sofia/default/4779206277@192.168.1.13:52632) State ROUTING going to sleep 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 306) 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:662 (sofia/default/4779206277@192.168.1.13:52632) State CONSUME_MEDIA 2019-07-04 16:05:44.787026 [DEBUG] switch_core_state_machine.c:662 (sofia/default/4779206277@192.168.1.13:52632) State CONSUME_MEDIA going to sleep 2019-07-04 16:05:44.907006 [DEBUG] sofia.c:7084 Channel sofia/default/4779206277@192.168.1.13:52632 entering state [proceeding][180] 2019-07-04 16:05:44.907006 [NOTICE] sofia.c:7192 Ring-Ready sofia/default/4779206277@192.168.1.13:52632! 2019-07-04 16:05:44.907006 [DEBUG] switch_channel.c:3346 (sofia/default/4779206277@192.168.1.13:52632) Callstate Change DOWN -> RINGING 2019-07-04 16:05:44.907006 [NOTICE] switch_ivr_originate.c:525 Ring Ready sofia/default/8889687188@pbx3.inexlocal.com! 2019-07-04 16:05:47.007062 [NOTICE] switch_channel.c:1104 New Channel sofia/default/7100815208@pbx3.inexlocal.com [7be92414-9e47-11e9-9564-2d0e45e4becc] 2019-07-04 16:05:47.007062 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_NEW (Cur 3 Tot 307) 2019-07-04 16:05:47.007062 [DEBUG] sofia.c:9873 sofia/default/7100815208@pbx3.inexlocal.com receiving invite from 192.168.1.43:5060 version: 1.6.20 64bit 2019-07-04 16:05:47.007062 [DEBUG] sofia.c:10044 IP 192.168.1.43 Rejected by acl "default". Falling back to Digest auth. 2019-07-04 16:05:47.007062 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'default' for [*102@pbx3.inexlocal.com] from ip 192.168.1.43 2019-07-04 16:05:47.007062 [DEBUG] switch_core_state_machine.c:603 (sofia/default/7100815208@pbx3.inexlocal.com) State NEW 2019-07-04 16:05:47.007062 [DEBUG] sofia.c:2334 detaching session 7be92414-9e47-11e9-9564-2d0e45e4becc 2019-07-04 16:05:47.027166 [DEBUG] sofia.c:2442 Re-attaching to session 7be92414-9e47-11e9-9564-2d0e45e4becc 2019-07-04 16:05:47.046998 [DEBUG] sofia.c:9873 sofia/default/7100815208@pbx3.inexlocal.com receiving invite from 192.168.1.43:5060 version: 1.6.20 64bit 2019-07-04 16:05:47.046998 [DEBUG] sofia.c:10044 IP 192.168.1.43 Rejected by acl "default". Falling back to Digest auth. 2019-07-04 16:05:47.067041 [DEBUG] sofia.c:7084 Channel sofia/default/7100815208@pbx3.inexlocal.com entering state [received][100] 2019-07-04 16:05:47.067041 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=twinkle 971131215 462933206 IN IP4 192.168.1.43 s=- c=IN IP4 192.168.1.43 t=0 0 m=audio 8000 RTP/AVP 98 97 8 0 3 101 a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:98:16000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [speex:97:8000:20:0:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1] 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/7100815208@pbx3.inexlocal.com PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2019-07-04 16:05:47.067041 [DEBUG] switch_core_codec.c:111 sofia/default/7100815208@pbx3.inexlocal.com Original read codec set to PCMA:8 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000 2019-07-04 16:05:47.067041 [DEBUG] switch_core_media.c:4767 sofia/default/7100815208@pbx3.inexlocal.com Set 2833 dtmf send payload to 101 recv payload to 101 2019-07-04 16:05:47.067041 [DEBUG] sofia.c:7507 (sofia/default/7100815208@pbx3.inexlocal.com) State Change CS_NEW -> CS_INIT 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_INIT (Cur 3 Tot 307) 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:627 (sofia/default/7100815208@pbx3.inexlocal.com) State INIT 2019-07-04 16:05:47.067041 [DEBUG] mod_sofia.c:90 sofia/default/7100815208@pbx3.inexlocal.com SOFIA INIT 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:40 sofia/default/7100815208@pbx3.inexlocal.com Standard INIT 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:48 (sofia/default/7100815208@pbx3.inexlocal.com) State Change CS_INIT -> CS_ROUTING 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:627 (sofia/default/7100815208@pbx3.inexlocal.com) State INIT going to sleep 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_ROUTING (Cur 3 Tot 307) 2019-07-04 16:05:47.067041 [DEBUG] switch_channel.c:2249 (sofia/default/7100815208@pbx3.inexlocal.com) Callstate Change DOWN -> RINGING 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:643 (sofia/default/7100815208@pbx3.inexlocal.com) State ROUTING 2019-07-04 16:05:47.067041 [DEBUG] mod_sofia.c:143 sofia/default/7100815208@pbx3.inexlocal.com SOFIA ROUTING 2019-07-04 16:05:47.067041 [DEBUG] switch_core_state_machine.c:236 sofia/default/7100815208@pbx3.inexlocal.com Standard ROUTING 2019-07-04 16:05:47.067041 [INFO] mod_dialplan_xml.c:637 Processing 7100815208 <7100815208>->*102 in context default 2019-07-04 16:05:47.086992 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f6b8805e880 Connected. 2019-07-04 16:05:47.086992 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM `system` WHERE group_title IN ('global','opensips','callingcard','calls','InternationalPrefixes') 2019-07-04 16:05:47.086992 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_ADDON_CONF] Query :SELECT package_name FROM addons 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] blind_flag: 0 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] TRAN user_domain: pbx3.inexlocal.com 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] hunt_destination_number: *102 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer_attended' limit 1 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer' limit 1 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Feature Code blind_value_two_digit*9 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Feature Code destination_number_two_digit*1 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Feature Code transfer_attended_two_digit*9 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : *102 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_code = '*102' limit 1 2019-07-04 16:05:47.107022 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Feature Code Action :::: call_pickup_same_group 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [FEATURE_CODE] sip_number :7100815208 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [get_sip_accountcode] Query :SELECT sip_devices.accountid from sip_devices,domains where sip_devices.accountid=domains.accountid and sip_devices.username = '7100815208' and domain = 'pbx3.inexlocal.com' limit 1 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation FROM sip_devices as sip_devices,accounts as accounts ,domains WHERE accounts.id=domains.accountid AND accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="7100815208" AND domains.domain="pbx3.inexlocal.com" limit 1 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [FEATURE_CODE] sip_info id :459 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [FEATURE_CODE] feature_code_action :call_pickup_same_group 2019-07-04 16:05:47.107022 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [PBX_SIP_ROUTING] [GET_ROUTING_INFO] Query :SELECT * from sip_device_routing WHERE sip_device_id = 459 limit 1 2019-07-04 16:05:47.129449 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_PICKUP_GROUP] Query :SELECT id,name from pickup_group where id IN (1,2,3,1,2,3) AND status = 0 2019-07-04 16:05:47.129449 [DEBUG] switch_cpp.cpp:1365 [ASTPP] Generated XML:
2019-07-04 16:05:47.129449 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f6b8805e880 released. Dialplan: sofia/default/7100815208@pbx3.inexlocal.com parsing [default->\*102] continue=false Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Regex (PASS) [\*102] destination_number(*102) =~ /\*102/ break=on-false Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Action export(bypass_media=true) Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Action export(did_user_domain=pbx3.inexlocal.com) Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Action play_and_get_digits(2 15 3 7000 # /usr/share/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav /invalid.wav foobar \d+) Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Action pickup(SIP_device_${foobar}) Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Action pickup(Allow-pick-up_${foobar}) Dialplan: sofia/default/7100815208@pbx3.inexlocal.com Action pickup(ABC_${foobar}) 2019-07-04 16:05:47.129449 [DEBUG] switch_core_state_machine.c:286 (sofia/default/7100815208@pbx3.inexlocal.com) State Change CS_ROUTING -> CS_EXECUTE 2019-07-04 16:05:47.129449 [DEBUG] switch_core_state_machine.c:643 (sofia/default/7100815208@pbx3.inexlocal.com) State ROUTING going to sleep 2019-07-04 16:05:47.129449 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_EXECUTE (Cur 3 Tot 307) 2019-07-04 16:05:47.129449 [DEBUG] switch_core_state_machine.c:650 (sofia/default/7100815208@pbx3.inexlocal.com) State EXECUTE 2019-07-04 16:05:47.129449 [DEBUG] mod_sofia.c:198 sofia/default/7100815208@pbx3.inexlocal.com SOFIA EXECUTE 2019-07-04 16:05:47.129449 [DEBUG] switch_core_state_machine.c:328 sofia/default/7100815208@pbx3.inexlocal.com Standard EXECUTE EXECUTE sofia/default/7100815208@pbx3.inexlocal.com export(bypass_media=true) 2019-07-04 16:05:47.129449 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [bypass_media]=[true] EXECUTE sofia/default/7100815208@pbx3.inexlocal.com export(did_user_domain=pbx3.inexlocal.com) 2019-07-04 16:05:47.129449 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [did_user_domain]=[pbx3.inexlocal.com] 2019-07-04 16:05:47.129449 [DEBUG] switch_core_session.c:2647 Application play_and_get_digits Requires media! pre_answering channel sofia/default/7100815208@pbx3.inexlocal.com 2019-07-04 16:05:47.129449 [INFO] switch_core_session.c:2649 Sending early media 2019-07-04 16:05:47.129449 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/7100815208@pbx3.inexlocal.com] 192.168.1.118 port 30396 -> 192.168.1.43 port 8000 codec: 8 ms: 20 2019-07-04 16:05:47.129449 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 2019-07-04 16:05:47.129449 [DEBUG] switch_core_media.c:7180 sofia/default/7100815208@pbx3.inexlocal.com Set 2833 dtmf send payload to 101 2019-07-04 16:05:47.129449 [DEBUG] switch_core_media.c:7187 sofia/default/7100815208@pbx3.inexlocal.com Set 2833 dtmf receive payload to 101 2019-07-04 16:05:47.129449 [DEBUG] switch_core_media.c:7210 sofia/default/7100815208@pbx3.inexlocal.com Set rtp dtmf delay to 40 2019-07-04 16:05:47.129449 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1562206151 1562206152 IN IP4 192.168.1.118 s=FreeSWITCH c=IN IP4 192.168.1.118 t=0 0 m=audio 30396 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-07-04 16:05:47.129449 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/default/7100815208@pbx3.inexlocal.com! 2019-07-04 16:05:47.129449 [DEBUG] switch_channel.c:3474 (sofia/default/7100815208@pbx3.inexlocal.com) Callstate Change RINGING -> EARLY EXECUTE sofia/default/7100815208@pbx3.inexlocal.com play_and_get_digits(2 15 3 7000 # /usr/share/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav /invalid.wav foobar \d+) 2019-07-04 16:05:47.129449 [DEBUG] switch_core_file.c:342 File /usr/share/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav sample rate 22050 doesn't match requested rate 8000 2019-07-04 16:05:47.129449 [WARNING] switch_core_file.c:360 File has 2 channels, muxing to 1 channel will occur. 2019-07-04 16:05:47.129449 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2019-07-04 16:05:47.129449 [DEBUG] sofia.c:7084 Channel sofia/default/7100815208@pbx3.inexlocal.com entering state [early][183] 2019-07-04 16:05:47.227061 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed. 2019-07-04 16:05:50.307057 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav 2019-07-04 16:05:57.327009 [ERR] mod_sndfile.c:204 Error Opening File [/invalid.wav] [System error : No such file or directory.] 2019-07-04 16:05:57.327009 [DEBUG] switch_core_file.c:342 File /usr/share/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav sample rate 22050 doesn't match requested rate 8000 2019-07-04 16:05:57.327009 [WARNING] switch_core_file.c:360 File has 2 channels, muxing to 1 channel will occur. 2019-07-04 16:05:57.327009 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2019-07-04 16:05:57.687039 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 7:800 2019-07-04 16:05:57.687039 [INFO] switch_channel.c:515 RECV DTMF 7:800 2019-07-04 16:05:57.687039 [DEBUG] switch_ivr_play_say.c:1942 done playing file /usr/share/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav 2019-07-04 16:05:58.307049 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 1:800 2019-07-04 16:05:58.307049 [INFO] switch_channel.c:515 RECV DTMF 1:800 2019-07-04 16:05:59.407021 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 0:800 2019-07-04 16:05:59.407021 [INFO] switch_channel.c:515 RECV DTMF 0:800 2019-07-04 16:05:59.946994 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 0:800 2019-07-04 16:05:59.946994 [INFO] switch_channel.c:515 RECV DTMF 0:800 2019-07-04 16:06:03.107038 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 8:800 2019-07-04 16:06:03.107038 [INFO] switch_channel.c:515 RECV DTMF 8:800 2019-07-04 16:06:03.667023 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 1:800 2019-07-04 16:06:03.667023 [INFO] switch_channel.c:515 RECV DTMF 1:800 2019-07-04 16:06:04.247000 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 5:800 2019-07-04 16:06:04.247000 [INFO] switch_channel.c:515 RECV DTMF 5:800 2019-07-04 16:06:07.027006 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 2:800 2019-07-04 16:06:07.027006 [INFO] switch_channel.c:515 RECV DTMF 2:800 2019-07-04 16:06:07.787059 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 0:800 2019-07-04 16:06:07.787059 [INFO] switch_channel.c:515 RECV DTMF 0:800 2019-07-04 16:06:08.327010 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF 8:800 2019-07-04 16:06:08.327010 [INFO] switch_channel.c:515 RECV DTMF 8:800 2019-07-04 16:06:08.946995 [DEBUG] switch_rtp.c:7534 RTP RECV DTMF #:800 2019-07-04 16:06:08.946995 [INFO] switch_channel.c:515 RECV DTMF #:800 EXECUTE sofia/default/7100815208@pbx3.inexlocal.com pickup(SIP_device_7100815208) EXECUTE sofia/default/7100815208@pbx3.inexlocal.com pickup(Allow-pick-up_7100815208) EXECUTE sofia/default/7100815208@pbx3.inexlocal.com pickup(ABC_7100815208) 2019-07-04 16:06:08.946995 [NOTICE] switch_core_state_machine.c:385 sofia/default/7100815208@pbx3.inexlocal.com has executed the last dialplan instruction, hanging up. 2019-07-04 16:06:08.946995 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/default/7100815208@pbx3.inexlocal.com [CS_EXECUTE] [NORMAL_CLEARING] 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:650 (sofia/default/7100815208@pbx3.inexlocal.com) State EXECUTE going to sleep 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_HANGUP (Cur 3 Tot 307) 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:850 (sofia/default/7100815208@pbx3.inexlocal.com) Callstate Change EARLY -> HANGUP 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:852 (sofia/default/7100815208@pbx3.inexlocal.com) State HANGUP 2019-07-04 16:06:08.946995 [DEBUG] mod_sofia.c:438 Channel sofia/default/7100815208@pbx3.inexlocal.com hanging up, cause: NORMAL_CLEARING 2019-07-04 16:06:08.946995 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:60 sofia/default/7100815208@pbx3.inexlocal.com Standard HANGUP, cause: NORMAL_CLEARING 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:852 (sofia/default/7100815208@pbx3.inexlocal.com) State HANGUP going to sleep 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:619 (sofia/default/7100815208@pbx3.inexlocal.com) State Change CS_HANGUP -> CS_REPORTING 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:584 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_REPORTING (Cur 3 Tot 307) 2019-07-04 16:06:08.946995 [DEBUG] switch_core_state_machine.c:938 (sofia/default/7100815208@pbx3.inexlocal.com) State REPORTING 2019-07-04 16:06:08.946995 [INFO] mod_json_cdr.c:271 Process [7be92414-9e47-11e9-9564-2d0e45e4becc.cdr.json] 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:174 sofia/default/7100815208@pbx3.inexlocal.com Standard REPORTING, cause: NORMAL_CLEARING 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:938 (sofia/default/7100815208@pbx3.inexlocal.com) State REPORTING going to sleep 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:610 (sofia/default/7100815208@pbx3.inexlocal.com) State Change CS_REPORTING -> CS_DESTROY 2019-07-04 16:06:08.967222 [DEBUG] switch_core_session.c:1665 Session 307 (sofia/default/7100815208@pbx3.inexlocal.com) Locked, Waiting on external entities 2019-07-04 16:06:08.967222 [NOTICE] switch_core_session.c:1683 Session 307 (sofia/default/7100815208@pbx3.inexlocal.com) Ended 2019-07-04 16:06:08.967222 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/7100815208@pbx3.inexlocal.com [CS_DESTROY] 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:741 (sofia/default/7100815208@pbx3.inexlocal.com) Running State Change CS_DESTROY (Cur 2 Tot 307) 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:751 (sofia/default/7100815208@pbx3.inexlocal.com) State DESTROY 2019-07-04 16:06:08.967222 [DEBUG] mod_sofia.c:343 sofia/default/7100815208@pbx3.inexlocal.com SOFIA DESTROY 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:181 sofia/default/7100815208@pbx3.inexlocal.com Standard DESTROY 2019-07-04 16:06:08.967222 [DEBUG] switch_core_state_machine.c:751 (sofia/default/7100815208@pbx3.inexlocal.com) State DESTROY going to sleep 2019-07-04 16:06:14.007022 [NOTICE] switch_ivr_originate.c:3612 Hangup sofia/default/4779206277@192.168.1.13:52632 [CS_CONSUME_MEDIA] [NO_ANSWER] 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_HANGUP (Cur 2 Tot 307) 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:850 (sofia/default/4779206277@192.168.1.13:52632) Callstate Change RINGING -> HANGUP 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:852 (sofia/default/4779206277@192.168.1.13:52632) State HANGUP 2019-07-04 16:06:14.007022 [DEBUG] mod_sofia.c:438 Channel sofia/default/4779206277@192.168.1.13:52632 hanging up, cause: NO_ANSWER 2019-07-04 16:06:14.007022 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [NO_ANSWER] 2019-07-04 16:06:14.007022 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 19 [NO_ANSWER] 2019-07-04 16:06:14.007022 [INFO] mod_dptools.c:3436 Originate Failed. Cause: NO_ANSWER 2019-07-04 16:06:14.007022 [DEBUG] mod_sofia.c:502 Sending CANCEL to sofia/default/4779206277@192.168.1.13:52632 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:60 sofia/default/4779206277@192.168.1.13:52632 Standard HANGUP, cause: NO_ANSWER 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:852 (sofia/default/4779206277@192.168.1.13:52632) State HANGUP going to sleep 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:619 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_HANGUP -> CS_REPORTING EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(on_busy_flag=1) 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:584 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_REPORTING (Cur 2 Tot 307) 2019-07-04 16:06:14.007022 [DEBUG] switch_core_state_machine.c:938 (sofia/default/4779206277@192.168.1.13:52632) State REPORTING 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [on_busy_flag]=[1] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(on_busy_destination=0) 2019-07-04 16:06:14.007022 [INFO] mod_json_cdr.c:271 Process [7a959930-9e47-11e9-9560-2d0e45e4becc.cdr.json] 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [on_busy_destination]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(no_answer_flag=1) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [no_answer_flag]=[1] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(no_answer_destination=0) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [no_answer_destination]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(not_register_flag=1) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [not_register_flag]=[1] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(not_register_destination=0) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [not_register_destination]=[0] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(opensips_flag=1) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [opensips_flag]=[1] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(variable_sip_to_host=pbx3.inexlocal.com) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [variable_sip_to_host]=[pbx3.inexlocal.com] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(opensips_domain=127.0.0.1) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [opensips_domain]=[127.0.0.1] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(leg_timeout=60) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [leg_timeout]=[60] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(userinfo_id=415) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [userinfo_id]=[415] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(sip_destination_number=4779206277) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [sip_destination_number]=[4779206277] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(destination_number=919724268060) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [destination_number]=[919724268060] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com set(did_number=919724268060) 2019-07-04 16:06:14.007022 [DEBUG] mod_dptools.c:1548 SET sofia/default/8889687188@pbx3.inexlocal.com [did_number]=[919724268060] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com lua(astpp/lib/pbx/astpp-sipdevice-routing.lua) 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:174 sofia/default/4779206277@192.168.1.13:52632 Standard REPORTING, cause: NO_ANSWER 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:938 (sofia/default/4779206277@192.168.1.13:52632) State REPORTING going to sleep 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:610 (sofia/default/4779206277@192.168.1.13:52632) State Change CS_REPORTING -> CS_DESTROY 2019-07-04 16:06:14.027016 [DEBUG] switch_core_session.c:1665 Session 306 (sofia/default/4779206277@192.168.1.13:52632) Locked, Waiting on external entities 2019-07-04 16:06:14.027016 [NOTICE] switch_cpp.cpp:1365 [Astpp_SIP-Devices] This is last dispositions NO_ANSWER This is SIP Number : 4779206277 2019-07-04 16:06:14.027016 [NOTICE] switch_core_session.c:1683 Session 306 (sofia/default/4779206277@192.168.1.13:52632) Ended 2019-07-04 16:06:14.027016 [NOTICE] switch_core_session.c:1687 Close Channel sofia/default/4779206277@192.168.1.13:52632 [CS_DESTROY] 2019-07-04 16:06:14.027016 [DEBUG] switch_cpp.cpp:1112 sofia/default/8889687188@pbx3.inexlocal.com destroy/unlink session from object 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:741 (sofia/default/4779206277@192.168.1.13:52632) Running State Change CS_DESTROY (Cur 1 Tot 307) EXECUTE sofia/default/8889687188@pbx3.inexlocal.com answer() 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:751 (sofia/default/4779206277@192.168.1.13:52632) State DESTROY 2019-07-04 16:06:14.027016 [DEBUG] mod_sofia.c:343 sofia/default/4779206277@192.168.1.13:52632 SOFIA DESTROY 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:181 sofia/default/4779206277@192.168.1.13:52632 Standard DESTROY 2019-07-04 16:06:14.027016 [DEBUG] switch_core_state_machine.c:751 (sofia/default/4779206277@192.168.1.13:52632) State DESTROY going to sleep 2019-07-04 16:06:14.027016 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/8889687188@pbx3.inexlocal.com] 192.168.1.118 port 26652 -> 192.168.1.151 port 5038 codec: 0 ms: 20 2019-07-04 16:06:14.027016 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms 2019-07-04 16:06:14.027016 [DEBUG] switch_core_media.c:7180 sofia/default/8889687188@pbx3.inexlocal.com Set 2833 dtmf send payload to 101 2019-07-04 16:06:14.027016 [DEBUG] switch_core_media.c:7187 sofia/default/8889687188@pbx3.inexlocal.com Set 2833 dtmf receive payload to 101 2019-07-04 16:06:14.027016 [DEBUG] switch_core_media.c:7210 sofia/default/8889687188@pbx3.inexlocal.com Set rtp dtmf delay to 40 2019-07-04 16:06:14.027016 [DEBUG] mod_sofia.c:850 Local SDP sofia/default/8889687188@pbx3.inexlocal.com: v=0 o=FreeSWITCH 1562209922 1562209923 IN IP4 192.168.1.118 s=FreeSWITCH c=IN IP4 192.168.1.118 t=0 0 m=audio 26652 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 2019-07-04 16:06:14.027016 [NOTICE] mod_dptools.c:1312 Channel [sofia/default/8889687188@pbx3.inexlocal.com] has been answered 2019-07-04 16:06:14.027016 [DEBUG] switch_channel.c:3773 (sofia/default/8889687188@pbx3.inexlocal.com) Callstate Change RINGING -> ACTIVE 2019-07-04 16:06:14.027016 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [completed][200] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com export(voicemail_alternate_greet_id=919724268060) 2019-07-04 16:06:14.027016 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [voicemail_alternate_greet_id]=[919724268060] EXECUTE sofia/default/8889687188@pbx3.inexlocal.com voicemail(default pbx3.inexlocal.com 4779206277) 2019-07-04 16:06:14.067068 [DEBUG] sofia.c:7084 Channel sofia/default/8889687188@pbx3.inexlocal.com entering state [ready][200] 2019-07-04 16:06:14.127017 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en] 2019-07-04 16:06:14.147139 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[voicemail/vm-person.wav] (en:en) 2019-07-04 16:06:14.147139 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2019-07-04 16:06:14.327028 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed. freeswitch@localhost.localdomain> ...