From Chocolate Hog, 5 Years ago, written in FreeSWITCH.
- view diff
Embed
  1. recv 850 bytes from udp/[10.50.180.1]:5060 at 14:30:03.109615:
  2.    ------------------------------------------------------------------------
  3.    INVITE sip:12345600@10.50.180.1:5060;transport=udp;gw=SIPGATEWAY SIP/2.0
  4.    Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKmsk0anzmkc0tak7wks7wsc0mz;Role=3;Hpt=8eb2_36
  5.    Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6
  6.    From: "123456789012"<sip:123456789012@10.50.180.1>;tag=aa2c106-oCxV22c986e11e
  7.    To: "1112345699"<sip:1112345699@10.50.180.1>
  8.    CSeq: 2685 INVITE
  9.   Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,INFO,REFER,NOTIFY,SUBSCRIBE,PRACK,UPDATE
  10.    Contact: <sip:123456789012@10.50.180.1:5060;Hpt=8eb2_16;CxtId=4;TRC=ffffffff-ffffffff>
  11.    Max-Forwards: 8
  12.    Supported: 100rel
  13.    User-Agent: ZTE Softswitch/1.0.0
  14.    P-Early-Media: gated
  15.    Content-Length: 176
  16.    Content-Type: application/sdp
  17.  
  18.    v=0
  19.    o=- 2287 28331 IN IP4 10.50.180.1
  20.    s=SBC call
  21.    c=IN IP4 10.50.180.1
  22.    t=0 0
  23.    m=audio 29112 RTP/AVP 8 0 18 97
  24.    a=rtpmap:97 telephone-event/8000
  25.    a=fmtp:97 0-15
  26.    a=ptime:20
  27.    ------------------------------------------------------------------------
  28. send 348 bytes to udp/[10.50.180.1]:5060 at 14:30:03.110166:
  29.    ------------------------------------------------------------------------
  30.    SIP/2.0 100 Trying
  31.    Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKmsk0anzmkc0tak7wks7wsc0mz;Role=3;Hpt=8eb2_36
  32.    From: "123456789012"<sip:123456789012@10.50.180.1>;tag=aa2c106-oCxV22c986e11e
  33.    To: "1112345699"<sip:1112345699@10.50.180.1>
  34.    Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6
  35.    CSeq: 2685 INVITE
  36.    User-Agent: SIPOne
  37.    Content-Length: 0
  38.  
  39.    ------------------------------------------------------------------------
  40. 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]
  41. 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)
  42. 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
  43. 2019-03-21 14:30:03.090731 [DEBUG] sofia.c:9989 IP 10.50.180.1 Approved by acl "default[]". Access Granted.
  44. 2019-03-21 14:30:03.090731 [DEBUG] sofia.c:7084 Channel sofia/SIP_SIPGATE/123456789012@10.50.180.1 entering state [received][100]
  45. 2019-03-21 14:30:03.090731 [DEBUG] sofia.c:7094 Remote SDP:
  46. v=0
  47. o=- 2287 28331 IN IP4 10.50.180.1
  48. s=SBC call
  49. c=IN IP4 10.50.180.1
  50. t=0 0
  51. m=audio 29112 RTP/AVP 8 0 18 97
  52. a=rtpmap:97 telephone-event/8000
  53. a=fmtp:97 0-15
  54. a=ptime:20
  55.  
  56. 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]
  57. 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]
  58. 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
  59. 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]
  60. 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
  61. 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]
  62. 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]
  63. 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]
  64. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 97@8000
  65. 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
  66. 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
  67. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 97@8000
  68. 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
  69. 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
  70. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:603 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State NEW
  71. 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)
  72. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:627 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State INIT
  73. 2019-03-21 14:30:03.110620 [DEBUG] mod_sofia.c:90 sofia/SIP_SIPGATE/123456789012@10.50.180.1 SOFIA INIT
  74. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:40 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Standard INIT
  75. 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
  76. 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
  77. 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)
  78. 2019-03-21 14:30:03.110620 [DEBUG] switch_channel.c:2249 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Callstate Change DOWN -> RINGING
  79. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:643 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State ROUTING
  80. 2019-03-21 14:30:03.110620 [DEBUG] mod_sofia.c:143 sofia/SIP_SIPGATE/123456789012@10.50.180.1 SOFIA ROUTING
  81. 2019-03-21 14:30:03.110620 [DEBUG] switch_core_state_machine.c:236 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Standard ROUTING
  82. 2019-03-21 14:30:03.110620 [INFO] mod_dialplan_xml.c:637 Processing 123456789012 <123456789012>->12345600 in context default
  83. 2019-03-21 14:30:03.110620 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f5b38229de0 Connected.
  84. 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')
  85. 2019-03-21 14:30:03.110620 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 12345600
  86. 2019-03-21 14:30:03.110620 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number  : 123456789012 / 123456789012
  87. 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
  88. 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
  89. 2019-03-21 14:30:03.110620 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : local
  90. 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
  91. 2019-03-21 14:30:03.110620 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 7565734248]
  92. 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
  93. 2019-03-21 14:30:03.130631 [WARNING] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] [7565734248] Insufficent balance (0) to make calls..!!
  94. 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
  95. 2019-03-21 14:30:03.130631 [DEBUG] switch_cpp.cpp:1365 [ASTPP] Generated XML:
  96. <?xml version="1.0" encoding="UTF-8" standalone="no"?>
  97. <document type="freeswitch/xml">
  98. <section name="dialplan" description="ASTPP Dialplan">
  99. <context name="default">
  100. <extension name="12345600">
  101. <condition field="destination_number" expression="12345600">
  102. <action application="log" data="WARNING Accountcode  doesn't have sufficiant fund!!"/>
  103. <action application="playback" data="/usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav"/>
  104. <action application="set" data="original_caller_id_name=123456789012"/>
  105. <action application="set" data="original_caller_id_number=123456789012"/>
  106. <action application="set" data="error_cdr=1"/>
  107. <action application="set" data="callstart=2019-03-21 09:00:03"/>
  108. <action application="set" data="account_id=4"/>
  109. <action application="set" data="call_direction=outbound"/>
  110. <action application="set" data="sip_ignore_remote_cause=true"/>
  111. <action application="set" data="call_processed=internal"/>
  112. <action application="set" data="effective_destination_number=12345600"/>
  113. <action application="set" data="last_bridge_hangup_cause=NO_SUFFICIENT_FUND"/>
  114. <action application="hangup" data="NO_SUFFICIENT_FUND"/>
  115. </condition>
  116. </extension>
  117. </context>
  118. </section>
  119. </document>
  120. 2019-03-21 14:30:03.130631 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f5b38229de0 released.
  121. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 parsing [default->12345600] continue=false
  122. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Regex (PASS) [12345600] destination_number(12345600) =~ /12345600/ break=on-false
  123. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action log(WARNING Accountcode  doesn't have sufficiant fund!!)
  124. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action playback(/usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav)
  125. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(original_caller_id_name=123456789012)
  126. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(original_caller_id_number=123456789012)
  127. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(error_cdr=1)
  128. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(callstart=2019-03-21 09:00:03)
  129. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(account_id=4)
  130. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(call_direction=outbound)
  131. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(sip_ignore_remote_cause=true)
  132. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(call_processed=internal)
  133. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(effective_destination_number=12345600)
  134. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action set(last_bridge_hangup_cause=NO_SUFFICIENT_FUND)
  135. Dialplan: sofia/SIP_SIPGATE/123456789012@10.50.180.1 Action hangup(NO_SUFFICIENT_FUND)
  136. 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
  137. 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
  138. 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)
  139. 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:650 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) State EXECUTE
  140. 2019-03-21 14:30:03.130631 [DEBUG] mod_sofia.c:198 sofia/SIP_SIPGATE/123456789012@10.50.180.1 SOFIA EXECUTE
  141. 2019-03-21 14:30:03.130631 [DEBUG] switch_core_state_machine.c:328 sofia/SIP_SIPGATE/123456789012@10.50.180.1 Standard EXECUTE
  142. EXECUTE sofia/SIP_SIPGATE/123456789012@10.50.180.1 log(WARNING Accountcode  doesn't have sufficiant fund!!)
  143. 2019-03-21 14:30:03.130631 [WARNING] mod_dptools.c:1742 Accountcode  doesn't have sufficiant fund!!
  144. 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
  145. 2019-03-21 14:30:03.130631 [INFO] switch_core_session.c:2649 Sending early media
  146. 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
  147. 2019-03-21 14:30:03.130631 [DEBUG] switch_rtp.c:4133 Not using a timer
  148. 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
  149. 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
  150. 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
  151. 2019-03-21 14:30:03.130631 [DEBUG] mod_sofia.c:2364 Ring SDP:
  152. v=0
  153. o=FreeSWITCH 1553140269 1553140270 IN IP4 103.54.24.21
  154. s=FreeSWITCH
  155. c=IN IP4 103.54.24.21
  156. t=0 0
  157. m=audio 18534 RTP/AVP 8 97
  158. a=rtpmap:8 PCMA/8000
  159. a=rtpmap:97 telephone-event/8000
  160. a=fmtp:97 0-16
  161. a=ptime:20
  162. a=sendrecv
  163.  
  164. 2019-03-21 14:30:03.130631 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/SIP_SIPGATE/123456789012@10.50.180.1!
  165. 2019-03-21 14:30:03.130631 [DEBUG] switch_channel.c:3474 (sofia/SIP_SIPGATE/123456789012@10.50.180.1) Callstate Change RINGING -> EARLY
  166. EXECUTE sofia/SIP_SIPGATE/123456789012@10.50.180.1 playback(/usr/local/freeswitch/sounds/en/us/callie/astpp-not-enough-credit.wav)
  167. send 987 bytes to udp/[10.50.180.1]:5060 at 14:30:03.145832:
  168.    ------------------------------------------------------------------------
  169.    SIP/2.0 183 Session Progress
  170.    Via: SIP/2.0/UDP 10.50.180.1:5060;branch=z9hG4bKmsk0anzmkc0tak7wks7wsc0mz;Role=3;Hpt=8eb2_36
  171.    From: "123456789012"<sip:123456789012@10.50.180.1>;tag=aa2c106-oCxV22c986e11e
  172.    To: "1112345699" <sip:1112345699@10.50.180.1>;tag=rNKN2DtBDtNae
  173.    Call-ID: asbc0ee622c986f-0286-0105@10.162.193.6
  174.    CSeq: 2685 INVITE
  175.    Contact: <sip:1112345699@10.50.180.1:5060;transport=udp>
  176.    User-Agent: SIPOne
  177.    Accept: application/sdp
  178.   Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, NOTIFY
  179.    Supported: path, replaces
  180.    Allow-Events: talk, hold, conference, refer
  181.    Content-Type: application/sdp
  182.    Content-Disposition: session
  183.    Content-Length: 217
  184.    Remote-Party-ID: "12345600" <sip:12345600@10.50.180.1>;party=calling;privacy=off;screen=no
  185.  
  186.    v=0
  187.    o=FreeSWITCH 1553140269 1553140270 IN IP4 103.54.24.21
  188.    s=FreeSWITCH
  189.    c=IN IP4 103.54.24.21
  190.    t=0 0
  191.    m=audio 18534 RTP/AVP 8 97
  192.    a=rtpmap:8 PCMA/8000
  193.    a=rtpmap:97 telephone-event/8000
  194.    a=fmtp:97 0-16
  195.    a=ptime:20
  196.    ------------------------------------------------------------------------
  197. 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
  198. 2019-03-21 14:30:03.130631 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
  199. 2019-03-21 14:30:03.130631 [DEBUG] sofia.c:7084 Channel sofia/SIP_SIPGATE/123456789012@10.50.180.1 entering state [early][183]
  200.