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"<sip:123456789012@10.50.180.1>;tag=aa2c106-oCxV22c986e11e
To: "1112345699"<sip:1112345699@10.50.180.1>
CSeq: 2685 INVITE
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,REFER,NOTIFY,SUBSCRIBE,PRACK,UPDATE
Contact: <sip:123456789012@10.50.180.1:5060;Hpt=8eb2_16;CxtId=4;TRC=ffffffff-ffffffff>
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"<sip:123456789012@10.50.180.1>;tag=aa2c106-oCxV22c986e11e
To: "1112345699"<sip:1112345699@10.50.180.1>
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:
<?xml version="1.0" encoding="UTF-8" standalone="no"?>
<document type="freeswitch/xml">
<section name="dialplan" description="ASTPP Dialplan">
<context name="default">
<extension name="12345600">
<condition field="destination_number" expression="12345600">
<action application="log" data="WARNING Accountcode doesn't have sufficiant fund!!"/>
<action application="playback" data="/usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav"/>
<action application="set" data="original_caller_id_name=123456789012"/>
<action application="set" data="original_caller_id_number=123456789012"/>
<action application="set" data="error_cdr=1"/>
<action application="set" data="callstart=2019-03-21 09:00:03"/>
<action application="set" data="account_id=4"/>
<action application="set" data="call_direction=outbound"/>
<action application="set" data="sip_ignore_remote_cause=true"/>
<action application="set" data="call_processed=internal"/>
<action application="set" data="effective_destination_number=12345600"/>
<action application="set" data="last_bridge_hangup_cause=NO_SUFFICIENT_FUND"/>
<action application="hangup" data="NO_SUFFICIENT_FUND"/>
</condition>
</extension>
</context>
</section>
</document>
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"<sip:123456789012@10.50.180.1>;tag=aa2c106-oCxV22c986e11e
To: "1112345699" <sip:1112345699@10.50.180.1>;tag=rNKN2DtBDtNae
Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6
CSeq: 2685 INVITE
Contact: <sip:1112345699@10.50.180.1:5060;transport=udp>
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" <sip:12345600@10.50.180.1>;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]