+OK log level [7] 2019-03-23 13:17:04.663666 [NOTICE] switch_channel.c:1104 New Channel sofia/SIP_SHRISAI_INT/1618@103.54.24.21 [52b1277e-8237-4d84-bdbf-281ddd1abc19] 2019-03-23 13:17:04.663666 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Running State Change CS_NEW (Cur 2 Tot 4057) 2019-03-23 13:17:04.663666 [DEBUG] sofia.c:9873 sofia/SIP_SHRISAI_INT/1618@103.54.24.21 receiving invite from 185.184.241.4:53883 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit 2019-03-23 13:17:04.663666 [DEBUG] sofia.c:10044 IP 185.184.241.4 Rejected by acl "default". Falling back to Digest auth. 2019-03-23 13:17:04.663666 [WARNING] sofia_reg.c:1792 SIP auth challenge (INVITE) on sofia profile 'SIP_SHRISAI_INT' for [900441923604021@103.54.24.21] from ip 185.184.241.4 2019-03-23 13:17:04.663666 [DEBUG] switch_core_state_machine.c:603 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State NEW 2019-03-23 13:17:04.663666 [DEBUG] sofia.c:2334 detaching session 52b1277e-8237-4d84-bdbf-281ddd1abc19 recv 851 bytes from udp/[10.50.180.1]:5060 at 13:17:06.001421: ------------------------------------------------------------------------ INVITE sip:61198600@10.50.180.1:5060;transport=udp;gw=GW_TTL_DEL SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKdnyddsnieciltdkbccdvdnnwy;Role=3;Hpt=8e72_36 Call-ID: asbc1aef2502b63-0286-0105@10.162.193.6 From: "918144659796";tag=aa2c106--3EG2502b6211e To: "1161198699" CSeq: 19035 INVITE Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,REFER,NOTIFY,SUBSCRIBE,PRACK,UPDATE Contact: Max-Forwards: 8 Supported: 100rel User-Agent: ZTE Softswitch/1.0.0 P-Early-Media: gated Content-Length: 176 Content-Type: application/sdp v=0 o=- 2130 32193 IN IP4 10.50.180.1 s=SBC call c=IN IP4 10.50.180.1 t=0 0 m=audio 34684 RTP/AVP 8 0 18 97 a=rtpmap:97 telephone-event/8000 a=fmtp:97 0-15 a=ptime:20 ------------------------------------------------------------------------ send 349 bytes to udp/[10.50.180.1]:5060 at 13:17:06.001795: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKdnyddsnieciltdkbccdvdnnwy;Role=3;Hpt=8e72_36 From: "918144659796";tag=aa2c106--3EG2502b6211e To: "1161198699" Call-ID: asbc1aef2502b63-0286-0105@10.162.193.6 CSeq: 19035 INVITE User-Agent: SIPOne Content-Length: 0 ------------------------------------------------------------------------ 2019-03-23 13:17:05.983678 [NOTICE] switch_channel.c:1104 New Channel sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [3aab0159-764e-4466-8881-cb6227188c0e] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_NEW (Cur 3 Tot 4058) 2019-03-23 13:17:05.983678 [DEBUG] sofia.c:9873 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 receiving invite from 10.50.180.1:5060 version: 1.6.19 git 7a77e0b 2017-07-13 12:01:45Z 64bit 2019-03-23 13:17:05.983678 [DEBUG] sofia.c:9989 IP 10.50.180.1 Approved by acl "default[]". Access Granted. 2019-03-23 13:17:05.983678 [DEBUG] sofia.c:7084 Channel sofia/SIP_TTL_DEL/918144659796@10.50.180.1 entering state [received][100] 2019-03-23 13:17:05.983678 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=- 2130 32193 IN IP4 10.50.180.1 s=SBC call c=IN IP4 10.50.180.1 t=0 0 m=audio 34684 RTP/AVP 8 0 18 97 a=rtpmap:97 telephone-event/8000 a=fmtp:97 0-15 a=ptime:20 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 97@8000 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:3061 Set Codec sofia/SIP_TTL_DEL/918144659796@10.50.180.1 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2019-03-23 13:17:05.983678 [DEBUG] switch_core_codec.c:111 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Original read codec set to PCMA:8 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 97@8000 2019-03-23 13:17:05.983678 [DEBUG] switch_core_media.c:4767 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Set 2833 dtmf send payload to 97 recv payload to 97 2019-03-23 13:17:05.983678 [DEBUG] sofia.c:7507 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State Change CS_NEW -> CS_INIT 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:603 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State NEW 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_INIT (Cur 3 Tot 4058) 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:627 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State INIT 2019-03-23 13:17:06.003680 [DEBUG] mod_sofia.c:90 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 SOFIA INIT 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:40 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Standard INIT 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:48 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State Change CS_INIT -> CS_ROUTING 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:627 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State INIT going to sleep 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_ROUTING (Cur 3 Tot 4058) 2019-03-23 13:17:06.003680 [DEBUG] switch_channel.c:2249 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Callstate Change DOWN -> RINGING 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:643 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State ROUTING 2019-03-23 13:17:06.003680 [DEBUG] mod_sofia.c:143 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 SOFIA ROUTING 2019-03-23 13:17:06.003680 [DEBUG] switch_core_state_machine.c:236 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Standard ROUTING 2019-03-23 13:17:06.003680 [INFO] mod_dialplan_xml.c:637 Processing 918144659796 <918144659796>->61198600 in context default 2019-03-23 13:17:06.003680 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f0da0207f30 Connected. 2019-03-23 13:17:06.003680 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard') 2019-03-23 13:17:06.003680 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 61198600 2019-03-23 13:17:06.003680 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number : 918144659796 / 918144659796 2019-03-23 13:17:06.003680 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_DID] Query :SELECT A.id as id,B.id as accountid,B.number as account_code,B.did_cid_translation as did_cid_translation,A.number as did_number,A.connectcost,A.includedseconds,A.cost,A.inc,A.extensions,A.maxchannels,A.call_type,A.city,A.province,A.init_inc,A.leg_timeout FROM dids AS A,accounts AS B WHERE A.status=0 AND B.status=0 AND B.deleted=0 AND B.id=A.accountid AND A.number ="61198600" LIMIT 1 2019-03-23 13:17:06.003680 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT 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 WHERE accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="61198600" limit 1 2019-03-23 13:17:06.003680 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : local 2019-03-23 13:17:06.003680 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [IPAUTHENTICATION] Query :SELECT ip_map.*, (SELECT number FROM accounts where id=accountid AND status=0 AND deleted=0) AS account_code FROM ip_map WHERE INET_ATON("10.50.180.1") BETWEEN(INET_ATON(SUBSTRING_INDEX(`ip`, '/', 1)) & 0xffffffff ^((0x1 <<(32 - SUBSTRING_INDEX(`ip`, '/', -1))) -1 )) AND(INET_ATON(SUBSTRING_INDEX(`ip`, '/', 1)) |((0x100000000 >> SUBSTRING_INDEX(`ip`,'/', -1)) -1)) AND "61198600" LIKE CONCAT(prefix,'%') ORDER BY LENGTH(prefix) DESC LIMIT 1 2019-03-23 13:17:06.003680 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 7335503421] 2019-03-23 13:17:06.003680 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "7335503421" OR id="7335503421") AND status=0 AND deleted=0 AND (expiry >= '2019-03-23 07:47:06' OR expiry = '0000-00-00 00:00:00') limit 1 2019-03-23 13:17:06.023685 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PACKAGE_INFO] Query :SELECT * FROM packages as P inner join package_patterns as PKGPTR on P.id = PKGPTR.package_id WHERE (patterns ='^61198600.*' OR patterns ='^6119860.*' OR patterns ='^611986.*' OR patterns ='^61198.*' OR patterns ='^6119.*' OR patterns ='^611.*' OR patterns ='^61.*' OR patterns ='^6.*' OR patterns ='--') AND status = 0 AND pricelist_id = 1 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information =================== 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 3 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 7335503421 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Balance : 100 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 0 [0:prepaid,1:postpaid] 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 1 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] ======================================================== 2019-03-23 13:17:06.023685 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 100 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information =================== 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 0 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Code : 61198600 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Destination : Local 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Initial Increment : 60 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Increment : 60 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 3 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================ 2019-03-23 13:17:06.023685 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 100 minutes 2019-03-23 13:17:06.023685 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT 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 WHERE accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="61198600" limit 1 2019-03-23 13:17:06.023685 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLLOCAL] Caller ID Translation Starts 2019-03-23 13:17:06.023685 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLLOCAL] Caller ID Translation Ends 2019-03-23 13:17:06.023685 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Generated XML:
2019-03-23 13:17:06.023685 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f0da0207f30 released. Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 parsing [default->61198600] continue=false Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Regex (PASS) [61198600] destination_number(61198600) =~ /61198600/ break=on-false Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(effective_destination_number=61198600) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action sched_hangup(+6000 normal_clearing) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(callstart=2019-03-23 07:47:06) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(hangup_after_bridge=true) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(continue_on_fail=!USER_BUSY) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(account_id=3) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(parent_id=0) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(entity_id=3) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(call_processed=internal) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(call_direction=local) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(accountname=TATA TRUNK) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(origination_rates=ID:0|CODE:61198600|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:60|RATEGROUP:1|MARKUP:0|ACCID:3) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action export(is_recording=1) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action export(media_bug_answer_req=true) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action export(RECORD_STEREO=true) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action export(record_sample_rate=8000) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action export(execute_on_answer=record_session $${recordings_dir}/${strftime(%Y-%m-%d-%H:%M:%S)}_7335503421.wav) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(original_caller_id_name=918144659796) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(original_caller_id_number=918144659796) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(effective_caller_id_name=918144659796) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(effective_caller_id_number=918144659796) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(calltype=LOCAL) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action set(receiver_accid=73) Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action bridge([leg_timeout=30]user/61198600@${domain_name}) |--- Dialplan: Processing recursive conditions level:1 [61198600_recur_1] require-nested=TRUE |--- Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Regex (PASS) [61198600_recur_1] ${cond(${user_data 61198600@${domain_name} param vm-enabled} == true ? YES : NO)}(YES) =~ /^YES$/ break=on-false |--- Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action answer() |--- Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action export(voicemail_alternate_greet_id=61198600) |--- Dialplan: sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Action voicemail(default $${domain_name} 61198600) 2019-03-23 13:17:06.023685 [DEBUG] switch_core_state_machine.c:286 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State Change CS_ROUTING -> CS_EXECUTE 2019-03-23 13:17:06.023685 [DEBUG] switch_core_state_machine.c:643 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State ROUTING going to sleep 2019-03-23 13:17:06.023685 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_EXECUTE (Cur 3 Tot 4058) 2019-03-23 13:17:06.023685 [DEBUG] switch_core_state_machine.c:650 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State EXECUTE 2019-03-23 13:17:06.023685 [DEBUG] mod_sofia.c:198 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 SOFIA EXECUTE 2019-03-23 13:17:06.023685 [DEBUG] switch_core_state_machine.c:328 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Standard EXECUTE EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(effective_destination_number=61198600) 2019-03-23 13:17:06.023685 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [effective_destination_number]=[61198600] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 sched_hangup(+6000 normal_clearing) 2019-03-23 13:17:06.023685 [DEBUG] switch_scheduler.c:249 Added task 36 switch_ivr_schedule_hangup (3aab0159-764e-4466-8881-cb6227188c0e) to run at 1553333226 EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(callstart=2019-03-23 07:47:06) 2019-03-23 13:17:06.023685 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [callstart]=[2019-03-23 07:47:06] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(hangup_after_bridge=true) 2019-03-23 13:17:06.023685 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [hangup_after_bridge]=[true] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(continue_on_fail=!USER_BUSY) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [continue_on_fail]=[!USER_BUSY] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(account_id=3) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [account_id]=[3] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(parent_id=0) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [parent_id]=[0] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(entity_id=3) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [entity_id]=[3] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(call_processed=internal) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [call_processed]=[internal] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(call_direction=local) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [call_direction]=[local] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(accountname=TATA TRUNK) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [accountname]=[TATA TRUNK] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(origination_rates=ID:0|CODE:61198600|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:60|RATEGROUP:1|MARKUP:0|ACCID:3) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [origination_rates]=[ID:0|CODE:61198600|DESTINATION:Local|CONNECTIONCOST:0|INCLUDEDSECONDS:0|COST:0|INC:60|INITIALBLOCK:60|RATEGROUP:1|MARKUP:0|ACCID:3] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 export(is_recording=1) 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [is_recording]=[1] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 export(media_bug_answer_req=true) 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [media_bug_answer_req]=[true] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 export(RECORD_STEREO=true) 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [RECORD_STEREO]=[true] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 export(record_sample_rate=8000) 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [record_sample_rate]=[8000] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 export(execute_on_answer=record_session /usr/local/freeswitch/recordings/2019-03-23-13:17:06_7335503421.wav) 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [execute_on_answer]=[record_session /usr/local/freeswitch/recordings/2019-03-23-13:17:06_7335503421.wav] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(original_caller_id_name=918144659796) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [original_caller_id_name]=[918144659796] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(original_caller_id_number=918144659796) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [original_caller_id_number]=[918144659796] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(effective_caller_id_name=918144659796) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [effective_caller_id_name]=[918144659796] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(effective_caller_id_number=918144659796) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [effective_caller_id_number]=[918144659796] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(calltype=LOCAL) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [calltype]=[LOCAL] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 set(receiver_accid=73) 2019-03-23 13:17:06.043708 [DEBUG] mod_dptools.c:1548 SET sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [receiver_accid]=[73] EXECUTE sofia/SIP_TTL_DEL/918144659796@10.50.180.1 bridge([leg_timeout=30]user/61198600@103.54.24.21) 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [is_recording]=[1] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [media_bug_answer_req]=[true] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [RECORD_STEREO]=[true] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [record_sample_rate]=[8000] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [execute_on_answer]=[record_session /usr/local/freeswitch/recordings/2019-03-23-13:17:06_7335503421.wav] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-03-23 13:17:06.043708 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [is_recording]=[1] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [media_bug_answer_req]=[true] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [RECORD_STEREO]=[true] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [record_sample_rate]=[8000] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_channel.c:1250 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 EXPORTING[export_vars] [execute_on_answer]=[record_session /usr/local/freeswitch/recordings/2019-03-23-13:17:06_7335503421.wav] to event 2019-03-23 13:17:06.043708 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables 2019-03-23 13:17:06.043708 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [error] cause: [USER_NOT_REGISTERED] 2019-03-23 13:17:06.043708 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2019-03-23 13:17:06.043708 [NOTICE] switch_ivr_originate.c:2851 Cannot create outgoing channel of type [user] cause: [USER_NOT_REGISTERED] 2019-03-23 13:17:06.043708 [DEBUG] switch_ivr_originate.c:3848 Originate Resulted in Error Cause: 606 [USER_NOT_REGISTERED] 2019-03-23 13:17:06.043708 [INFO] mod_dptools.c:3436 Originate Failed. Cause: USER_NOT_REGISTERED 2019-03-23 13:17:06.043708 [NOTICE] switch_channel.c:4844 Hangup sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [CS_EXECUTE] [USER_NOT_REGISTERED] 2019-03-23 13:17:06.043708 [DEBUG] switch_core_session.c:2815 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:650 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State EXECUTE going to sleep 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_HANGUP (Cur 3 Tot 4058) 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:850 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Callstate Change RINGING -> HANGUP 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:852 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State HANGUP 2019-03-23 13:17:06.043708 [DEBUG] mod_sofia.c:438 Channel sofia/SIP_TTL_DEL/918144659796@10.50.180.1 hanging up, cause: USER_NOT_REGISTERED 2019-03-23 13:17:06.043708 [DEBUG] mod_sofia.c:577 Responding to INVITE with: 480 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:60 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Standard HANGUP, cause: USER_NOT_REGISTERED 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:852 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State HANGUP going to sleep 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:619 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State Change CS_HANGUP -> CS_REPORTING 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_REPORTING (Cur 3 Tot 4058) 2019-03-23 13:17:06.043708 [DEBUG] switch_core_state_machine.c:938 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State REPORTING send 724 bytes to udp/[10.50.180.1]:5060 at 13:17:06.059982: ------------------------------------------------------------------------ SIP/2.0 480 Temporarily Unavailable Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKdnyddsnieciltdkbccdvdnnwy;Role=3;Hpt=8e72_36 Max-Forwards: 8 From: "918144659796";tag=aa2c106--3EG2502b6211e To: "1161198699" ;tag=vva12r0jyZ57D Call-ID: asbc1aef2502b63-0286-0105@10.162.193.6 CSeq: 19035 INVITE User-Agent: SIPOne Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Reason: SIP;cause=606;text="USER_NOT_REGISTERED" Content-Length: 0 Remote-Party-ID: "61198600" ;party=calling;privacy=off;screen=no ------------------------------------------------------------------------ 2019-03-23 13:17:06.043708 [INFO] mod_json_cdr.c:271 Process [3aab0159-764e-4466-8881-cb6227188c0e.cdr.json] 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:174 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Standard REPORTING, cause: USER_NOT_REGISTERED 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:938 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State REPORTING going to sleep 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:610 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State Change CS_REPORTING -> CS_DESTROY 2019-03-23 13:17:06.063697 [DEBUG] switch_core_session.c:1665 Session 4058 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Locked, Waiting on external entities 2019-03-23 13:17:06.063697 [NOTICE] switch_core_session.c:1683 Session 4058 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Ended 2019-03-23 13:17:06.063697 [NOTICE] switch_core_session.c:1687 Close Channel sofia/SIP_TTL_DEL/918144659796@10.50.180.1 [CS_DESTROY] 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:741 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) Running State Change CS_DESTROY (Cur 2 Tot 4058) 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:751 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State DESTROY 2019-03-23 13:17:06.063697 [DEBUG] mod_sofia.c:343 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 SOFIA DESTROY 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:181 sofia/SIP_TTL_DEL/918144659796@10.50.180.1 Standard DESTROY 2019-03-23 13:17:06.063697 [DEBUG] switch_core_state_machine.c:751 (sofia/SIP_TTL_DEL/918144659796@10.50.180.1) State DESTROY going to sleep recv 413 bytes from udp/[10.50.180.1]:5060 at 13:17:06.081357: ------------------------------------------------------------------------ ACK sip:61198600@10.50.180.1:5060;transport=udp;gw=GW_TTL_DEL SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKdnyddsnieciltdkbccdvdnnwy;Role=3;Hpt=8e72_36 Call-ID: asbc1aef2502b63-0286-0105@10.162.193.6 From: "918144659796";tag=aa2c106--3EG2502b6211e To: "1161198699";tag=vva12r0jyZ57D CSeq: 19035 ACK Max-Forwards: 70 Content-Length: 0 ------------------------------------------------------------------------ 2019-03-23 13:17:06.523736 [DEBUG] switch_scheduler.c:144 Deleting task 36 switch_ivr_schedule_hangup (3aab0159-764e-4466-8881-cb6227188c0e) 2019-03-23 13:17:10.183662 [WARNING] switch_core_state_machine.c:687 8d8b9db8-449a-4785-8c29-f129a263ad2d sofia/SIP_SHRISAI_INT/78007@103.54.24.21 Abandoned 2019-03-23 13:17:10.183662 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/SIP_SHRISAI_INT/78007@103.54.24.21 [CS_NEW] [WRONG_CALL_STATE] 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) Running State Change CS_HANGUP (Cur 2 Tot 4058) 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:850 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) Callstate Change DOWN -> HANGUP 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:852 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State HANGUP 2019-03-23 13:17:10.183662 [DEBUG] mod_sofia.c:438 Channel sofia/SIP_SHRISAI_INT/78007@103.54.24.21 hanging up, cause: WRONG_CALL_STATE 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:60 sofia/SIP_SHRISAI_INT/78007@103.54.24.21 Standard HANGUP, cause: WRONG_CALL_STATE 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:852 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State HANGUP going to sleep 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:619 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State Change CS_HANGUP -> CS_REPORTING 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) Running State Change CS_REPORTING (Cur 2 Tot 4058) 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:938 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State REPORTING 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:174 sofia/SIP_SHRISAI_INT/78007@103.54.24.21 Standard REPORTING, cause: WRONG_CALL_STATE 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:938 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State REPORTING going to sleep 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:610 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State Change CS_REPORTING -> CS_DESTROY 2019-03-23 13:17:10.183662 [DEBUG] switch_core_session.c:1665 Session 4056 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) Locked, Waiting on external entities 2019-03-23 13:17:10.183662 [NOTICE] switch_core_session.c:1683 Session 4056 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) Ended 2019-03-23 13:17:10.183662 [NOTICE] switch_core_session.c:1687 Close Channel sofia/SIP_SHRISAI_INT/78007@103.54.24.21 [CS_DESTROY] 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:741 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) Running State Change CS_DESTROY (Cur 1 Tot 4058) 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:751 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State DESTROY 2019-03-23 13:17:10.183662 [DEBUG] mod_sofia.c:343 sofia/SIP_SHRISAI_INT/78007@103.54.24.21 SOFIA DESTROY 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:181 sofia/SIP_SHRISAI_INT/78007@103.54.24.21 Standard DESTROY 2019-03-23 13:17:10.183662 [DEBUG] switch_core_state_machine.c:751 (sofia/SIP_SHRISAI_INT/78007@103.54.24.21) State DESTROY going to sleep send 461 bytes to udp/[10.50.180.1]:5060 at 13:17:10.260484: ------------------------------------------------------------------------ OPTIONS sip:10.50.180.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1;rport;branch=z9hG4bKD13aKceXvejUS Max-Forwards: 70 From: ;tag=X53S4KHpU8UtS To: Call-ID: b4ab4fdb-c7e2-1237-fc88-000c29acab0e CSeq: 2109056 OPTIONS User-Agent: SIPOne Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 413 bytes from udp/[10.50.180.1]:5060 at 13:17:10.279538: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.180.1;branch=z9hG4bKD13aKceXvejUS;received=10.50.182.26;rport=5060 Call-ID: b4ab4fdb-c7e2-1237-fc88-000c29acab0e From: ;tag=X53S4KHpU8UtS To: ;tag=yavw4kw4 CSeq: 2109056 OPTIONS Allow: OPTIONS,NOTIFY,SUBSCRIBE,INFO,REGISTER,MESSAGE,REFER,UPDATE,PRACK,BYE,CANCEL,ACK,INVITE Supported: privacy,precondition,100rel Content-Length: 0 ------------------------------------------------------------------------ 2019-03-23 13:17:12.603663 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'SIP_SHRISAI_INT' for [61198699@sip.saispacenet.com] from ip 103.54.26.90 2019-03-23 13:17:12.703659 [WARNING] sofia_reg.c:1737 SIP auth failure (REGISTER) on sofia profile 'SIP_SHRISAI_INT' for [61198699@sip.saispacenet.com] from ip 103.54.26.90 2019-03-23 13:17:14.683670 [WARNING] switch_core_state_machine.c:687 52b1277e-8237-4d84-bdbf-281ddd1abc19 sofia/SIP_SHRISAI_INT/1618@103.54.24.21 Abandoned 2019-03-23 13:17:14.683670 [NOTICE] switch_core_state_machine.c:690 Hangup sofia/SIP_SHRISAI_INT/1618@103.54.24.21 [CS_NEW] [WRONG_CALL_STATE] 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Running State Change CS_HANGUP (Cur 1 Tot 4058) 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:850 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Callstate Change DOWN -> HANGUP 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:852 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State HANGUP 2019-03-23 13:17:14.683670 [DEBUG] mod_sofia.c:438 Channel sofia/SIP_SHRISAI_INT/1618@103.54.24.21 hanging up, cause: WRONG_CALL_STATE 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:60 sofia/SIP_SHRISAI_INT/1618@103.54.24.21 Standard HANGUP, cause: WRONG_CALL_STATE 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:852 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State HANGUP going to sleep 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:619 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State Change CS_HANGUP -> CS_REPORTING 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Running State Change CS_REPORTING (Cur 1 Tot 4058) 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:938 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State REPORTING 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:174 sofia/SIP_SHRISAI_INT/1618@103.54.24.21 Standard REPORTING, cause: WRONG_CALL_STATE 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:938 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State REPORTING going to sleep 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:610 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State Change CS_REPORTING -> CS_DESTROY 2019-03-23 13:17:14.683670 [DEBUG] switch_core_session.c:1665 Session 4057 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Locked, Waiting on external entities 2019-03-23 13:17:14.683670 [NOTICE] switch_core_session.c:1683 Session 4057 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Ended 2019-03-23 13:17:14.683670 [NOTICE] switch_core_session.c:1687 Close Channel sofia/SIP_SHRISAI_INT/1618@103.54.24.21 [CS_DESTROY] 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:741 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) Running State Change CS_DESTROY (Cur 0 Tot 4058) 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:751 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State DESTROY 2019-03-23 13:17:14.683670 [DEBUG] mod_sofia.c:343 sofia/SIP_SHRISAI_INT/1618@103.54.24.21 SOFIA DESTROY 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:181 sofia/SIP_SHRISAI_INT/1618@103.54.24.21 Standard DESTROY 2019-03-23 13:17:14.683670 [DEBUG] switch_core_state_machine.c:751 (sofia/SIP_SHRISAI_INT/1618@103.54.24.21) State DESTROY going to sleep send 461 bytes to udp/[10.50.180.1]:5060 at 13:17:20.273338: ------------------------------------------------------------------------ OPTIONS sip:10.50.180.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1;rport;branch=z9hG4bKeaX3m7y0SQ8DN Max-Forwards: 70 From: ;tag=yeXj6e2SrHjDN To: Call-ID: baa32651-c7e2-1237-fc88-000c29acab0e CSeq: 2109057 OPTIONS User-Agent: SIPOne Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 413 bytes from udp/[10.50.180.1]:5060 at 13:17:20.292845: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.180.1;branch=z9hG4bKeaX3m7y0SQ8DN;received=10.50.182.26;rport=5060 Call-ID: baa32651-c7e2-1237-fc88-000c29acab0e From: ;tag=yeXj6e2SrHjDN To: ;tag=ydbnxe4x CSeq: 2109057 OPTIONS Allow: OPTIONS,NOTIFY,SUBSCRIBE,INFO,REGISTER,MESSAGE,REFER,UPDATE,PRACK,BYE,CANCEL,ACK,INVITE Supported: privacy,precondition,100rel Content-Length: 0 ------------------------------------------------------------------------ 2019-03-23 13:17:24.903710 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'SIP_SHRISAI_INT' for [61198699@sip.saispacenet.com] from ip 103.54.26.90 2019-03-23 13:17:25.043679 [WARNING] sofia_reg.c:1737 SIP auth failure (REGISTER) on sofia profile 'SIP_SHRISAI_INT' for [61198699@sip.saispacenet.com] from ip 103.54.26.90 send 724 bytes to udp/[10.50.180.1]:5060 at 13:17:26.606324: ------------------------------------------------------------------------ REGISTER sip:10.50.180.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1;rport;branch=z9hG4bKFKpvp2F4p0y0g Max-Forwards: 70 From: ;tag=XZD2F9eH6S6mS To: Call-ID: 94917812-97e5-4436-8da3-b062d3250600 CSeq: 2108889 REGISTER Contact: Expires: 300 User-Agent: SIPOne Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Authorization: Digest username="61198600", realm="SIP-61198600", nonce="3d12913e9c59d5bed72504870e4b2d30", algorithm=MD5, uri="sip:10.50.180.1;transport=udp", response="473c365ac83b273fbf90ef014e8b8ea9" Content-Length: 0 ------------------------------------------------------------------------ recv 462 bytes from udp/[10.50.180.1]:5060 at 13:17:26.633052: ------------------------------------------------------------------------ SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.50.180.1;branch=z9hG4bKFKpvp2F4p0y0g;received=10.50.182.26;rport=5060 Call-ID: 94917812-97e5-4436-8da3-b062d3250600 From: ;tag=XZD2F9eH6S6mS To: ;tag=knskesib CSeq: 2108889 REGISTER User-Agent: ZTE-SoftSwitch WWW-Authenticate: Digest realm="SIP-61198600",nonce="0cfdbedcbc080b0987d270d19833bb93",ZTE-ID=14136c2a8c3d7dcea8a62c59fda33da9 Content-Length: 0 ------------------------------------------------------------------------ send 724 bytes to udp/[10.50.180.1]:5060 at 13:17:26.633288: ------------------------------------------------------------------------ REGISTER sip:10.50.180.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1;rport;branch=z9hG4bKgvFNrX07K9mKc Max-Forwards: 70 From: ;tag=XZD2F9eH6S6mS To: Call-ID: 94917812-97e5-4436-8da3-b062d3250600 CSeq: 2108890 REGISTER Contact: Expires: 300 User-Agent: SIPOne Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Authorization: Digest username="61198600", realm="SIP-61198600", nonce="0cfdbedcbc080b0987d270d19833bb93", algorithm=MD5, uri="sip:10.50.180.1;transport=udp", response="331942235744440fe56c2e3f0fecf4b7" Content-Length: 0 ------------------------------------------------------------------------ recv 510 bytes from udp/[10.50.180.1]:5060 at 13:17:26.661048: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.180.1;branch=z9hG4bKgvFNrX07K9mKc;received=10.50.182.26;rport=5060 Call-ID: 94917812-97e5-4436-8da3-b062d3250600 From: ;tag=XZD2F9eH6S6mS To: ;tag=skc4biyi CSeq: 2108890 REGISTER User-Agent: ZTE-SoftSwitch Date: Sat, 23 Mar 2019 13:17:26 GMT Contact: ;expires=300 X-ZTE-ServerHost: , Content-Length: 0 ------------------------------------------------------------------------ send 461 bytes to udp/[10.50.180.1]:5060 at 13:17:30.287297: ------------------------------------------------------------------------ OPTIONS sip:10.50.180.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1;rport;branch=z9hG4bKH58DtrHBHjB6Q Max-Forwards: 70 From: ;tag=ZQpB89jXNt8Zg To: Call-ID: c09b29ba-c7e2-1237-fc88-000c29acab0e CSeq: 2109058 OPTIONS User-Agent: SIPOne Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 413 bytes from udp/[10.50.180.1]:5060 at 13:17:30.307021: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.180.1;branch=z9hG4bKH58DtrHBHjB6Q;received=10.50.182.26;rport=5060 Call-ID: c09b29ba-c7e2-1237-fc88-000c29acab0e From: ;tag=ZQpB89jXNt8Zg To: ;tag=atbs4yen CSeq: 2109058 OPTIONS Allow: OPTIONS,NOTIFY,SUBSCRIBE,INFO,REGISTER,MESSAGE,REFER,UPDATE,PRACK,BYE,CANCEL,ACK,INVITE Supported: privacy,precondition,100rel Content-Length: 0 ------------------------------------------------------------------------ 2019-03-23 13:17:37.143683 [WARNING] sofia_reg.c:1792 SIP auth challenge (REGISTER) on sofia profile 'SIP_SHRISAI_INT' for [61198699@sip.saispacenet.com] from ip 103.54.26.90 2019-03-23 13:17:37.243672 [WARNING] sofia_reg.c:1737 SIP auth failure (REGISTER) on sofia profile 'SIP_SHRISAI_INT' for [61198699@sip.saispacenet.com] from ip 103.54.26.90 send 461 bytes to udp/[10.50.180.1]:5060 at 13:17:40.301004: ------------------------------------------------------------------------ OPTIONS sip:10.50.180.1;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1;rport;branch=z9hG4bKje26UK2eeU1rK Max-Forwards: 70 From: ;tag=00F49430j3yjc To: Call-ID: c6932113-c7e2-1237-fc88-000c29acab0e CSeq: 2109059 OPTIONS User-Agent: SIPOne Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY Supported: path, replaces Allow-Events: talk, hold, conference, refer Content-Length: 0 ------------------------------------------------------------------------ recv 413 bytes from udp/[10.50.180.1]:5060 at 13:17:40.320295: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.180.1;branch=z9hG4bKje26UK2eeU1rK;received=10.50.182.26;rport=5060 Call-ID: c6932113-c7e2-1237-fc88-000c29acab0e From: ;tag=00F49430j3yjc To: ;tag=sixkcivi CSeq: 2109059 OPTIONS Allow: OPTIONS,NOTIFY,SUBSCRIBE,INFO,REGISTER,MESSAGE,REFER,UPDATE,PRACK,BYE,CANCEL,ACK,INVITE Supported: privacy,precondition,100rel Content-Length: 0 ------------------------------------------------------------------------