recv 850 bytes from udp/[10.50.180.1]:5060 at 14:30:03.109615: ------------------------------------------------------------------------ INVITE sip:12345600@10.50.180.1:5060;transport=udp;gw=SIPGATEWAY SIP/2.0 Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKmsk0anzmkc0tak7wks7wsc0mz;Role=3;Hpt=8eb2_36 Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6 From: "123456789012";tag=aa2c106-oCxV22c986e11e To: "1112345699" CSeq: 2685 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=- 2287 28331 IN IP4 10.50.180.1 s=SBC call c=IN IP4 10.50.180.1 t=0 0 m=audio 29112 RTP/AVP 8 0 18 97 a=rtpmap:97 telephone-event/8000 a=fmtp:97 0-15 a=ptime:20 ------------------------------------------------------------------------ send 348 bytes to udp/[10.50.180.1]:5060 at 14:30:03.110166: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKmsk0anzmkc0tak7wks7wsc0mz;Role=3;Hpt=8eb2_36 From: "123456789012";tag=aa2c106-oCxV22c986e11e To: "1112345699" Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6 CSeq: 2685 INVITE User-Agent: SIPOne Content-Length: 0 ------------------------------------------------------------------------ 2019-03-21 14:30:03.090731 [NOTICE] switch_channel.c:1104 New Channel sofia/SIP_SIPGATE/123456789012@10.50.180.1 [cd7c336b-02c5-43a9-8203-182236b1d6ea] 2019-03-21 14:30:03.090731 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Running State Change CS_NEW (Cur 1 Tot 29) 2019-03-21 14:30:03.090731 [DEBUG] sofia.c:9873 sofia/SIP_SIPGATE/123456789012@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-21 14:30:03.090731 [DEBUG] sofia.c:9989 IP 10.50.180.1 Approved by acl "default[]". Access Granted. 2019-03-21 14:30:03.090731 [DEBUG] sofia.c:7084 Channel sofia/SIP_SIPGATE/123456789012@10.50.180.1 entering state [received][100] 2019-03-21 14:30:03.090731 [DEBUG] sofia.c:7094 Remote SDP: v=0 o=- 2287 28331 IN IP4 10.50.180.1 s=SBC call c=IN IP4 10.50.180.1 t=0 0 m=audio 29112 RTP/AVP 8 0 18 97 a=rtpmap:97 telephone-event/8000 a=fmtp:97 0-15 a=ptime:20 2019-03-21 14:30:03.090731 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-03-21 14:30:03.090731 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-03-21 14:30:03.090731 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 2019-03-21 14:30:03.090731 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 2019-03-21 14:30:03.090731 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1] 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1] 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 97@8000 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:3061 Set Codec sofia/SIP_SIPGATE/123456789012@10.50.180.1 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 2019-03-21 14:30:03.110620 [DEBUG] switch_core_codec.c:111 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Original read codec set to PCMA:8 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 97@8000 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4767 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Set 2833 dtmf send payload to 97 recv payload to 97 2019-03-21 14:30:03.110620 [DEBUG] sofia.c:7507 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State Change CS_NEW -> CS_INIT 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:603 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State NEW 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Running State Change CS_INIT (Cur 1 Tot 29) 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:627 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State INIT 2019-03-21 14:30:03.110620 [DEBUG] mod_sofia.c:90 sofia/SIP_SIPGATE/123456789012@10.50.180.1 SOFIA INIT 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:40 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Standard INIT 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:48 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State Change CS_INIT -> CS_ROUTING 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:627 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State INIT going to sleep 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Running State Change CS_ROUTING (Cur 1 Tot 29) 2019-03-21 14:30:03.110620 [DEBUG] switch_channel.c:2249 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Callstate Change DOWN -> RINGING 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:643 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State ROUTING 2019-03-21 14:30:03.110620 [DEBUG] mod_sofia.c:143 sofia/SIP_SIPGATE/123456789012@10.50.180.1 SOFIA ROUTING 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:236 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Standard ROUTING 2019-03-21 14:30:03.110620 [INFO] mod_dialplan_xml.c:637 Processing 123456789012 <123456789012>->12345600 in context default 2019-03-21 14:30:03.110620 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f5b38229de0 Connected. 2019-03-21 14:30:03.110620 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard') 2019-03-21 14:30:03.110620 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 12345600 2019-03-21 14:30:03.110620 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number : 123456789012 / 123456789012 2019-03-21 14:30:03.110620 [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 ="12345600" LIMIT 1 2019-03-21 14:30:03.110620 [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="12345600" limit 1 2019-03-21 14:30:03.110620 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : local 2019-03-21 14:30:03.110620 [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 "12345600" LIKE CONCAT(prefix,'%') ORDER BY LENGTH(prefix) DESC LIMIT 1 2019-03-21 14:30:03.110620 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 7565734248] 2019-03-21 14:30:03.110620 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "7565734248" OR id="7565734248") AND status=0 AND deleted=0 AND (expiry >= '2019-03-21 09:00:03' OR expiry = '0000-00-00 00:00:00') limit 1 2019-03-21 14:30:03.130631 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] [7565734248] Insufficent balance (0) to make calls..!! 2019-03-21 14:30:03.130631 [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 ='^12345600.*' 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-21 14:30:03.130631 [DEBUG] switch_cpp.cpp:1365 [ASTPP] Generated XML:
2019-03-21 14:30:03.130631 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f5b38229de0 released. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 parsing [default->12345600] continue=false Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Regex (PASS) [12345600] destination_number(12345600) =~ /12345600/ break=on-false Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action log(WARNING Accountcode doesn't have sufficiant fund!!) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action playback(/usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(original_caller_id_name=123456789012) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(original_caller_id_number=123456789012) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(error_cdr=1) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(callstart=2019-03-21 09:00:03) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(account_id=4) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(call_direction=outbound) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(sip_ignore_remote_cause=true) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(call_processed=internal) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(effective_destination_number=12345600) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(last_bridge_hangup_cause=NO_SUFFICIENT_FUND) Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action hangup(NO_SUFFICIENT_FUND) 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:286 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State Change CS_ROUTING -> CS_EXECUTE 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:643 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State ROUTING going to sleep 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:584 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Running State Change CS_EXECUTE (Cur 1 Tot 29) 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:650 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State EXECUTE 2019-03-21 14:30:03.130631 [DEBUG] mod_sofia.c:198 sofia/SIP_SIPGATE/123456789012@10.50.180.1 SOFIA EXECUTE 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:328 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Standard EXECUTE EXECUTE sofia/SIP_SIPGATE/123456789012@10.50.180.1 log(WARNING Accountcode doesn't have sufficiant fund!!) 2019-03-21 14:30:03.130631 [WARNING] mod_dptools.c:1742 Accountcode doesn't have sufficiant fund!! 2019-03-21 14:30:03.130631 [DEBUG] switch_core_session.c:2647 Application playback Requires media! pre_answering channel sofia/SIP_SIPGATE/123456789012@10.50.180.1 2019-03-21 14:30:03.130631 [INFO] switch_core_session.c:2649 Sending early media 2019-03-21 14:30:03.130631 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/SIP_SIPGATE/123456789012@10.50.180.1] 103.54.24.21 port 18534 -> 10.50.180.1 port 29112 codec: 8 ms: 20 2019-03-21 14:30:03.130631 [DEBUG] switch_rtp.c:4133 Not using a timer 2019-03-21 14:30:03.130631 [DEBUG] switch_core_media.c:7179 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Set 2833 dtmf send payload to 97 2019-03-21 14:30:03.130631 [DEBUG] switch_core_media.c:7186 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Set 2833 dtmf receive payload to 97 2019-03-21 14:30:03.130631 [DEBUG] switch_core_media.c:7209 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Set rtp dtmf delay to 40 2019-03-21 14:30:03.130631 [DEBUG] mod_sofia.c:2364 Ring SDP: v=0 o=FreeSWITCH 1553140269 1553140270 IN IP4 103.54.24.21 s=FreeSWITCH c=IN IP4 103.54.24.21 t=0 0 m=audio 18534 RTP/AVP 8 97 a=rtpmap:8 PCMA/8000 a=rtpmap:97 telephone-event/8000 a=fmtp:97 0-16 a=ptime:20 a=sendrecv 2019-03-21 14:30:03.130631 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/SIP_SIPGATE/123456789012@10.50.180.1! 2019-03-21 14:30:03.130631 [DEBUG] switch_channel.c:3474 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Callstate Change RINGING -> EARLY EXECUTE sofia/SIP_SIPGATE/123456789012@10.50.180.1 playback(/usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav) send 987 bytes to udp/[10.50.180.1]:5060 at 14:30:03.145832: ------------------------------------------------------------------------ SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKmsk0anzmkc0tak7wks7wsc0mz;Role=3;Hpt=8eb2_36 From: "123456789012";tag=aa2c106-oCxV22c986e11e To: "1112345699" ;tag=rNKN2DtBDtNae Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6 CSeq: 2685 INVITE Contact: 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 Content-Type: application/sdp Content-Disposition: session Content-Length: 217 Remote-Party-ID: "12345600" ;party=calling;privacy=off;screen=no v=0 o=FreeSWITCH 1553140269 1553140270 IN IP4 103.54.24.21 s=FreeSWITCH c=IN IP4 103.54.24.21 t=0 0 m=audio 18534 RTP/AVP 8 97 a=rtpmap:8 PCMA/8000 a=rtpmap:97 telephone-event/8000 a=fmtp:97 0-16 a=ptime:20 ------------------------------------------------------------------------ 2019-03-21 14:30:03.130631 [DEBUG] switch_core_file.c:342 File /usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav sample rate 16000 doesn't match requested rate 8000 2019-03-21 14:30:03.130631 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms 2019-03-21 14:30:03.130631 [DEBUG] sofia.c:7084 Channel sofia/SIP_SIPGATE/123456789012@10.50.180.1 entering state [early][183]