1. 2019-05-22 19:11:55.910784 [NOTICE] switch_channel.c:1104 New Channel sofia/gateway1/0449131272@202.10.26.1:5060 [a6ef2390-7c71-11e9-a7fe-33f71d9eef79]
2. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_NEW (Cur 5 Tot 338354)
3. 2019-05-22 19:11:55.910784 [DEBUG] sofia.c:9873 sofia/gateway1/0449131272@202.10.26.1:5060 receiving invite from 202.10.26.1:5060 version: 1.6.20  64bit
4. 2019-05-22 19:11:55.910784 [DEBUG] sofia.c:9989 IP 202.10.26.1 Approved by acl "default[]". Access Granted.
5. 2019-05-22 19:11:55.910784 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [received][100]
6. 2019-05-22 19:11:55.910784 [DEBUG] sofia.c:7094 Remote SDP:
7. v=0
8. o=- 89383072259254 89383072259254 IN IP4 202.10.26.1
9. s=-
10. c=IN IP4 202.10.26.1
11. t=0 0
12. m=audio 43506 RTP/AVP 8 0 18 101
13. a=rtpmap:8 PCMA/8000
14. a=rtpmap:0 PCMU/8000
15. a=rtpmap:18 G729/8000
16. a=fmtp:18 annexb=no
17. a=rtpmap:101 telephone-event/8000
18. a=ptime:20
19.  
20. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
21. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
22. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
23. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G729:18:8000:20:8000:1]
24. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
25. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
26. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
27. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G729:18:8000:20:8000:1]
28. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMU:0:8000:20:64000:1]
29. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[PCMA:8:8000:20:64000:1]
30. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [G729:18:8000:20:8000:1]/[G729:18:8000:20:8000:1]
31. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [G729:18:8000:20:8000:1] ++++ is saved as a match
32. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
33. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:3061 Set Codec sofia/gateway1/0449131272@202.10.26.1:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
34. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_codec.c:111 sofia/gateway1/0449131272@202.10.26.1:5060 Original read codec set to PCMA:8
35. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
36. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_media.c:4767 sofia/gateway1/0449131272@202.10.26.1:5060 Set 2833 dtmf send payload to 101 recv payload to 101
37. 2019-05-22 19:11:55.910784 [DEBUG] sofia.c:7507 (sofia/gateway1/0449131272@202.10.26.1:5060) State Change CS_NEW -> CS_INIT
38. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:603 (sofia/gateway1/0449131272@202.10.26.1:5060) State NEW
39. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_INIT (Cur 5 Tot 338354)
40. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:627 (sofia/gateway1/0449131272@202.10.26.1:5060) State INIT
41. 2019-05-22 19:11:55.910784 [DEBUG] mod_sofia.c:90 sofia/gateway1/0449131272@202.10.26.1:5060 SOFIA INIT
42. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:40 sofia/gateway1/0449131272@202.10.26.1:5060 Standard INIT
43. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:48 (sofia/gateway1/0449131272@202.10.26.1:5060) State Change CS_INIT -> CS_ROUTING
44. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:627 (sofia/gateway1/0449131272@202.10.26.1:5060) State INIT going to sleep
45. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_ROUTING (Cur 5 Tot 338354)
46. 2019-05-22 19:11:55.910784 [DEBUG] switch_channel.c:2249 (sofia/gateway1/0449131272@202.10.26.1:5060) Callstate Change DOWN -> RINGING
47. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:643 (sofia/gateway1/0449131272@202.10.26.1:5060) State ROUTING
48. 2019-05-22 19:11:55.910784 [DEBUG] mod_sofia.c:143 sofia/gateway1/0449131272@202.10.26.1:5060 SOFIA ROUTING
49. 2019-05-22 19:11:55.910784 [DEBUG] switch_core_state_machine.c:236 sofia/gateway1/0449131272@202.10.26.1:5060 Standard ROUTING
50. 2019-05-22 19:11:55.910784 [INFO] mod_dialplan_xml.c:637 Processing 0449131272 <0449131272>->0283965200 in context default
51. 2019-05-22 19:11:55.910784 [DEBUG] freeswitch_lua.cpp:365 DBH handle 0x7f3eb406b550 Connected.
52. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [LOAD_CONF] Query :SELECT name,value FROM system WHERE group_title IN ('global','opensips','callingcard')
53. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Dialed number : 0283965200
54. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Caller Id name / number  : 0449131272 / 0449131272
55. 2019-05-22 19:11:55.910784 [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 ="0283965200" LIMIT 1
56. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Call direction : inbound
57. 2019-05-22 19:11:55.910784 [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("202.10.26.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 "0283965200"  LIKE CONCAT(prefix,'%') ORDER BY LENGTH(prefix) DESC LIMIT 1
58. 2019-05-22 19:11:55.910784 [NOTICE] switch_cpp.cpp:1365 [ASTPP] [Accountcode : 7335503421]
59. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "7335503421" OR id="7335503421") AND status=0 AND deleted=0 AND (expiry >= '2019-05-22 09:11:58' OR expiry = '0000-00-00 00:00:00') limit 1
60. 2019-05-22 19:11:55.910784 [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 ='^0283965200.*' OR patterns ='^028396520.*' OR patterns ='^02839652.*' OR patterns ='^0283965.*' OR patterns ='^028396.*' OR patterns ='^02839.*' OR patterns ='^0283.*' OR patterns ='^028.*' OR patterns ='^02.*' OR patterns ='^0.*' OR patterns ='--') AND status = 0 AND pricelist_id = 1 ORDER BY LENGTH(PKGPTR.patterns) DESC LIMIT 1
61. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Account Information ===================
62. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] User id : 3
63. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Account code : 7335503421
64. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Balance : 10000
65. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Type : 0 [0:prepaid,1:postpaid]
66. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Ratecard id : 1
67. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ========================================================
68. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0
69. 2019-05-22 19:11:55.910784 [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 ="0283965200" LIMIT 1
70. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information ===================
71. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 1209
72. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.00000
73. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0
74. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.00000
75. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : 0283965200
76. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 3
77. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================
78. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 1000000
79. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Call Max length duration : 1000000 minutes
80. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [DOAUTHORIZATION] Query :SELECT * FROM accounts WHERE (number = "16" OR id="16") AND status=0 AND deleted=0 AND (expiry >= '2019-05-22 09:11:58' OR expiry = '0000-00-00 00:00:00') limit 1
81. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_PRICELIST_INFO] Query :select * from pricelists WHERE id = 1 AND status = 0
82. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [GET_RATES] Query :SELECT * FROM routes WHERE (pattern ='^0283965200.*' OR pattern ='^028396520.*' OR pattern ='^02839652.*' OR pattern ='^0283965.*' OR pattern ='^028396.*' OR pattern ='^02839.*' OR pattern ='^0283.*' OR pattern ='^028.*' OR pattern ='^02.*' OR pattern ='^0.*' OR pattern ='--') AND status = 0 AND pricelist_id = 1  ORDER BY LENGTH(pattern) DESC,cost DESC LIMIT 1
83. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] =============== Rates Information ===================
84. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ID : 5
85. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Connectcost : 0.08000
86. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Includedseconds : 0
87. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Cost : 0.00000
88. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] comment : National
89. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] Accid : 3
90. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] ================================================================
91. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [FIND_MAXLENGTH] Call is free - assigning max length!!! :: 1000000
92. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML:3
93. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Userinfo XML:3
94. 2019-05-22 19:11:55.910784 [INFO] switch_cpp.cpp:1365 [ASTPP] [userinfo] Actual CustomerInfo XML : 3
95. 2019-05-22 19:11:55.910784 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLINBOUND] Caller ID Translation Starts
96. 2019-05-22 19:11:55.910784 [WARNING] switch_cpp.cpp:1365 [ASTPP] [FSXMLINBOUND] Caller ID Translation Ends
97. 2019-05-22 19:11:55.910784 [DEBUG] switch_cpp.cpp:1365 [ASTPP] [Dialplan] Generated XML:<?xml version="1.0" encoding="UTF-8" standalone="no"?>
98. <document type="freeswitch/xml">
99. <section name="dialplan" description="ASTPP Dialplan">
100. <context name="default">
101. <extension name="0283965200">
102. <condition field="destination_number" expression="0283965200">
103. <action application="set" data="effective_destination_number=0283965200"/>
104. <action application="sched_hangup" data="+60000000 normal_clearing"/>
105. <action application="set" data="callstart=2019-05-22 09:11:58"/>
106. <action application="set" data="hangup_after_bridge=true"/>
107. <action application="set" data="continue_on_fail=true"/>
108. <action application="set" data="account_id=3"/>
109. <action application="set" data="parent_id=0"/>
110. <action application="set" data="entity_id=3"/>
111. <action application="set" data="call_processed=internal"/>
112. <action application="set" data="call_direction=inbound"/>
113. <action application="set" data="accountname=CTS 2"/>
114. <action application="set" data="origination_rates_did=ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16"/>
115. <action application="set" data="origination_rates=ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3"/>
116. <action application="set" data="original_caller_id_name=0449131272"/>
117. <action application="set" data="original_caller_id_number=0449131272"/>
118. <action application="set" data="effective_caller_id_name=0449131272"/>
119. <action application="set" data="effective_caller_id_number=0449131272"/>
120. <action application="set" data="receiver_accid=16"/>
121. <action application="set" data="calltype=SIP-DID"/>
122. <action application="bridge" data="{sip_contact_user=0283965200}[leg_timeout=30]sofia/default/0283965200${regex(${sofia_contact(1976788220@${domain_name})}|^[^@]+(.*)|%1)}"/>
123. <condition field="${cond(${user_data 1976788220@${domain_name} param vm-enabled} == true ? YES : NO)}" expression="^YES$">
124. <action application="answer"/>
125. <action application="export" data="voicemail_alternate_greet_id=0283965200"/>
126. <action application="voicemail" data="default $${domain_name} 1976788220"/>
127. <anti-action application="hangup" data="${originate_disposition}"/>
128. </condition>
129. </condition>
130. </extension>
131. </context>
132. </section>
133. </document>
134. 2019-05-22 19:11:55.910784 [DEBUG] freeswitch_lua.cpp:382 DBH handle 0x7f3eb406b550 released.
135. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 parsing [default->0283965200] continue=false
136. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Regex (PASS) [0283965200] destination_number(0283965200) =~ /0283965200/ break=on-false
137. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(effective_destination_number=0283965200)
138. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action sched_hangup(+60000000 normal_clearing)
139. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(callstart=2019-05-22 09:11:58)
140. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(hangup_after_bridge=true)
141. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(continue_on_fail=true)
142. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(account_id=3)
143. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(parent_id=0)
144. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(entity_id=3)
145. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(call_processed=internal)
146. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(call_direction=inbound)
147. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(accountname=CTS 2)
148. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(origination_rates_did=ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16)
149. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(origination_rates=ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3)
150. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(original_caller_id_name=0449131272)
151. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(original_caller_id_number=0449131272)
152. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(effective_caller_id_name=0449131272)
153. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(effective_caller_id_number=0449131272)
154. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(receiver_accid=16)
155. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action set(calltype=SIP-DID)
156. Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Action bridge({sip_contact_user=0283965200}[leg_timeout=30]sofia/default/0283965200${regex(${sofia_contact(1976788220@${domain_name})}|^[^@]+(.*)|%1)})
157. |--- Dialplan: Processing recursive conditions level:1 [0283965200_recur_1] require-nested=TRUE
158. |--- Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 Regex (FAIL) [0283965200_recur_1] ${cond(${user_data 1976788220@${domain_name} param vm-enabled} == true ? YES : NO)}(NO) =~ /^YES$/ break=on-false
159. |--- Dialplan: sofia/gateway1/0449131272@202.10.26.1:5060 ANTI-Action hangup(${originate_disposition})
160. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:286 (sofia/gateway1/0449131272@202.10.26.1:5060) State Change CS_ROUTING -> CS_EXECUTE
161. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:643 (sofia/gateway1/0449131272@202.10.26.1:5060) State ROUTING going to sleep
162. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/gateway1/0449131272@202.10.26.1:5060) Running State Change CS_EXECUTE (Cur 5 Tot 338354)
163. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:650 (sofia/gateway1/0449131272@202.10.26.1:5060) State EXECUTE
164. 2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:198 sofia/gateway1/0449131272@202.10.26.1:5060 SOFIA EXECUTE
165. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:328 sofia/gateway1/0449131272@202.10.26.1:5060 Standard EXECUTE
166. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(effective_destination_number=0283965200)
167. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [effective_destination_number]=[0283965200]
168. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 sched_hangup(+60000000 normal_clearing)
169. 2019-05-22 19:11:55.930798 [DEBUG] switch_scheduler.c:249 Added task 148509 switch_ivr_schedule_hangup (a6ef2390-7c71-11e9-a7fe-33f71d9eef79) to run at 1618516315
170. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(callstart=2019-05-22 09:11:58)
171. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [callstart]=[2019-05-22 09:11:58]
172. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(hangup_after_bridge=true)
173. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [hangup_after_bridge]=[true]
174. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(continue_on_fail=true)
175. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [continue_on_fail]=[true]
176. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(account_id=3)
177. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [account_id]=[3]
178. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(parent_id=0)
179. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [parent_id]=[0]
180. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(entity_id=3)
181. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [entity_id]=[3]
182. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(call_processed=internal)
183. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [call_processed]=[internal]
184. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(call_direction=inbound)
185. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [call_direction]=[inbound]
186. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(accountname=CTS 2)
187. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [accountname]=[CTS 2]
188. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(origination_rates_did=ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16)
189. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [origination_rates_did]=[ID:1209|CODE:^.0283965200.*|DESTINATION:0283965200|CONNECTIONCOST:0.00000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:0|MARKUP:0|ACCID:16]
190. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(origination_rates=ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3)
191. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [origination_rates]=[ID:5|CODE:^02.*|DESTINATION:National|CONNECTIONCOST:0.08000|INCLUDEDSECONDS:0|COST:0.00000|INC:0|INITIALBLOCK:0|RATEGROUP:1|MARKUP:0|ACCID:3]
192. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(original_caller_id_name=0449131272)
193. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [original_caller_id_name]=[0449131272]
194. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(original_caller_id_number=0449131272)
195. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [original_caller_id_number]=[0449131272]
196. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(effective_caller_id_name=0449131272)
197. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [effective_caller_id_name]=[0449131272]
198. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(effective_caller_id_number=0449131272)
199. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [effective_caller_id_number]=[0449131272]
200. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(receiver_accid=16)
201. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [receiver_accid]=[16]
202. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 set(calltype=SIP-DID)
203. 2019-05-22 19:11:55.930798 [DEBUG] mod_dptools.c:1548 SET sofia/gateway1/0449131272@202.10.26.1:5060 [calltype]=[SIP-DID]
204. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 bridge({sip_contact_user=0283965200}[leg_timeout=30]sofia/default/0283965200@58.96.28.252:5060;transport=UDP)
205. 2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:2142 Parsing global variables
206. 2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:2669 Parsing session specific variables
207. 2019-05-22 19:11:55.930798 [NOTICE] switch_channel.c:1104 New Channel sofia/default/0283965200@58.96.28.252:5060 [a6f3d052-7c71-11e9-a818-33f71d9eef79]
208. 2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:4819 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_NEW -> CS_INIT
209. 2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:2963 sofia/default/0283965200@58.96.28.252:5060 Setting leg timeout to 30
210. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_INIT (Cur 6 Tot 338355)
211. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0283965200@58.96.28.252:5060) State INIT
212. 2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:90 sofia/default/0283965200@58.96.28.252:5060 SOFIA INIT
213. 2019-05-22 19:11:55.930798 [DEBUG] sofia_glue.c:1295 sofia/default/0283965200@58.96.28.252:5060 sending invite version: 1.6.20  64bit
214. Local SDP:
215. v=0
216. o=FreeSWITCH 1558492093 1558492094 IN IP4 59.100.179.100
217. s=FreeSWITCH
218. c=IN IP4 59.100.179.100
219. t=0 0
220. m=audio 24222 RTP/AVP 8 101
221. a=rtpmap:8 PCMA/8000
222. a=rtpmap:101 telephone-event/8000
223. a=fmtp:101 0-16
224. a=ptime:20
225. a=sendrecv
226.  
227. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:40 sofia/default/0283965200@58.96.28.252:5060 Standard INIT
228. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:48 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_INIT -> CS_ROUTING
229. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:627 (sofia/default/0283965200@58.96.28.252:5060) State INIT going to sleep
230. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_ROUTING (Cur 6 Tot 338355)
231. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0283965200@58.96.28.252:5060) State ROUTING
232. 2019-05-22 19:11:55.930798 [DEBUG] mod_sofia.c:143 sofia/default/0283965200@58.96.28.252:5060 SOFIA ROUTING
233. 2019-05-22 19:11:55.930798 [DEBUG] switch_ivr_originate.c:67 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
234. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:643 (sofia/default/0283965200@58.96.28.252:5060) State ROUTING going to sleep
235. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_CONSUME_MEDIA (Cur 6 Tot 338355)
236. 2019-05-22 19:11:55.930798 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [calling][0]
237. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:662 (sofia/default/0283965200@58.96.28.252:5060) State CONSUME_MEDIA
238. 2019-05-22 19:11:55.930798 [DEBUG] switch_core_state_machine.c:662 (sofia/default/0283965200@58.96.28.252:5060) State CONSUME_MEDIA going to sleep
239. 2019-05-22 19:11:56.230755 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [proceeding][183]
240. 2019-05-22 19:11:56.230755 [DEBUG] sofia.c:7094 Remote SDP:
241. v=0
242. o=SBC 1399 1001 IN IP4 58.96.28.252
243. s=VoipCall
244. c=IN IP4 58.96.28.252
245. t=0 0
246. m=audio 16676 RTP/AVP 8 101
247. c=IN IP4 58.96.28.252
248. a=rtpmap:8 PCMA/8000
249. a=rtpmap:101 telephone-event/8000
250. a=fmtp:101 0-15
251. a=ptime:20
252. a=maxptime:40
253. a=rtcp:16677
254.  
255. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
256. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
257. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
258. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:3061 Set Codec sofia/default/0283965200@58.96.28.252:5060 PCMA/8000 20 ms 160 samples 64000 bits 1 channels
259. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_codec.c:111 sofia/default/0283965200@58.96.28.252:5060 Original read codec set to PCMA:8
260. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
261. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:4767 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101 recv payload to 101
262. 2019-05-22 19:11:56.230755 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/default/0283965200@58.96.28.252:5060] 192.168.2.210 port 24222 -> 58.96.28.252 port 16676 codec: 8 ms: 20
263. 2019-05-22 19:11:56.230755 [DEBUG] switch_rtp.c:4137 Starting timer [soft] 160 bytes per 20ms
264. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7096 Activating RTCP PORT 16677
265. 2019-05-22 19:11:56.250767 [DEBUG] switch_rtp.c:4533 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 16677
266. 2019-05-22 19:11:56.250767 [DEBUG] switch_rtp.c:2567 Setting RTCP remote addr to 58.96.28.252:16677 2
267. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7180 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101
268. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7187 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf receive payload to 101
269. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7210 sofia/default/0283965200@58.96.28.252:5060 Set rtp dtmf delay to 40
270. 2019-05-22 19:11:56.250767 [NOTICE] sofia_media.c:92 Pre-Answer sofia/default/0283965200@58.96.28.252:5060!
271. 2019-05-22 19:11:56.250767 [DEBUG] switch_channel.c:3474 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change DOWN -> EARLY
272. 2019-05-22 19:11:56.250767 [INFO] switch_ivr_originate.c:3654 Sending early media
273. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:6878 AUDIO RTP [sofia/gateway1/0449131272@202.10.26.1:5060] 10.239.237.34 port 23138 -> 202.10.26.1 port 43506 codec: 8 ms: 20
274. 2019-05-22 19:11:56.250767 [DEBUG] switch_rtp.c:4159 Not using a timer
275. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7180 sofia/gateway1/0449131272@202.10.26.1:5060 Set 2833 dtmf send payload to 101
276. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7187 sofia/gateway1/0449131272@202.10.26.1:5060 Set 2833 dtmf receive payload to 101
277. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_media.c:7210 sofia/gateway1/0449131272@202.10.26.1:5060 Set rtp dtmf delay to 40
278. 2019-05-22 19:11:56.250767 [DEBUG] mod_sofia.c:2364 Ring SDP:
279. v=0
280. o=FreeSWITCH 1558493178 1558493179 IN IP4 10.239.237.34
281. s=FreeSWITCH
282. c=IN IP4 10.239.237.34
283. t=0 0
284. m=audio 23138 RTP/AVP 8 101
285. a=rtpmap:8 PCMA/8000
286. a=rtpmap:101 telephone-event/8000
287. a=fmtp:101 0-16
288. a=ptime:20
289. a=sendrecv
290.  
291. 2019-05-22 19:11:56.250767 [NOTICE] mod_sofia.c:2367 Pre-Answer sofia/gateway1/0449131272@202.10.26.1:5060!
292. 2019-05-22 19:11:56.250767 [DEBUG] switch_channel.c:3474 (sofia/gateway1/0449131272@202.10.26.1:5060) Callstate Change RINGING -> EARLY
293. 2019-05-22 19:11:56.250767 [DEBUG] switch_ivr_originate.c:3705 Originate Resulted in Success: [sofia/default/0283965200@58.96.28.252:5060]
294. 2019-05-22 19:11:56.250767 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [early][183]
295. 2019-05-22 19:11:56.250767 [DEBUG] switch_ivr_bridge.c:1614 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
296. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_EXCHANGE_MEDIA (Cur 6 Tot 338355)
297. 2019-05-22 19:11:56.250767 [DEBUG] switch_core_state_machine.c:653 (sofia/default/0283965200@58.96.28.252:5060) State EXCHANGE_MEDIA
298. 2019-05-22 19:11:56.250767 [DEBUG] mod_sofia.c:631 SOFIA EXCHANGE_MEDIA
299. 2019-05-22 19:11:56.330746 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
300. 2019-05-22 19:11:56.350747 [DEBUG] switch_rtp.c:1887 rtcp_stats_init: audio ssrc[4170685508] base_seq[45584]
301. 2019-05-22 19:11:56.510748 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [proceeding][180]
302. 2019-05-22 19:11:56.510748 [NOTICE] sofia.c:7192 Ring-Ready sofia/default/0283965200@58.96.28.252:5060!
303. 2019-05-22 19:11:56.510748 [DEBUG] switch_channel.c:3346 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change EARLY -> RINGING
304. 2019-05-22 19:11:56.610748 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
305. 2019-05-22 19:11:56.750750 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [completing][200]
306. 2019-05-22 19:11:56.750750 [DEBUG] sofia.c:7091 Duplicate SDP
307. v=0
308. o=SBC 1399 1001 IN IP4 58.96.28.252
309. s=VoipCall
310. c=IN IP4 58.96.28.252
311. t=0 0
312. m=audio 16676 RTP/AVP 8 101
313. c=IN IP4 58.96.28.252
314. a=rtpmap:8 PCMA/8000
315. a=rtpmap:101 telephone-event/8000
316. a=fmtp:101 0-15
317. a=ptime:20
318. a=maxptime:40
319. a=rtcp:16677
320.  
321. 2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0499080933 entering state [completing][200]
322. 2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7091 Duplicate SDP
323. v=0
324. o=- 90353734859613 90353734859613 IN IP4 202.10.26.1
325. s=-
326. c=IN IP4 202.10.26.1
327. t=0 0
328. m=audio 43396 RTP/AVP 8 101
329. a=rtpmap:8 PCMA/8000
330. a=rtpmap:101 telephone-event/8000
331. a=fmtp:101 0-16
332. a=ptime:20
333.  
334. 2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0499080933 entering state [ready][200]
335. 2019-05-22 19:11:56.770755 [NOTICE] sofia.c:8159 Channel [sofia/gateway1/0499080933] has been answered
336. 2019-05-22 19:11:56.770755 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [ready][200]
337. 2019-05-22 19:11:56.770755 [DEBUG] switch_channel.c:3773 (sofia/gateway1/0499080933) Callstate Change EARLY -> ACTIVE
338. 2019-05-22 19:11:56.770755 [NOTICE] sofia.c:8159 Channel [sofia/default/0283965200@58.96.28.252:5060] has been answered
339. 2019-05-22 19:11:56.770755 [DEBUG] switch_channel.c:3773 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change RINGING -> ACTIVE
340. 2019-05-22 19:11:56.790752 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/0731589144@192.168.2.210.
341. 2019-05-22 19:11:56.790752 [DEBUG] mod_sofia.c:850 Local SDP sofia/default/0731589144@192.168.2.210:
342. v=0
343. o=FreeSWITCH 1558493939 1558493941 IN IP4 192.168.2.210
344. s=FreeSWITCH
345. c=IN IP4 192.168.2.210
346. t=0 0
347. m=audio 22368 RTP/AVP 8 101
348. a=rtpmap:8 PCMA/8000
349. a=rtpmap:101 telephone-event/8000
350. a=fmtp:101 0-16
351. a=ptime:20
352. a=sendrecv
353.  
354. 2019-05-22 19:11:56.790752 [NOTICE] switch_ivr_bridge.c:623 Channel [sofia/default/0731589144@192.168.2.210] has been answered
355. 2019-05-22 19:11:56.790752 [DEBUG] switch_channel.c:3773 (sofia/default/0731589144@192.168.2.210) Callstate Change EARLY -> ACTIVE
356. 2019-05-22 19:11:56.790752 [DEBUG] sofia.c:7084 Channel sofia/default/0731589144@192.168.2.210 entering state [completed][200]
357. 2019-05-22 19:11:56.790752 [DEBUG] sofia.c:7084 Channel sofia/default/0731589144@192.168.2.210 entering state [ready][200]
358. 2019-05-22 19:11:56.790752 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/gateway1/0449131272@202.10.26.1:5060.
359. 2019-05-22 19:11:56.790752 [DEBUG] mod_sofia.c:850 Local SDP sofia/gateway1/0449131272@202.10.26.1:5060:
360. v=0
361. o=FreeSWITCH 1558493178 1558493180 IN IP4 10.239.237.34
362. s=FreeSWITCH
363. c=IN IP4 10.239.237.34
364. t=0 0
365. m=audio 23138 RTP/AVP 8 101
366. a=rtpmap:8 PCMA/8000
367. a=rtpmap:101 telephone-event/8000
368. a=fmtp:101 0-16
369. a=ptime:20
370. a=sendrecv
371.  
372. 2019-05-22 19:11:56.790752 [NOTICE] switch_ivr_bridge.c:623 Channel [sofia/gateway1/0449131272@202.10.26.1:5060] has been answered
373. 2019-05-22 19:11:56.790752 [DEBUG] switch_channel.c:3773 (sofia/gateway1/0449131272@202.10.26.1:5060) Callstate Change EARLY -> ACTIVE
374. 2019-05-22 19:11:56.790752 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [completed][200]
375. 2019-05-22 19:11:56.830758 [DEBUG] sofia.c:7084 Channel sofia/gateway1/0449131272@202.10.26.1:5060 entering state [ready][200]
376. 2019-05-22 19:11:56.830758 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
377. 2019-05-22 19:11:56.870749 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
378. 2019-05-22 19:11:56.870749 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
379. 2019-05-22 19:12:01.150735 [DEBUG] switch_rtp.c:7308 Correct audio ip/port confirmed.
380. 2019-05-22 19:12:11.350750 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [received][100]
381. 2019-05-22 19:12:11.350750 [DEBUG] sofia.c:7094 Remote SDP:
382. v=0
383. o=SBC 1399 1002 IN IP4 58.96.28.252
384. s=VoipCall
385. c=IN IP4 58.96.28.252
386. t=0 0
387. m=audio 16676 RTP/AVP 8 101 13
388. c=IN IP4 58.96.28.252
389. a=rtpmap:8 PCMA/8000
390. a=rtpmap:101 telephone-event/8000
391. a=fmtp:101 0-15
392. a=rtpmap:13 CN/8000
393. a=inactive
394. a=ptime:20
395. a=maxptime:40
396. a=rtcp:16677
397.  
398. 2019-05-22 19:12:11.350750 [DEBUG] switch_channel.c:1844 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change ACTIVE -> HELD
399. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
400. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
401. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
402. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4373 Set comfort noise payload to 13
403. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
404. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4720 Set comfort noise payload to 13@8000
405. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:4767 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101 recv payload to 101
406. 2019-05-22 19:12:11.610733 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/0283965200@58.96.28.252:5060.
407. 2019-05-22 19:12:11.610733 [DEBUG] sofia.c:7999 Processing updated SDP
408. 2019-05-22 19:12:11.630749 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [completed][200]
409. 2019-05-22 19:12:11.630749 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [ready][200]
410. 2019-05-22 19:12:11.650741 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [received][100]
411. 2019-05-22 19:12:11.650741 [DEBUG] sofia.c:7094 Remote SDP:
412. v=0
413. o=SBC 1399 1003 IN IP4 58.96.28.252
414. s=VoipCall
415. c=IN IP4 58.96.28.252
416. t=0 0
417. m=audio 16676 RTP/AVP 8 101
418. c=IN IP4 58.96.28.252
419. a=rtpmap:8 PCMA/8000
420. a=rtpmap:101 telephone-event/8000
421. a=fmtp:101 0-15
422. a=ptime:20
423. a=maxptime:40
424. a=rtcp:16677
425.  
426. 2019-05-22 19:12:11.910744 [DEBUG] switch_channel.c:2029 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change HELD -> UNHELD
427. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4449 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
428. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4504 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
429. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4365 Set telephone-event payload to 101@8000
430. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4708 Set telephone-event payload to 101@8000
431. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:4767 sofia/default/0283965200@58.96.28.252:5060 Set 2833 dtmf send payload to 101 recv payload to 101
432. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_media.c:6861 Audio params are unchanged for sofia/default/0283965200@58.96.28.252:5060.
433. 2019-05-22 19:12:11.910744 [DEBUG] sofia.c:7999 Processing updated SDP
434. 2019-05-22 19:12:11.910744 [DEBUG] switch_core_io.c:941 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change UNHELD -> ACTIVE
435. 2019-05-22 19:12:11.910744 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [completed][200]
436. 2019-05-22 19:12:11.910744 [DEBUG] sofia.c:7084 Channel sofia/default/0283965200@58.96.28.252:5060 entering state [ready][200]
437. 2019-05-22 19:12:13.090745 [DEBUG] switch_ivr.c:623 sofia/gateway1/0449131272@202.10.26.1:5060 Command Execute playback(local_stream://moh)
438. EXECUTE sofia/gateway1/0449131272@202.10.26.1:5060 playback(local_stream://moh)
439. 2019-05-22 19:12:13.090745 [DEBUG] mod_local_stream.c:871 Opening Stream [moh/8000] 8000hz
440. 2019-05-22 19:12:13.090745 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
441. 2019-05-22 19:12:35.590742 [NOTICE] sofia.c:1012 Hangup sofia/default/0283965200@58.96.28.252:5060 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]
442. 2019-05-22 19:12:35.590742 [DEBUG] switch_ivr_bridge.c:787 BRIDGE THREAD DONE [sofia/default/0283965200@58.96.28.252:5060]
443. 2019-05-22 19:12:35.590742 [DEBUG] switch_core_state_machine.c:653 (sofia/default/0283965200@58.96.28.252:5060) State EXCHANGE_MEDIA going to sleep
444. 2019-05-22 19:12:35.590742 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_HANGUP (Cur 6 Tot 338355)
445. 2019-05-22 19:12:35.590742 [DEBUG] switch_core_state_machine.c:850 (sofia/default/0283965200@58.96.28.252:5060) Callstate Change ACTIVE -> HANGUP
446. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0283965200@58.96.28.252:5060) State HANGUP
447. 2019-05-22 19:12:35.610746 [DEBUG] mod_sofia.c:438 Channel sofia/default/0283965200@58.96.28.252:5060 hanging up, cause: NORMAL_CLEARING
448. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:60 sofia/default/0283965200@58.96.28.252:5060 Standard HANGUP, cause: NORMAL_CLEARING
449. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:852 (sofia/default/0283965200@58.96.28.252:5060) State HANGUP going to sleep
450. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:619 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_HANGUP -> CS_REPORTING
451. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:584 (sofia/default/0283965200@58.96.28.252:5060) Running State Change CS_REPORTING (Cur 6 Tot 338355)
452. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0283965200@58.96.28.252:5060) State REPORTING
453. 2019-05-22 19:12:35.610746 [INFO] mod_json_cdr.c:271 Process [a6f3d052-7c71-11e9-a818-33f71d9eef79.cdr.json]
454. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:174 sofia/default/0283965200@58.96.28.252:5060 Standard REPORTING, cause: NORMAL_CLEARING
455. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:938 (sofia/default/0283965200@58.96.28.252:5060) State REPORTING going to sleep
456. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_state_machine.c:610 (sofia/default/0283965200@58.96.28.252:5060) State Change CS_REPORTING -> CS_DESTROY
457. 2019-05-22 19:12:35.610746 [DEBUG] switch_core_session.c:1665 Session 338355 (sofia/default/0283965200@58.96.28.252:5060) Locked, Waiting on external entities