From Sharp Meerkat, 5 Years ago, written in FreeSWITCH.
- view diff
Embed
  1. span style="color: cornflowerblue; font-weight: bold;"> 2018-10-30 14:12:19.046978 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/27104760604@sbc.brightnetworks.co.za [122d8ce4-d465-47b3-aa00-6a77cd84a0d7]
  2. 2018-10-30 14:12:19.046978 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_NEW (Cur 1 Tot 6)
  3. 2018-10-30 14:12:19.046978 [DEBUG] sofia.c:10080 sofia/internal/27104760604@sbc.brightnetworks.co.za receiving invite from 10.192.0.82:59138 version: 1.8.2 -3-a98a958ac3 64bit
  4. 2018-10-30 14:12:19.046978 [DEBUG] sofia.c:10206 1 acls to check for proxy
  5. 2018-10-30 14:12:19.046978 [DEBUG] sofia.c:10211 checking 10.192.0.82 against acl proxies
  6. 2018-10-30 14:12:19.046978 [DEBUG] sofia.c:10251 IP 10.192.0.82 Rejected by acl "proxies". Falling back to Digest auth.
  7. 2018-10-30 14:12:19.046978 [WARNING] sofia_reg.c:1793 SIP auth challenge (INVITE) on sofia profile 'internal' for [0112340142@sbc.brightnetworks.co.za] from ip 10.192.0.82
  8. 2018-10-30 14:12:19.046978 [DEBUG] switch_core_state_machine.c:603 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State NEW
  9. 2018-10-30 14:12:19.046978 [DEBUG] sofia.c:2413 detaching session 122d8ce4-d465-47b3-aa00-6a77cd84a0d7
  10. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:2522 Re-attaching to session 122d8ce4-d465-47b3-aa00-6a77cd84a0d7
  11. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:10080 sofia/internal/27104760604@sbc.brightnetworks.co.za receiving invite from 10.192.0.82:59138 version: 1.8.2 -3-a98a958ac3 64bit
  12. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:10206 1 acls to check for proxy
  13. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:10211 checking 10.192.0.82 against acl proxies
  14. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:10251 IP 10.192.0.82 Rejected by acl "proxies". Falling back to Digest auth.
  15. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:11388 Setting NAT mode based on via received
  16. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:7291 Channel sofia/internal/27104760604@sbc.brightnetworks.co.za entering state [received][100]
  17. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:7301 Remote SDP:
  18. v=0
  19. o=- 1 2 IN IP4 192.168.16.55
  20. s=CounterPath eyeBeam 1.5
  21. c=IN IP4 192.168.16.55
  22. t=0 0
  23. m=audio 35140 RTP/AVP 18 101
  24. a=fmtp:18 annexb=no
  25. a=rtpmap:101 telephone-event/8000
  26. a=fmtp:101 0-15
  27. a=alt:1 1 : o1ILEpNa eXMn2R4/ 192.168.16.55 35140
  28. a=x-rtp-session-id:4A8532B61C1F4ADC934D59760B14A10B
  29. m=video 48068 RTP/AVP 125 115 34
  30. a=rtpmap:125 H264/90000
  31. a=fmtp:125 profile-level-id=42e015; max-br=4000; max-mbps=19800
  32. a=rtpmap:115 H263-1998/90000
  33. a=fmtp:115 QCIF=1 MAXBR=10485
  34. a=rtpmap:34 H263/90000
  35. a=fmtp:34 QCIF=1 MAXBR=10485
  36. a=alt:1 1 : 03rz/Rlv 0BWxB52R 192.168.16.55 48068
  37. a=x-rtp-session-id:0690740DF0294703B4B878CBC2CB6B2B
  38.  
  39. 2018-10-30 14:12:19.186978 [DEBUG] sofia.c:7695 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State Change CS_NEW -> CS_INIT
  40. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_INIT (Cur 1 Tot 6)
  41. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State INIT
  42. 2018-10-30 14:12:19.186978 [DEBUG] mod_sofia.c:93 sofia/internal/27104760604@sbc.brightnetworks.co.za SOFIA INIT
  43. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:40 sofia/internal/27104760604@sbc.brightnetworks.co.za Standard INIT
  44. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State Change CS_INIT -> CS_ROUTING
  45. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State INIT going to sleep
  46. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_ROUTING (Cur 1 Tot 6)
  47. 2018-10-30 14:12:19.186978 [DEBUG] switch_channel.c:2249 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Callstate Change DOWN -> RINGING
  48. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State ROUTING
  49. 2018-10-30 14:12:19.186978 [DEBUG] mod_sofia.c:154 sofia/internal/27104760604@sbc.brightnetworks.co.za SOFIA ROUTING
  50. 2018-10-30 14:12:19.186978 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  51. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='a6e32d84-0d4c-476a-a0a8-1f4b229027f6']
  52. 2018-10-30 14:12:19.186978 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account a6e32d84-0d4c-476a-a0a8-1f4b229027f6 (balance = -968.139016)
  53. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:236 sofia/internal/27104760604@sbc.brightnetworks.co.za Standard ROUTING
  54. 2018-10-30 14:12:19.186978 [INFO] mod_dialplan_xml.c:637 Processing 27104760604 <27104760604>->0112340142 in context cgrtbilling
  55. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za parsing [cgrtbilling->unloop] continue=false
  56. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
  57. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
  58. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za parsing [cgrtbilling->call_debug] continue=true
  59. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (FAIL) [call_debug] ${call_debug}(false) =~ /^true$/ break=never
  60. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za parsing [cgrtbilling->block_account] continue=false
  61. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (FAIL) [block_account] destination_number(0112340142) =~ /^(block_account)$/ break=on-false
  62. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za parsing [cgrtbilling->check_auth] continue=true
  63. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (PASS) [check_auth] ${sip_authorized}(true) =~ /^true$/ break=never
  64. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za parsing [cgrtbilling->calls_from_converged] continue=true
  65. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (FAIL) [calls_from_converged] ${sip_req_host}(sbc.brightnetworks.co.za) =~ /^sbc.convergedgroup.co.za$/ break=on-false
  66. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za parsing [cgrtbilling->calls_from_tenants] continue=true
  67. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Regex (PASS) [calls_from_tenants] destination_number(0112340142) =~ /^(.*)$/ break=on-false
  68. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Action translate(${destination_number} sbc.convergedgroup.co.za-za)
  69. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Action set(destination_number=${translated})
  70. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Action set(outside_call=true)
  71. Dialplan: sofia/internal/27104760604@sbc.brightnetworks.co.za Action lua(cgrtbilling/cgrtbilling_v2.luac)
  72. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State Change CS_ROUTING -> CS_EXECUTE
  73. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State ROUTING going to sleep
  74. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_EXECUTE (Cur 1 Tot 6)
  75. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State EXECUTE
  76. 2018-10-30 14:12:19.186978 [DEBUG] mod_sofia.c:209 sofia/internal/27104760604@sbc.brightnetworks.co.za SOFIA EXECUTE
  77. 2018-10-30 14:12:19.186978 [DEBUG] switch_core_state_machine.c:328 sofia/internal/27104760604@sbc.brightnetworks.co.za Standard EXECUTE
  78. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za translate(0112340142 sbc.convergedgroup.co.za-za)
  79. 2018-10-30 14:12:19.186978 [DEBUG] mod_translate.c:128 translating [0112340142] against [sbc.convergedgroup.co.za-za] profile
  80. 2018-10-30 14:12:19.186978 [DEBUG] mod_translate.c:137 0112340142 =~ /^\+(\d+)$/
  81. 2018-10-30 14:12:19.186978 [DEBUG] mod_translate.c:137 0112340142 =~ /^00(\d{9,17})$/
  82. 2018-10-30 14:12:19.186978 [DEBUG] mod_translate.c:137 0112340142 =~ /^0(\d+)$/
  83. 2018-10-30 14:12:19.186978 [NOTICE] mod_translate.c:249 Translated: 27112340142
  84. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za set(destination_number=27112340142)
  85. 2018-10-30 14:12:19.186978 [DEBUG] mod_dptools.c:1598 SET sofia/internal/27104760604@sbc.brightnetworks.co.za [destination_number]=[27112340142]
  86. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za set(outside_call=true)
  87. 2018-10-30 14:12:19.186978 [DEBUG] mod_dptools.c:1598 SET sofia/internal/27104760604@sbc.brightnetworks.co.za [outside_call]=[true]
  88. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za lua(cgrtbilling/cgrtbilling_v2.luac)
  89. 2018-10-30 14:12:19.186978 [INFO] switch_cpp.cpp:1442 Destination_number: 27112340142<-----------
  90.  
  91. 2018-10-30 14:12:19.186978 [NOTICE] switch_cpp.cpp:1442 SELECT mc.id, mc.name, mc.account_type, mc.account_code, b.balance_uuid, b.value as balance, t.name as tenant,
  92.     mc.origination, mc.orig_credit_limit, mc.max_per_minute_rate as max_rate, mc.max_daily_spend, mc.play_audio_messages as play_msgs,
  93.     mc.orig_max_channels as max_channels, mc.orig_max_cps as max_cps, tc.max_call_length as max_duration, mc.enable_calls, mc.enabled
  94.     FROM management_client mc
  95.     INNER JOIN management_tenant t ON t.id = mc.tenant_id
  96.     INNER JOIN management_tenantconfiguration tc ON ( t.id = tc.tenant_id )
  97.     INNER JOIN management_clientbalances b ON mc.id = b.client_id
  98.     WHERE mc.account_code = '0823913044' AND b.balance_type = '*monetary' AND weight = '10'
  99. 2018-10-30 14:12:19.226953 [NOTICE] switch_cpp.cpp:1442 <-------> Enable calls: 1 -----
  100.  
  101. 2018-10-30 14:12:19.226953 [WARNING] switch_cpp.cpp:1442 <------- Getting Account Info for Client: Bright Office with account_code: 0823913044 ------->
  102.  
  103. 2018-10-30 14:12:19.226953 [NOTICE] switch_cpp.cpp:1442 SELECT mc.account_code, s.username, s.password, s.ip_address, s.caller_id_name as cid_name, s.caller_id_number as cid_number,
  104.     s.bypass_media as bymedia, s.pass_thru_caller_id, s.custom_sip_headers, c1.description as c1, c2.description as c2,
  105.     c3.description as c3, c4.description as c4, s.enabled
  106.     FROM management_sipaccount s
  107.     INNER JOIN management_client mc ON s.client_id = mc.id
  108.     LEFT OUTER JOIN configuration_codecpreference c1 ON s.codec1_id = c1.id
  109.     LEFT OUTER JOIN configuration_codecpreference c2 ON s.codec2_id = c2.id
  110.     LEFT OUTER JOIN configuration_codecpreference c3 ON s.codec3_id = c3.id
  111.     LEFT OUTER JOIN configuration_codecpreference c4 ON s.codec4_id = c4.id
  112.     WHERE  mc.id = '5473851498396115' AND s.username = '27104760604'AND s.enabled = 't'
  113. 2018-10-30 14:12:19.246992 [WARNING] switch_cpp.cpp:1442 elapsed time: 0.002857
  114.  
  115. 2018-10-30 14:12:19.246992 [WARNING] switch_cpp.cpp:1442 -------------> Geting Client Tariff Plan info ------------->
  116.  
  117. 2018-10-30 14:12:19.246992 [NOTICE] switch_cpp.cpp:1442 SELECT mt.tech_prefix, mt.tpb_id, t.name as tpb_name, mt.routing_plan_id, r.routing_type, r.allow_negative_profit
  118.       FROM management_tpballocation mt
  119.       INNER JOIN management_client mc ON mt.client_id = mc.id
  120.       INNER JOIN routing_routingplan r ON mt.routing_plan_id = r.id
  121.       INNER JOIN tariff_plans_tpb t ON t.id = mt.tpb_id
  122.       WHERE mc.account_code = '0823913044'
  123. 2018-10-30 14:12:19.246992 [INFO] switch_cpp.cpp:1442 <----------------------------------------------------->
  124. 2018-10-30 14:12:19.246992 [INFO] switch_cpp.cpp:1442 Trying without tech prefix
  125. 2018-10-30 14:12:19.246992 [INFO] switch_cpp.cpp:1442 Dialed number : 27112340142
  126. 2018-10-30 14:12:19.246992 [INFO] switch_cpp.cpp:1442 Tariff Plan Name : BRONZE
  127. 2018-10-30 14:12:19.246992 [INFO] switch_cpp.cpp:1442 <----------------------------------------------------->
  128.  
  129. 2018-10-30 14:12:19.246992 [WARNING] switch_cpp.cpp:1442 ------------  Getting Call cost for client  ------------
  130.  
  131. 2018-10-30 14:12:19.246992 [NOTICE] switch_cpp.cpp:1442 SELECT tp.code, tp.destination_name, tp.connect_fee, tp.rate, tp.rate_minimum, tp.rate_increment, tp.effective_date, tp.expiry_date, tp.enabled
  132.     FROM tariff_plans_rates tp
  133.     WHERE code @> '27112340142' AND tpb_id = '5465386174008112' AND tp.effective_date <= tp.expiry_date AND tp.expiry_date >= now()
  134.     ORDER BY CODE ASC LIMIT 1
  135. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 Code: 2711
  136. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(execute_on_answer=nibblebill adjust -0)
  137. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [execute_on_answer]=[nibblebill adjust -0]
  138. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('connect_fee', '0')
  139. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nibble_rate', '0.4')
  140. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nibble_minimum', '0.0066666666666667')
  141. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nibble_increment', '1')
  142. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nibble_account', 'A6E32D84-0D4C-476A-A0A8-1F4B229027F6')
  143. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_account', '0823913044')
  144. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('client_id', '5473851498396115')
  145. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_tenant', 'sbc.brightnetworks.co.za')
  146. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('nobal_amt', '-5000')
  147. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za nibblebill(heartbeat 60)
  148. 2018-10-30 14:12:19.266971 [WARNING] switch_core_session.c:1654 sofia/internal/27104760604@sbc.brightnetworks.co.za using scheduler due to bypass media or media is not established.
  149. 2018-10-30 14:12:19.266971 [DEBUG] switch_scheduler.c:249 Added task 10 switch_core_session_sched_heartbeat (122d8ce4-d465-47b3-aa00-6a77cd84a0d7) to run at 1540901599
  150. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_dept', ' ')
  151. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_site', ' ')
  152. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_extension', ' ')
  153. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_custom', ' ')
  154. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_subject', ' ')
  155. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_supplier', ' ')
  156. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_reqtype', 'POSTPAID')
  157. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('o_category', 'BRONZE')
  158. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('prefix', '2711')
  159. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('destination_name', 'SA National_2711')
  160. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('destination_number', '27112340142')
  161. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('tor', '*voice')
  162. 2018-10-30 14:12:19.266971 [WARNING] switch_cpp.cpp:1442 -------------> Removing unwanted SIP Headers ------------->
  163.  
  164. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za unset(sip_h_X-accountcode)
  165. 2018-10-30 14:12:19.266971 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-accountcode]
  166. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za unset(sip_h_X-username)
  167. 2018-10-30 14:12:19.266971 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-username]
  168. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za unset(sip_h_X-extension)
  169. 2018-10-30 14:12:19.266971 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-extension]
  170. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za unset(sip_h_X-dept)
  171. 2018-10-30 14:12:19.266971 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-dept]
  172. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za unset(sip_h_X-site)
  173. 2018-10-30 14:12:19.266971 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-site]
  174. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za unset(sip_h_X-custom)
  175. 2018-10-30 14:12:19.266971 [DEBUG] mod_dptools.c:1743 UNSET [sip_h_X-custom]
  176. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 Checking if 27112340142 is a DID <-------------
  177. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 SELECT status from management_did where did_number = '27112340142' and status != 'ported_out'
  178. 2018-10-30 14:12:19.266971 [WARNING] switch_cpp.cpp:1442 ------------  Getting LCR info  ------------
  179.  
  180. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 SELECT *
  181.     FROM (SELECT DISTINCT ON (t.name) t.name as tariff_plan, rt.id AS rt_id, r.code, r.destination_name, r.connect_fee, r.rate, r.rate_minimum, r.rate_increment,
  182.     t.prefix, t.suffix, t.quality, t.reliability, t.client_id AS carrier_id, r.effective_date, r.expiry_date, t.gw1_id, t.gw2_id, t.gw3_id, r.enabled
  183.     FROM tariff_plans_rates r
  184.     INNER JOIN tariff_plans_tpb t ON r.tpb_id = t.id
  185.     INNER JOIN routing_routingplantariff rt ON rt.tariff_plan_id = t.id
  186.     WHERE rt.routing_plan_id = '5465431039104489' AND code @> '27112340142' AND enabled = 't' AND (CURRENT_TIMESTAMP BETWEEN r.effective_date AND r.expiry_date)
  187.     ORDER BY t.name, code ASC, "effective_date" DESC) n
  188.     ORDER BY rate ASC, quality DESC, reliability DESC
  189. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ------------------  No of routes found: 1  ------------------
  190. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ------->                   lcr_profile: lc
  191. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ------->     lcr_allow_negative_profit: 1.00
  192.  
  193. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 -----------------------  Route [ 1 of 1 ] -----------------------
  194. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->             lcr_code[1]: 2711
  195. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 -------> lcr_destination_name[1]: SA National_2711
  196. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->      lcr_connect_fee[1]: 0.00000
  197. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->             lcr_rate[1]: 0.16000
  198. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->     lcr_rate_minimum[1]: 1
  199. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->   lcr_rate_increment[1]: 1
  200. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->           lcr_prefix[1]:
  201. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->      lcr_tariff_plan[1]: PROVIDER_CONVERGED
  202. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->       lcr_carrier_id[1]: 5465400089730286
  203. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->   lcr_effective_date[1]: 2018-10-19 02:03:38
  204. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->      lcr_expiry_date[1]: 2028-10-19 02:03:38
  205. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 ------->          lcr_enabled[1]: 1
  206. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ------------------------------------------------------------------
  207.  
  208. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('sip_h_X-cid', '6532fb1e7b72f826ZDljYjFhNzA3YTM3YWRhZmExODVhZGRhYTdlMTMwNDI.')
  209. 2018-10-30 14:12:19.266971 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: sip_h_X-cid 6532fb1e7b72f826ZDljYjFhNzA3YTM3YWRhZmExODVhZGRhYTdlMTMwNDI.<-------------
  210. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ----------> Call progressing through the diaplan <----------
  211.  
  212. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 --------------------- Customer rate: 0.4
  213. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ----------- Negative profit allowed: 1.00%
  214. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 ---- Maximum provider rate for call: 0.404
  215.  
  216. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za limit(hash sbc.brightnetworks.co.za 27104760604 20 5/1 !CLIENT_LIMIT_EXCEEDED)
  217. 2018-10-30 14:12:19.266971 [DEBUG] switch_limit.c:126 incr called: sbc.brightnetworks.co.za_27104760604 max:20, interval:0
  218. 2018-10-30 14:12:19.266971 [DEBUG] mod_hash.c:196 Usage for sbc.brightnetworks.co.za_27104760604 is now 1/20
  219. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 Limit for this client: 27104760604 is 20 Concurrent and 5 CPS <-----------
  220.  
  221. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 -------------> Provider_1 rate: 0.16000 <-----------
  222. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 <-------------------------------------------------->
  223. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 SELECT mc.account_code, mc.account_type, mc.orig_credit_limit, mb.balance_uuid
  224.             FROM management_client mc
  225.             INNER JOIN management_clientbalances mb ON mc.id = mb.client_id
  226.             WHERE mb.client_id = '5465400089730286' AND mb.balance_type = '*monetary' AND mb.weight=10 AND mb.enabled = 't'
  227.  
  228. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 -----------------> Trying LCR Route = 1 of 1 <-----------------
  229.  
  230. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(execute_on_answer=nibblebill adjust -0)
  231. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [execute_on_answer]=[nibblebill adjust -0]
  232. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:connect_fee=0.00000)
  233. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [connect_fee]=[0.00000]
  234. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:nibble_rate=0.16000)
  235. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [nibble_rate]=[0.16000]
  236. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:nibble_minimum=0.0026666666666667)
  237. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [nibble_minimum]=[0.0026666666666667]
  238. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:nibble_increment=1)
  239. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [nibble_increment]=[1]
  240. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:nibble_account=CCE9A0C3-B568-424A-A254-90474CED1E60)
  241. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [nibble_account]=[CCE9A0C3-B568-424A-A254-90474CED1E60]
  242. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_account=5428397474)
  243. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_account]=[5428397474]
  244. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_tenant=sbc.brightnetworks.co.za)
  245. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_tenant]=[sbc.brightnetworks.co.za]
  246. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_dept= )
  247. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_dept]=[ ]
  248. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_site= )
  249. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_site]=[ ]
  250. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_extension= )
  251. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_extension]=[ ]
  252. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_custom= )
  253. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_custom]=[ ]
  254. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_subject= )
  255. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_subject]=[ ]
  256. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_supplier= )
  257. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_supplier]=[ ]
  258. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_reqtype=POSTPAID)
  259. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_reqtype]=[POSTPAID]
  260. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:o_category=PROVIDER_CONVERGED)
  261. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [o_category]=[PROVIDER_CONVERGED]
  262. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:prefix=2711)
  263. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [prefix]=[2711]
  264. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:destination_name=SA National_2711)
  265. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [destination_name]=[SA National_2711]
  266. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:destination_number=27112340142)
  267. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [destination_number]=[27112340142]
  268. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:tor=*voice)
  269. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [tor]=[*voice]
  270. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:nobal_amt=-30000)
  271. 2018-10-30 14:12:19.266971 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [nobal_amt]=[-30000]
  272. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za nibblebill(heartbeat 60)
  273. 2018-10-30 14:12:19.266971 [WARNING] switch_core_session.c:1654 sofia/internal/27104760604@sbc.brightnetworks.co.za using scheduler due to bypass media or media is not established.
  274. 2018-10-30 14:12:19.266971 [DEBUG] switch_scheduler.c:249 Added task 11 switch_core_session_sched_heartbeat (122d8ce4-d465-47b3-aa00-6a77cd84a0d7) to run at 1540901599
  275. 2018-10-30 14:12:19.266971 [DEBUG] switch_scheduler.c:144 Deleting task 10 switch_core_session_sched_heartbeat (122d8ce4-d465-47b3-aa00-6a77cd84a0d7)
  276. 2018-10-30 14:12:19.266971 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('execute_on_answer', 'sched_hangup +7200 allotted_timeout')
  277. 2018-10-30 14:12:19.266971 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: execute_on_answer sched_hangup +7200 allotted_timeout<-------------
  278. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 SELECT lead_strip, tail_strip, add_prefix, add_suffix, terminator_id
  279.         FROM routing_providernumbertranslation
  280.         WHERE routing_providernumbertranslation.terminator_id = '5465400089730286' AND substring('27112340142',1,length(lead_strip)) = lead_strip
  281. 2018-10-30 14:12:19.266971 [NOTICE] switch_cpp.cpp:1442 SELECT name AS g_name, proxy, sip_cid_type, ignore_early_media, leg_timeout, channels, enabled
  282.     FROM management_providergateway g
  283.     WHERE id = '5465413257484362' AND enabled = 't'
  284. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za limit(hash sbc.brightnetworks.co.za Bright-Converged 100!BEARERCAPABILITY_NOTAVAIL)
  285. 2018-10-30 14:12:19.266971 [DEBUG] switch_limit.c:126 incr called: sbc.brightnetworks.co.za_Bright-Converged max:100, interval:0
  286. 2018-10-30 14:12:19.266971 [DEBUG] mod_hash.c:196 Usage for sbc.brightnetworks.co.za_Bright-Converged is now 1/100
  287. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 Maximum concurrent calls for Gateway 1: Bright-Converged = 100 <-----------
  288.  
  289. 2018-10-30 14:12:19.266971 [INFO] switch_cpp.cpp:1442 Now Bridging the call to ...[originate_continue_on_timeout=true,sip_cid_type=pid,ignore_early_media=false][leg_progress_timeout=20]sofia/gateway/Bright-Converged/27112340142 <-----------
  290.  
  291. 2018-10-30 14:12:19.306937 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('effective_caller_id_name', '27104760604')
  292. 2018-10-30 14:12:19.306937 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: effective_caller_id_name 27104760604<-------------
  293. 2018-10-30 14:12:19.306937 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('effective_caller_id_number', '27104760604')
  294. 2018-10-30 14:12:19.306937 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('call_direction', 'outbound')
  295. 2018-10-30 14:12:19.306937 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: call_direction outbound<-------------
  296. 2018-10-30 14:12:19.306937 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('continue_on_fail', 'true')
  297. 2018-10-30 14:12:19.306937 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: continue_on_fail true<-------------
  298. 2018-10-30 14:12:19.306937 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('hangup_after_bridge', 'true')
  299. 2018-10-30 14:12:19.306937 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: hangup_after_bridge true<-------------
  300. 2018-10-30 14:12:19.306937 [DEBUG] switch_cpp.cpp:755 CoreSession::setVariable('ignore_display_updates', 'true')
  301. 2018-10-30 14:12:19.306937 [WARNING] switch_cpp.cpp:1442 ------->122d8ce4-d465-47b3-aa00-6a77cd84a0d7 - WS CALL Set value :.....: ignore_display_updates true<-------------
  302. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(codec_string=G729)
  303. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [codec_string]=[G729]
  304. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(nolocal:absolute_codec_string=G729)
  305. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) (REMOTE ONLY) [absolute_codec_string]=[G729]
  306. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(fax_enable_t38_request=true)
  307. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [fax_enable_t38_request]=[true]
  308. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za export(fax_enable_t38=true)
  309. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1296 EXPORT (export_vars) [fax_enable_t38]=[true]
  310. EXECUTE sofia/internal/27104760604@sbc.brightnetworks.co.za bridge([originate_continue_on_timeout=true,sip_cid_type=pid,ignore_early_media=false][leg_progress_timeout=20]sofia/gateway/Bright-Converged/27112340142)
  311. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [execute_on_answer]=[sched_hangup +7200 allotted_timeout] to event
  312. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [execute_on_answer]=[sched_hangup +7200 allotted_timeout] to event
  313. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [connect_fee]=[0.00000] to event
  314. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [nibble_rate]=[0.16000] to event
  315. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [nibble_minimum]=[0.0026666666666667] to event
  316. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [nibble_increment]=[1] to event
  317. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [nibble_account]=[CCE9A0C3-B568-424A-A254-90474CED1E60] to event
  318. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_account]=[5428397474] to event
  319. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_tenant]=[sbc.brightnetworks.co.za] to event
  320. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_dept]=[ ] to event
  321. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_site]=[ ] to event
  322. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_extension]=[ ] to event
  323. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_custom]=[ ] to event
  324. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_subject]=[ ] to event
  325. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_supplier]=[ ] to event
  326. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_reqtype]=[POSTPAID] to event
  327. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [o_category]=[PROVIDER_CONVERGED] to event
  328. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [prefix]=[2711] to event
  329. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [destination_name]=[SA National_2711] to event
  330. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [destination_number]=[27112340142] to event
  331. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [tor]=[*voice] to event
  332. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [nobal_amt]=[-30000] to event
  333. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [codec_string]=[G729] to event
  334. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [absolute_codec_string]=[G729] to event
  335. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [fax_enable_t38_request]=[true] to event
  336. 2018-10-30 14:12:19.306937 [DEBUG] switch_channel.c:1250 sofia/internal/27104760604@sbc.brightnetworks.co.za EXPORTING[export_vars] [fax_enable_t38]=[true] to event
  337. 2018-10-30 14:12:19.306937 [DEBUG] switch_ivr_originate.c:2204 Parsing global variables
  338. 2018-10-30 14:12:19.306937 [DEBUG] switch_ivr_originate.c:2749 Parsing session specific variables
  339. 2018-10-30 14:12:19.306937 [NOTICE] switch_channel.c:1104 New Channel sofia/external/27112340142 [c57d428f-7703-4c48-afe1-ba215b216b3e]
  340. 2018-10-30 14:12:19.306937 [DEBUG] mod_sofia.c:5028 (sofia/external/27112340142) State Change CS_NEW -> CS_INIT
  341. 2018-10-30 14:12:19.306937 [DEBUG] switch_ivr_originate.c:3065 sofia/external/27112340142 Setting leg progress timeout to 20
  342. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:584 (sofia/external/27112340142) Running State Change CS_INIT (Cur 2 Tot 7)
  343. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:627 (sofia/external/27112340142) State INIT
  344. 2018-10-30 14:12:19.306937 [DEBUG] mod_sofia.c:93 sofia/external/27112340142 SOFIA INIT
  345. 2018-10-30 14:12:19.306937 [DEBUG] sofia_glue.c:1299 sofia/external/27112340142 sending invite version: 1.8.2 -3-a98a958ac3 64bit
  346. Local SDP:
  347. v=0
  348. o=cgrtbilling 1540872245 1540872246 IN IP4 154.118.252.37
  349. s=cgrtbilling
  350. c=IN IP4 154.118.252.37
  351. t=0 0
  352. m=audio 29294 RTP/AVP 18 101
  353. a=rtpmap:18 G729/8000
  354. a=fmtp:18 annexb=no
  355. a=rtpmap:101 telephone-event/8000
  356. a=fmtp:101 0-16
  357. a=silenceSupp:off - - - -
  358. a=ptime:20
  359. a=sendrecv
  360.  
  361. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:40 sofia/external/27112340142 Standard INIT
  362. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:48 (sofia/external/27112340142) State Change CS_INIT -> CS_ROUTING
  363. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:627 (sofia/external/27112340142) State INIT going to sleep
  364. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:584 (sofia/external/27112340142) Running State Change CS_ROUTING (Cur 2 Tot 7)
  365. 2018-10-30 14:12:19.306937 [DEBUG] sofia.c:7291 Channel sofia/external/27112340142 entering state [calling][0]
  366. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:643 (sofia/external/27112340142) State ROUTING
  367. 2018-10-30 14:12:19.306937 [DEBUG] mod_sofia.c:154 sofia/external/27112340142 SOFIA ROUTING
  368. 2018-10-30 14:12:19.306937 [DEBUG] switch_ivr_originate.c:67 (sofia/external/27112340142) State Change CS_ROUTING -> CS_CONSUME_MEDIA
  369. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:506 Attempting to bill at $0.16000 per minute to account CCE9A0C3-B568-424A-A254-90474CED1E60
  370. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:518 Not billing CCE9A0C3-B568-424A-A254-90474CED1E60 - call is not in answered state
  371. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  372. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='CCE9A0C3-B568-424A-A254-90474CED1E60']
  373. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account CCE9A0C3-B568-424A-A254-90474CED1E60 (balance = -670.539500)
  374. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:523 Comparing -670.539500 to hangup balance of -30000.000000, taking into account minimum charge of 0.002667
  375. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  376. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='CCE9A0C3-B568-424A-A254-90474CED1E60']
  377. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account CCE9A0C3-B568-424A-A254-90474CED1E60 (balance = -670.539500)
  378. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:643 (sofia/external/27112340142) State ROUTING going to sleep
  379. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:584 (sofia/external/27112340142) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 7)
  380. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:662 (sofia/external/27112340142) State CONSUME_MEDIA
  381. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:506 Attempting to bill at $0.16000 per minute to account CCE9A0C3-B568-424A-A254-90474CED1E60
  382. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:518 Not billing CCE9A0C3-B568-424A-A254-90474CED1E60 - call is not in answered state
  383. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  384. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='CCE9A0C3-B568-424A-A254-90474CED1E60']
  385. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account CCE9A0C3-B568-424A-A254-90474CED1E60 (balance = -670.539500)
  386. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:523 Comparing -670.539500 to hangup balance of -30000.000000, taking into account minimum charge of 0.002667
  387. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  388. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='CCE9A0C3-B568-424A-A254-90474CED1E60']
  389. 2018-10-30 14:12:19.306937 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account CCE9A0C3-B568-424A-A254-90474CED1E60 (balance = -670.539500)
  390. 2018-10-30 14:12:19.306937 [DEBUG] sofia.c:7291 Channel sofia/external/27112340142 entering state [calling][0]
  391. 2018-10-30 14:12:19.306937 [WARNING] switch_core_session.c:1654 sofia/external/27112340142 using scheduler due to bypass media or media is not established.
  392. 2018-10-30 14:12:19.306937 [DEBUG] switch_scheduler.c:249 Added task 12 switch_core_session_sched_heartbeat (c57d428f-7703-4c48-afe1-ba215b216b3e) to run at 1540901569
  393. 2018-10-30 14:12:19.306937 [DEBUG] switch_core_state_machine.c:662 (sofia/external/27112340142) State CONSUME_MEDIA going to sleep
  394. 2018-10-30 14:12:19.366940 [DEBUG] sofia.c:7291 Channel sofia/external/27112340142 entering state [terminated][500]
  395. 2018-10-30 14:12:19.366940 [NOTICE] sofia.c:8484 Hangup sofia/external/27112340142 [CS_CONSUME_MEDIA] [NORMAL_TEMPORARY_FAILURE]
  396. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:584 (sofia/external/27112340142) Running State Change CS_HANGUP (Cur 2 Tot 7)
  397. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:847 (sofia/external/27112340142) Callstate Change DOWN -> HANGUP
  398. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:849 (sofia/external/27112340142) State HANGUP
  399. 2018-10-30 14:12:19.366940 [DEBUG] mod_sofia.c:449 Channel sofia/external/27112340142 hanging up, cause: NORMAL_TEMPORARY_FAILURE
  400. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:506 Attempting to bill at $0.16000 per minute to account CCE9A0C3-B568-424A-A254-90474CED1E60
  401. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:518 Not billing CCE9A0C3-B568-424A-A254-90474CED1E60 - call is not in answered state
  402. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  403. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='CCE9A0C3-B568-424A-A254-90474CED1E60']
  404. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account CCE9A0C3-B568-424A-A254-90474CED1E60 (balance = -670.539500)
  405. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:523 Comparing -670.539500 to hangup balance of -30000.000000, taking into account minimum charge of 0.002667
  406. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  407. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='CCE9A0C3-B568-424A-A254-90474CED1E60']
  408. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account CCE9A0C3-B568-424A-A254-90474CED1E60 (balance = -670.539500)
  409. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:60 sofia/external/27112340142 Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
  410. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:849 (sofia/external/27112340142) State HANGUP going to sleep
  411. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:619 (sofia/external/27112340142) State Change CS_HANGUP -> CS_REPORTING
  412. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:584 (sofia/external/27112340142) Running State Change CS_REPORTING (Cur 2 Tot 7)
  413. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:935 (sofia/external/27112340142) State REPORTING
  414. 2018-10-30 14:12:19.366940 [INFO] mod_json_cdr.c:271 Process [c57d428f-7703-4c48-afe1-ba215b216b3e.cdr.json]
  415. 2018-10-30 14:12:19.366940 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/c57d428f-7703-4c48-afe1-ba215b216b3e.cdr.json]
  416. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:174 sofia/external/27112340142 Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
  417. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:935 (sofia/external/27112340142) State REPORTING going to sleep
  418. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:610 (sofia/external/27112340142) State Change CS_REPORTING -> CS_DESTROY
  419. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_session.c:1714 Session 7 (sofia/external/27112340142) Locked, Waiting on external entities
  420. 2018-10-30 14:12:19.366940 [DEBUG] switch_ivr_originate.c:3941 Originate Resulted in Error Cause: 41 [NORMAL_TEMPORARY_FAILURE]
  421. 2018-10-30 14:12:19.366940 [NOTICE] switch_core_session.c:1732 Session 7 (sofia/external/27112340142) Ended
  422. 2018-10-30 14:12:19.366940 [NOTICE] switch_core_session.c:1736 Close Channel sofia/external/27112340142 [CS_DESTROY]
  423. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:738 (sofia/external/27112340142) Running State Change CS_DESTROY (Cur 1 Tot 7)
  424. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:748 (sofia/external/27112340142) State DESTROY
  425. 2018-10-30 14:12:19.366940 [DEBUG] mod_sofia.c:354 sofia/external/27112340142 SOFIA DESTROY
  426. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:181 sofia/external/27112340142 Standard DESTROY
  427. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:748 (sofia/external/27112340142) State DESTROY going to sleep
  428. 2018-10-30 14:12:19.366940 [INFO] mod_dptools.c:3518 Originate Failed.  Cause: NORMAL_TEMPORARY_FAILURE
  429. 2018-10-30 14:12:19.366940 [WARNING] switch_cpp.cpp:1442 The call failed with NORMAL_TEMPORARY_FAILURE <-----------
  430.  
  431. 2018-10-30 14:12:19.366940 [DEBUG] switch_cpp.cpp:1187 sofia/internal/27104760604@sbc.brightnetworks.co.za destroy/unlink session from object
  432. 2018-10-30 14:12:19.366940 [NOTICE] switch_core_state_machine.c:385 sofia/internal/27104760604@sbc.brightnetworks.co.za has executed the last dialplan instruction, hanging up.
  433. 2018-10-30 14:12:19.366940 [NOTICE] switch_core_state_machine.c:387 Hangup sofia/internal/27104760604@sbc.brightnetworks.co.za [CS_EXECUTE] [NORMAL_CLEARING]
  434. 2018-10-30 14:12:19.366940 [DEBUG] mod_hash.c:297 Usage for sbc.brightnetworks.co.za_Bright-Converged is now 0
  435. 2018-10-30 14:12:19.366940 [DEBUG] mod_hash.c:297 Usage for sbc.brightnetworks.co.za_27104760604 is now 0
  436. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State EXECUTE going to sleep
  437. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_HANGUP (Cur 1 Tot 7)
  438. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:847 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Callstate Change RINGING -> HANGUP
  439. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State HANGUP
  440. 2018-10-30 14:12:19.366940 [DEBUG] mod_sofia.c:443 sofia/internal/27104760604@sbc.brightnetworks.co.za Overriding SIP cause 480 with 500 from the other leg
  441. 2018-10-30 14:12:19.366940 [DEBUG] mod_sofia.c:449 Channel sofia/internal/27104760604@sbc.brightnetworks.co.za hanging up, cause: NORMAL_CLEARING
  442. 2018-10-30 14:12:19.366940 [DEBUG] mod_sofia.c:588 Responding to INVITE with: 500
  443. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:506 Attempting to bill at $0.4 per minute to account A6E32D84-0D4C-476A-A0A8-1F4B229027F6
  444. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:518 Not billing A6E32D84-0D4C-476A-A0A8-1F4B229027F6 - call is not in answered state
  445. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  446. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='A6E32D84-0D4C-476A-A0A8-1F4B229027F6']
  447. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account A6E32D84-0D4C-476A-A0A8-1F4B229027F6 (balance = -968.139016)
  448. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:523 Comparing -968.139016 to hangup balance of -5000.000000, taking into account minimum charge of 0.006667
  449. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:422 Doing lookup query
  450. [SELECT value AS nibble_balance FROM management_clientbalances WHERE balance_uuid='A6E32D84-0D4C-476A-A0A8-1F4B229027F6']
  451. 2018-10-30 14:12:19.366940 [DEBUG] mod_nibblebill.c:430 Retrieved current balance for account A6E32D84-0D4C-476A-A0A8-1F4B229027F6 (balance = -968.139016)
  452. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:60 sofia/internal/27104760604@sbc.brightnetworks.co.za Standard HANGUP, cause: NORMAL_CLEARING
  453. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:849 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State HANGUP going to sleep
  454. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State Change CS_HANGUP -> CS_REPORTING
  455. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_REPORTING (Cur 1 Tot 7)
  456. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State REPORTING
  457. 2018-10-30 14:12:19.366940 [INFO] mod_json_cdr.c:271 Process [122d8ce4-d465-47b3-aa00-6a77cd84a0d7.cdr.json]
  458. 2018-10-30 14:12:19.366940 [INFO] mod_json_cdr.c:275 Log to disk [/var/log/freeswitch/json_cdr/122d8ce4-d465-47b3-aa00-6a77cd84a0d7.cdr.json]
  459. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:174 sofia/internal/27104760604@sbc.brightnetworks.co.za Standard REPORTING, cause: NORMAL_CLEARING
  460. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:935 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State REPORTING going to sleep
  461. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State Change CS_REPORTING -> CS_DESTROY
  462. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_session.c:1714 Session 6 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Locked, Waiting on external entities
  463. 2018-10-30 14:12:19.366940 [NOTICE] switch_core_session.c:1732 Session 6 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Ended
  464. 2018-10-30 14:12:19.366940 [NOTICE] switch_core_session.c:1736 Close Channel sofia/internal/27104760604@sbc.brightnetworks.co.za [CS_DESTROY]
  465. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:738 (sofia/internal/27104760604@sbc.brightnetworks.co.za) Running State Change CS_DESTROY (Cur 0 Tot 7)
  466. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State DESTROY
  467. 2018-10-30 14:12:19.366940 [DEBUG] mod_sofia.c:354 sofia/internal/27104760604@sbc.brightnetworks.co.za SOFIA DESTROY
  468. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:181 sofia/internal/27104760604@sbc.brightnetworks.co.za Standard DESTROY
  469. 2018-10-30 14:12:19.366940 [DEBUG] switch_core_state_machine.c:748 (sofia/internal/27104760604@sbc.brightnetworks.co.za) State DESTROY going to sleep
  470. 2018-10-30 14:12:19.786983 [DEBUG] switch_scheduler.c:144 Deleting task 11 switch_core_session_sched_heartbeat (122d8ce4-d465-47b3-aa00-6a77cd84a0d7)
  471. 2018-10-30 14:12:19.786983 [DEBUG] switch_scheduler.c:144 Deleting task 12 switch_core_session_sched_heartbeat (c57d428f-7703-4c48-afe1-ba215b216b3e)
  472. freeswitch@freeswitch>
  473.