From Prashant Kumar, 1 Year ago, written in FreeSWITCH.
- view diff
Embed
  1. freeswitch@devangnewdeb11>
  2. freeswitch@devangnewdeb11>
  3. freeswitch@devangnewdeb11>
  4. 2022-07-12 12:04:19.636103 93.90% [NOTICE] switch_channel.c:1123 New Channel sofia/default/2357506173@alpha.astppbilling.org [613e403b-c406-45ba-a56d-5a322f5fc923]
  5. 2022-07-12 12:04:19.636103 93.90% [DEBUG] switch_core_state_machine.c:581 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_NEW (Cur 1 Tot 431)
  6. 2022-07-12 12:04:19.636103 93.90% [INFO] sofia.c:10462 sofia/default/2357506173@alpha.astppbilling.org receiving invite from 103.240.35.46:5062 version: 1.10.7 -release 64bit call-id: 887602120-5062-28@BJC.BGI.B.BGB
  7. 2022-07-12 12:04:19.636103 93.90% [DEBUG] sofia.c:10556 verifying acl "default" for ip/port 103.240.35.46:0.
  8. 2022-07-12 12:04:19.636103 93.90% [WARNING] sofia_reg.c:1861 SIP auth challenge (INVITE) on sofia profile 'default' for [*98@alpha.astppbilling.org] from ip 103.240.35.46
  9. 2022-07-12 12:04:19.636103 93.90% [DEBUG] switch_core_state_machine.c:600 (sofia/default/2357506173@alpha.astppbilling.org) State NEW
  10. 2022-07-12 12:04:19.636103 93.90% [DEBUG] sofia.c:2419 detaching session 613e403b-c406-45ba-a56d-5a322f5fc923
  11. 2022-07-12 12:04:19.816116 93.90% [DEBUG] sofia.c:2532 Re-attaching to session 613e403b-c406-45ba-a56d-5a322f5fc923
  12. 2022-07-12 12:04:19.816116 93.90% [INFO] sofia.c:10462 sofia/default/2357506173@alpha.astppbilling.org receiving invite from 103.240.35.46:5062 version: 1.10.7 -release 64bit call-id: 887602120-5062-28@BJC.BGI.B.BGB
  13. 2022-07-12 12:04:19.816116 93.90% [DEBUG] sofia.c:10556 verifying acl "default" for ip/port 103.240.35.46:0.
  14. 2022-07-12 12:04:19.816116 93.90% [DEBUG] sofia.c:7499 Channel sofia/default/2357506173@alpha.astppbilling.org entering state [received][100]
  15. 2022-07-12 12:04:19.816116 93.90% [DEBUG] sofia.c:7509 Remote SDP:
  16. v=0
  17. o=2357506173 8001 8000 IN IP4 103.240.35.46
  18. s=SIP Call
  19. c=IN IP4 103.240.35.46
  20. t=0 0
  21. m=audio 5008 RTP/AVP 0 8 18 9 2 101
  22. a=rtpmap:0 PCMU/8000
  23. a=rtpmap:8 PCMA/8000
  24. a=rtpmap:18 G729/8000
  25. a=fmtp:18 annexb=no
  26. a=rtpmap:9 G722/8000
  27. a=rtpmap:2 G726-32/8000
  28. a=rtpmap:101 telephone-event/8000
  29. a=fmtp:101 0-15
  30. a=ptime:20
  31.  
  32. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  33. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  34. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
  35. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  36. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5705 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
  37. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  38. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
  39. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
  40. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
  41. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
  42. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMA:8:8000:20:64000:1]
  43. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5650 Audio Codec Compare [G726-32:2:8000:20:0:1]/[PCMU:0:8000:20:64000:1]
  44. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5566 Set telephone-event payload to 101@8000
  45. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:3870 Set Codec sofia/default/2357506173@alpha.astppbilling.org PCMU/8000 20 ms 160 samples 64000 bits 1 channels
  46. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_codec.c:111 sofia/default/2357506173@alpha.astppbilling.org Original read codec set to PCMU:0
  47. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5915 Set telephone-event payload to 101@8000
  48. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_media.c:5973 sofia/default/2357506173@alpha.astppbilling.org Set 2833 dtmf send payload to 101 recv payload to 101
  49. 2022-07-12 12:04:19.816116 93.90% [DEBUG] sofia.c:7933 (sofia/default/2357506173@alpha.astppbilling.org) State Change CS_NEW -> CS_INIT
  50. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:581 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_INIT (Cur 1 Tot 431)
  51. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:624 (sofia/default/2357506173@alpha.astppbilling.org) State INIT
  52. 2022-07-12 12:04:19.816116 93.90% [DEBUG] mod_sofia.c:97 sofia/default/2357506173@alpha.astppbilling.org SOFIA INIT
  53. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:40 sofia/default/2357506173@alpha.astppbilling.org Standard INIT
  54. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:48 (sofia/default/2357506173@alpha.astppbilling.org) State Change CS_INIT -> CS_ROUTING
  55. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:624 (sofia/default/2357506173@alpha.astppbilling.org) State INIT going to sleep
  56. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:581 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_ROUTING (Cur 1 Tot 431)
  57. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_channel.c:2380 (sofia/default/2357506173@alpha.astppbilling.org) Callstate Change DOWN -> RINGING
  58. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:640 (sofia/default/2357506173@alpha.astppbilling.org) State ROUTING
  59. 2022-07-12 12:04:19.816116 93.90% [DEBUG] mod_sofia.c:158 sofia/default/2357506173@alpha.astppbilling.org SOFIA ROUTING
  60. 2022-07-12 12:04:19.816116 93.90% [DEBUG] switch_core_state_machine.c:230 sofia/default/2357506173@alpha.astppbilling.org Standard ROUTING
  61. 2022-07-12 12:04:19.816116 93.90% [INFO] mod_dialplan_xml.c:639 Processing Agent Softphone <2357506173>->*98 in context default
  62. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_cpp.cpp:1465 [ASTPP] USING CACHE
  63. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CACHING_DEBUG_SYSTEM]1.0
  64. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CACHING_DEBUG_SYSTEM]1.0
  65. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [LOAD_ADDON_CONF] Query :SELECT package_name FROM addons
  66. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_cpp.cpp:1465 [ASTPP] [feature_code_call_transfer] Blind Call Flag: 0
  67. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_cpp.cpp:1465 [ASTPP] [feature_code_call_transfer] Hunt Destination Number: *98
  68. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer_attended' limit 1
  69. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_action = 'call_transfer' limit 1
  70. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_cpp.cpp:1465 [ASTPP] [feature_code_call_transfer] Feature Code Transfer Blind Value :*2
  71. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_cpp.cpp:1465 [ASTPP] [Dialplan] Dialed number : *98
  72. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CHECK_FEATURE_CODE] Query :SELECT id,feature_action,feature_code from feature_code where feature_code = '*98' limit 1
  73. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_cpp.cpp:1465 [ASTPP] [PBX] Feature Code Action : spy_call
  74. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [get_Sip_Accountcode] Query :SELECT sip_devices.accountid from sip_devices,domains where sip_devices.accountid=domains.accountid and sip_devices.username = '2357506173' and domain = 'alpha.astppbilling.org' limit 1
  75. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CHECK_LOCAL_CALL] Query :SELECT sip_devices.id as sip_id,sip_devices.username as username,accounts.number as accountcode,sip_devices.accountid as accountid,accounts.did_cid_translation as did_cid_translation,sip_devices.codec as sip_codec FROM sip_devices as sip_devices,accounts as  accounts ,domains WHERE accounts.id=domains.accountid AND accounts.status=0 AND accounts.deleted=0 AND accounts.id=sip_devices.accountid AND sip_devices.username="2357506173"  AND domains.domain="alpha.astppbilling.org" limit 1
  76. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [FEATURE_CODE] Sip Info Id :57
  77. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [FEATURE_CODE] Feature Code Action :spy_call
  78. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] Generated XML:
  79. <?xml version="1.0" encoding="UTF-8" standalone="no"?>
  80. <document type="freeswitch/xml">
  81. <section name="dialplan" description="ASTPP Dialplan">
  82. <context name="default">
  83. <extension name="\*98">
  84. <condition field="destination_number" expression="\*98">
  85. <action application="export" data="did_user_domain=alpha.astppbilling.org"/>
  86. <action application="set" data="feature_code_type=mod_spy"/>
  87. <action application="set" data="user_domain=alpha.astppbilling.org"/>
  88. <action application="lua" data="astpp/lib/pbx/astpp-feature-code.lua"/>
  89. </condition>
  90. </extension>
  91. </context>
  92. </section>
  93. </document>
  94. Dialplan: sofia/default/2357506173@alpha.astppbilling.org parsing [default->\*98] continue=false
  95. Dialplan: sofia/default/2357506173@alpha.astppbilling.org Regex (PASS) [\*98] destination_number(*98) =~ /\*98/ break=on-false
  96. Dialplan: sofia/default/2357506173@alpha.astppbilling.org Action export(did_user_domain=alpha.astppbilling.org)
  97. Dialplan: sofia/default/2357506173@alpha.astppbilling.org Action set(feature_code_type=mod_spy)
  98. Dialplan: sofia/default/2357506173@alpha.astppbilling.org Action set(user_domain=alpha.astppbilling.org)
  99. Dialplan: sofia/default/2357506173@alpha.astppbilling.org Action lua(astpp/lib/pbx/astpp-feature-code.lua)
  100. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_state_machine.c:281 (sofia/default/2357506173@alpha.astppbilling.org) State Change CS_ROUTING -> CS_EXECUTE
  101. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_state_machine.c:640 (sofia/default/2357506173@alpha.astppbilling.org) State ROUTING going to sleep
  102. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_state_machine.c:581 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_EXECUTE (Cur 1 Tot 431)
  103. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_state_machine.c:647 (sofia/default/2357506173@alpha.astppbilling.org) State EXECUTE
  104. 2022-07-12 12:04:19.836095 93.90% [DEBUG] mod_sofia.c:213 sofia/default/2357506173@alpha.astppbilling.org SOFIA EXECUTE
  105. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_state_machine.c:323 sofia/default/2357506173@alpha.astppbilling.org Standard EXECUTE
  106. EXECUTE [depth=0] sofia/default/2357506173@alpha.astppbilling.org export(did_user_domain=alpha.astppbilling.org)
  107. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [did_user_domain]=[alpha.astppbilling.org]
  108. EXECUTE [depth=0] sofia/default/2357506173@alpha.astppbilling.org set(feature_code_type=mod_spy)
  109. 2022-07-12 12:04:19.836095 93.90% [DEBUG] mod_dptools.c:1685 SET sofia/default/2357506173@alpha.astppbilling.org [feature_code_type]=[mod_spy]
  110. EXECUTE [depth=0] sofia/default/2357506173@alpha.astppbilling.org set(user_domain=alpha.astppbilling.org)
  111. 2022-07-12 12:04:19.836095 93.90% [DEBUG] mod_dptools.c:1685 SET sofia/default/2357506173@alpha.astppbilling.org [user_domain]=[alpha.astppbilling.org]
  112. EXECUTE [depth=0] sofia/default/2357506173@alpha.astppbilling.org lua(astpp/lib/pbx/astpp-feature-code.lua)
  113. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [CACHING_DEBUG_SYSTEM]1.0
  114. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM `system` WHERE group_title IN ('global','opensips','callingcard','calls','international_prefixes','interconnect_code')
  115. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_cpp.cpp:1465 [FEATURE_CODE] Feature Code Type :mod_spy
  116. 2022-07-12 12:04:19.836095 93.90% [INFO] switch_ivr_play_say.c:2541 Sending early media
  117. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_media.c:8777 AUDIO RTP [sofia/default/2357506173@alpha.astppbilling.org] 168.119.48.166 port 29126 -> 103.240.35.46 port 5008 codec: 0 ms: 20
  118. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_rtp.c:4619 Starting timer [soft] 160 bytes per 20ms
  119. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_media.c:9089 sofia/default/2357506173@alpha.astppbilling.org Set 2833 dtmf send payload to 101
  120. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_media.c:9096 sofia/default/2357506173@alpha.astppbilling.org Set 2833 dtmf receive payload to 101
  121. 2022-07-12 12:04:19.836095 93.90% [DEBUG] switch_core_media.c:9119 sofia/default/2357506173@alpha.astppbilling.org Set rtp dtmf delay to 40
  122. 2022-07-12 12:04:19.836095 93.90% [DEBUG] mod_sofia.c:2610 Ring SDP:
  123. v=0
  124. o=FreeSWITCH 1657598333 1657598334 IN IP4 168.119.48.166
  125. s=FreeSWITCH
  126. c=IN IP4 168.119.48.166
  127. t=0 0
  128. m=audio 29126 RTP/AVP 0 101
  129. a=rtpmap:0 PCMU/8000
  130. a=rtpmap:101 telephone-event/8000
  131. a=fmtp:101 0-15
  132. a=ptime:20
  133. a=sendrecv
  134.  
  135. 2022-07-12 12:04:19.836095 93.90% [NOTICE] mod_sofia.c:2613 Pre-Answer sofia/default/2357506173@alpha.astppbilling.org!
  136. 2022-07-12 12:04:19.856092 93.90% [DEBUG] switch_channel.c:3622 (sofia/default/2357506173@alpha.astppbilling.org) Callstate Change RINGING -> EARLY
  137. 2022-07-12 12:04:19.856092 93.90% [DEBUG] switch_core_file.c:444 File /usr/local/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav sample rate 22050 doesn't match requested rate 8000
  138. 2022-07-12 12:04:19.856092 93.90% [WARNING] switch_core_file.c:463 File has 2 channels, muxing to 1 channel will occur.
  139. 2022-07-12 12:04:19.856092 93.90% [DEBUG] switch_ivr_play_say.c:1556 Codec Activated L16@8000hz 1 channels 20ms
  140. 2022-07-12 12:04:19.856092 93.90% [DEBUG] sofia.c:7499 Channel sofia/default/2357506173@alpha.astppbilling.org entering state [early][183]
  141. 2022-07-12 12:04:20.176093 93.90% [DEBUG] switch_rtp.c:7934 Correct audio ip/port confirmed.
  142. 2022-07-12 12:04:23.016086 94.03% [DEBUG] switch_ivr_play_say.c:2001 done playing file /usr/local/freeswitch/sounds/en/us/callie/astpp-pbx-extension-number.wav
  143. 2022-07-12 12:04:23.356091 94.30% [INFO] switch_channel.c:527 RECV DTMF 1:1920
  144. 2022-07-12 12:04:23.356091 94.30% [DEBUG] sofia.c:10126 INFO DTMF(1)
  145. 2022-07-12 12:04:23.536132 94.30% [DEBUG] switch_rtp.c:8179 RTP RECV DTMF 1:1280
  146. 2022-07-12 12:04:23.536132 94.30% [INFO] switch_channel.c:527 RECV DTMF 1:1280
  147. 2022-07-12 12:04:24.236102 94.30% [INFO] switch_channel.c:527 RECV DTMF 0:1920
  148. 2022-07-12 12:04:24.236102 94.30% [DEBUG] sofia.c:10126 INFO DTMF(0)
  149. 2022-07-12 12:04:24.456123 94.27% [DEBUG] switch_rtp.c:8179 RTP RECV DTMF 0:1280
  150. 2022-07-12 12:04:24.456123 94.27% [INFO] switch_channel.c:527 RECV DTMF 0:1280
  151. 2022-07-12 12:04:24.956094 94.27% [INFO] switch_channel.c:527 RECV DTMF 1:1920
  152. 2022-07-12 12:04:24.956094 94.27% [DEBUG] sofia.c:10126 INFO DTMF(1)
  153. 2022-07-12 12:04:25.136081 94.27% [DEBUG] switch_rtp.c:8179 RTP RECV DTMF 1:1280
  154. 2022-07-12 12:04:25.136081 94.27% [INFO] switch_channel.c:527 RECV DTMF 1:1280
  155. 2022-07-12 12:04:26.316087 94.30% [DEBUG] switch_rtp.c:8179 RTP RECV DTMF #:1280
  156. span style="color: green; font-weight: bold;"> 2022-07-12 12:04:26.316087 94.30% [INFO] switch_channel.c:527 RECV DTMF #:1280
  157. span style="color: goldenrod; font-weight: bold;"> 2022-07-12 12:04:26.316087 94.30% [DEBUG] switch_cpp.cpp:1465 [FEATURE_CODE] Extension Number:110011
  158. 2022-07-12 12:04:26.316087 94.30% [DEBUG] switch_cpp.cpp:1465 [FEATURE_CODE] Extension Statusshow channels like 110011
  159. 2022-07-12 12:04:26.316087 94.30% [DEBUG] switch_core_file.c:444 File /usr/local/freeswitch/sounds/en/us/callie/astpp-goodbye.wav sample rate 16000 doesn't match requested rate 8000
  160. 2022-07-12 12:04:26.316087 94.30% [DEBUG] switch_ivr_play_say.c:1556 Codec Activated L16@8000hz 1 channels 20ms
  161. 2022-07-12 12:04:26.356091 94.37% [INFO] switch_channel.c:527 RECV DTMF #:1920
  162. span style="color: green; font-weight: bold;"> 2022-07-12 12:04:26.356091 94.37% [DEBUG] sofia.c:10126 INFO DTMF(#)
  163. span style="color: goldenrod; font-weight: bold;"> 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_ivr_play_say.c:2001 done playing file /usr/local/freeswitch/sounds/en/us/callie/astpp-goodbye.wav
  164. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_cpp.cpp:749 CoreSession::hangup
  165. 2022-07-12 12:04:27.116106 94.37% [NOTICE] switch_cpp.cpp:751 Hangup sofia/default/2357506173@alpha.astppbilling.org [CS_EXECUTE] [NORMAL_CLEARING]
  166. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_cpp.cpp:1209 sofia/default/2357506173@alpha.astppbilling.org destroy/unlink session from object
  167. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_session.c:2983 sofia/default/2357506173@alpha.astppbilling.org skip receive message [PHONE_EVENT] (channel is hungup already)
  168. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:647 (sofia/default/2357506173@alpha.astppbilling.org) State EXECUTE going to sleep
  169. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:581 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_HANGUP (Cur 1 Tot 431)
  170. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:844 (sofia/default/2357506173@alpha.astppbilling.org) Callstate Change EARLY -> HANGUP
  171. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:846 (sofia/default/2357506173@alpha.astppbilling.org) State HANGUP
  172. 2022-07-12 12:04:27.116106 94.37% [DEBUG] mod_sofia.c:468 Channel sofia/default/2357506173@alpha.astppbilling.org hanging up, cause: NORMAL_CLEARING
  173. 2022-07-12 12:04:27.116106 94.37% [DEBUG] mod_sofia.c:613 Responding to INVITE with: 480
  174. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:59 sofia/default/2357506173@alpha.astppbilling.org Standard HANGUP, cause: NORMAL_CLEARING
  175. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:846 (sofia/default/2357506173@alpha.astppbilling.org) State HANGUP going to sleep
  176. 2022-07-12 12:04:27.116106 94.37% [DEBUG] switch_core_state_machine.c:616 (sofia/default/2357506173@alpha.astppbilling.org) State Change CS_HANGUP -> CS_REPORTING
  177. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:581 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_REPORTING (Cur 1 Tot 431)
  178. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:932 (sofia/default/2357506173@alpha.astppbilling.org) State REPORTING
  179. 2022-07-12 12:04:27.136092 94.37% [INFO] mod_json_cdr.c:271 Process [613e403b-c406-45ba-a56d-5a322f5fc923.cdr.json]
  180. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:168 sofia/default/2357506173@alpha.astppbilling.org Standard REPORTING, cause: NORMAL_CLEARING
  181. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:932 (sofia/default/2357506173@alpha.astppbilling.org) State REPORTING going to sleep
  182. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:607 (sofia/default/2357506173@alpha.astppbilling.org) State Change CS_REPORTING -> CS_DESTROY
  183. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_session.c:1753 Session 431 (sofia/default/2357506173@alpha.astppbilling.org) Locked, Waiting on external entities
  184. 2022-07-12 12:04:27.136092 94.37% [NOTICE] switch_core_session.c:1771 Session 431 (sofia/default/2357506173@alpha.astppbilling.org) Ended
  185. 2022-07-12 12:04:27.136092 94.37% [NOTICE] switch_core_session.c:1775 Close Channel sofia/default/2357506173@alpha.astppbilling.org [CS_DESTROY]
  186. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:735 (sofia/default/2357506173@alpha.astppbilling.org) Running State Change CS_DESTROY (Cur 0 Tot 431)
  187. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:745 (sofia/default/2357506173@alpha.astppbilling.org) State DESTROY
  188. 2022-07-12 12:04:27.136092 94.37% [DEBUG] mod_sofia.c:379 sofia/default/2357506173@alpha.astppbilling.org SOFIA DESTROY
  189. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:175 sofia/default/2357506173@alpha.astppbilling.org Standard DESTROY
  190. 2022-07-12 12:04:27.136092 94.37% [DEBUG] switch_core_state_machine.c:745 (sofia/default/2357506173@alpha.astppbilling.org) State DESTROY going to sleep
  191. 2022-07-12 12:04:34.496094 96.00% [WARNING] sofia_reg.c:1861 SIP auth challenge (REGISTER) on sofia profile 'default' for [8746774227@alpha4.astppbilling.org] from ip 103.240.35.46
  192. 2022-07-12 12:04:34.976110 96.00% [WARNING] sofia_reg.c:1861 SIP auth challenge (INVITE) on sofia profile 'default' for [8746774227@alpha4.astppbilling.org] from ip 103.240.35.46
  193. freeswitch@devangnewdeb11>